[Openswan dev] kernel Oops
hiren joshi
joshihirenn at gmail.com
Thu Mar 6 10:14:30 EST 2008
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.2 proto=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.2 requested.
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/20080306/b75a25fb/attachment-0001.html
More information about the Dev
mailing list