printk(): add KERN_CONT where needed

From: Kay Sievers <[email protected]>
Subject: printk(): add KERN_CONT where needed

A prototype for kmsg records instead of a byte-stream buffer revealed a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce one record per printk() call, while all should have ended up in a single record.

Instead of:
ACPI: (supports S0 S5)
ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
hpet0: at MMIO 0xfed00000, IRQs 2 , 8 , 0

It prints:
ACPI: (supports S0
S5
)
ACPI: PCI Interrupt Link [LNKA] (IRQs
5
*10
11
)
hpet0: at MMIO 0xfed00000, IRQs
2
, 8
, 0

---
 drivers/acpi/pci_link.c |   12 ++++++------
 drivers/acpi/sleep.c    |    8 ++++----
 drivers/char/hpet.c     |    4 ++--
 drivers/tty/vt/vt.c     |    3 +--
 mm/page_alloc.c         |    6 +++---
 5 files changed, 16 insertions(+), 17 deletions(-)

@@ -720,21 +720,21 @@ static int acpi_pci_link_add(struct acpi
 	       acpi_device_bid(device));
 	for (i = 0; i < link->irq.possible_count; i++) {
 		if (link->irq.active == link->irq.possible[i]) {
-			printk(" *%d", link->irq.possible[i]);
+			printk(KERN_CONT " *%d", link->irq.possible[i]);
 			found = 1;
 		} else
-			printk(" %d", link->irq.possible[i]);
+			printk(KERN_CONT " %d", link->irq.possible[i]);
 	}
 
-	printk(")");
+	printk(KERN_CONT ")");
 
 	if (!found)
-		printk(" *%d", link->irq.active);
+		printk(KERN_CONT " *%d", link->irq.active);
 
 	if (!link->device->status.enabled)
-		printk(", disabled.");
+		printk(KERN_CONT ", disabled.");
 
-	printk("\n");
+	printk(KERN_CONT "\n");
 
 	list_add_tail(&link->list, &acpi_link_list);
 

@@ -883,7 +883,7 @@ int __init acpi_sleep_init(void)
 		status = acpi_get_sleep_type_data(i, &type_a, &type_b);
 		if (ACPI_SUCCESS(status)) {
 			sleep_states[i] = 1;
-			printk(" S%d", i);
+			printk(KERN_CONT " S%d", i);
 		}
 	}
 

@@ -897,7 +897,7 @@ int __init acpi_sleep_init(void)
 		hibernation_set_ops(old_suspend_ordering ?
 			&acpi_hibernation_ops_old : &acpi_hibernation_ops);
 		sleep_states[ACPI_STATE_S4] = 1;
