Inconsistent console logging using 'quiet' with encrypted root fs

Inconsistent console logging using 'quiet' with encrypted root fs

[Frans Pop]

The boot option 'quiet' sets console_loglevel to 4 (KERN_WARNING) instead 
of the default 7 (KERN_DEBUG).

This is respected during the early part of the boot of my system (x86_64, 
Debian stable), when kernel and initrd are loaded/run. But after the 
boot process mounts root and starts udev, I suddenly get a lot of messages 
of level KERN_INFO. That can't be the intention of 'quiet'...

When I look at /proc/sys/kernel/printk after the boot, I see 
console_loglevel is set to 7 instead of 4.

After some instrumentation I've found the cause for this problem.

My root partition is part of an encrypted LVM volume. So the initramfs 
prompts for the passphrase needed to unlock the PV, and Debian's 
cryptsetup package disables console logging around that to avoid the user 
interaction getting messed up by kernel printks. That this is needed can 
be seen from the partial log below.

To disable and re-enable logging to console, Debian's cryptsetup uses
klogctl(6, NULL, 0) and klogctl(7, NULL, 0). Problem is that the latter 
resores console_loglevel to the *default* level instead of the previous 
level. And thus the 'quiet' boot becomes noisy from that point onwards.

It seems reasonable to have "enable logging to console" restore the 
previous level instead. I'll follow up with a patch that does that.

Cheers,
FJP

dmesg *after* patch in follow-up mail was applied, with instrumentation:
[...]
usb 5-2: configuration #1 chosen from 1 choice
[cryptsetup prompts for passphrase -> logging disabled]
FJP: console logging disabled (console_loglevel: 1)
FJP: console_loglevel change 4->1
usb 1-2.2: new full speed USB device using ehci_hcd and address 4
ieee1394: Host added: ID:BUS[0-00:1023]  GUID[001b249929192210]
usb 1-2.2: configuration #1 chosen from 1 choice
usb 1-2.3: new low speed USB device using ehci_hcd and address 5
usb 1-2.3: configuration #1 chosen from 1 choice
usbcore: registered new interface driver hiddev
input: Logitech USB Receiver as /class/input/input1
generic-usb 0003:046D:C50D.0001: input: USB HID v1.10 Mouse
   [Logitech USB Receiver] on usb-0000:00:1a.7-2.3/input0
usbcore: registered new interface driver usbhid
usbhid: v2.6:USB HID core driver
usb 1-2.4: new low speed USB device using ehci_hcd and address 6
usb 1-2.4: configuration #1 chosen from 1 choice
input: USB Compliant Keyboard as /class/input/input2
generic-usb 0003:05A4:9841.0002: input: USB HID v1.10 Keyboard
   [USB Compliant Keyboard] on usb-0000:00:1a.7-2.4/input0
input: USB Compliant Keyboard as /class/input/input3
generic-usb 0003:05A4:9841.0003: input: USB HID v1.10 Device
   [USB Compliant Keyboard]  on usb-0000:00:1a.7-2.4/input1
[incorrect passphrase entered]
FJP: console logging enabled (console_loglevel: 4)
FJP: console_loglevel change 1->4
[incorrect passphrase, so cryptsetup asks again]
FJP: console logging disabled (console_loglevel: 1)
FJP: console_loglevel change 4->1
FJP: console logging enabled (console_loglevel: 4)
FJP: console_loglevel change 1->4
PM: Starting manual resume from disk
kjournald starting.  Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
[root file system mounted]
[...]

[PATCH,RFC] printk: Restore to previous console_loglevel when re-enabling logging

[Frans Pop]

When logging to console is disabled from userspace using klogctl
and later re-enabled, console_loglevel gets set to the default
log level instead to the previous value.
This means that if the kernel was booted with 'quiet', the boot is
suddenly no longer quiet after logging to console gets re-enabled.

Save the current console_loglevel when logging is disabled and
restore to that value. If the log level is set to a specific value
while disabled, this is interpreted as an implicit re-enabling of
the logging.

Signed-off-by: Frans Pop <elendil@planet.nl>
---

There are two variations possible on the patch below.

1) If klogctl(7) is called while logging is not disabled, then set level
   to default (partially preserving current functionality):
 	case 7:		/* Enable logging to console */
-		console_loglevel = default_console_loglevel;
+		if (saved_console_loglevel == -1)
+			console_loglevel = default_console_loglevel;
+		else {
+			console_loglevel = saved_console_loglevel;
+			saved_console_loglevel = -1;
+		}

2) If klogctl(8) is called while logging is disabled, then don't enable
   logging, but remember the requested value for when logging does get
   enabled again:
 	case 8:		/* Set level of messages printed to console */
[...]
- 		console_loglevel = len;
+		if (saved_console_loglevel == -1)
+	 		console_loglevel = len;
+		else
+			saved_console_loglevel = len;

Yet either option would be to ignore the request.


diff --git a/kernel/printk.c b/kernel/printk.c
index b4d97b5..acbf050 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -271,6 +271,7 @@ int do_syslog(int type, char __user *buf, int len)
 	int do_clear = 0;
 	char c;
 	int error = 0;
+	static int saved_console_loglevel = -1;
 
 	error = security_syslog(type);
 	if (error)
@@ -372,10 +373,15 @@ int do_syslog(int type, char __user *buf, int len)
 		logged_chars = 0;
 		break;
 	case 6:		/* Disable logging to console */
+		if (saved_console_loglevel == -1)
+			saved_console_loglevel = console_loglevel;
 		console_loglevel = minimum_console_loglevel;
 		break;
 	case 7:		/* Enable logging to console */
-		console_loglevel = default_console_loglevel;
+		if (saved_console_loglevel != -1) {
+			console_loglevel = saved_console_loglevel;
+			saved_console_loglevel = -1;
+		}
 		break;
 	case 8:		/* Set level of messages printed to console */
 		error = -EINVAL;
@@ -384,6 +390,8 @@ int do_syslog(int type, char __user *buf, int len)
 		if (len < minimum_console_loglevel)
 			len = minimum_console_loglevel;
 		console_loglevel = len;
+		/* Implicitly re-enable logging to console */
+		saved_console_loglevel = -1;
 		error = 0;
 		break;
 	case 9:		/* Number of chars in the log buffer */