Hello All,<br><br>Doing an Root Cause Analysis of the problem, I have concluded that when ipsec_sa_wipe() is called on existing ipsec_sa, it generates Oops.<br><br>Is this a known issue? Could someone please help me with the solution?<br>
<br>I am giving below all details including testbed setup used to prove the issue, detailed logs (klips-debug), work-around patch in ipsec.ko (linux/net/ipsec/pfkey_v2_parser.c).<br><br>Thanks in advance.<br><br>I am posting the details here.<br>
<br>------------------------ Details start here ---------------------------<br><br><br> Analyzing the debug mode logs in /var/log/messages, I found that following lines appear each time when there is an Oops.<br><br> 125934-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_add_parse: found an old ipsec_sa for <a href="mailto:SAesp.2000010@122.166.6.233">SAesp.2000010@122.166.6.233</a>, delete it first.<br>
125935-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: message parsing failed with error -17.<br> 125936-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_wipe: removing SA=esp.2000010@122.166.6.233(0pc0eac000), SAref=57, table=0(0pde993000), entry=57 from the refTable.<br>
125937-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.2000010@122.166.6.233">esp.2000010@122.166.6.233</a>, ref:-1 reference count decremented.<br> 125938-Feb 22 21:19:29 1203695369 kernel: Unable to handle kernel NULL pointer dereference at virtual address 00000010<br>
<br> From above – I inferred that when ipsec_sa_wipe() is called on existing ipsec_sa, it generates Oops. To prove the inference, I tried to regenerate the same in my testbed setup.<br> The testbed setup:<br><br> left PC ipsec gw-left router ipsec gw-right right PC<br>
| <a href="http://192.168.1.2">192.168.1.2</a> | ---- | <a href="http://192.168.1.1">192.168.1.1</a> & <a href="http://172.16.1.2">172.16.1.2</a> | ---- | <a href="http://172.16.1.1">172.16.1.1</a> & <a href="http://172.16.2.1">172.16.2.1</a> | ---- | <a href="http://172.16.2.2">172.16.2.2</a> & <a href="http://192.168.2.1">192.168.2.1</a> | ---- | <a href="http://192.168.2.2">192.168.2.2</a> |<br>
<br> A simple tunnel with preshared key protecting left PC and right PC created. Here is the output of `ipsec spi`<br><br> [root@manage ipsec]# ipsec spi<br> <a href="mailto:esp0xcc561bf3@172.16.2.2">esp0xcc561bf3@172.16.2.2</a> ESP_3DES_HMAC_MD5: dir=out src=<a href="http://172.16.1.2">172.16.1.2</a> iv_bits=64bits iv=0xfe99b0b8a1fdc2d5 ooowin=64 alen=128 aklen=128 eklen=192 life(c,s,h)=addtime(15,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=13 reftable=0 refentry=13<br>
<br> <An SA having same SPI as above will be added manually><br> <a href="mailto:esp0x315597b4@172.16.1.2">esp0x315597b4@172.16.1.2</a> ESP_3DES_HMAC_MD5: dir=in src=<a href="http://172.16.2.2">172.16.2.2</a> iv_bits=64bits iv=0x74b7ebf27d990ab4 ooowin=64 alen=128 aklen=128 eklen=192 life(c,s,h)=addtime(28,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=8 reftable=0 refentry=8<br>
<a href="mailto:tun0x1002@172.16.2.2">tun0x1002@172.16.2.2</a> IPIP: dir=out src=<a href="http://172.16.1.2">172.16.1.2</a> life(c,s,h)=addtime(17,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=12 reftable=0 refentry=12<br>
<a href="mailto:tun0x1001@172.16.1.2">tun0x1001@172.16.1.2</a> IPIP: dir=in src=<a href="http://172.16.2.2">172.16.2.2</a> policy=<a href="http://192.168.2.2/32-">192.168.2.2/32-</a>><a href="http://192.168.1.2/32">192.168.1.2/32</a> flags=0x8<> life(c,s,h)=addtime(29,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=7 reftable=0 refentry=7<br>
<br> To regenerate the Oops, I added an SA that was already there in the database <Please reffere to the same mark above>.<br><br> [root@manage ipsec]# ipsec spi --af inet --edst <a href="http://172.16.2.2">172.16.2.2</a> --spi 0xcc561bf3 --proto esp --src <a href="http://172.16.1.2">172.16.1.2</a> --esp 3des-md5-96 --enckey 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012 --authkey 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012<br>
Segmentation fault<br><br> /var/log/messages:<br><br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_sa_process: .<br> Feb 24 21:55:50 1203870350 kernel: klips_debug: ipsec_alg_sa_init() :entering for encalg=3, authalg=2<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug: ipsec_alg_sa_init() :found ipsec_alg (ixt_e=c7bbc624) for encalg=3<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: processing ext 5 0pc1eab228 with processor 0pc7b89540.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://172.16.1.2">172.16.1.2</a>.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: found src address.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: successful.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: processing ext 6 0pc1eab240 with processor 0pc7b89540.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://172.16.2.2">172.16.2.2</a>.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: found dst address.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: ips_said.dst set to <a href="http://172.16.2.2">172.16.2.2</a>.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process: successful.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: processing ext 8 0pc1eab258 with processor 0pc7b89b00.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: .<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: allocating 96 bytes for authkey.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: success.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: processing ext 9 0pc1eab2c0 with processor 0pc7b89b00.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: .<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: allocating 96 bytes for enckey.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: success.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: parsing message type 3(add) with msg_parser 0pc7b84b60.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_add_parse: .<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_getbyid: linked entry in ipsec_sa table for hash=108 of SA:<a href="mailto:esp.cc561bf3@172.16.2.2">esp.cc561bf3@172.16.2.2</a> requested.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.cc561bf3@172.16.2.2">esp.cc561bf3@172.16.2.2</a>, ref:13 reference count decremented.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_add_parse: found an old ipsec_sa for <a href="mailto:SAesp.cc561bf3@172.16.2.2">SAesp.cc561bf3@172.16.2.2</a>, delete it first.<br>
Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp: message parsing failed with error -17.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_wipe: removing SA=esp.cc561bf3@172.16.2.2(0pc5be1400), SAref=17, table=0(0pc79cf000), entry=17 from t<br>
he refTable.<br> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.cc561bf3@172.16.2.2">esp.cc561bf3@172.16.2.2</a>, ref:-1 reference count decremented.<br> Feb 24 21:55:50 1203870350 kernel: Unable to handle kernel paging request at virtual address 78563422<br>
Feb 24 21:55:50 1203870350 kernel: printing eip:<br> Feb 24 21:55:50 1203870350 kernel: c01b1f1e<br> Feb 24 21:55:50 1203870350 kernel: *pde = 00000000<br> Feb 24 21:55:51 1203870351 kernel: Oops: 0000 [#4]<br>
Feb 24 21:55:51 1203870351 kernel: Modules linked in: ppp_deflate zlib_deflate zlib_inflate bsd_comp ip_nat_ftp ip_conntrack_ftp ip_conntrack_netlink<br> ipsec sha512 ip_nat_h323 ip_conntrack_h323 ip_nat_irc ip_conntrack_irc ip_nat_pptp ip_conntrack_pptp ip_nat_tftp ip_conntrack_tftp sch_htb md5<br>
sha1 sha256 des blowfish cast5 serpent twofish aes pppoe pppox ppp_synctty ppp_asy nc crc_ccitt ppp_generic slhc ipt_MASQUERADE ipt_iprange ipt_ULOG<br> imq ipt_mport ipt_status xt_pkttype ipt_REDIRECT arptable_filter arp_tables ipt_hashlimit xt_tcpudp ipt_unclean ipt_recent ipt_NOTRACK ipt_IMQ ipt_CONNMARK<br>
xt_state iptable_raw iptable_mangle ipt_ipp2p iptable_nat ip_nat ip_conntrack nfnetlink iptable_filter ip_tables x_tables e100 8021q<br> Feb 24 21:55:51 1203870351 kernel: CPU: 0<br> Feb 24 21:55:51 1203870351 kernel: EIP: 0060:[crypto_free_tfm+30/160] Not tainted VLI<br>
Feb 24 21:55:51 1203870351 kernel: EFLAGS: 00010286 (2.6.16.13-1 #71)<br> Feb 24 21:55:51 1203870351 kernel: EIP is at crypto_free_tfm+0x1e/0xa0<br> Feb 24 21:55:51 1203870351 kernel: eax: c7bbc624 ebx: 78563412 ecx: c1000000 edx: 00000000<br>
Feb 24 21:55:51 1203870351 kernel: esi: c57d48c0 edi: c57d48c0 ebp: ffffffff esp: c5de1c7c<br> Feb 24 21:55:51 1203870351 kernel: ds: 007b es: 007b ss: 0068<br> Feb 24 21:55:51 1203870351 kernel: Process spi (pid: 19646, threadinfo=c5de0000 task=c15a3030)<br>
Feb 24 21:55:51 1203870351 kernel: Stack: <0>00000000 c5be1400 00000000 c57d48c0 ffffffff c7b75bf3 c57d48c0 c57d48c0<br> Feb 24 21:55:51 1203870351 kernel: c5be1400 00000011 00000000 c79cf000 00000011 2e707365 36356363 33666231<br>
Feb 24 21:55:51 1203870351 kernel: 32373140 2e36312e 00322e32 c7bac060 00000048 00000246 c1eab2c0 00000000<br> Feb 24 21:55:51 1203870351 kernel: Call Trace:<br> Feb 24 21:55:51 1203870351 kernel: [pg0+125647859/1069925376] ipsec_sa_wipe+0x2c3/0x3e0 [ipsec]<br>
Feb 24 21:55:51 1203870351 kernel: [printk+23/32] printk+0x17/0x20<br> Feb 24 21:55:51 1203870351 kernel: [pg0+125764973/1069925376] ipsec_alg_get+0x2d/0x50 [ipsec]<br> Feb 24 21:55:51 1203870351 kernel: [printk+23/32] printk+0x17/0x20<br>
Feb 24 21:55:51 1203870351 kernel: [pg0+125726755/1069925376] pfkey_msg_interp+0x1a3/0x350 [ipsec]<br> Feb 24 21:55:51 1203870351 kernel: [pg0+125709152/1069925376] pfkey_add_parse+0x0/0x6f0 [ipsec]<br> Feb 24 21:55:51 1203870351 kernel: [pg0+125701282/1069925376] pfkey_sendmsg+0x192/0x4b0 [ipsec]<br>
Feb 24 21:55:51 1203870351 kernel: [do_sock_write+161/192] do_sock_write+0xa1/0xc0<br> Feb 24 21:55:51 1203870351 kernel: [sock_aio_write+148/160] sock_aio_write+0x94/0xa0<br> Feb 24 21:55:51 1203870351 kernel: [find_get_page+27/64] find_get_page+0x1b/0x40<br>
Feb 24 21:55:51 1203870351 kernel: [do_sync_write+209/288] do_sync_write+0xd1/0x120<br> Feb 24 21:55:51 1203870351 kernel: [autoremove_wake_function+0/96] autoremove_wake_function+0x0/0x60<br> Feb 24 21:55:51 1203870351 kernel: [vfs_write+364/384] vfs_write+0x16c/0x180<br>
Feb 24 21:55:51 1203870351 kernel: [sys_write+81/128] sys_write+0x51/0x80<br> Feb 24 21:55:51 1203870351 kernel: [syscall_call+7/11] syscall_call+0x7/0xb<br> Feb 24 21:55:51 1203870351 kernel: Code: ff 89 c5 e9 34 ff ff ff 90 8d 74 26 00 83 ec 14 89 74 24 08 8b 74 24 18 89 5c 24 04 89 7c 24 0c 85 f6 89 6c 24 10 74<br>
69 8b 5e 28 <8b> 6b 10 89 34 24 e8 37 fe ff ff 8b 83 c0 00 00 00 83 c5 2c 85<br> Feb 24 21:55:51 1203870351 kernel: <6>klips_debug:pfkey_release: sock=0pc5fa2080 sk=0pc5167800<br> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket: 0pc5167800<br>
Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_remove_socket: 0pc5167800<br> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket: pfkey_remove_socket called, sk=0pc5167800<br> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket: sk(0pc5167800)->(&0pc5167854)receive_queue.{next=0pc5167854,prev=0pc5167854}.<br>
Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket: destroyed.<br> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_list_remove_socket: removing sock=0pc5fa2080<br> Feb 24 21:55:51 1203870351 last message repeated 12 times<br>
Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_release: succeeded.<br><br> As the root cause is known and proven, finally, as a workaround, I patched the kernel (linux/net/ipsec/pfkey_v2_parser.c) to disable calling ipsec_sa_wipe() in case of existing ipsec_sa.<br>
<br> Here is the diff:<br><br> [root@kerneldev ipsec]# diff pfkey_v2_parser_OLD.c pfkey_v2_parser_NEW.c<br> 2882c2882<br> < if(extr.ips != NULL) {<br> ---<br> > KLIPS_PRINT(debug_pfkey,<br>
> "klips_debug:pfkey_msg_interp ::::: EXTRA ::::: "<br> > "FINAL ERROR CODE IS: %d.\n",<br> > error);<br> ><br> > if(extr.ips != NULL && (error != EEXIST && error != -EEXIST)) {<br>
2885c2885<br> < if(extr.ips2 != NULL) {<br> ---<br> > if(extr.ips2 != NULL && (error != EEXIST && error != -EEXIST)) {<br><br> To prove the patchwork, I tried to regenerate the Oops:<br>
<br> [root@manage ipsec]# ipsec spi<br> <a href="mailto:esp0x47e3e1bf@172.16.2.2">esp0x47e3e1bf@172.16.2.2</a> ESP_3DES_HMAC_MD5: dir=out src=<a href="http://172.16.1.2">172.16.1.2</a> iv_bits=64bits iv=0xade7b400194850c7 ooowin=64 alen=128 aklen=128 eklen=192 life(c,s,h)=addtime(87,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=13 reftable=0 refentry=13<br>
<br> <<An SA with the same SPI as above will be added manually>> <br><br> <a href="mailto:tun0x1002@172.16.2.2">tun0x1002@172.16.2.2</a> IPIP: dir=out src=<a href="http://172.16.1.2">172.16.1.2</a> life(c,s,h)=addtime(88,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=12 reftable=0 refentry=12<br>
<a href="mailto:tun0x1001@172.16.1.2">tun0x1001@172.16.1.2</a> IPIP: dir=in src=<a href="http://172.16.2.2">172.16.2.2</a> policy=<a href="http://192.168.2.2/32-">192.168.2.2/32-</a>><a href="http://192.168.1.2/32">192.168.1.2/32</a> flags=0x8<> life(c,s,h)=addtime(101,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=7 reftable=0 refentry=7<br>
<a href="mailto:esp0xe8bc3444@172.16.1.2">esp0xe8bc3444@172.16.1.2</a> ESP_3DES_HMAC_MD5: dir=in src=<a href="http://172.16.2.2">172.16.2.2</a> iv_bits=64bits iv=0x3adeea59bb86710e ooowin=64 alen=128 aklen=128 eklen=192 life(c,s,h)=addtime(100,0,0) natencap=none natsport=0 natdport=0 refcount=4 ref=8 reftable=0 refentry=8<br>
<br> [root@manage ipsec]# ipsec spi --af inet --edst <a href="http://172.16.2.2">172.16.2.2</a> --spi 0x47e3e1bf --proto esp --src <a href="http://172.16.1.2">172.16.1.2</a> --esp 3des-md5-96 --enckey 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012 --authkey 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012<br>
/usr/libexec/ipsec/spi: pfkey write failed (errno=17): SA already in use. Delete old one first.<br><br> /var/log/messages:<br><br> Feb 24 22:07:28 1203871048 kernel: klips_debug:pfkey_create: sock=0pc5a4a200 type:3 state:1 flags:0 protocol:2<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_create: sock->fasync_list=0p00000000 sk->sleep=0pc5a4a218.<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_insert_socket: sk=0pc5554000<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_list_insert_socket: allocating 8 bytes for socketp=0pc5a4a200<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_create: Socket sock=0pc5a4a200 sk=0pc5554000 initialised.<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg: .<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg: allocating 296 bytes for downward message.<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg: msg sent for parsing.<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_msg_interp: parsing message ver=2, type=3, errno=0, satype=3(ESP), len=37, res=0, seq=1, pid=22344.<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_SAref_alloc: SAref requested... head=17, cont=256, tail=255, listsize=256.<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_SAref_alloc: allocating SAref=17, table=0, entry=17 of 65536.<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_sa_alloc: allocated 532 bytes for ipsec_sa struct=0pc1273c00 ref=17.<br> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_msg_interp: allocated extr->ips=0pc1273c00.<br>
Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_msg_interp: satype 3 lookups to proto=50.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing message ver=2, type=3(add), errno=0, satype=3(ESP), len=37, res=0, seq=1, pid=22344.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: satype 3(ESP) conversion to proto gives 50 for msg_type 3(add).<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=35<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: extensions permitted=78001ffb, required=00000063.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing ext type=1(security-association) remain=35.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=35 ext_type=1(security-association) ext_len=3 parsing ext 0pc1c4c010 with parser pfkey_sa_parse.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sa_parse: successfully found len=3 exttype=1(security-association) spi=47e3e1bf replay=0 state=1 auth=2 encrypt=3 flags=0 ref=-1.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: Extension 1(security-association) parsed.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing ext type=5(source-address) remain=32.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=32 ext_type=5(source-address) ext_len=3 parsing ext 0pc1c4c028 with parser pfkey_address_parse.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse: found exttype=5(source-address) family=2(AF_INET) address=<a href="http://172.16.1.2">172.16.1.2</a> proto=0 port=0.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse: successful.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: Extension 5(source-address) parsed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing ext type=6(destination-address) remain=29.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=29 ext_type=6(destination-address) ext_len=3 parsing ext 0pc1c4c040 with parser pfkey_address_parse.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse: found exttype=6(destination-address) family=2(AF_INET) address=<a href="http://172.16.2.2">172.16.2.2</a> proto=0 port=0.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse: successful.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: Extension 6(destination-address) parsed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing ext type=8(authentication-key) remain=26.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=26 ext_type=8(authentication-key) ext_len=13 parsing ext 0pc1c4c058 with parser pfkey_key_parse.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_parse: success, found len=13 exttype=8(authentication-key) bits=768 reserved=0.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: Extension 8(authentication-key) parsed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: parsing ext type=9(cipher-key) remain=13.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: remain=13 ext_type=9(cipher-key) ext_len=13 parsing ext 0pc1c4c0c0 with parser pfkey_key_parse.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_parse: success, found len=13 exttype=9(cipher-key) bits=768 reserved=0.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: Extension 9(cipher-key) parsed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse: extensions permitted=78001ffb, seen=00000363, required=00000063.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: processing ext 1 0pc1c4c010 with processor 0pc7b89220.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sa_process: .<br> Feb 24 22:07:30 1203871050 kernel: klips_debug: ipsec_alg_sa_init() :entering for encalg=3, authalg=2<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug: ipsec_alg_sa_init() :found ipsec_alg (ixt_e=c7bbc6c4) for encalg=3<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: processing ext 5 0pc1c4c028 with processor 0pc7b89590.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://172.16.1.2">172.16.1.2</a>.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: found src address.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: successful.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: processing ext 6 0pc1c4c040 with processor 0pc7b89590.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://172.16.2.2">172.16.2.2</a>.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: found dst address.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: ips_said.dst set to <a href="http://172.16.2.2">172.16.2.2</a>.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process: successful.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: processing ext 8 0pc1c4c058 with processor 0pc7b89b50.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: .<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: allocating 96 bytes for authkey.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: success.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: processing ext 9 0pc1c4c0c0 with processor 0pc7b89b50.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: .<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: allocating 96 bytes for enckey.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: success.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: parsing message type 3(add) with msg_parser 0pc7b84b60.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_add_parse: .<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:ipsec_sa_getbyid: linked entry in ipsec_sa table for hash=84 of SA:<a href="mailto:esp.47e3e1bf@172.16.2.2">esp.47e3e1bf@172.16.2.2</a> requested.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.47e3e1bf@172.16.2.2">esp.47e3e1bf@172.16.2.2</a>, ref:13 reference count decremented.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_add_parse: found an old ipsec_sa for <a href="mailto:SAesp.47e3e1bf@172.16.2.2">SAesp.47e3e1bf@172.16.2.2</a>, delete it first.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp: message parsing failed with error -17.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp ::::: EXTRA ::::: FINAL ERROR CODE IS: -17.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: pfkey_msg_parse returns -17.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending up error=-17 message=0pc6187220 to socket=0pc5a4a200.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: allocating 16 bytes...<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: ...allocated at 0pc5990380.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending up error message to socket=0pc5a4a200 succeeded.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending up error=-17 message=0pc6187220 to socket=0pc24c8800.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: allocating 16 bytes...<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: ...allocated at 0pc30b3780.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending up error message to socket=0pc24c8800 succeeded.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_release: sock=0pc5a4a200 sk=0pc5554000<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket: 0pc5554000<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_remove_socket: 0pc5554000<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket: pfkey_remove_socket called, sk=0pc5554000<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket: sk(0pc5554000)->(&0pc5554054)receive_queue.{next=0pc5990380,prev=0pc5990380}.<br>
Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket: skb=0pc5990380 freed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket: destroyed.<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_list_remove_socket: removing sock=0pc5a4a200<br>
Feb 24 22:07:30 1203871050 last message repeated 12 times<br> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_release: succeeded.<br><br> This is just a work-around and can have side-effects. I observed following logs in /var/log/secure which I am not sure whether they are result of the patch I did:<br>
Mar 06 09:49:07 1204777147 pluto[14814]: packet from <a href="http://122.167.236.87:500">122.167.236.87:500</a>: Quick Mode message is for a non-existent (expired?) ISAKMP SA<br><br> I am not aware of the actual code-flow. Request help for a solution on this. A quick reply would be of great help.<br>
<br>------------------------ Details end here ---------------------------<br><br><div class="gmail_quote">On Wed, Mar 5, 2008 at 2:38 PM, hiren joshi <<a href="mailto:joshihirenn@gmail.com">joshihirenn@gmail.com</a>> wrote:<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">barf available on request.<br><br>Thanks.<div><div></div><div class="Wj3C7c"><br><br><div class="gmail_quote">
On Wed, Mar 5, 2008 at 2:33 PM, hiren joshi <<a href="mailto:joshihirenn@gmail.com" target="_blank">joshihirenn@gmail.com</a>> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<div><div></div><div><br><br><div class="gmail_quote">On Tue, Feb 26, 2008 at 8:20 PM, hiren joshi <<a href="mailto:joshihirenn@gmail.com" target="_blank">joshihirenn@gmail.com</a>> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
uploading debug mode logs:<br><br>KLIPS - /var/log/messages:<br><br>125894-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_parse: successful. <br>125895-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: Extension 6(destination-address) parsed. <br>
125896-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: parsing ext type=8(authentication-key) remain=7. <br>125897-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: remain=7 ext_type=8(authentication-key) ext_len=3 parsing ext 0pdde3b2b8 with parser pfkey_key_parse. <br>
125898-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_parse: success, found len=3 exttype=8(authentication-key) bits=128 reserved=0. <br>125899-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: Extension 8(authentication-key) parsed. <br>
125900-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: parsing ext type=9(cipher-key) remain=4. <br>125901-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: remain=4 ext_type=9(cipher-key) ext_len=4 parsing ext 0pdde3b2d0 with parser pfkey_key_parse. <br>
125902-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_parse: success, found len=4 exttype=9(cipher-key) bits=192 reserved=0. <br>125903-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: Extension 9(cipher-key) parsed. <br>
125904-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_parse: extensions permitted=78001ffb, seen=00000363, required=00000063. <br>125905-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: processing ext 1 0pdde3b270 with processor 0pdf237390. <br>
125906-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_sa_process: . <br>125907-Feb 22 21:19:29 1203695369 kernel: klips_debug: ipsec_alg_sa_init() :entering for encalg=3, authalg=2 <br>125908-Feb 22 21:19:29 1203695369 kernel: klips_debug: ipsec_alg_sa_init() :found ipsec_alg (ixt_e=df26aa04) for encalg=3 <br>
125909-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: processing ext 5 0pdde3b288 with processor 0pdf237700. <br>125910-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: <br>125911-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://122.166.6.187" target="_blank">122.166.6.187</a>. <br>
125912-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: found src address. <br>125913-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr. <br>125914-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: successful. <br>
125915-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: processing ext 6 0pdde3b2a0 with processor 0pdf237700. <br>125916-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: <br>125917-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: found address family=2, AF_INET, <a href="http://122.166.6.233" target="_blank">122.166.6.233</a>. <br>
125918-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: found dst address. <br>125919-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: allocating 16 bytes for saddr. <br>125920-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: ips_said.dst set to <a href="http://122.166.6.233" target="_blank">122.166.6.233</a>. <br>
125921-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_address_process: successful. <br>125922-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: processing ext 8 0pdde3b2b8 with processor 0pdf237cc0. <br>
125923-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: . <br>125924-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: allocating 16 bytes for authkey. <br>125925-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: success. <br>
125926-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: processing ext 9 0pdde3b2d0 with processor 0pdf237cc0. <br>125927-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: . <br>125928-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: allocating 24 bytes for enckey. <br>
125929-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_key_process: success. <br>125930-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: parsing message type 3(add) with msg_parser 0pdf232ce0. <br>125931-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_add_parse: . <br>
125932-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_getbyid: linked entry in ipsec_sa table for hash=22 of SA:<a href="mailto:esp.2000010@122.166.6.233" target="_blank">esp.2000010@122.166.6.233</a> requested. <br>
125933-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.2000010@122.166.6.233" target="_blank">esp.2000010@122.166.6.233</a>, ref:33 reference count decremented. <br>
125934-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_add_parse: found an old ipsec_sa for <a href="mailto:SAesp.2000010@122.166.6.233" target="_blank">SAesp.2000010@122.166.6.233</a>, delete it first. <br>125935-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_msg_interp: message parsing failed with error -17. <br>
125936-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_wipe: removing SA=esp.2000010@122.166.6.233(0pc0eac000), SAref=57, table=0(0pde993000), entry=57 from the refTable. <br>125937-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put: ipsec_sa SA:<a href="mailto:esp.2000010@122.166.6.233" target="_blank">esp.2000010@122.166.6.233</a>, ref:-1 reference count decremented. <br>
125938-Feb 22 21:19:29 1203695369 kernel: Unable to handle kernel NULL pointer dereference at virtual address 00000010 <br>125939-Feb 22 21:19:29 1203695369 kernel: printing eip: <br>125940-Feb 22 21:19:29 1203695369 kernel: c01bfafe <br>
125941-Feb 22 21:19:29 1203695369 kernel: *pde = 00000000 <br>125942:Feb 22 21:19:29 1203695369 kernel: Oops: 0000 [#1] <br><br>pluto (/var/log/secure):<br><br>10643648-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_key_build: <br>
10643649-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: pfkey_msg=0p0x814bad8 allocated 144 bytes, &(extensions[0])=0p0xbf8324d0 <br>10643650-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[1] (type=1) <br>
10643651-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[5] (type=5) <br>10643652-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[6] (type=6) <br>
10643653-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[8] (type=8) <br>10643654-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: copying 32 bytes from extensions[9] (type=9) <br>
10643655-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_build: extensions permitted=78001ffb, seen=00000363, required=00000063. <br>10643656-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing message ver=2, type=3(add), errno=0, satype=3(ESP), len=18, res=0, seq=46, pid=9041. <br>
10643657-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: satype 3(ESP) conversion to proto gives 50 for msg_type 3(add). <br>10643658-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=16 <br>
10643659-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: extensions permitted=78001ffb, required=00000063. <br>10643660-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing ext type=1(security-association) remain=16. <br>
10643661-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=16 ext_type=1(security-association) ext_len=3 parsing ext 0p0x814bae8 with parser pfkey_sa_parse. <br>10643662-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_sa_parse: successfully found len=3 exttype=1(security-association) spi=02000010 replay=64 state=1 auth=2 encrypt=3 flags=0 ref=-1. <br>
10643663-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: Extension 1(security-association) parsed. <br>10643664-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing ext type=5(source-address) remain=13. <br>
10643665-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=13 ext_type=5(source-address) ext_len=3 parsing ext 0p0x814bb00 with parser pfkey_address_parse. <br>10643666-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_address_parse: found exttype=5(source-address) family=2(AF_INET) address=<a href="http://122.166.6.187" target="_blank">122.166.6.187</a> proto=0 port=0. <br>
10643667-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_address_parse: successful. <br>10643668-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: Extension 5(source-address) parsed. <br>
10643669-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing ext type=6(destination-address) remain=10. <br>10643670-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=10 ext_type=6(destination-address) ext_len=3 parsing ext 0p0x814bb18 with parser pfkey_address_parse. <br>
10643671-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_address_parse: found exttype=6(destination-address) family=2(AF_INET) address=<a href="http://122.166.6.233" target="_blank">122.166.6.233</a> proto=0 port=0. <br>
10643672-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_address_parse: successful. <br>
10643673-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: Extension 6(destination-address) parsed. <br>10643674-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing ext type=8(authentication-key) remain=7. <br>
10643675-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=7 ext_type=8(authentication-key) ext_len=3 parsing ext 0p0x814bb30 with parser pfkey_key_parse. <br>10643676-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_key_parse: success, found len=3 exttype=8(authentication-key) bits=128 reserved=0. <br>
10643677-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: Extension 8(authentication-key) parsed. <br>10643678-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: parsing ext type=9(cipher-key) remain=4. <br>
10643679-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: remain=4 ext_type=9(cipher-key) ext_len=4 parsing ext 0p0x814bb48 with parser pfkey_key_parse. <br>10643680-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_key_parse: success, found len=4 exttype=9(cipher-key) bits=192 reserved=0. <br>
10643681-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: Extension 9(cipher-key) parsed. <br>10643682-Feb 22 21:19:26 1203695366 pluto[9041]: | pfkey_lib_debug:pfkey_msg_parse: extensions permitted=78001ffb, seen=00000363, required=00000063. <br>
10643683-Feb 22 21:19:26 1203695366 pluto[9041]: | finish_pfkey_msg: SADB_ADD message 46 for Add SA <a href="mailto:esp.2000010@122.166.6.233" target="_blank">esp.2000010@122.166.6.233</a><br>10643684-Feb 22 21:19:26 1203695366 pluto[9041]: | 02 03 00 03 12 00 00 00 2e 00 00 00 51 23 00 00<br>
10643685-Feb 22 21:19:26 1203695366 pluto[9041]: | 03 00 01 00 02 00 00 10 40 01 02 03 00 00 00 00<br>10643686-Feb 22 21:19:26 1203695366 pluto[9041]: | ff ff ff ff 00 00 00 00 03 00 05 00 00 00 00 00<br>10643687:Feb 22 21:19:29 1203695369 pluto[9041]: | 02 00 00 00 7a a6 06 bb 00 00 00 00 00 00 00 00<br>
10643688:Feb 22 21:19:29 1203695369 pluto[9041]: | 03 00 06 00 00 00 00 00 02 00 00 00 7a a6 06 e9<br>10643689:Feb 22 21:19:29 1203695369 pluto[9041]: | 00 00 00 00 00 00 00 00 03 00 08 00 80 00 00 00<br>10643690:Feb 22 21:19:29 1203695369 pluto[9041]: | a8 de 04 00 3a 4c 1d 9d 7f 63 c9 d0 83 1e bf ad<br>
10643691:Feb 22 21:19:29 1203695369 pluto[9041]: | 04 00 09 00 c0 00 00 00 79 3c 43 09 86 3e 06 a6<br>10643692:Feb 22 21:19:29 1203695369 pluto[9041]: | 3a 40 53 2e 94 61 b1 a5 77 08 eb df 09 9f 0d 3d<div><div>
</div><div><br><br><br>
<br><br><div class="gmail_quote">On Fri, Feb 22, 2008 at 5:00 PM, hiren joshi <<a href="mailto:joshihirenn@gmail.com" target="_blank">joshihirenn@gmail.com</a>> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
hello,<br><br>kernel (using KLIPS) generates Oops:<br><br>Dec 18 07:48:34 1197944314 kernel: Unable to handle kernel paging request at virtual address 00676673<br>Dec 18 07:48:35 1197944315 kernel: printing eip:<br>Dec 18 07:48:35 1197944315 kernel: c01bfafe<br>
Dec 18 07:48:35 1197944315 kernel: *pde = 00000000<br>Dec 18 07:48:35 1197944315 kernel: Oops: 0000 [#1]<br>Dec 18 07:48:35 1197944315 kernel: Modules linked in: ppp_deflate zlib_deflate zlib_inflate bsd_comp ip_nat_ftp ip_conntrack_ftp ipsec ip_conntrack_netlink sha512 crypto_null ip_nat_h323 ip_conntrack_h323 ip_nat_irc ip_conntrack_irc ip_nat_pptp ip_conntrack_pptp ip_nat_tftp ip_conntrack_tftp sch_htb md5 sha1 sha256 des blowfish cast5 serpent twofish aes ipt_MASQUERADE ipt_iprange pppoe pppox ppp_synctty ppp_async crc_ccitt ppp_generic slhc ipt_ULOG imq ipt_mport ipt_status xt_pkttype ip_conntrack_elite_proxy ipt_REDIRECT arptable_filter arp_tables ipt_hashlimit xt_tcpudp ipt_unclean ipt_recent ipt_NOTRACK ipt_IMQ ipt_CONNMARK ipt_set ipt_OUTDEV ipt_ENTITY xt_state ipt_entity ip_conntrack_master_fillup ip_conntrack_direction_helper ip_set_markipmap ip_set ipt_APPCLASS iptable_raw iptable_mangle ipt_ipp2p iptable_nat ip_nat ip_conntrack nfnetlink iptable_filter ip_tables x_tables e100 8021q<br>
Dec 18 07:48:35 1197944315 kernel: CPU: 0<br>Dec 18 07:48:35 1197944315 kernel: EIP: 0060:[crypto_free_tfm+30/160] Not tainted VLI<br>Dec 18 07:48:35 1197944315 kernel: EFLAGS: 00010282 (2.6.16.13-1 #66)<br>Dec 18 07:48:35 1197944315 kernel: EIP is at crypto_free_tfm+0x1e/0xa0<br>
Dec 18 07:48:35 1197944315 kernel: eax: deb08a04 ebx: 00676663 ecx: 00000000 edx: 00000000<br>Dec 18 07:48:35 1197944315 kernel: esi: c60adc20 edi: c60adc20 ebp: 00000000 esp: d16e3c7c<br>Dec 18 07:48:35 1197944315 kernel: ds: 007b es: 007b ss: 0068<br>
Dec 18 07:48:35 1197944315 kernel: Process pluto (pid: 9289, threadinfo=d16e2000 task=c7ecc580)<br>Dec 18 07:48:35 1197944315 kernel: Stack: <0>00000020 d5e44800 00000000 c60adc20 00000000 deac1c43 c60adc20 c60adc20<br>
Dec 18 07:48:35 1197944315 kernel: d16e3cb0 00000064 00000000 00000000 c699984c 2e707365 30303032 40303130<br>Dec 18 07:48:35 1197944315 kernel: 2e323231 2e363631 33392e36 c143f500 c6999800 00000286 00000286 deb0b480<br>
Dec 18 07:48:35 1197944315 ipsec__plutorun: !pluto failure!: exited with error status 139 (signal 11)<br>Dec 18 07:48:35 1197944315 kernel: Call Trace:<br>Dec 18 07:48:35 1197944315 ipsec__plutorun: restarting IPsec after pause...<br>
Dec 18 07:48:35 1197944315 kernel: [pg0+510307395/1069446144] ipsec_sa_wipe+0x2c3/0x3e0 [ipsec]<br>Dec 18 07:48:35 1197944315 kernel: [_read_unlock+11/16] _read_unlock+0xb/0x10<br>Dec 18 07:48:35 1197944315 kernel: [pg0+510424935/1069446144] ipsec_alg_get+0x57/0x70 [ipsec]<br>
Dec 18 07:48:35 1197944315 kernel: [pg0+510389633/1069446144] pfkey_key_process+0xc1/0x1f0 [ipsec]<br>Dec 18 07:48:35 1197944315 kernel: [pg0+510386659/1069446144] pfkey_msg_interp+0x1a3/0x350 [ipsec]<br>Dec 18 07:48:35 1197944315 kernel: [pg0+510361090/1069446144] pfkey_sendmsg+0x192/0x4b0 [ipsec]<br>
Dec 18 07:48:35 1197944315 kernel: [do_sock_write+161/192] do_sock_write+0xa1/0xc0<br>Dec 18 07:48:35 1197944315 kernel: [sock_aio_write+148/160] sock_aio_write+0x94/0xa0<br>Dec 18 07:48:35 1197944315 kernel: [do_sync_write+209/288] do_sync_write+0xd1/0x120<br>
Dec 18 07:48:35 1197944315 kernel: [autoremove_wake_function+0/96] autoremove_wake_function+0x0/0x60<br>Dec 18 07:48:35 1197944315 kernel: [_spin_lock+11/16] _spin_lock+0xb/0x10<br>Dec 18 07:48:35 1197944315 kernel: [vfs_write+364/384] vfs_write+0x16c/0x180<br>
Dec 18 07:48:35 1197944315 kernel: [sys_write+81/128] sys_write+0x51/0x80<br>Dec 18 07:48:35 1197944315 kernel: [syscall_call+7/11] syscall_call+0x7/0xb<br>Dec 18 07:48:35 1197944315 kernel: Code: ff 89 c5 e9 34 ff ff ff 90 8d 74 26 00 83 ec 14 89 74 24 08 8b 74 24 18 89 5c 24 04 89 7c 24 0c 85 f6 89 6c 24 10 74 69 8b 5e 28 <8b> 6b 10 89 34 24 e8 37 fe ff ff 8b 83 c0 00 00 00 83 c5 2c 85<br>
Dec 18 07:48:45 1197944325 kernel: <2>IPSEC EVENT: KLIPS device ipsec0 shut down.<br>Dec 18 07:48:45 1197944325 kernel: IPSEC EVENT: KLIPS device ipsec1 shut down.<br>Dec 18 07:48:45 1197944325 kernel:<br>Dec 18 07:48:45 1197944325 ipsec_setup: ...Openswan IPsec stopped<br>
Dec 18 07:48:45 1197944325 ipsec_setup: Stopping Openswan IPsec...<br>Dec 18 07:48:45 1197944325 ipsec_setup: Removing orphaned /var/run/pluto/pluto.pid:<br>Dec 18 07:48:45 1197944325 ipsec_setup: ERROR: Module ipsec is in use<br>
Dec 18 07:48:45 1197944325 ipsec_setup: Error: an inet prefix is expected rather than "dev".<br>Dec 18 07:48:45 1197944325 ipsec_setup: RTNETLINK answers: Cannot assign requested address<br><br>the last line in /var/log/secure before Oops is always -<br>
<br>Dec 18 07:48:32 1197944312 pluto[9289]: "T-1" #995: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2<br><br>after Oops pluto restarts:<br><br>Dec 18 07:48:48 1197944328 ipsec__plutorun: Restarting Pluto subsystem...<br>
Dec 18 07:48:48 1197944328 ipsec__plutorun: Unknown default RSA hostkey scheme, not generating a default hostkey<br>
Dec 18 07:48:48 1197944328 pluto[17193]: Starting Pluto (Openswan
Version 2.4.8 LDAP_V3 PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR; Vendor ID
OE]bWX`QBruL)<br>
<br>kernel: 2.6.16.13-1<br>Openswan: 2.4.8<br><br>it is only when i use a D-Link router at the other end.<br><br>any clue?<br><br>regards,<br><font color="#888888">-hiren<br>
</font></blockquote></div><br>
</div></div></blockquote></div><br>
</div></div></blockquote></div><br>
</div></div></blockquote></div><br>