[Openswan dev] kernel Oops

hiren joshi joshihirenn at gmail.com
Wed Mar 12 08:26:34 EDT 2008


Thanks much for quick feedback.

Could you please suggest whether you plan to take this in main-stream? Do
you advise me to post a bug at: bugs.openswan.org?

Thanks and Regards,
-hiren

On Tue, Mar 11, 2008 at 10:04 PM, Paul Wouters <paul at xelerance.com> wrote:

> On Tue, 11 Mar 2008, hiren joshi wrote:
>
> It looks like the right fix, but we havent had time to fully evaluate
> it and apply it to our trees.
>
> Paul
>
> > Date: Tue, 11 Mar 2008 20:04:18 +0530
> > From: hiren joshi <joshihirenn at gmail.com>
> > To:  <dev at openswan.org>
> > Subject: Re: [Openswan dev] kernel Oops
> >
> > 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
> > > > > > >
> > > > > >
> > > > > >
> > > > >
> > > >
> > >
> >
>
> --
> Building and integrating Virtual Private Networks with Openswan:
> http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/dev/attachments/20080312/f3f06943/attachment-0001.html 


More information about the Dev mailing list