Hello, 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/