-		printk(" S4");
+		printk(KERN_CONT " S4");
 		if (!nosigcheck) {
 			acpi_get_table(ACPI_SIG_FACS, 1,
 				(struct acpi_table_header **)&facs);

@@ -910,11 +910,11 @@ int __init acpi_sleep_init(void)
 	status = acpi_get_sleep_type_data(ACPI_STATE_S5, &type_a, &type_b);
 	if (ACPI_SUCCESS(status)) {
 		sleep_states[ACPI_STATE_S5] = 1;
-		printk(" S5");
+		printk(KERN_CONT " S5");
 		pm_power_off_prepare = acpi_power_off_prepare;
 		pm_power_off = acpi_power_off;
 	}
-	printk(")\n");
+	printk(KERN_CONT ")\n");
 	/*
 	 * Register the tts_notifier to reboot notifier list so that the _TTS
 	 * object can also be evaluated when the system enters S5.

@@ -906,8 +906,8 @@ int hpet_alloc(struct hpet_data *hdp)
 		hpetp->hp_which, hdp->hd_phys_address,
 		hpetp->hp_ntimer > 1 ? "s" : "");
 	for (i = 0; i < hpetp->hp_ntimer; i++)
-		printk("%s %d", i > 0 ? "," : "", hdp->hd_irq[i]);
-	printk("\n");
+		printk(KERN_CONT "%s %d", i > 0 ? "," : "", hdp->hd_irq[i]);
+	printk(KERN_CONT "\n");
 
 	temp = hpetp->hp_tick_freq;
 	remainder = do_div(temp, 1000000);

@@ -2932,11 +2932,10 @@ static int __init con_init(void)
 	gotoxy(vc, vc->vc_x, vc->vc_y);
 	csi_J(vc, 0);
 	update_screen(vc);
-	pr_info("Console: %s %s %dx%d",
+	pr_info("Console: %s %s %dx%d\n",
 		vc->vc_can_do_color ? "colour" : "mono",
 		display_desc, vc->vc_cols, vc->vc_rows);
 	printable = 1;
-	printk("\n");
 
 	console_unlock();
 

@@ -4763,12 +4763,12 @@ void __init free_area_init_nodes(unsigne
 	for (i = 0; i < MAX_NR_ZONES; i++) {
 		if (i == ZONE_MOVABLE)
 			continue;
-		printk("  %-8s ", zone_names[i]);
+		printk(KERN_CONT "  %-8s ", zone_names[i]);
 		if (arch_zone_lowest_possible_pfn[i] ==
 				arch_zone_highest_possible_pfn[i])
-			printk("empty\n");
+			printk(KERN_CONT "empty\n");
 		else
-			printk("%0#10lx -> %0#10lx\n",
+			printk(KERN_CONT "%0#10lx -> %0#10lx\n",
 				arch_zone_lowest_possible_pfn[i],
 				arch_zone_highest_possible_pfn[i]);
 	}

You are going to find many, many _hundreds_ of these.

Maybe it'd be better to aggregate content rather like printk does. Aggregate until you get a newline or a new KERN_<LEVEL>

A couple of other trivial comments:

It's better to try to coalesce multiple printks(KERN_CONT (perhaps it's better to use pr_cont instead too)

Branches with the same printks should be hoisted where possible.

	for (i = 0; ...) {
		pr_cont(" %d", link->irq.possible[i]);
		if (link->irq.active == link->irq.possible[i])
 			found = 1;
	}

	if (!found)
		pr_cont(") *%d%s\n",
			link->irq.active,
			!link->device->status.enabled ? ", disabled" : "");
	else
		pr_cont("}%s\n",
			!link->device->status.enabled ? ", disabled" : "")

Yeah, and they should all be fixed over time. It's 2012 and time to make kernel log messages readable for machines, not for humans to puzzle them together. :)

The continuation printk() can can always go wrong when multiple threads do that in parallel. We can try to make it better with a per-cpu buffer, but I guess there will always be a situation where this can happen.

I'm confident, that only callers who are willing to take that 'risk' of interleaved messages should be exposed to the problem, and never ones who print proper single lines.

In other words, we should guarantee that there is no garbage left from any earlier printk() for someone who does not want to play this continuation print() game.

Sure, please send patches for anything that is more appropriate to use here.

I did not want to change any logic which needs to be tested. I just trivially added the obviously missing prefix, which solved the problem, and which could be applied right away.

Kay

Actually, you didn't solve any problem. You just made it less likely to be interleaved against any other bare printk. But there are still _thousands_ of bare printks.

I think you should do it "right" rather than add
trivial markers.

The trivial markers _are_ correct. And they really fix things as soon as we start storing machine-readable records with printk(), instead of blindly glueing bytes together with each printk() call, for humans to puzzle with them if things go wrong.

The stuff you propose is a pretty different story. I see your point, but it's more 'cosmetics' in code than not simple correctness fixes.

Kay

These KERN_CONT changes don't _fix_ things, they just make it less likely to cause problems.

Imagine two threads with printks extended with KERN_CONT

Thread 1: Thread 2:

printk(KERN_INFO "info message: ");
                                          printk(KERN_ERR "err message: ");
printk(KERN_CONT "online\n");
                                          printk(KERN_CONT "offline\n");

Instead of a guarantee of "info message: online" and "err message: offline", buffering could still join the messages to "err message: online".

I believe the only _guaranteed_ way to correctly assemble these messages is to use a initiator with a cookie and pass that cookie to assembling printks.

Something like:

	cookie = multi_printk_start()
	multi_printk(cookie, level fmt, ...);
	...
	multi_printk_end(cookie);

Though get_current() might be a reasonable cookie so perhaps the multi_ variants aren't needed.

git.kernel.org isn't responding right now. I can't read the link you sent me privately to check if you are using get_current() or some other current_thread_info() constuct.

They sure changes things, as you can see in the first message in this thread. This is a real paste of output, not made up stuff.

It will matter as soon as we do not allow the next printk() to get appended to 'left-over garbage' of the last printk() without a trailing '\n'. We should not allow that, and the 'risk' of interleaving and garbled messages should be limited to threads which _both_ do continuation at the same time. The likeliness of that will get pretty low.

We should make absolutely sure, it will never affect the thread which does a proper single and complete line.

Yes, both threads play racy games with continuation, and that makes them both vulnerable to interleaving. But we must make sure, that single and complete lines are never affected by that.

I did not claim to address the problem of concurrent continuation line writers, and this patch has absolutely nothing to do with that problem. It _does_ fix encountered problems, and it is correct as it is. Please do not mix other issues you bring up here into it, they should go into a separate thread, unrelated to this patch.

Apart from *possibly* switching to per-cpu buffers for printk() core, I think the callers should probably just do that on their own, maybe just on the stack, if the message is small enough.

No, it does not change any current behaviour or gets any knowledge about threads, it just makes sure that full and single line always ends up in its own record instead of accepting unterminated left-overs from earlier printk()s.

Thanks,
Kay

No it doesn't. It fixes problems _you_ encounter
with an unpublished modification of the printk
subsystem.

Exactly. And that is what is written in the changelog of the patch. But all that does not matter, the change results in more correct code than the current one is; and that is all that matters.

Sure, I see your point, and support your effort, but I don't think your arguments are related to this patch and you are hijacking something unrelated, which should be discussed in a separate mail thread, that's all.

Thanks,
Kay

Conversations happen all over the place and making separate discussions isn't that valuable nor are they really controllable.

Just write the change log to simply state "add KERN_CONT" without mentioning your unpublished stuff.

cheers, Joe

Sure, but this is not a conversation in that sense, you reply to a patch that something is not correct, but what's not correct is not a subject of the patch. And that I need to correct.

The changelog says:

"A prototype for kmsg records instead of a byte-stream buffer revealed a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce one record per printk() call, while all should have ended up in a single record."

What else do you need?

Kay

You need less.

This has nothing to do with the current printk subsystem, it has only to do with using KERN_CONT.

Maybe:

trivial: add some KERN_CONT markers to continuation lines

or something like:

commit 66d0ae4d6ffa45b8e6d8bdbf85f8f1b285c8152d

Author: Jiri Slaby <[email protected]>
Date:   Sun Dec 6 16:16:24 2009 +0100

PM / Hibernate: Swap, use KERN_CONT

Use KERN_CONT in save_image() for printks, so that anybody won't try to add a loglevel.

Maybe we can be a bit smarter. For example, if `current' is unchanged and __builtin_return_address(0) is unchanged, keep on buffering.

It's all a bit hacky, but weeding out all those thousands of printks which never get printed anyway doesn't sound much fun either.

There are dozens to hundreds of existing sequences like:

void some_func(...)

{
	printk("some additional data");
}

...

void some_device_init(...)

{
	...
	printk([KERN_LEVEL or not] "some initiator")
	some_func();
	printk("\n");
}

Nope. That isn't any fun.

So given the example above, maybe check if the initial printk's __builtin_return_address(0) exists in some level of the stack say up to 3 deep for each subsequent printk.

I don't remember any threads spun off to emit printk continuation lines so maybe that'd work reasonably well.

Too true.