[Vpn-help] Shrew v. 2.1.4 Openswan 2.4.6.1

Fri Nov 21 05:24:49 CST 2008

Matthew Grooms schrieb:
> Hmmm, not a lot to work with here. It looks like the only information 
> being logged is related to packet reception. I would venture to guess 
> that the log level is set too low to be of any use in identifying or 
> resolving the problem.

I just started to run ipsec with debug switch:

hopefully this is a bit more verbose:

klips_debug:ipsec_sa_put: ipsec_sa SA:unk0:0@<invalid>, ref:-1
reference count decremented.
klips_debug:pfkey_sendmsg: .
klips_debug:pfkey_sendmsg: allocating 16 bytes for downward message.
klips_debug:pfkey_sendmsg: msg sent for parsing.
klips_debug:pfkey_msg_interp: parsing message ver=2, type=7, errno=0,
satype=9(IPIP), len=2, res=0, seq=4, pid=3592.
klips_debug:ipsec_SAref_alloc: SAref requested... head=6, cont=256,
tail=255, listsize=256.
klips_debug:ipsec_SAref_alloc: allocating SAref=6, table=0, entry=6 of
65536.
klips_debug:ipsec_sa_alloc: allocated 552 bytes for ipsec_sa
struct=0p80af4c00 ref=6.
klips_debug:pfkey_msg_interp: allocated extr->ips=0p80af4c00.
klips_debug:pfkey_msg_parse: parsing message ver=2, type=7(register),
errno=0, satype=9(IPIP), len=2, res=0, seq=4, pid=3592.
klips_debug:pfkey_msg_parse: remain=0
klips_debug:pfkey_msg_parse: extensions permitted=00000001,
required=00000001.
klips_debug:pfkey_msg_parse: extensions permitted=00000001,
seen=00000001, required=00000001.
klips_debug:pfkey_msg_interp: parsing message type 7(register) with
msg_parser 0pc0154748.
klips_debug:pfkey_register_parse: .
klips_debug:pfkey_list_insert_socket: allocating 8 bytes for
socketp=0p80de5ce8
klips_debug:pfkey_register_parse: SATYPE=09(IPIP) successfully
registered by KMd (pid=3592).
klips_debug:pfkey_register_reply: pfkey_supported_list[9]=0p80a35840
klips_debug:pfkey_register_reply: checking supported=0p80a35840
klips_debug:pfkey_register_reply: adding encrypt alg.
klips_debug:pfkey_register_reply: checking supported=0p80a35780
klips_debug:pfkey_register_reply: adding encrypt alg.
klips_debug:pfkey_register_reply: checking supported=0p80a35880
klips_debug:pfkey_register_reply: adding encrypt alg.
klips_debug:pfkey_register_reply: checking supported=0p80a35820
klips_debug:pfkey_register_reply: adding encrypt alg.
klips_debug:pfkey_register_reply: allocating 32 bytes for enc algs.
klips_debug:pfkey_register_reply: found satype=9(IPIP) exttype=15 id=4
ivlen=0 minbits=128 maxbits=128.
klips_debug:pfkey_register_reply: found satype=9(IPIP) exttype=15 id=3
ivlen=0 minbits=32 maxbits=128.
klips_debug:pfkey_register_reply: found satype=9(IPIP) exttype=15 id=2
ivlen=0 minbits=128 maxbits=32.
klips_debug:pfkey_register_reply: found satype=9(IPIP) exttype=15 id=1
ivlen=0 minbits=32 maxbits=32.
klips_debug:pfkey_msg_hdr_build:
klips_debug:pfkey_msg_hdr_build: on_entry &pfkey_ext=0p80607c70
pfkey_ext=0p80607c90 *pfkey_ext=0p00000000.
klips_debug:pfkey_msg_hdr_build: on_exit &pfkey_ext=0p80607c70
pfkey_ext=0p80607c90 *pfkey_ext=0p80550aa0.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_msg_build: pfkey_msg=0p80dc0320 allocated 56 bytes,
&(extensions[0])=0p80607c90
klips_debug:pfkey_msg_build: copying 40 bytes from extensions[15]
(type=15)
klips_debug:pfkey_msg_build: extensions permitted=0000c001,
seen=00008001, required=00000001.
klips_debug:pfkey_upmsg: allocating 56 bytes...
klips_debug:pfkey_upmsg: ...allocated at 0p806de8e0.
klips_debug:pfkey_register_reply: sending up register message for
satype=9(IPIP) to socket=0p80de5ce8 succeeded.
klips_debug:ipsec_sa_wipe: removing SA=unk0:0@<invalid>(0p80af4c00),
SAref=6, table=0(0pc0195000), entry=6 from the refTable.
klips_debug:ipsec_sa_put: ipsec_sa SA:unk0:0@<invalid>, ref:-1
reference count decremented.
klips_debug:pfkey_sendmsg: .
klips_debug:pfkey_sendmsg: allocating 184 bytes for downward message.
klips_debug:pfkey_sendmsg: msg sent for parsing.
klips_debug:pfkey_msg_interp: parsing message ver=2, type=14, errno=0,
satype=11(INT), len=23, res=0, seq=5, pid=3592.
klips_debug:ipsec_SAref_alloc: SAref requested... head=7, cont=256,
tail=255, listsize=256.
klips_debug:ipsec_SAref_alloc: allocating SAref=7, table=0, entry=7 of
65536.
klips_debug:ipsec_sa_alloc: allocated 552 bytes for ipsec_sa
struct=0p80af4c00 ref=7.
klips_debug:pfkey_msg_interp: allocated extr->ips=0p80af4c00.
klips_debug:pfkey_msg_interp: satype 11 lookups to proto=61.
klips_debug:pfkey_msg_parse: parsing message ver=2,
type=14(x-addflow(eroute)), errno=0, satype=11(INT), len=23, res=0,
seq=5, pid=3592.
klips_debug:pfkey_msg_parse: satype 11(INT) conversion to proto gives
61 for msg_type 14(x-addflow(eroute)).
klips_debug:pfkey_msg_parse: remain=21
klips_debug:pfkey_msg_parse: extensions permitted=05e00c63,
required=01e00043.
klips_debug:pfkey_msg_parse: parsing ext type=1(security-association)
remain=21.
klips_debug:pfkey_msg_parse: remain=21
ext_type=1(security-association) ext_len=3 parsing ext 0p80ad4490 with
parser pfkey_sa_parse.
klips_debug:pfkey_sa_parse: successfully found len=3
exttype=1(security-association) spi=00000104 replay=0 state=0 auth=0
encrypt=0 flags=0 ref=-1.
klips_debug:pfkey_msg_parse: Extension 1(security-association) parsed.
klips_debug:pfkey_msg_parse: parsing ext type=5(source-address) remain=18.
klips_debug:pfkey_msg_parse: remain=18 ext_type=5(source-address)
ext_len=3 parsing ext 0p80ad44a8 with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found exttype=5(source-address)
family=2(AF_INET) address=10.8.0.1 proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 5(source-address) parsed.
klips_debug:pfkey_msg_parse: parsing ext type=6(destination-address)
remain=15.
klips_debug:pfkey_msg_parse: remain=15 ext_type=6(destination-address)
ext_len=3 parsing ext 0p80ad44c0 with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found exttype=6(destination-address)
family=2(AF_INET) address=0.0.0.0 proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 6(destination-address) parsed.
klips_debug:pfkey_msg_parse: parsing ext
type=21(X-source-flow-address) remain=12.
klips_debug:pfkey_msg_parse: remain=12
ext_type=21(X-source-flow-address) ext_len=3 parsing ext 0p80ad44d8
with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found
exttype=21(X-source-flow-address) family=2(AF_INET) address=10.10.0.0
proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 21(X-source-flow-address) parsed.
klips_debug:pfkey_msg_parse: parsing ext type=22(X-dest-flow-address)
remain=9.
klips_debug:pfkey_msg_parse: remain=9 ext_type=22(X-dest-flow-address)
ext_len=3 parsing ext 0p80ad44f0 with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found exttype=22(X-dest-flow-address)
family=2(AF_INET) address=192.168.100.0 proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 22(X-dest-flow-address) parsed.
klips_debug:pfkey_msg_parse: parsing ext type=23(X-source-mask) remain=6.
klips_debug:pfkey_msg_parse: remain=6 ext_type=23(X-source-mask)
ext_len=3 parsing ext 0p80ad4508 with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found exttype=23(X-source-mask)
family=2(AF_INET) address=255.255.255.0 proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 23(X-source-mask) parsed.
klips_debug:pfkey_msg_parse: parsing ext type=24(X-dest-mask) remain=3.
klips_debug:pfkey_msg_parse: remain=3 ext_type=24(X-dest-mask)
ext_len=3 parsing ext 0p80ad4520 with parser pfkey_address_parse.
klips_debug:pfkey_address_parse: found exttype=24(X-dest-mask)
family=2(AF_INET) address=255.255.255.0 proto=0 port=0.
klips_debug:pfkey_address_parse: successful.
klips_debug:pfkey_msg_parse: Extension 24(X-dest-mask) parsed.
klips_debug:pfkey_msg_parse: extensions permitted=05e00c63,
seen=01e00063, required=01e00043.
klips_debug:pfkey_msg_interp: processing ext 1 0p80ad4490 with
processor 0pc0157710.
klips_debug:pfkey_sa_process: .
klips_debug:pfkey_msg_interp: processing ext 5 0p80ad44a8 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
10.8.0.1.
klips_debug:pfkey_address_process: found src address.
klips_debug:pfkey_address_process: allocating 16 bytes for saddr.
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: processing ext 6 0p80ad44c0 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
0.0.0.0.
klips_debug:pfkey_address_process: found dst address.
klips_debug:pfkey_address_process: allocating 16 bytes for saddr.
klips_debug:pfkey_address_process: ips_said.dst set to 0.0.0.0.
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: processing ext 21 0p80ad44d8 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
10.10.0.0.
klips_debug:pfkey_address_process: found src flow address.
klips_debug:pfkey_alloc_eroute: allocating 200 bytes for an eroute at
0p80ad4780
klips_debug:pfkey_address_parse: extr->eroute set to
10.10.0.0/0:0->0.0.0.0/0:0
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: processing ext 22 0p80ad44f0 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
192.168.100.0.
klips_debug:pfkey_address_process: found dst flow address.
klips_debug:pfkey_alloc_eroute: eroute struct already allocated
klips_debug:pfkey_address_parse: extr->eroute set to
10.10.0.0/0:0->192.168.100.0/0:0
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: processing ext 23 0p80ad4508 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
255.255.255.0.
klips_debug:pfkey_address_process: found src mask address.
klips_debug:pfkey_alloc_eroute: eroute struct already allocated
klips_debug:pfkey_address_parse: extr->eroute set to
10.10.0.0/24:0->192.168.100.0/0:0
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: processing ext 24 0p80ad4520 with
processor 0pc0157ac0.
klips_debug:pfkey_address_process:
klips_debug:pfkey_address_process: found address family=2, AF_INET,
255.255.255.0.
klips_debug:pfkey_address_process: found dst mask address.
klips_debug:pfkey_alloc_eroute: eroute struct already allocated
klips_debug:pfkey_address_parse: extr->eroute set to
10.10.0.0/24:0->192.168.100.0/24:0
klips_debug:pfkey_address_process: successful.
klips_debug:pfkey_msg_interp: parsing message type
14(x-addflow(eroute)) with msg_parser 0pc01553d8.
klips_debug:pfkey_x_addflow_parse: .
klips_debug:pfkey_x_addflow_parse: calling breakeroute and/or
makeroute for 10.10.0.0/24->192.168.100.0/24
klips_debug:pfkey_x_addflow_parse: calling makeroute.
klips_debug:ipsec_makeroute: attempting to allocate 200 bytes to
insert eroute for 10.10.0.0/24->192.168.100.0/24, SA: %trap, PID:3592,
skb=0p00000000, ident:NULL->NULL
klips_debug:ipsec_makeroute: 141a10000a0a0000c0a864000000000000000000
/ 141aff00ffffff00ffffff000000000000000000
klips_debug:ipsec_makeroute: calling rj_addroute now
klips_debug:ipsec_makeroute: pid=03592 count=         0 lasttime=
0 10.10.0.0/24       -> 192.168.100.0/24   => %trap
klips_debug:ipsec_makeroute: succeeded.
klips_debug:pfkey_x_addflow_parse: makeroute call successful.
klips_debug:pfkey_msg_hdr_build:
klips_debug:pfkey_msg_hdr_build: on_entry &pfkey_ext=0p80607b10
pfkey_ext=0p80607bd0 *pfkey_ext=0p00000000.
klips_debug:pfkey_msg_hdr_build: on_exit &pfkey_ext=0p80607b10
pfkey_ext=0p80607bd0 *pfkey_ext=0p807c6300.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_sa_build: spi=00000104 replay=0 sa_state=0 auth=0
encrypt=0 flags=0
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=5 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=10.8.0.1:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=6 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=0.0.0.0:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=21 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=10.10.0.0:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=22 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=192.168.100.0:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=23 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=255.255.255.0:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_address_build: exttype=24 proto=0 prefixlen=0
klips_debug:pfkey_address_build: found address family AF_INET.
klips_debug:pfkey_address_build: found address=255.255.255.0:0.
klips_debug:pfkey_address_build: successful created len: 3.
klips_debug:pfkey_safe_build: error=0
klips_debug:pfkey_safe_build:success.
klips_debug:pfkey_msg_build: pfkey_msg=0p80ad4a80 allocated 184 bytes,
&(extensions[0])=0p80607bd0
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[1] (type=1)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[5] (type=5)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[6] (type=6)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[21]
(type=21)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[22]
(type=22)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[23]
(type=23)
klips_debug:pfkey_msg_build: copying 24 bytes from extensions[24]
(type=24)
klips_debug:pfkey_msg_build: extensions permitted=05e00063,
seen=01e00063, required=01e00043.
klips_debug:pfkey_upmsg: allocating 184 bytes...
klips_debug:pfkey_upmsg: ...allocated at 0p80e70380.
klips_debug:pfkey_x_addflow_parse: sending up x_addflow reply message
for satype=11(INT) (proto=61) to socket=0p80de5ce8 succeeded.
klips_debug:pfkey_x_addflow_parse: extr->ips cleaned up and freed.
klips_debug:ipsec_sa_wipe: removing SA=%trap(0p80af4c00), SAref=7,
table=0(0pc0195000), entry=7 from the refTable.
klips_debug:ipsec_sa_put: ipsec_sa SA:%trap, ref:-1 reference count
decremented.
klips_debug:ipsec_rcv: suspected ESPinUDP packet (NAT-Traversal) [1].
klips_debug:   IP: ihl:20 ver:4 tos:0 tlen:340 id:1303 frag_off:0
ttl:54 proto:17 (UDP) chk:26227 saddr:85.181.184.81:500 daddr:10.8.0.1:500
klips_debug:ipsec_rcv: IKE packet - not handled here
klips_debug:ipsec_rcv: suspected ESPinUDP packet (NAT-Traversal) [1].
klips_debug:   IP: ihl:20 ver:4 tos:0 tlen:265 id:1559 frag_off:0
ttl:54 proto:17 (UDP) chk:26046 saddr:85.181.184.81:500 daddr:10.8.0.1:500
klips_debug:ipsec_rcv: IKE packet - not handled here
klips_debug:ipsec_rcv: suspected ESPinUDP packet (NAT-Traversal) [2].
klips_debug:   IP: ihl:20 ver:4 tos:0 tlen:1668 id:1815 frag_off:0
ttl:54 proto:17 (UDP) chk:24387 saddr:85.181.184.81:4500
daddr:10.8.0.1:4500
klips_debug:ipsec_rcv: IKE packet - not handled here

-- 

stefan