sleeping function called from invalid context in slab.c and sock.c (long,code,stacktrace)
Helmut Duregger
We are sending ICMP echo requests inside an iptables module.
The 'match' function of the module invokes the 'send_probe' method,
which sends the ICMP echo request over a socket, that we
keep reusing for that purpose.
We also add a struct timespec to the ICMP data to measure the RTT.
Developing in User Mode Linux we get the following
"sleeping function called from invalid context" warning
everytime the ICMP paket is send, still the module works and
continues to do so.
The first time the bug appears in mm/slab.c:2901
http://lxr.linux.no/source/mm/slab.c?v=2.6.18;a=x86_64#L2901
when the socket is allocated.
After that the socket is reused and the problem appears in
net/core/sock.c:1536
http://lxr.linux.no/source/net/core/sock.c?v=2.6.18;a=x86_64#L1536
repeatedly, everytime another ICMP packet is being sent.
I am on User Mode Linux 2.6.18.2, running on an AMD64 host with
2.6.17-10-generic (Ubuntu Dapper Drake).
Again, everything else works, the packets are being sent and
the module does not panic the kernel.
Thanks for any help solving this issue!
Best regards,
Helmut
Code and stacktrace following:
Here the relevant part of the code ------------------------
...
/* basically from iputils_ping but modified */
u_char outpack[0x10000];
int datalen = DEFDATALEN;
int cmsg_len = sizeof(cmsg);
struct socket *sock = NULL;
struct sockaddr_in source;
struct sockaddr_in whereto; /* who to ping */
int send_probe(u_int32_t target, unsigned int id)
{
struct icmphdr *icp;
int cc;
int error;
struct timespec ts;
memset(&source, 0, sizeof(source));
source.sin_family = AF_INET;
source.sin_addr.s_addr = INADDR_ANY;
source.sin_port = htons(12345); // TODO
if (!sock) {
error = sock_create_kern(PF_INET, SOCK_RAW, IPPROTO_ICMP, &sock);
if (error) {
printk("Could not create socket\n");
return 1;
}
error = sock->ops->bind(sock, (struct sockaddr*)&source, sizeof(struct
sockaddr_in));
if (error) {
printk("could not bind socket\n");
return 1;
}
}
memset((char *)&whereto,0, sizeof(whereto));
whereto.sin_family = AF_INET;
whereto.sin_addr.s_addr = target;
icp = (struct icmphdr *)outpack;
icp->type = ICMP_ECHO;
icp->code = 0;
icp->checksum = 0;
icp->un.echo.sequence = 0;
icp->un.echo.id = id;
getnstimeofday(&ts);
printk("[%li.%.6li] writing tstamp to ICMP echo request\n", ts.tv_sec,
ts.tv_nsec);
memcpy(icp+1, &ts, sizeof(struct timespec));
cc = datalen + 8;
/* compute ICMP checksum here */
icp->checksum = in_cksum((u_short *)icp, cc);
do {
static struct iovec iov = {outpack, 0};
static struct msghdr m = { &whereto, sizeof(whereto), &iov, 1, &cmsg,
0, 0 };
m.msg_controllen = cmsg_len;
iov.iov_len = cc;
kernel_sendmsg(sock, &m, (struct kvec*)&iov, 1, cc);
} while (0);
return 0;
} /* end -- from iputils_ping tool but modified */
------------------------------------------------------------
The stack trace ---------------------------------------------
[42955822.340000] Sending ICMP echo request
[42955822.340000] BUG: sleeping function called from invalid context at
mm/slab.c:2901
[42955822.340000] in_atomic():1, irqs_disabled():0
[42955822.340000] Call Trace:
[42955822.340000] 601df3f8: [<60028e44>] __might_sleep+0xb0/0xbc
[42955822.340000] 601df438: [<60068ae0>] kmem_cache_alloc+0x30/0xaa
[42955822.340000] 601df478: [<6011c6cd>] sock_alloc_inode+0x17/0x60
[42955822.340000] 601df498: [<60083fc7>] alloc_inode+0x1b/0x190
[42955822.340000] 601df4c8: [<600849f3>] new_inode+0xf/0xa7
[42955822.340000] 601df4e8: [<6011ca63>] sock_alloc+0x18/0x61
[42955822.340000] 601df508: [<6011d870>] __sock_create+0xb3/0x1c4
[42955822.340000] 601df518: [<6017ee1e>] _spin_unlock_irqrestore+0x15/0x19
[42955822.340000] 601df558: [<6011d99e>] sock_create_kern+0xf/0x11
[42955822.340000] 601df568: [<6298f0ce>] send_probe+0x60/0x171
[ipt_piggyback]
[42955822.340000] 601df598: [<6298f42c>] match+0x24d/0x3b7 [ipt_piggyback]
[42955822.340000] 601df5d8: [<60035213>] __mod_timer+0xbe/0xd0
[42955822.340000] 601df638: [<629d0205>] ipt_do_table+0x1de/0x30b
[ip_tables]
[42955822.340000] 601df6e8: [<629bc01a>] ipt_route_hook+0x1a/0x1c
[iptable_mangle]
[42955822.340000] 601df6f8: [<60136bc1>] nf_iterate+0x3f/0x76
[42955822.340000] 601df720: [<6013f9d8>] ip_rcv_finish+0x0/0x240
[42955822.340000] 601df738: [<60136c52>] nf_hook_slow+0x5a/0xc3
[42955822.340000] 601df740: [<6013f9d8>] ip_rcv_finish+0x0/0x240
[42955822.340000] 601df7a8: [<6013f783>] ip_rcv+0x21d/0x472
[42955822.340000] 601df7f8: [<60127869>] netif_receive_skb+0x190/0x1ac
[42955822.340000] 601df838: [<60127917>] process_backlog+0x92/0x113
[42955822.340000] 601df888: [<60127a05>] net_rx_action+0x6d/0xfc
[42955822.340000] 601df8c8: [<600313ee>] __do_softirq+0x53/0xb0
[42955822.340000] 601df8d8: [<6004b5a1>] handle_IRQ_event+0x5f/0x6e
[42955822.340000] 601df908: [<60031488>] do_softirq+0x3d/0x4b
[42955822.340000] 601df918: [<6004b693>] __do_IRQ+0xe3/0xf4
[42955822.340000] 601df938: [<600314ce>] irq_exit+0x38/0x3a
[42955822.340000] 601df958: [<6000ff07>] do_IRQ+0x27/0x2e
[42955822.340000] 601df978: [<6000fae9>] sigio_handler+0x4b/0x5f
[42955822.340000] 601df988: [<6000fa9e>] sigio_handler+0x0/0x5f
[42955822.340000] 601df998: [<6002457f>] sig_handler_common_skas+0xdb/0xf2
[42955822.340000] 601df9c0: [<600142b9>] start_kernel_proc+0x0/0x37
[42955822.340000] 601df9d8: [<600212e6>] sig_handler+0x35/0x3f
[42955822.340000] 601dfa40: [<600142b9>] start_kernel_proc+0x0/0x37
[42955822.340000] 601dfae8: [<600219c1>] switch_timers+0x95/0xb4
[42955822.340000] 601dfb68: [<60013feb>] switch_to_skas+0x63/0x6e
[42955822.340000] 601dfba8: [<60010ebb>] _switch_to+0x4b/0x93
[42955822.340000] 601dfbd8: [<6017ee30>] _spin_unlock_irq+0xe/0x10
[42955822.340000] 601dfbe8: [<6017d230>] schedule+0x3f6/0x45d
[42955822.340000] 601dfc28: [<60021a25>] idle_sleep+0x1e/0x23
[42955822.340000] 601dfc48: [<600110cf>] default_idle+0x2c/0x2e
[42955822.340000] 601dfc68: [<600142b2>] init_idle_skas+0x2e/0x35
[42955822.340000] 601dfc98: [<600110da>] cpu_idle+0x9/0xb
[42955822.340000] 601dfca8: [<6000f007>] rest_init+0x1f/0x21
[42955822.340000] 601dfcb8: [<60001530>] start_kernel+0x193/0x195
[42955822.340000] 601dfcd8: [<600142ec>] start_kernel_proc+0x33/0x37
[42955822.340000] 601dfcf8: [<6002086e>] run_kernel_thread+0x47/0x52
[42955822.340000] 601dfd10: [<600142b9>] start_kernel_proc+0x0/0x37
[42955822.340000] 601dfd38: [<600142b9>] start_kernel_proc+0x0/0x37
[42955822.340000] 601dfde8: [<600142b9>] start_kernel_proc+0x0/0x37
[42955822.340000] 601dfdf8: [<60014092>] new_thread_handler+0x9c/0xca
[42955822.340000]
[42955822.340000] [1163598896.747788000] writing tstamp to ICMP echo request
[42955822.340000] new tstamp added to already existing id 5
[42955822.340000] 192 168 0 20 reading tstamp [1163598896.747788000]
from ICMP echo reply
[42955822.340000] id: 5, 0.397000s difference
[42955822.390000] new tstamp added to already existing id 5
[42955822.550000] new tstamp added to already existing id 5
[42955822.600000] new tstamp added to already existing id 5
[42955822.600000] new tstamp added to already existing id 5
[42955822.820000] Sending ICMP echo request
[42955822.820000] [1163598897.234718000] writing tstamp to ICMP echo request
[42955822.820000] new tstamp added to already existing id 5
[42955822.820000] 192 168 0 20 reading tstamp [1163598897.234718000]
from ICMP echo reply
[42955822.820000] id: 5, 0.397000s difference
[42955822.940000] new tstamp added to already existing id 5
[42955823.050000] new tstamp added to already existing id 5
[42955823.140000] new tstamp added to already existing id 5
[42955823.240000] new tstamp added to already existing id 5
[42955823.350000] Sending ICMP echo request
[42955823.350000] [1163598897.734609000] writing tstamp to ICMP echo request
[42955823.350000] BUG: sleeping function called from invalid context at
net/core/sock.c:1536
[42955823.350000] in_atomic():1, irqs_disabled():0
[42955823.350000] Call Trace:
[42955823.350000] 601df258: [<60028e44>] __might_sleep+0xb0/0xbc
[42955823.350000] 601df298: [<60120788>] lock_sock+0x1d/0x4e
[42955823.350000] 601df2b8: [<6015c873>] raw_sendmsg+0x2b2/0x3b7
[42955823.350000] 601df318: [<60014db6>] uml_console_write+0x50/0x5c
[42955823.350000] 601df378: [<6016415f>] inet_sendmsg+0x46/0x53
[42955823.350000] 601df3a8: [<6011cc23>] sock_sendmsg+0xf0/0x109
[42955823.350000] 601df418: [<6003febd>] autoremove_wake_function+0x0/0x36
[42955823.350000] 601df488: [<6002c2a4>] printk+0xa0/0xa2
[42955823.350000] 601df4e8: [<6017ee1e>] _spin_unlock_irqrestore+0x15/0x19
[42955823.350000] 601df508: [<60012660>] do_gettimeofday+0x37/0x71
[42955823.350000] 601df538: [<6011cc77>] kernel_sendmsg+0x3b/0x47
[42955823.350000] 601df568: [<6298f1d6>] send_probe+0x168/0x171
[ipt_piggyback]
[42955823.350000] 601df598: [<6298f42c>] match+0x24d/0x3b7 [ipt_piggyback]
[42955823.350000] 601df5d8: [<60035213>] __mod_timer+0xbe/0xd0
[42955823.350000] 601df638: [<629d0205>] ipt_do_table+0x1de/0x30b
[ip_tables]
[42955823.350000] 601df6e8: [<629bc01a>] ipt_route_hook+0x1a/0x1c
[iptable_mangle]
[42955823.350000] 601df6f8: [<60136bc1>] nf_iterate+0x3f/0x76
[42955823.350000] 601df720: [<6013f9d8>] ip_rcv_finish+0x0/0x240
[42955823.350000] 601df738: [<60136c52>] nf_hook_slow+0x5a/0xc3
[42955823.350000] 601df740: [<6013f9d8>] ip_rcv_finish+0x0/0x240
[42955823.350000] 601df7a8: [<6013f783>] ip_rcv+0x21d/0x472
[42955823.350000] 601df7f8: [<60127869>] netif_receive_skb+0x190/0x1ac
[42955823.350000] 601df838: [<60127917>] process_backlog+0x92/0x113
[42955823.350000] 601df888: [<60127a05>] net_rx_action+0x6d/0xfc
[42955823.350000] 601df8c8: [<600313ee>] __do_softirq+0x53/0xb0
[42955823.350000] 601df8d8: [<6004b5a1>] handle_IRQ_event+0x5f/0x6e
[42955823.350000] 601df908: [<60031488>] do_softirq+0x3d/0x4b
[42955823.350000] 601df918: [<6004b693>] __do_IRQ+0xe3/0xf4
[42955823.350000] 601df938: [<600314ce>] irq_exit+0x38/0x3a
[42955823.350000] 601df958: [<6000ff07>] do_IRQ+0x27/0x2e
[42955823.350000] 601df978: [<6000fae9>] sigio_handler+0x4b/0x5f
[42955823.350000] 601df988: [<6000fa9e>] sigio_handler+0x0/0x5f
[42955823.350000] 601df998: [<6002457f>] sig_handler_common_skas+0xdb/0xf2
[42955823.350000] 601df9c0: [<600142b9>] start_kernel_proc+0x0/0x37
[42955823.350000] 601df9d8: [<600212e6>] sig_handler+0x35/0x3f
[42955823.350000] 601dfa40: [<600142b9>] start_kernel_proc+0x0/0x37
[42955823.350000] 601dfae8: [<600219c1>] switch_timers+0x95/0xb4
[42955823.350000] 601dfb68: [<60013feb>] switch_to_skas+0x63/0x6e
[42955823.350000] 601dfba8: [<60010ebb>] _switch_to+0x4b/0x93
[42955823.350000] 601dfbd8: [<6017ee30>] _spin_unlock_irq+0xe/0x10
[42955823.350000] 601dfbe8: [<6017d230>] schedule+0x3f6/0x45d
[42955823.350000] 601dfc28: [<60021a25>] idle_sleep+0x1e/0x23
[42955823.350000] 601dfc48: [<600110cf>] default_idle+0x2c/0x2e
[42955823.350000] 601dfc68: [<600142b2>] init_idle_skas+0x2e/0x35
[42955823.350000] 601dfc98: [<600110da>] cpu_idle+0x9/0xb
[42955823.350000] 601dfca8: [<6000f007>] rest_init+0x1f/0x21
[42955823.350000] 601dfcb8: [<60001530>] start_kernel+0x193/0x195
[42955823.350000] 601dfcd8: [<600142ec>] start_kernel_proc+0x33/0x37
[42955823.350000] 601dfcf8: [<6002086e>] run_kernel_thread+0x47/0x52
[42955823.350000] 601dfd10: [<600142b9>] start_kernel_proc+0x0/0x37
[42955823.350000] 601dfd38: [<600142b9>] start_kernel_proc+0x0/0x37
[42955823.350000] 601dfde8: [<600142b9>] start_kernel_proc+0x0/0x37
[42955823.350000] 601dfdf8: [<60014092>] new_thread_handler+0x9c/0xca
[42955823.350000]
...repeats with BUG: ... in net/core/sock.c:1536 whenever ICMP echo
request is being sent.
--
Kernelnewbies: Help each other learn about the Linux kernel.
Archive: http://mail.nl.linux.org/kernelnewbies/
FAQ: http://kernelnewbies.org/faq/
Mulyadi Santosa
> We are sending ICMP echo requests inside an iptables module.
> The 'match' function of the module invokes the 'send_probe' method,
> which sends the ICMP echo request over a socket, that we
> keep reusing for that purpose.
> We also add a struct timespec to the ICMP data to measure the RTT.
>
> Developing in User Mode Linux we get the following
> "sleeping function called from invalid context" warning
> everytime the ICMP paket is send, still the module works and
> continues to do so.
The message itself is quite clear IMHO, you did something blocking in
atomic/ interrupt disabled area. The question is, which one?
Looking from stack trace, I have a pretty good guess that it is
sock_create_kern() that cause the trouble.
The solution is, if you really need to create a socket, somehow creates
the socket outside the iptables matching/filtering context.
Hope it helps.
regards,
Mulyadi
Helmut Duregger
>> We are sending ICMP echo requests inside an iptables module.
>> The 'match' function of the module invokes the 'send_probe' method,
>> which sends the ICMP echo request over a socket, that we
>> keep reusing for that purpose.
>> Developing in User Mode Linux we get the following
>> "sleeping function called from invalid context" warning
>> everytime the ICMP paket is send, still the module works and
>> continues to do so.
>
> Looking from stack trace, I have a pretty good guess that it is
> sock_create_kern() that cause the trouble.
>
> The solution is, if you really need to create a socket, somehow creates
> the socket outside the iptables matching/filtering context.
We moved the creation of the socket outside of the match() function
into the init() area of the module. And the warning for that vanished as
was to be expected.
Thanks for the help there.
But the warning that appears everytime kernel_sendmsg() is invoked
still remains.
Therefore we tried to move the transmission of the ICMP echo requests
into an iptables target module, hoping that this will change context of
the call, but it did not.
Unfortunately, this is the only solution to sending ICMP echo requests
from inside the kernel that we came up with. We still can't manage to
alter an existing UDP sk_buff for use in
icmp_send(skbuff, ICMP_ECHO, 0, 0), it always segfaults.
What problems are to be expected if we deploy with the existing sleep
bug (the module seems to keep running fine)?
Is this only important for SMP and multicore systems (which the
system we deploy on might not necessarily be)?
Thanks for any help,
Helmut
Mulyadi Santosa
> We moved the creation of the socket outside of the match() function
> into the init() area of the module. And the warning for that vanished
> as was to be expected.
> Thanks for the help there.
OK, one problem was solved....
> But the warning that appears everytime kernel_sendmsg() is invoked
> still remains.
Hm.... honestly I have no good idea about it. It could be a blocking
function too, possibly because of page allocation (non atomic..)
> Therefore we tried to move the transmission of the ICMP echo requests
> into an iptables target module, hoping that this will change context
> of the call, but it did not.
>
> Unfortunately, this is the only solution to sending ICMP echo
> requests from inside the kernel that we came up with. We still can't
> manage to alter an existing UDP sk_buff for use in
> icmp_send(skbuff, ICMP_ECHO, 0, 0), it always segfaults.
Just a raw idea....what if you move the ICMP delivery part completely
out from iptables context...shall we say..into separate kernel threads?
What do you think? Is it doable?
> What problems are to be expected if we deploy with the existing sleep
> bug (the module seems to keep running fine)?
CMIIW, I believe by far you only tested it on UML kernel, right? Well,
in UML, I think it won't bring too much trouble since basically UML is
just simulating the atomic context when in reality it is still an
interruptible context... but...
in real machine and real kernel (non UML), IMHO it could bring problem,
possibly kernel panic. But to see if my theory is correct, please try
your program/patch inside qemu. Since qemu simulate a complete x86
system, you can 99% accurately predict what will happen in real iron.
> Is this only important for SMP and multicore systems (which the
> system we deploy on might not necessarily be)?
I don't think so. Even in UP, atomic is still atomic ..of course there
is a good reason why a section is marked as atomic. Mostly, it is
because of the need to avoid race condition (e.g competing with another
invocation of another interrupt handler).
regards,
Mulyadi
Mulyadi Santosa
> We moved the creation of the socket outside of the match() function
> into the init() area of the module. And the warning for that vanished
> as was to be expected.
> Thanks for the help there.
OK, one problem was solved....
> But the warning that appears everytime kernel_sendmsg() is invoked
> still remains.
Hm.... honestly I have no good idea about it. It could be a blocking
function too, possibly because of page allocation (non atomic..)
> Therefore we tried to move the transmission of the ICMP echo requests
> into an iptables target module, hoping that this will change context
> of the call, but it did not.
>
> Unfortunately, this is the only solution to sending ICMP echo
> requests from inside the kernel that we came up with. We still can't
> manage to alter an existing UDP sk_buff for use in
> icmp_send(skbuff, ICMP_ECHO, 0, 0), it always segfaults.
Just a raw idea....what if you move the ICMP delivery part completely
out from iptables context...shall we say..into separate kernel threads?
What do you think? Is it doable?
> What problems are to be expected if we deploy with the existing sleep
> bug (the module seems to keep running fine)?
CMIIW, I believe by far you only tested it on UML kernel, right? Well,
in UML, I think it won't bring too much trouble since basically UML is
just simulating the atomic context when in reality it is still an
interruptible context... but...
in real machine and real kernel (non UML), IMHO it could bring problem,
possibly kernel panic. But to see if my theory is correct, please try
your program/patch inside qemu. Since qemu simulate a complete x86
system, you can 99% accurately predict what will happen in real iron.
> Is this only important for SMP and multicore systems (which the
> system we deploy on might not necessarily be)?
I don't think so. Even in UP, atomic is still atomic ..of course there
is a good reason why a section is marked as atomic. Mostly, it is
because of the need to avoid race condition (e.g competing with another
invocation of another interrupt handler).
regards,
Mulyadi