Re: [PATCH v2] printk: Have printk() never buffer its data

[Steven Rostedt <rostedt@goodmis.org>]

On Mon, 2012-06-25 at 15:56 +0200, Ingo Molnar wrote:

> > @@ -836,14 +854,45 @@ static size_t msg_print_text(const struct log *msg, bool syslog,
> >  		}
> >  
> >  		if (buf) {
> > -			if (print_prefix(msg, syslog, NULL) +
> > -			    text_len + 1>= size - len)
> > -				break;
> > +			static bool last_newline = true;
> 
> I'd suggest to move this last_newline flag up to the logbuf_lock 
> block of global variables - it belongs there. Statics are easily 
> overlooked and maybe something else running under the 
> logbuf_lock will want to access this variable in the future.

Will do.

> 
> > +			bool newline = true;
> > +			bool prefix = true;
> > +			int facility = msg->level >> 3;
> > +
> > +			/*
> > +			 * The kernel sends some commands via the facility.
> > +			 * To do so, a high number mask is used (LOG_KERNEL)
> > +			 * and the low bits of the mask hold the command bits
> > +			 * that the kernel printk() will use to state how the
> > +			 * msg will be printed.
> > +			 */
> > +			if ((facility & LOG_KERNEL) == LOG_KERNEL) {
> > +				if (facility & LOG_NOPREFIX_SET)
> > +					prefix = false;
> > +				if (facility & LOG_NONL_SET)
> > +					newline = false;
> > +			}
> 
> I suspect using a separate command flag and passing it along 
> would be somewhat cleaner - but no strong objections against 
> this approach either.

Yeah, I hate passing info via the facility, but I didn't want to bloat
the struct log any more. As the msg_print_text() is run separately from
printk, via the console_unlock(), the struct log is the only way to send
information from printk_emit() to msg_print_text().

Right now we have:

struct log {
	u64 ts_nsec;		/* timestamp in nanoseconds */
	u16 len;		/* length of entire record */
	u16 text_len;		/* length of text buffer */
	u16 dict_len;		/* length of dictionary buffer */
	u16 level;		/* syslog level + facility */
};

This is actually saved on the printk buffer (just not printed). Maybe a
better idea would be to break up the level more formally:

instead of:

	msg->level = (facility << 3) | (level & 7);

we could do:

	msg->level = (flags << 12) | ((facility & 0x1ff) << 3) | (level & 7);

and pass in the flags separately.

Yeah, I think this may be a cleaner solution.


> 
> > +			if (prefix) {
> > +				/*
> > +				 * Force newline, for last line if this line
> > +				 * is printing out a prefix.
> > +				 */
> > +				if (!last_newline)
> > +					buf[len++] = '\n';
> > +
> > +				if (print_prefix(msg, syslog, NULL) +
> > +				    text_len + 1 >= size - len)
> > +					break;
> > +
> > +				len += print_prefix(msg, syslog, buf + len);
> > +			}
> 
> Just a side note, this is a problem that exists in the new 
> devkmsg_user code, message size limit handling of 
> devkmsg_user->buf[] is non-existent and conditions for and 
> protections against triggering overflow are unclear - right now 
> it's probably addressed by making the buffer excessively large:
> 
> struct devkmsg_user {
>         u64 seq;
>         u32 idx;
>         struct mutex lock;
>         char buf[8192];
> };
> 
> but this may eventually have to be addressed - various things 
> like newline insertion or automatic escaping can enlargen the 
> buffer - if an attacker ever has control over a large enough 
> printk'ed text then this is a potential root hole.

Agreed, this part made me a little nervous about buffer overflow too.

> 
> >  
> > -			len += print_prefix(msg, syslog, buf + len);
> >  			memcpy(buf + len, text, text_len);
> >  			len += text_len;
> > -			buf[len++] = '\n';
> > +			if (newline)
> > +				buf[len++] = '\n';
> > +			last_newline = newline;
> >  		} else {
> >  			/* SYSLOG_ACTION_* buffer size only calculation */
> >  			len += print_prefix(msg, syslog, NULL);
> > @@ -1267,6 +1316,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  	static char cont_buf[LOG_LINE_MAX];
> >  	static size_t cont_len;
> >  	static int cont_level;
> > +	static bool cont_prefix;
> >  	static struct task_struct *cont_task;
> >  	static char textbuf[LOG_LINE_MAX];
> 
> 
> argh. So the vprintk_emit() muck introduced its own large set of 
> function local statics? Taste fail, really ...
> 
> >  	char *text = textbuf;
> > @@ -1275,8 +1325,12 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  	int this_cpu;
> >  	bool newline = false;
> >  	bool prefix = false;
> > +	bool flush;
> >  	int printed_len = 0;
> >  
> > +	/* output from printk() always flush to console (no line buffering) */
> > +	flush = facility == 0;
> 
> While your code is correct, this pattern is easily mistaken for 
> the 'a = b = c' pattern, so I'd suggest writing it as:
> 
> 	flush = (facility == 0);

Yeah, that looks better. Will fix.

> 
> Anyway, bike shed painting aside, the patch looks like a 
> workable solution to me.

Great! Lets hope Kay feels the same way.

-- Steve