Re: Logging information through printk

[Alex Iribarren <alex dot iribarren dot lists at gmail dot com>]

Martin Hunt wrote:
>> I've written a systemtap script that tracks network connections and logs
>> data about them. I'm using printk to log the data, but this is causing
>> kernel panics when there are a lot of connections.
>>     
> If you have that much data, do you really want to log to the system log?
> How much data are you talking about?
>   
Its pretty convenient to have it in syslog because it makes it much
easier to read. This is what the output looks like:

Jun  4 17:41:13 node01 kernel: netlog: sshd[3545]: TCP connect start
X.X.X.146:22 <- X.X.X.184:43705 (uid=0)
Jun  4 17:41:13 node01 sshd[12676]: Accepted kerberos5 for root from
X.X.X.184 port 47530
Jun  4 15:41:13 node01 sshd[12677]: Accepted kerberos for root from
X.X.X.184 port 47530 krb5 t
Jun  4 17:41:14 node01 kernel: netlog: sshd[12676]: TCP listen start on
port 6012 (uid=0)
Jun  4 17:41:14 node01 kernel: netlog: sshd[12676]: TCP listen start on
port 6012 (uid=0)
Jun  4 17:41:14 node01 sshd(pam_unix)[12678]: session opened for user
root by (uid=0)
Jun  4 17:41:14 node01 kernel: netlog: wget[12704]: TCP connect start
X.X.X.146:33370 -> X.X.X.235:20480 (uid=0)
Jun  4 17:41:14 node01 kernel: netlog: wget[12704]: TCP connect stop
X.X.X.146:33370 <-> X.X.X.235:20480 (uid=0)

I don't think its that there's too much data, but that the more times I
call printk(), the higher the chances of hitting the deadlock condition.
I'm using a slightly modified RHEL 4.5 kernel (2.6.9-42), by the way.

> It is safe in most, but not all, places in the kernel.  That is why we
> don't include it in systemtap.
>   
I don't really understand why I'm using it in a dangerous place. These
are my probes:

kernel.function("tcp_accept").return
kernel.function("tcp_v4_connect").return
kernel.function("tcp_close")
kernel.function("tcp_listen_start").return
kernel.function("tcp_listen_stop").return

At the end of each one, I call printk(). Nothing too fancy. Here's what
the call trace looks like at the moment of the lockup.

Jun  1 14:55:30 Call Trace:<ffffffff80247686>{serial8250_console_write+113} <ffffffff80137fb0>{__call_console_drivers+68}
Jun  1 14:55:30        <ffffffff8013821d>{release_console_sem+276} <ffffffff801384a8>{vprintk+498}
Jun  1 14:55:30        <ffffffff80138552>{printk+141} <ffffffffa0220dac>{:netlog:_stp_snprintf+131}
Jun  1 14:55:30        <ffffffff802a9dfd>{release_sock+16} <ffffffff802d28c8>{tcp_recvmsg+1798}
Jun  1 14:55:30        <ffffffffa0224032>{:netlog:function_log+1085} <ffffffffa022408f>{:netlog:function_log+1178}
Jun  1 14:55:30        <ffffffffa02264da>{:netlog:probe_1500+1502} <ffffffff802d3305>{tcp_close+10}
Jun  1 14:55:30        <ffffffff802d3306>{tcp_close+11} <ffffffffa022717a>{:netlog:enter_kprobe_probe+210}


If anyone can offer any ideas other, I'd really appreciate it.

Cheers,
Alex

Attachment: signature.asc
Description: OpenPGP digital signature