[Openswan dev] kernel Oops
hiren joshi
joshihirenn at gmail.com
Tue Mar 11 10:34:18 EDT 2008
Hello All,
A quick reply would be of great help.
Thanks for your valuable time.
Regards,
-hiren
On Thu, Mar 6, 2008 at 8:44 PM, hiren joshi <joshihirenn at gmail.com> wrote:
> Hello All,
>
> 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.
>
> Is this a known issue? Could someone please help me with the solution?
>
> 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).
>
> Thanks in advance.
>
> I am posting the details here.
>
> ------------------------ Details start here ---------------------------
>
>
> Analyzing the debug mode logs in /var/log/messages, I found that
> following lines appear each time when there is an Oops.
>
> 125934-Feb 22 21:19:29 1203695369 kernel: klips_debug:pfkey_add_parse:
> found an old ipsec_sa for SAesp.2000010 at 122.166.6.233, delete it first.
> 125935-Feb 22 21:19:29 1203695369 kernel:
> klips_debug:pfkey_msg_interp: message parsing failed with error -17.
> 125936-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_wipe:
> removing SA=esp.2000010 at 122.166.6.233(0pc0eac000), SAref=57,
> table=0(0pde993000), entry=57 from the refTable.
> 125937-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put:
> ipsec_sa SA:esp.2000010 at 122.166.6.233, ref:-1 reference count decremented.
> 125938-Feb 22 21:19:29 1203695369 kernel: Unable to handle kernel NULL
> pointer dereference at virtual address 00000010
>
> 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.
> The testbed setup:
>
> left PC ipsec gw-left
> router ipsec gw-right right PC
> | 192.168.1.2 | ---- | 192.168.1.1 & 172.16.1.2 | ---- | 172.16.1.1
> & 172.16.2.1 | ---- | 172.16.2.2 & 192.168.2.1 | ---- | 192.168.2.2 |
>
> A simple tunnel with preshared key protecting left PC and right PC
> created. Here is the output of `ipsec spi`
>
> [root at manage ipsec]# ipsec spi
> esp0xcc561bf3 at 172.16.2.2 ESP_3DES_HMAC_MD5: dir=out src=172.16.1.2iv_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
>
> <An SA having same SPI as above will be added manually>
> esp0x315597b4 at 172.16.1.2 ESP_3DES_HMAC_MD5: dir=in src=172.16.2.2iv_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
> tun0x1002 at 172.16.2.2 IPIP: dir=out src=172.16.1.2life(c,s,h)=addtime(17,0,0) natencap=none natsport=0 natdport=0 refcount=4
> ref=12 reftable=0 refentry=12
> tun0x1001 at 172.16.1.2 IPIP: dir=in src=172.16.2.2 policy=
> 192.168.2.2/32->192.168.1.2/32 flags=0x8<> life(c,s,h)=addtime(29,0,0)
> natencap=none natsport=0 natdport=0 refcount=4 ref=7 reftable=0 refentry=7
>
> To regenerate the Oops, I added an SA that was already there in the
> database <Please reffere to the same mark above>.
>
>
> [root at manage ipsec]# ipsec spi --af inet --edst 172.16.2.2 --spi
> 0xcc561bf3 --proto esp --src 172.16.1.2 --esp 3des-md5-96 --enckey
> 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012
> --authkey
> 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012
> Segmentation fault
>
> /var/log/messages:
>
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_sa_process: .
> Feb 24 21:55:50 1203870350 kernel: klips_debug: ipsec_alg_sa_init()
> :entering for encalg=3, authalg=2
> Feb 24 21:55:50 1203870350 kernel: klips_debug: ipsec_alg_sa_init()
> :found ipsec_alg (ixt_e=c7bbc624) for encalg=3
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> processing ext 5 0pc1eab228 with processor 0pc7b89540.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> found address family=2, AF_INET, 172.16.1.2.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> found src address.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> allocating 16 bytes for saddr.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> successful.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> processing ext 6 0pc1eab240 with processor 0pc7b89540.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> found address family=2, AF_INET, 172.16.2.2.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> found dst address.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> allocating 16 bytes for saddr.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> ips_said.dst set to 172.16.2.2.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_address_process:
> successful.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> processing ext 8 0pc1eab258 with processor 0pc7b89b00.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: .
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process:
> allocating 96 bytes for authkey.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process:
> success.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> processing ext 9 0pc1eab2c0 with processor 0pc7b89b00.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process: .
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process:
> allocating 96 bytes for enckey.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_key_process:
> success.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> parsing message type 3(add) with msg_parser 0pc7b84b60.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_add_parse: .
> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_getbyid:
> linked entry in ipsec_sa table for hash=108 of SA:esp.cc561bf3 at 172.16.2.2requested.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_put: ipsec_sa
> SA:esp.cc561bf3 at 172.16.2.2, ref:13 reference count decremented.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_add_parse: found
> an old ipsec_sa for SAesp.cc561bf3 at 172.16.2.2, delete it first.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:pfkey_msg_interp:
> message parsing failed with error -17.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_wipe: removing
> SA=esp.cc561bf3 at 172.16.2.2(0pc5be1400), SAref=17, table=0(0pc79cf000),
> entry=17 from t
> he refTable.
> Feb 24 21:55:50 1203870350 kernel: klips_debug:ipsec_sa_put: ipsec_sa
> SA:esp.cc561bf3 at 172.16.2.2, ref:-1 reference count decremented.
> Feb 24 21:55:50 1203870350 kernel: Unable to handle kernel paging
> request at virtual address 78563422
> Feb 24 21:55:50 1203870350 kernel: printing eip:
> Feb 24 21:55:50 1203870350 kernel: c01b1f1e
> Feb 24 21:55:50 1203870350 kernel: *pde = 00000000
> Feb 24 21:55:51 1203870351 kernel: Oops: 0000 [#4]
> 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
> 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
> 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
> 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
> xt_state iptable_raw iptable_mangle ipt_ipp2p iptable_nat ip_nat
> ip_conntrack nfnetlink iptable_filter ip_tables x_tables e100 8021q
> Feb 24 21:55:51 1203870351 kernel: CPU: 0
> Feb 24 21:55:51 1203870351 kernel: EIP:
> 0060:[crypto_free_tfm+30/160] Not tainted VLI
> Feb 24 21:55:51 1203870351 kernel: EFLAGS: 00010286 (2.6.16.13-1#71)
> Feb 24 21:55:51 1203870351 kernel: EIP is at crypto_free_tfm+0x1e/0xa0
> Feb 24 21:55:51 1203870351 kernel: eax: c7bbc624 ebx: 78563412
> ecx: c1000000 edx: 00000000
> Feb 24 21:55:51 1203870351 kernel: esi: c57d48c0 edi: c57d48c0
> ebp: ffffffff esp: c5de1c7c
> Feb 24 21:55:51 1203870351 kernel: ds: 007b es: 007b ss: 0068
> Feb 24 21:55:51 1203870351 kernel: Process spi (pid: 19646,
> threadinfo=c5de0000 task=c15a3030)
> Feb 24 21:55:51 1203870351 kernel: Stack: <0>00000000 c5be1400
> 00000000 c57d48c0 ffffffff c7b75bf3 c57d48c0 c57d48c0
> Feb 24 21:55:51 1203870351 kernel: c5be1400 00000011 00000000
> c79cf000 00000011 2e707365 36356363 33666231
> Feb 24 21:55:51 1203870351 kernel: 32373140 2e36312e 00322e32
> c7bac060 00000048 00000246 c1eab2c0 00000000
> Feb 24 21:55:51 1203870351 kernel: Call Trace:
> Feb 24 21:55:51 1203870351 kernel: [pg0+125647859/1069925376]
> ipsec_sa_wipe+0x2c3/0x3e0 [ipsec]
> Feb 24 21:55:51 1203870351 kernel: [printk+23/32] printk+0x17/0x20
> Feb 24 21:55:51 1203870351 kernel: [pg0+125764973/1069925376]
> ipsec_alg_get+0x2d/0x50 [ipsec]
> Feb 24 21:55:51 1203870351 kernel: [printk+23/32] printk+0x17/0x20
> Feb 24 21:55:51 1203870351 kernel: [pg0+125726755/1069925376]
> pfkey_msg_interp+0x1a3/0x350 [ipsec]
> Feb 24 21:55:51 1203870351 kernel: [pg0+125709152/1069925376]
> pfkey_add_parse+0x0/0x6f0 [ipsec]
> Feb 24 21:55:51 1203870351 kernel: [pg0+125701282/1069925376]
> pfkey_sendmsg+0x192/0x4b0 [ipsec]
> Feb 24 21:55:51 1203870351 kernel: [do_sock_write+161/192]
> do_sock_write+0xa1/0xc0
> Feb 24 21:55:51 1203870351 kernel: [sock_aio_write+148/160]
> sock_aio_write+0x94/0xa0
> Feb 24 21:55:51 1203870351 kernel: [find_get_page+27/64]
> find_get_page+0x1b/0x40
> Feb 24 21:55:51 1203870351 kernel: [do_sync_write+209/288]
> do_sync_write+0xd1/0x120
> Feb 24 21:55:51 1203870351 kernel: [autoremove_wake_function+0/96]
> autoremove_wake_function+0x0/0x60
> Feb 24 21:55:51 1203870351 kernel: [vfs_write+364/384]
> vfs_write+0x16c/0x180
> Feb 24 21:55:51 1203870351 kernel: [sys_write+81/128]
> sys_write+0x51/0x80
> Feb 24 21:55:51 1203870351 kernel: [syscall_call+7/11]
> syscall_call+0x7/0xb
> 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
> 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
> Feb 24 21:55:51 1203870351 kernel: <6>klips_debug:pfkey_release:
> sock=0pc5fa2080 sk=0pc5167800
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket:
> 0pc5167800
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_remove_socket:
> 0pc5167800
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket:
> pfkey_remove_socket called, sk=0pc5167800
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket:
> sk(0pc5167800)->(&0pc5167854)receive_queue.{next=0pc5167854,prev=0pc5167854}.
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_destroy_socket:
> destroyed.
> Feb 24 21:55:51 1203870351 kernel:
> klips_debug:pfkey_list_remove_socket: removing sock=0pc5fa2080
> Feb 24 21:55:51 1203870351 last message repeated 12 times
> Feb 24 21:55:51 1203870351 kernel: klips_debug:pfkey_release:
> succeeded.
>
> 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.
>
> Here is the diff:
>
> [root at kerneldev ipsec]# diff pfkey_v2_parser_OLD.c
> pfkey_v2_parser_NEW.c
> 2882c2882
> < if(extr.ips != NULL) {
> ---
> > KLIPS_PRINT(debug_pfkey,
> > "klips_debug:pfkey_msg_interp ::::: EXTRA ::::: "
> > "FINAL ERROR CODE IS: %d.\n",
> > error);
> >
> > if(extr.ips != NULL && (error != EEXIST && error != -EEXIST))
> {
> 2885c2885
> < if(extr.ips2 != NULL) {
> ---
> > if(extr.ips2 != NULL && (error != EEXIST && error != -EEXIST))
> {
>
> To prove the patchwork, I tried to regenerate the Oops:
>
> [root at manage ipsec]# ipsec spi
> esp0x47e3e1bf at 172.16.2.2 ESP_3DES_HMAC_MD5: dir=out src=172.16.1.2iv_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
>
> <<An SA with the same SPI as above will be added manually>>
>
> tun0x1002 at 172.16.2.2 IPIP: dir=out src=172.16.1.2life(c,s,h)=addtime(88,0,0) natencap=none natsport=0 natdport=0 refcount=4
> ref=12 reftable=0 refentry=12
> tun0x1001 at 172.16.1.2 IPIP: dir=in src=172.16.2.2 policy=
> 192.168.2.2/32->192.168.1.2/32 flags=0x8<> life(c,s,h)=addtime(101,0,0)
> natencap=none natsport=0 natdport=0 refcount=4 ref=7 reftable=0 refentry=7
> esp0xe8bc3444 at 172.16.1.2 ESP_3DES_HMAC_MD5: dir=in src=172.16.2.2iv_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
>
> [root at manage ipsec]# ipsec spi --af inet --edst 172.16.2.2 --spi
> 0x47e3e1bf --proto esp --src 172.16.1.2 --esp 3des-md5-96 --enckey
> 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012
> --authkey
> 0x123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012
> /usr/libexec/ipsec/spi: pfkey write failed (errno=17): SA already in
> use. Delete old one first.
>
> /var/log/messages:
>
> Feb 24 22:07:28 1203871048 kernel: klips_debug:pfkey_create:
> sock=0pc5a4a200 type:3 state:1 flags:0 protocol:2
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_create:
> sock->fasync_list=0p00000000 sk->sleep=0pc5a4a218.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_insert_socket:
> sk=0pc5554000
> Feb 24 22:07:29 1203871049 kernel:
> klips_debug:pfkey_list_insert_socket: allocating 8 bytes for
> socketp=0pc5a4a200
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_create: Socket
> sock=0pc5a4a200 sk=0pc5554000 initialised.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg: .
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg:
> allocating 296 bytes for downward message.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_sendmsg: msg sent
> for parsing.
> 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.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_SAref_alloc:
> SAref requested... head=17, cont=256, tail=255, listsize=256.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_SAref_alloc:
> allocating SAref=17, table=0, entry=17 of 65536.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:ipsec_sa_alloc:
> allocated 532 bytes for ipsec_sa struct=0pc1273c00 ref=17.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_msg_interp:
> allocated extr->ips=0pc1273c00.
> Feb 24 22:07:29 1203871049 kernel: klips_debug:pfkey_msg_interp:
> satype 3 lookups to proto=50.
> 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.
> 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).
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> remain=35
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> extensions permitted=78001ffb, required=00000063.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> parsing ext type=1(security-association) remain=35.
> 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.
> 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.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> Extension 1(security-association) parsed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> parsing ext type=5(source-address) remain=32.
> 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.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse:
> found exttype=5(source-address) family=2(AF_INET) address=172.16.1.2proto=0 port=0.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse:
> successful.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> Extension 5(source-address) parsed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> parsing ext type=6(destination-address) remain=29.
> 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.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse:
> found exttype=6(destination-address) family=2(AF_INET) address=172.16.2.2proto=0 port=0.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_parse:
> successful.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> Extension 6(destination-address) parsed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> parsing ext type=8(authentication-key) remain=26.
> 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.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_parse:
> success, found len=13 exttype=8(authentication-key) bits=768 reserved=0.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> Extension 8(authentication-key) parsed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> parsing ext type=9(cipher-key) remain=13.
> 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.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_parse:
> success, found len=13 exttype=9(cipher-key) bits=768 reserved=0.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> Extension 9(cipher-key) parsed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_parse:
> extensions permitted=78001ffb, seen=00000363, required=00000063.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> processing ext 1 0pc1c4c010 with processor 0pc7b89220.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sa_process: .
> Feb 24 22:07:30 1203871050 kernel: klips_debug: ipsec_alg_sa_init()
> :entering for encalg=3, authalg=2
> Feb 24 22:07:30 1203871050 kernel: klips_debug: ipsec_alg_sa_init()
> :found ipsec_alg (ixt_e=c7bbc6c4) for encalg=3
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> processing ext 5 0pc1c4c028 with processor 0pc7b89590.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> found address family=2, AF_INET, 172.16.1.2.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> found src address.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> allocating 16 bytes for saddr.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> successful.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> processing ext 6 0pc1c4c040 with processor 0pc7b89590.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> found address family=2, AF_INET, 172.16.2.2.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> found dst address.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> allocating 16 bytes for saddr.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> ips_said.dst set to 172.16.2.2.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_address_process:
> successful.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> processing ext 8 0pc1c4c058 with processor 0pc7b89b50.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: .
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process:
> allocating 96 bytes for authkey.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process:
> success.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> processing ext 9 0pc1c4c0c0 with processor 0pc7b89b50.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process: .
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process:
> allocating 96 bytes for enckey.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_key_process:
> success.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> parsing message type 3(add) with msg_parser 0pc7b84b60.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_add_parse: .
> Feb 24 22:07:30 1203871050 kernel: klips_debug:ipsec_sa_getbyid:
> linked entry in ipsec_sa table for hash=84 of SA:esp.47e3e1bf at 172.16.2.2requested.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:ipsec_sa_put: ipsec_sa
> SA:esp.47e3e1bf at 172.16.2.2, ref:13 reference count decremented.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_add_parse: found
> an old ipsec_sa for SAesp.47e3e1bf at 172.16.2.2, delete it first.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp:
> message parsing failed with error -17.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_msg_interp :::::
> EXTRA ::::: FINAL ERROR CODE IS: -17.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg:
> pfkey_msg_parse returns -17.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending
> up error=-17 message=0pc6187220 to socket=0pc5a4a200.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: allocating
> 16 bytes...
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg:
> ...allocated at 0pc5990380.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending
> up error message to socket=0pc5a4a200 succeeded.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending
> up error=-17 message=0pc6187220 to socket=0pc24c8800.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg: allocating
> 16 bytes...
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_upmsg:
> ...allocated at 0pc30b3780.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_sendmsg: sending
> up error message to socket=0pc24c8800 succeeded.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_release:
> sock=0pc5a4a200 sk=0pc5554000
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket:
> 0pc5554000
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_remove_socket:
> 0pc5554000
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket:
> pfkey_remove_socket called, sk=0pc5554000
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket:
> sk(0pc5554000)->(&0pc5554054)receive_queue.{next=0pc5990380,prev=0pc5990380}.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket:
> skb=0pc5990380 freed.
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_destroy_socket:
> destroyed.
> Feb 24 22:07:30 1203871050 kernel:
> klips_debug:pfkey_list_remove_socket: removing sock=0pc5a4a200
> Feb 24 22:07:30 1203871050 last message repeated 12 times
> Feb 24 22:07:30 1203871050 kernel: klips_debug:pfkey_release:
> succeeded.
>
> 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:
> Mar 06 09:49:07 1204777147 pluto[14814]: packet from
> 122.167.236.87:500: Quick Mode message is for a non-existent (expired?)
> ISAKMP SA
>
> I am not aware of the actual code-flow. Request help for a solution on
> this. A quick reply would be of great help.
>
> ------------------------ Details end here ---------------------------
>
>
> On Wed, Mar 5, 2008 at 2:38 PM, hiren joshi <joshihirenn at gmail.com> wrote:
>
> > barf available on request.
> >
> > Thanks.
> >
> >
> > On Wed, Mar 5, 2008 at 2:33 PM, hiren joshi <joshihirenn at gmail.com>
> > wrote:
> >
> > >
> > >
> > > On Tue, Feb 26, 2008 at 8:20 PM, hiren joshi <joshihirenn at gmail.com>
> > > wrote:
> > >
> > > > uploading debug mode logs:
> > > >
> > > > KLIPS - /var/log/messages:
> > > >
> > > > 125894-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_parse: successful.
> > > > 125895-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: Extension 6(destination-address) parsed.
> > > > 125896-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: parsing ext type=8(authentication-key)
> > > > remain=7.
> > > > 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.
> > > > 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.
> > > > 125899-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: Extension 8(authentication-key) parsed.
> > > > 125900-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: parsing ext type=9(cipher-key) remain=4.
> > > > 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.
> > > > 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.
> > > > 125903-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: Extension 9(cipher-key) parsed.
> > > > 125904-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_parse: extensions permitted=78001ffb, seen=00000363,
> > > > required=00000063.
> > > > 125905-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: processing ext 1 0pdde3b270 with processor
> > > > 0pdf237390.
> > > > 125906-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_sa_process: .
> > > > 125907-Feb 22 21:19:29 1203695369 kernel: klips_debug:
> > > > ipsec_alg_sa_init() :entering for encalg=3, authalg=2
> > > > 125908-Feb 22 21:19:29 1203695369 kernel: klips_debug:
> > > > ipsec_alg_sa_init() :found ipsec_alg (ixt_e=df26aa04) for encalg=3
> > > > 125909-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: processing ext 5 0pdde3b288 with processor
> > > > 0pdf237700.
> > > > 125910-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process:
> > > > 125911-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: found address family=2, AF_INET,
> > > > 122.166.6.187.
> > > > 125912-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: found src address.
> > > > 125913-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: allocating 16 bytes for saddr.
> > > > 125914-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: successful.
> > > > 125915-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: processing ext 6 0pdde3b2a0 with processor
> > > > 0pdf237700.
> > > > 125916-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process:
> > > > 125917-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: found address family=2, AF_INET,
> > > > 122.166.6.233.
> > > > 125918-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: found dst address.
> > > > 125919-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: allocating 16 bytes for saddr.
> > > > 125920-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: ips_said.dst set to 122.166.6.233.
> > > >
> > > > 125921-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_address_process: successful.
> > > > 125922-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: processing ext 8 0pdde3b2b8 with processor
> > > > 0pdf237cc0.
> > > > 125923-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: .
> > > > 125924-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: allocating 16 bytes for authkey.
> > > > 125925-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: success.
> > > > 125926-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: processing ext 9 0pdde3b2d0 with processor
> > > > 0pdf237cc0.
> > > > 125927-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: .
> > > > 125928-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: allocating 24 bytes for enckey.
> > > > 125929-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_key_process: success.
> > > > 125930-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: parsing message type 3(add) with msg_parser
> > > > 0pdf232ce0.
> > > > 125931-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_add_parse: .
> > > > 125932-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:ipsec_sa_getbyid: linked entry in ipsec_sa table for hash=22 of
> > > > SA:esp.2000010 at 122.166.6.233 requested.
> > > > 125933-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put:
> > > > ipsec_sa SA:esp.2000010 at 122.166.6.233, ref:33 reference count
> > > > decremented.
> > > > 125934-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_add_parse: found an old ipsec_sa for
> > > > SAesp.2000010 at 122.166.6.233, delete it first.
> > > > 125935-Feb 22 21:19:29 1203695369 kernel:
> > > > klips_debug:pfkey_msg_interp: message parsing failed with error -17.
> > > > 125936-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_wipe:
> > > > removing SA=esp.2000010 at 122.166.6.233(0pc0eac000), SAref=57,
> > > > table=0(0pde993000), entry=57 from the refTable.
> > > > 125937-Feb 22 21:19:29 1203695369 kernel: klips_debug:ipsec_sa_put:
> > > > ipsec_sa SA:esp.2000010 at 122.166.6.233, ref:-1 reference count
> > > > decremented.
> > > > 125938-Feb 22 21:19:29 1203695369 kernel: Unable to handle kernel
> > > > NULL pointer dereference at virtual address 00000010
> > > > 125939-Feb 22 21:19:29 1203695369 kernel: printing eip:
> > > > 125940-Feb 22 21:19:29 1203695369 kernel: c01bfafe
> > > > 125941-Feb 22 21:19:29 1203695369 kernel: *pde = 00000000
> > > > 125942:Feb 22 21:19:29 1203695369 kernel: Oops: 0000 [#1]
> > > >
> > > > pluto (/var/log/secure):
> > > >
> > > > 10643648-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_key_build:
> > > > 10643649-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: pfkey_msg=0p0x814bad8 allocated 144 bytes,
> > > > &(extensions[0])=0p0xbf8324d0
> > > > 10643650-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[1]
> > > > (type=1)
> > > > 10643651-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[5]
> > > > (type=5)
> > > > 10643652-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[6]
> > > > (type=6)
> > > > 10643653-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[8]
> > > > (type=8)
> > > > 10643654-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: copying 32 bytes from extensions[9]
> > > > (type=9)
> > > > 10643655-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_build: extensions permitted=78001ffb,
> > > > seen=00000363, required=00000063.
> > > > 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.
> > > > 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).
> > > > 10643658-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: remain=16
> > > > 10643659-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: extensions permitted=78001ffb,
> > > > required=00000063.
> > > > 10643660-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: parsing ext type=1(security-association)
> > > > remain=16.
> > > > 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.
> > > > 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.
> > > > 10643663-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: Extension 1(security-association) parsed.
> > > > 10643664-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: parsing ext type=5(source-address)
> > > > remain=13.
> > > > 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.
> > > > 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=122.166.6.187 proto=0 port=0.
> > > > 10643667-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_address_parse: successful.
> > > > 10643668-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: Extension 5(source-address) parsed.
> > > > 10643669-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: parsing ext type=6(destination-address)
> > > > remain=10.
> > > > 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.
> > > > 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=122.166.6.233 proto=0 port=0.
> > > > 10643672-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_address_parse: successful.
> > > > 10643673-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: Extension 6(destination-address) parsed.
> > > > 10643674-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: parsing ext type=8(authentication-key)
> > > > remain=7.
> > > > 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.
> > > > 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.
> > > > 10643677-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: Extension 8(authentication-key) parsed.
> > > > 10643678-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: parsing ext type=9(cipher-key) remain=4.
> > > > 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.
> > > > 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.
> > > > 10643681-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: Extension 9(cipher-key) parsed.
> > > > 10643682-Feb 22 21:19:26 1203695366 pluto[9041]: |
> > > > pfkey_lib_debug:pfkey_msg_parse: extensions permitted=78001ffb,
> > > > seen=00000363, required=00000063.
> > > > 10643683-Feb 22 21:19:26 1203695366 pluto[9041]: | finish_pfkey_msg:
> > > > SADB_ADD message 46 for Add SA esp.2000010 at 122.166.6.233
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > > 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
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > On Fri, Feb 22, 2008 at 5:00 PM, hiren joshi <joshihirenn at gmail.com>
> > > > wrote:
> > > >
> > > > > hello,
> > > > >
> > > > > kernel (using KLIPS) generates Oops:
> > > > >
> > > > > Dec 18 07:48:34 1197944314 kernel: Unable to handle kernel paging
> > > > > request at virtual address 00676673
> > > > > Dec 18 07:48:35 1197944315 kernel: printing eip:
> > > > > Dec 18 07:48:35 1197944315 kernel: c01bfafe
> > > > > Dec 18 07:48:35 1197944315 kernel: *pde = 00000000
> > > > > Dec 18 07:48:35 1197944315 kernel: Oops: 0000 [#1]
> > > > > 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
> > > > > Dec 18 07:48:35 1197944315 kernel: CPU: 0
> > > > > Dec 18 07:48:35 1197944315 kernel: EIP:
> > > > > 0060:[crypto_free_tfm+30/160] Not tainted VLI
> > > > > Dec 18 07:48:35 1197944315 kernel: EFLAGS: 00010282 (2.6.16.13-1#66)
> > > > > Dec 18 07:48:35 1197944315 kernel: EIP is at
> > > > > crypto_free_tfm+0x1e/0xa0
> > > > > Dec 18 07:48:35 1197944315 kernel: eax: deb08a04 ebx: 00676663
> > > > > ecx: 00000000 edx: 00000000
> > > > > Dec 18 07:48:35 1197944315 kernel: esi: c60adc20 edi: c60adc20
> > > > > ebp: 00000000 esp: d16e3c7c
> > > > > Dec 18 07:48:35 1197944315 kernel: ds: 007b es: 007b ss: 0068
> > > > > Dec 18 07:48:35 1197944315 kernel: Process pluto (pid: 9289,
> > > > > threadinfo=d16e2000 task=c7ecc580)
> > > > > Dec 18 07:48:35 1197944315 kernel: Stack: <0>00000020 d5e44800
> > > > > 00000000 c60adc20 00000000 deac1c43 c60adc20 c60adc20
> > > > > Dec 18 07:48:35 1197944315 kernel: d16e3cb0 00000064
> > > > > 00000000 00000000 c699984c 2e707365 30303032 40303130
> > > > > Dec 18 07:48:35 1197944315 kernel: 2e323231 2e363631
> > > > > 33392e36 c143f500 c6999800 00000286 00000286 deb0b480
> > > > > Dec 18 07:48:35 1197944315 ipsec__plutorun: !pluto failure!:
> > > > > exited with error status 139 (signal 11)
> > > > > Dec 18 07:48:35 1197944315 kernel: Call Trace:
> > > > > Dec 18 07:48:35 1197944315 ipsec__plutorun: restarting IPsec after
> > > > > pause...
> > > > > Dec 18 07:48:35 1197944315 kernel: [pg0+510307395/1069446144]
> > > > > ipsec_sa_wipe+0x2c3/0x3e0 [ipsec]
> > > > > Dec 18 07:48:35 1197944315 kernel: [_read_unlock+11/16]
> > > > > _read_unlock+0xb/0x10
> > > > > Dec 18 07:48:35 1197944315 kernel: [pg0+510424935/1069446144]
> > > > > ipsec_alg_get+0x57/0x70 [ipsec]
> > > > > Dec 18 07:48:35 1197944315 kernel: [pg0+510389633/1069446144]
> > > > > pfkey_key_process+0xc1/0x1f0 [ipsec]
> > > > > Dec 18 07:48:35 1197944315 kernel: [pg0+510386659/1069446144]
> > > > > pfkey_msg_interp+0x1a3/0x350 [ipsec]
> > > > > Dec 18 07:48:35 1197944315 kernel: [pg0+510361090/1069446144]
> > > > > pfkey_sendmsg+0x192/0x4b0 [ipsec]
> > > > > Dec 18 07:48:35 1197944315 kernel: [do_sock_write+161/192]
> > > > > do_sock_write+0xa1/0xc0
> > > > > Dec 18 07:48:35 1197944315 kernel: [sock_aio_write+148/160]
> > > > > sock_aio_write+0x94/0xa0
> > > > > Dec 18 07:48:35 1197944315 kernel: [do_sync_write+209/288]
> > > > > do_sync_write+0xd1/0x120
> > > > > Dec 18 07:48:35 1197944315 kernel:
> > > > > [autoremove_wake_function+0/96] autoremove_wake_function+0x0/0x60
> > > > > Dec 18 07:48:35 1197944315 kernel: [_spin_lock+11/16]
> > > > > _spin_lock+0xb/0x10
> > > > > Dec 18 07:48:35 1197944315 kernel: [vfs_write+364/384]
> > > > > vfs_write+0x16c/0x180
> > > > > Dec 18 07:48:35 1197944315 kernel: [sys_write+81/128]
> > > > > sys_write+0x51/0x80
> > > > > Dec 18 07:48:35 1197944315 kernel: [syscall_call+7/11]
> > > > > syscall_call+0x7/0xb
> > > > > 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
> > > > > Dec 18 07:48:45 1197944325 kernel: <2>IPSEC EVENT: KLIPS device
> > > > > ipsec0 shut down.
> > > > > Dec 18 07:48:45 1197944325 kernel: IPSEC EVENT: KLIPS device
> > > > > ipsec1 shut down.
> > > > > Dec 18 07:48:45 1197944325 kernel:
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: ...Openswan IPsec stopped
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: Stopping Openswan IPsec...
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: Removing orphaned
> > > > > /var/run/pluto/pluto.pid:
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: ERROR: Module ipsec is in
> > > > > use
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: Error: an inet prefix is
> > > > > expected rather than "dev".
> > > > > Dec 18 07:48:45 1197944325 ipsec_setup: RTNETLINK answers: Cannot
> > > > > assign requested address
> > > > >
> > > > > the last line in /var/log/secure before Oops is always -
> > > > >
> > > > > Dec 18 07:48:32 1197944312 pluto[9289]: "T-1" #995:
> > > > > STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> > > > >
> > > > > after Oops pluto restarts:
> > > > >
> > > > > Dec 18 07:48:48 1197944328 ipsec__plutorun: Restarting Pluto
> > > > > subsystem...
> > > > > Dec 18 07:48:48 1197944328 ipsec__plutorun: Unknown default RSA
> > > > > hostkey scheme, not generating a default hostkey
> > > > > 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)
> > > > >
> > > > > kernel: 2.6.16.13-1
> > > > > Openswan: 2.4.8
> > > > >
> > > > > it is only when i use a D-Link router at the other end.
> > > > >
> > > > > any clue?
> > > > >
> > > > > regards,
> > > > > -hiren
> > > > >
> > > >
> > > >
> > >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/dev/attachments/20080311/d41cdc6e/attachment-0001.html
More information about the Dev
mailing list