On 11-07-11 03:29 PM, [email protected] wrote: > > we do have some logic in the imfile to allow it to combine multiple line > logs into one log entry,
Interesting. > it has a problem right now that it doesn't > sanitize the newlines so when you forward it things will probably get > broken up again. OK. One thing I did notice when I sent a multiline message to rsyslogd just using logger is that it converted the newline to a literal "#012". Is that what rsyslogd does with a multiline message? Is it configurable? Do most people really just have long syslog lines with a bunch of "#012"s in them? > similar logic could probably be added to the kmesg input, but it is > going to be tricky. Yeah. I don't think I imagined it would always be perfect. > the problem that you have is how to clearly identify the beginning of a > new message. Indeed. I was thinking of using time as a heuristic. Perhaps since for a given spate of messages, like an OOM or other stack trace, the messages all come in so tightly packed (in terms of time) I wonder if can be reasonable to allow an amount of time to expire to mark the end of a multiline message. > in imfile it can do three things > > 1. each line is a separate log > > 2. if a line starts with whitespace, it's part of a earlier log entry An interesting heuristic. I wonder if we can apply this to the kernel, or have the kernel fixed to abide by some such indicator. > 3. log entries are separated by a blank line Another interesting mechanism. Although that does mean banning empty lines elsewhere, not that I know that there are any used anywhere else. > now, #2 and #3 both mean that the log entry cannot be sent until the > next log entry arrives Indeed. With time however you only have to wait long enough. > with messages from the kernel, if they have timestamps on the front of > them added by the kernel, it is going to be hard to tell if it is a > continuation or not, but without those timestampes (or if you teach > kmesg input to skip them), I think that approach #2 will work. Yeah, I need to look more deeply into how the kernel is pushing messages up to userspace and what they look like in that channel. > I would suggest dumping dmesg output from a few systems and try running > them through the imfile mode #2 and see how the results look. Yeah, that's not going to work just given the first sample I looked at (sorry for the wrapping -- stupid thunderbird): [ 7680.300076] INFO: task dbus-daemon:3613 blocked for more than 120 seconds. [ 7680.300082] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7680.300085] dbus-daemon D f48035b0 0 3613 1 0x00000000 [ 7680.300091] eff19dc0 00000086 f4803584 f48035b0 d9ea3af8 000006cf f081daec c183a8c0 [ 7680.300098] d9e2bc15 000006cf f081dae8 c183a8c0 c183a8c0 f48068c0 f081d860 f0b80ca0 [ 7680.300104] c105685c f8eaa4e0 eff19d80 c1509dad eff19dbc f8e99444 0000b4c0 00000028 [ 7680.300111] Call Trace: [ 7680.300122] [<c105685c>] ? irq_exit+0x3c/0x80 [ 7680.300139] [<c1509dad>] ? _raw_spin_lock+0xd/0x10 [ 7680.300166] [<f8e99444>] ? rpcauth_lookup_credcache+0x134/0x1f0 [sunrpc] [ 7680.300190] [<f8f2921d>] ? nfs_access_get_cached+0x5d/0x160 [nfs] [ 7680.300195] [<c1508dc6>] __mutex_lock_slowpath+0xd6/0x140 [ 7680.300207] [<f8f29342>] ? nfs_do_access+0x22/0xc0 [nfs] [ 7680.300211] [<c1508935>] mutex_lock+0x25/0x40 [ 7680.300216] [<c1131ee7>] do_lookup+0x157/0x260 [ 7680.300219] [<c11327bb>] link_path_walk+0x13b/0xb10 [ 7680.300224] [<c1249ec3>] ? apparmor_file_alloc_security+0x23/0x50 [ 7680.300227] [<c1249ec3>] ? apparmor_file_alloc_security+0x23/0x50 [ 7680.300231] [<c1133404>] do_path_lookup+0x44/0x120 [ 7680.300234] [<c113414f>] do_filp_open+0x18f/0x6e0 [ 7680.300238] [<c113384a>] ? user_path_at+0x4a/0x80 [ 7680.300242] [<c127bc12>] ? copy_to_user+0x42/0x60 [ 7680.300246] [<c1136d50>] ? filldir+0x0/0xe0 [ 7680.300250] [<c113fee9>] ? vfsmount_lock_local_unlock+0x19/0x20 [ 7680.300255] [<c1126736>] do_sys_open+0x56/0x120 [ 7680.300258] [<c112853d>] ? fput+0x1d/0x30 [ 7680.300261] [<c112682e>] sys_open+0x2e/0x40 [ 7680.300265] [<c150a1d4>] syscall_call+0x7/0xb > I think that the kernel is pretty consistant about having every new > message start at the beginning of a line, but I'm not sure that it > indents everything (especially oops and stack trace messages) Right. It seems to return to position "0" for the Call Trace: line before the stack trace as well as other places in what I would consider a single message. > even if it doesn't indent them, you could add logic to the kmesg input > module to watch for, Indeed, I had wondered about teaching the kmesg input what various multiline messages look like too, combined with time, it might be fairly effective. > but that > could become very messy (and change from kernel version to kernel > version), Agreed. > if the simple indentation approach does not work, I would > suggest asking on the kernel mailing list before starting any other work. Yes, good idea. I'm not holding my breath, but worth a query. :-) Cheers, b.
signature.asc
Description: OpenPGP digital signature
_______________________________________________ rsyslog mailing list http://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com
