Got the following call trace when running an ipsec connection between my
2.6.0-test8-mm1 box and a Checkpoint FW-1 NG firewall:
Uninitialised timer!
This is just a warning. Your computer is OK
function=0x00030004, data=0x0
Call Trace:
[<c0124288>] check_timer_failed+0x40/0x4f
[<c0124567>] del_timer+0x17/0x9a
[<c02ccdfb>] xfrm_policy_gc_kill+0x4f/0x7d
[<c02ccea8>] xfrm_policy_gc_task+0x7f/0x8f
[<c012ad36>] worker_thread+0x189/0x254
[<c02cce29>] xfrm_policy_gc_task+0x0/0x8f
[<c011ae23>] default_wake_function+0x0/0x18
[<c02dce66>] ret_from_fork+0x6/0x14
[<c011ae23>] default_wake_function+0x0/0x18
[<c012abad>] worker_thread+0x0/0x254
[<c010a7a1>] kernel_thread_helper+0x5/0xb
After this warning, racoon started taking 100% CPU. I tried to gather as
much information as possible, but since racoon wasn't built with debug
symbols, it might be useless..
Anyway this is probably caused by a bug in racoon not catching an error
condition correctly.. in which case, ignore the info down below :)
(ps: platform is Redhat Severn beta3 / Fedora Core release 0.95,
whatever it's called these days -- ipsec-tools 0.2.2)
# gdb /usr/local/sbin/racoon 2643
GNU gdb Red Hat Linux (5.3.90-0.20030710.21rh)
Copyright 2003 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you
are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for
details.
This GDB was configured as "i386-redhat-linux-gnu"...(no debugging
symbols found)...Using host libthread_db library
"/lib/tls/libthread_db.so.1".
Attaching to program: /usr/local/sbin/racoon, process 2643
Error while mapping shared library sections:
linux-gate.so.1: Success.
Error while reading shared library symbols:
linux-gate.so.1: No such file or directory.
Reading symbols from /lib/libcrypto.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib/libcrypto.so.2
Reading symbols from /lib/libssl.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib/libssl.so.2
Reading symbols from /lib/libresolv.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /usr/local/lib/libipsec.so.0...done.
Loaded symbols for /usr/local/lib/libipsec.so.0
Reading symbols from /lib/tls/libc.so.6...done.
Loaded symbols for /lib/tls/libc.so.6
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
0xffffd405 in ?? ()
(gdb) bt
#0 0xffffd405 in ?? ()
#1 0x44ff1516 in munmap () from /lib/tls/libc.so.6
#2 0x44f88fcc in munmap_chunk () from /lib/tls/libc.so.6
#3 0x0805c5b8 in ?? ()
#4 0x40127008 in ?? ()
#5 0x40127008 in ?? ()
#6 0x0006fba0 in ?? ()
#7 0x00000002 in ?? ()
#8 0x03000802 in ?? ()
#9 0xdff6df74 in ?? ()
#10 0xdff6df74 in ?? ()
#11 0xffffffff in ?? ()
#12 0x0809ab48 in ?? ()
Output from ldd:
# ldd /usr/local/sbin/racoon
linux-gate.so.1 => linux-gate.so.1 (0xffffd000)
libcrypto.so.2 => /lib/libcrypto.so.2 (0x40017000)
libssl.so.2 => /lib/libssl.so.2 (0x400ec000)
libresolv.so.2 => /lib/libresolv.so.2 (0x451b5000)
libipsec.so.0 => /usr/local/lib/libipsec.so.0 (0x4011b000)
libc.so.6 => /lib/tls/libc.so.6 (0x44f1a000)
libdl.so.2 => /lib/libdl.so.2 (0x45078000)
/lib/ld-linux.so.2 => /lib/ld-linux.so.2 (0x44f02000)
Might also be useful:
# cat /proc/2643/maps
08048000-0808e000 r-xp 00000000 03:04 536072 /usr/local/sbin/racoon
0808e000-08091000 rw-p 00045000 03:04 536072 /usr/local/sbin/racoon
08091000-080b3000 rwxp 00000000 00:00 0
40016000-40017000 rw-p 00000000 00:00 0
40017000-400dd000 r-xp 00000000 03:04 125763
/lib/libcrypto.so.0.9.6b
400dd000-400e8000 rw-p 000c6000 03:04 125763
/lib/libcrypto.so.0.9.6b
400e8000-400ec000 rw-p 00000000 00:00 0
400ec000-40118000 r-xp 00000000 03:04 125229 /lib/libssl.so.0.9.6b
40118000-4011b000 rw-p 0002c000 03:04 125229 /lib/libssl.so.0.9.6b
4011b000-40125000 r-xp 00000000 03:04 244826
/usr/local/lib/libipsec.so.0.0.0
40125000-40126000 rw-p 0000a000 03:04 244826
/usr/local/lib/libipsec.so.0.0.0
40126000-40197000 rw-p 00000000 00:00 0
44f02000-44f17000 r-xp 00000000 03:04 91885 /lib/ld-2.3.2.so
44f17000-44f18000 rw-p 00015000 03:04 91885 /lib/ld-2.3.2.so
44f1a000-4504c000 r-xp 00000000 03:04 91895 /lib/tls/libc-2.3.2.so
4504c000-4504f000 rw-p 00132000 03:04 91895 /lib/tls/libc-2.3.2.so
4504f000-45052000 rw-p 00000000 00:00 0
45078000-4507a000 r-xp 00000000 03:04 91896 /lib/libdl-2.3.2.so
4507a000-4507b000 rw-p 00001000 03:04 91896 /lib/libdl-2.3.2.so
451b5000-451c4000 r-xp 00000000 03:04 91953 /lib/libresolv-2.3.2.so
451c4000-451c5000 rw-p 0000e000 03:04 91953 /lib/libresolv-2.3.2.so
451c5000-451c7000 rw-p 00000000 00:00 0
bfffd000-c0000000 rwxp ffffe000 00:00 0
ffffd000-ffffe000 r-xp 00000000 00:00 0
Syslog entries leading upto the error (IP addresses have been blanked):
Oct 21 23:13:52 kvo racoon: INFO: isakmp.c:1520:isakmp_ph1expire():
ISAKMP-SA expired yyy.yyy.yyy.yyy[500]-xxx.xxx.xxx.xxx[500]
spi:4bb85fd05fa31b03:47fc2a1953b3c1b0
Oct 21 23:13:53 kvo racoon: INFO: isakmp.c:1568:isakmp_ph1delete():
ISAKMP-SA deleted yyy.yyy.yyy.yyy[500]-xxx.xxx.xxx.xxx[500]
spi:4bb85fd05fa31b03:47fc2a1953b3c1b0
Oct 21 23:14:53 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel xxx.xxx.xxx.xxx->yyy.yyy.yyy.yyy
spi=164184855(0x9c94317)
Oct 21 23:14:53 kvo racoon: INFO: isakmp.c:1688:isakmp_post_acquire():
IPsec-SA request for xxx.xxx.xxx.xxx queued due to no phase1 found.
Oct 21 23:14:53 kvo racoon: INFO: isakmp.c:797:isakmp_ph1begin_i():
initiate new phase 1 negotiation:
yyy.yyy.yyy.yyy[500]<=>xxx.xxx.xxx.xxx[500]
Oct 21 23:14:53 kvo racoon: INFO: isakmp.c:802:isakmp_ph1begin_i():
begin Aggressive mode.
Oct 21 23:14:53 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel yyy.yyy.yyy.yyy->xxx.xxx.xxx.xxx
spi=378352362(0x168d32ea)
Oct 21 23:14:53 kvo racoon: NOTIFY: oakley.c:2040:oakley_skeyid():
couldn't find the proper pskey, try to get one by the peer's address.
Oct 21 23:14:53 kvo racoon: INFO: isakmp.c:2418:log_ph1established():
ISAKMP-SA established yyy.yyy.yyy.yyy[500]-xxx.xxx.xxx.xxx[500]
spi:28435203179be423:b84
08bd066aea6b4
Oct 21 23:14:54 kvo racoon: INFO: isakmp.c:941:isakmp_ph2begin_i():
initiate new phase 2 negotiation:
yyy.yyy.yyy.yyy[0]<=>xxx.xxx.xxx.xxx[0]
Oct 21 23:14:54 kvo racoon: ERROR: ipsec_doi.c:3306:ipsecdoi_setid2():
no policy found for spid:33.
Oct 21 23:14:54 kvo racoon: ERROR: isakmp_quick.c:203:quick_i1send():
failed to get ID.
Oct 21 23:14:54 kvo racoon: ERROR: pfkey.c:897:pk_recvgetspi(): failed
to start post getspi.
Oct 21 23:15:24 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel xxx.xxx.xxx.xxx->yyy.yyy.yyy.yyy
spi=144112996(0x896fd64)
Oct 21 23:16:05 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel xxx.xxx.xxx.xxx->yyy.yyy.yyy.yyy
spi=10920659(0xa6a2d3)
Oct 21 23:16:05 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel yyy.yyy.yyy.yyy->xxx.xxx.xxx.xxx
spi=378352365(0x168d32ed)
Oct 21 23:16:53 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel xxx.xxx.xxx.xxx->yyy.yyy.yyy.yyy
spi=164184855(0x9c94317)
Oct 21 23:16:53 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel yyy.yyy.yyy.yyy->xxx.xxx.xxx.xxx
spi=378352362(0x168d32ea)
Oct 21 23:17:21 kvo smartd[560]: Device: /dev/hda, SMART Usage
Attribute: 194 Temperature_Celsius changed from 40 to 41
Oct 21 23:18:05 kvo racoon: INFO: pfkey.c:1367:pk_recvexpire(): IPsec-SA
expired: ESP/Tunnel xxx.xxx.xxx.xxx->yyy.yyy.yyy.yyy
spi=10920659(0xa6a2d3)
Oct 21 23:18:05 kvo kernel: Uninitialised timer!
Oct 21 23:18:05 kvo kernel: This is just a warning. Your computer is OK
Oct 21 23:18:05 kvo kernel: function=0x00030004, data=0x0
Oct 21 23:18:05 kvo kernel: Call Trace:
Oct 21 23:18:05 kvo kernel: [<c0124288>] check_timer_failed+0x40/0x4f
Oct 21 23:18:05 kvo kernel: [<c0124567>] del_timer+0x17/0x9a
Oct 21 23:18:05 kvo kernel: [<c02ccdfb>] xfrm_policy_gc_kill+0x4f/0x7d
Oct 21 23:18:05 kvo kernel: [<c02ccea8>] xfrm_policy_gc_task+0x7f/0x8f
Oct 21 23:18:05 kvo kernel: [<c012ad36>] worker_thread+0x189/0x254
Oct 21 23:18:05 kvo kernel: [<c02cce29>] xfrm_policy_gc_task+0x0/0x8f
Oct 21 23:18:05 kvo kernel: [<c011ae23>] default_wake_function+0x0/0x18
Oct 21 23:18:05 kvo kernel: [<c02dce66>] ret_from_fork+0x6/0x14
Oct 21 23:18:05 kvo kernel: [<c011ae23>] default_wake_function+0x0/0x18
Oct 21 23:18:05 kvo kernel: [<c012abad>] worker_thread+0x0/0x254
Oct 21 23:18:05 kvo kernel: [<c010a7a1>] kernel_thread_helper+0x5/0xb
Oct 21 23:18:05 kvo kernel:
-
: send the line "unsubscribe linux-net" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
