libpcap issue: tcpdump consumes 100% cpu power after interface shutdown
Thomas Osterried
thomas at x-berg.in-berlin.de
Fri Aug 7 10:13:02 UTC 2009
Hello,
I've investigated some time in tracing the bug I reported to
https://bugs.launchpad.net/ubuntu/+source/tcpdump/+bug/369288
a while ago. [Nobody responded]
Today I developed a fix. But perhaps it may be needed to check why it
occured: has libpcap recently changed in the poll() handling - or did
the linux kernel code change?
test screnario:
root at tomate:/tmp# openvpn --dev tun &
root at tomate:/tmp# ifconfig tun0 up &
root at tomate:/tmp# tcpdump -ni tun0 &
strace -tt -p 12238 >/tmp/a 2>&1
10:14:39.250055 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
10:14:40.251505 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
10:14:41.252910 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
10:14:42.254355 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
10:14:43.255764 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
10:14:44.257102 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
here i terminated openvpn; dev tun0 closes
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
10:14:45.258137 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.392988 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393089 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393182 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393257 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393361 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393436 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393520 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393621 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393694 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393851 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.393924 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.394020 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.394093 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.394165 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:45.394260 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
[..]
10:14:58.921514 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
10:14:58.921558 poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
thomas at tomate:~$ grep ^10:14:45 /tmp/a|wc
12508 112572 1088196
thomas at tomate:~$ grep ^10:14:46 /tmp/a|wc
22874 205866 1990038
thomas at tomate:~$ grep ^10:14:47 /tmp/a|wc
22488 202392 1956456
thomas at tomate:~$ grep ^10:14:48 /tmp/a|wc
22853 205677 1988211
thomas at tomate:~$ grep ^10:14:49 /tmp/a|wc
22924 206316 1994388
thomas at tomate:~$ grep ^10:14:50 /tmp/a|wc
22975 206775 1998825
thomas at tomate:~$ grep ^10:14:51 /tmp/a|wc
22130 199170 1925310
thomas at tomate:~$ grep ^10:14:52 /tmp/a|wc
22778 205002 1981686
thomas at tomate:~$ grep ^10:14:53 /tmp/a|wc
23061 207549 2006307
thomas at tomate:~$ grep ^10:14:54 /tmp/a|wc
22982 206838 1999434
thomas at tomate:~$ grep ^10:14:55 /tmp/a|wc
22937 206433 1995519
thomas at tomate:~$ grep ^10:14:56 /tmp/a|wc
22906 206154 1992822
thomas at tomate:~$ grep ^10:14:57 /tmp/a|wc
22742 204678 1978554
thomas at tomate:~$ grep ^10:14:58 /tmp/a|wc
21115 190033 1836989
----> much the same :(
..and aways POLLERR:
thomas at tomate:~$ grep -i poll /tmp/a |grep 10.14:5|grep -v POLLERR
thomas at tomate:~$
It eats 100% CPU load forever
tcpdump bug?
tcpdump compiled with debug symbols (recompiled from deb-src). gdb attached:
Program received signal SIGINT, Interrupt.
0x00007f8a4de4145f in poll () from /lib/libc.so.6
(gdb) bt
#0 0x00007f8a4de4145f in poll () from /lib/libc.so.6
#1 0x00007f8a4e0deba4 in ?? () from /usr/lib/libpcap.so.0.8
#2 0x00007f8a4e0e2dd9 in pcap_loop () from /usr/lib/libpcap.so.0.8
#3 0x000000000044b7ed in ?? ()
#4 0x00007f8a4dd835a6 in __libc_start_main () from /lib/libc.so.6
#5 0x0000000000402c09 in ?? ()
#6 0x00007fff568b3068 in ?? ()
-> tcpdump is not responsible. It's a libpcap issue.
libpcap recompiled with debug symbols from deb-src:
Program received signal SIGINT, Interrupt.
0x00007ff5817b545f in poll () from /lib/libc.so.6
(gdb) bt
#0 0x00007ff5817b545f in poll () from /lib/libc.so.6
#1 0x00007ff581a547fd in pcap_read_linux_mmap (handle=0x1263860,
max_packets=-1, callback=0x44c030 <pcap_dump_close at plt+300128>,
user=0x7fff8a22f7c0 "P\206C") at ./pcap-linux.c:2194
#2 0x00007ff581a5884c in pcap_loop (p=0x1263860, cnt=-1,
callback=0x44c030 <pcap_dump_close at plt+300128>,
user=0x7fff8a22f7c0 "P\206C") at ./pcap.c:302
#3 0x000000000044b7ed in ?? ()
#4 0x00007ff5816f75a6 in __libc_start_main () from /lib/libc.so.6
-> ok, here we go.
./pcap-linux.c:2194
it's this do-while block eating all my cpu power:
do {
/* poll() requires a negative timeout to wait forever */
ret = poll(&pollinfo, 1, (handle->md.timeout > 0)?
handle->md.timeout: -1);
if ((ret < 0) && (errno != EINTR)) {
snprintf(handle->errbuf, PCAP_ERRBUF_SIZE,
"can't poll on packet socket fd %d: %d-_%s",
handle->fd, errno, _pcap_strerror(errno));
return -1;
}
/* check for break loop condition on interrupted _syscall*/
if (handle->break_loop) {
handle->break_loop = 0;
return -2;
}
} while (ret < 0);
Return value of poll() is checked. ret is > -1 (it's 1 due to strace,
see above) and errno is not set because it's not a ret = -1 condition.
Interrupted syscall condition is not true (handle->break_loop).
revents=POLLERR is not checked. [Imho, at least POLLERR, POLLUP and POLLNVAL
are possible cases to handle; unsure with POLLRDHUP]
Why it occured? Either your code has changed. Or perhaps the kernel
poll() behaviour on this error event has changed (returns not -1
anymore; and now likes to set bits on revents).
My kernel is
Linux tomate 2.6.28-14-generic #47-Ubuntu SMP Sat Jul 25 01:19:55 UTC 2009 x86_64 GNU/Linu)
My suggestion for a fix (after you may have verified with the kernel dev team)
is this:
normal events are:
poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLIN}])
write(1, "11:12:36.440319 IP x.x.x.x"..., 11911:12:36.440319 IP x.x.x.x.655 > x.x.x.x.36321: . ack 865 win 2595 <nop,nop,timestamp 1373567254 21184905>) = 119
error event is:
poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
returnvalue in the error case is not -1, not 0, not < -1.
man page of poll says:
On success, a positive number is returned; this is the number of struc‐
tures which have non-zero revents fields (in other words, those
descriptors with events or errors reported). A value of 0 indicates
that the call timed out and no file descriptors were ready. On error,
-1 is returned, and errno is set appropriately.
-> thus on error events, the return value is > 0
--- pcap-linux-orig.c 2009-08-07 11:35:56.518551462 +0200
+++ pcap-linux.c 2009-08-07 11:30:10.426556000 +0200
@@ -2199,7 +2199,20 @@
handle->fd, errno, pcap_strerror(errno));
return -1;
}
- /* check for break loop condition on interrupted syscall*/
+
+ /* poll() sometimes returns > 0 even in error cases
+ * and sets error-bits like POLLERR, POLLHUP, ..
+ * Are also "good" bits are possible, like POLLPRI.
+ * TODO: what's with POLLRDHUP since kernel 2.6.17?
+ */
+ if (ret > 0 && pollinfo.revents & (POLLERR | POLLHUP | POLLNVAL)) {
+ snprintf(handle->errbuf, PCAP_ERRBUF_SIZE,
+ "critical revent in poll on packet socket fd %d: 0x%4.4x",
+ handle->fd, pollinfo.revents);
+ return -1;
+ }
+
+ /* check for break loop condition on interrupted _syscall*/
if (handle->break_loop) {
handle->break_loop = 0;
return -2;
root at tomate:/tmp# fg 1
openvpn --dev tun
^CFri Aug 7 11:47:06 2009 event_wait : Interrupted system call (code=4)
tcpdump: pcap_loop: critical revent in poll on packet socket fd 3: 0x0008
0 packets captured
0 packets received by filter
0 packets dropped by kernel
Fri Aug 7 11:47:06 2009 SIGINT[hard,] received, process exiting
Looks good. Btw, same result for just setting "ifconfig tun0 down".
Let's strace it:
poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=3, events=POLLIN}], 1, 1000) = 1 ([{fd=3, revents=POLLERR}])
write(2, "tcpdump: pcap_loop: critical revent in poll on packet socket fd 3: 0x0008\n"..., 74) = 74
getsockopt(3, SOL_PACKET, PACKET_STATISTICS, "\0\0\0\0\0\0\0\0"..., [8]) = 0
write(2, "0 packets captured"..., 18) = 18
write(2, "\n"..., 1) = 1
write(2, "0 packets received by filter"..., 28) = 28
write(2, "\n"..., 1) = 1
write(2, "0 packets dropped by kernel\n"..., 28) = 28
setsockopt(3, SOL_PACKET, PACKET_RX_RING, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16) = -1 EBUSY (Device or resource busy)
munmap(0x7f27b3f1b000, 2146304) = 0
close(3) = 0
exit_group(1) = ?
Looks fine.
[Hmm. Is the last setsockopt(3, SOL_PACKET, PACKET_RX_RING, ..) on the dead
file descriptor really needed?...]
Btw, I run ubuntu jaunty amd64.
tcpdump is Version: 3.9.8-4ubuntu2
libpcap0.8 is Version: 1.0.0-1
Regards,
- Thomas Osterried
More information about the Ubuntu-devel-discuss
mailing list