Test Information

TitleUsing new SA for outbound traffic **
CommandLine./ENODE/I_RFC2408_5_3_2_1.seq -pkt ./ENODE/I_RFC2408_5_3_2_1.def test_phase=2 test_type=BASIC -log 110.html -ti Using new SA for outbound traffic **
TestVersionundefined
ToolVersionREL_3_0_8
Start2006/03/16 15:09:31
Tn/usr/local/v6eval//etc//tn.def
Nu/usr/local/v6eval//etc//nut.def
Pkt./ENODE/I_RFC2408_5_3_2_1.def
Systemfreebsd-i386
TargetNamefreebsd5.4
HostNameracoon
Typehost

Test Sequence Execution Log

15:09:32Start

*** Target IKE initialization phase ***
Target: Reset IKE SA entries: saddump
15:09:32 vRemote(ikeResetSA.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ikeResetSA.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 saddump ''
Connected

dell# 
dell# /usr/local/sbin/setkey -c <<EOD
dump;
flush;
EOD

? dump;
? flush;
? EOD
No SAD entries.
dell# 
dell# sendMessagesSync: never got /usr/local/sbin/setkey -c <<EODdump;flush;EOD
echo $status
0
dell# kill -TERM `head -1 /var/run/racoon.pid`
head: /var/run/racoon.pid: No such file or directory

dell# 
echo $status
dell# echo $status
1
dell# /bin/rm -f /var/run/racoon.pid

dell# 
dell# echo $status
0~
[EOT]

Target: Clear SPD entries: spddump
15:09:39 vRemote(ipsecResetSPD.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ipsecResetSPD.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 spddump ''
Connected

dell# 
dell# /usr/local/sbin/setkey -c <<EOD
spddump;
spdflush;? spddump;

EOD

? spdflush;
EOD

? EOD
No SPD entries.
dell# 
dell# sendMessagesSync: never got /usr/local/sbin/setkey -c <<EODspddump;spdflush;EOD
echo $status
0~
[EOT]

Target: Set SPD entries: src=3ffe:501:ffff:100:290:99ff:fe7e:3e52 dst=3ffe:501:ffff:101::11 upperspec=any direction=out protocol=PROTO_IPSEC_ESP mode=Transport
15:09:47 vRemote(ipsecSetSPD.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ipsecSetSPD.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 src=3ffe:501:ffff:100:290:99ff:fe7e:3e52 dst=3ffe:501:ffff:101::11 upperspec=any direction=out protocol=PROTO_IPSEC_ESP mode=Transport ''
Connected

dell# 
dell# /usr/local/sbin/setkey -c <<EOD
spdadd 3ffe:501:ffff:100:290:99ff:fe7e:3e52 3ffe:501:ffff:101::11
       any
       -P out ipsec
       esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::11/require
;
spddump;
EOD

? spdadd 3ffe:501:ffff:100:290:99ff:fe7e:3e52 3ffe:501:ffff:101::11
       any
       -P out ipsec
       esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::11/require
;
spddump;
EOD

?        any
?        -P out ipsec
?        esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::1 1/require
? ;
? spddump;
? EOD
3ffe:501:ffff:100:290:99ff:fe7e:3e52[any] 3ffe:501:ffff:101::11[any] any
        out ipsec
        esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::11/require
        created: Mar 16 06:17:02 2006  lastused: Mar 16 06:17:02 2006
        lifetime: 0(s) validtime: 0(s)
        spid=17790 seq=0 pid=1571
        refcnt=1
dell# 
dell# sendMessagesSync: never got /usr/local/sbin/setkey -c <<EODspdadd 3ffe:501:ffff:100:290:99ff:fe7e:3e52 3ffe:501:ffff:101::11       any       -P out ipsec       esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::11/require;spddump;EOD
echo $status
0~
[EOT]

Target: Set IKE SA entries: dst=3ffe:501:ffff:101::11 dst_port=500 exchange_mode=main doi=ipsec_doi situation=identity_only isakmp_src_id_type=address isakmp_src_id=3ffe:501:ffff:100:290:99ff:fe7e:3e52 dh_group=2 lifetime=28800 lifetime_unit=seconds encryption_algorithm=3des hash_algorithm=sha1 authentication_method=pre_shared_key key_id=3ffe:501:ffff:101::11 key_value=0x494b452d54455354 ph2_id_type=address ph2_src_id=3ffe:501:ffff:100:290:99ff:fe7e:3e52 ph2_dst_id=3ffe:501:ffff:101::11 ph2_src_upper=any ph2_dst_upper=any ipsec_p_num=1 ipsec_p1_t_num=1 ph2_p1_t1_lt=60 ph2_p1_t1_lt_unit=seconds ph2_p1_t1_enc_alg=ESP_3DES ph2_p1_t1_auth_mtd=HMAC_SHA
15:09:55 vRemote(ikeSetSA.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ikeSetSA.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 dst=3ffe:501:ffff:101::11 dst_port=500 exchange_mode=main doi=ipsec_doi situation=identity_only isakmp_src_id_type=address isakmp_src_id=3ffe:501:ffff:100:290:99ff:fe7e:3e52 dh_group=2 lifetime=28800 lifetime_unit=seconds encryption_algorithm=3des hash_algorithm=sha1 authentication_method=pre_shared_key key_id=3ffe:501:ffff:101::11 key_value=0x494b452d54455354 ph2_id_type=address ph2_src_id=3ffe:501:ffff:100:290:99ff:fe7e:3e52 ph2_dst_id=3ffe:501:ffff:101::11 ph2_src_upper=any ph2_dst_upper=any ipsec_p_num=1 ipsec_p1_t_num=1 ph2_p1_t1_lt=60 ph2_p1_t1_lt_unit=seconds ph2_p1_t1_enc_alg=ESP_3DES ph2_p1_t1_auth_mtd=HMAC_SHA ''
Connected

dell# 
dell# ~[set] echocheck

dell# 
dell# ~[put] freebsd-i386.psk.txt /tmp/psk.txt
D
dell# 

dell# 
dell# /bin/chmod 600 /tmp/psk.txt
dell# echo $status
0
dell# ~[set] echocheck

dell# 
dell# ~[put] freebsd-i386.ike.conf /tmp/ike.conf
Ddell# 
dell# 
dell# test -f /var/run/racoon.pid &&kill -TERM `head -1 /var/run/racoon.pid`

dell# 
dell# echo $status
1
dell# /usr/local/sbin/racoon -f /tmp/ike.conf

dell# 
echo $status
dell# echo $status
0~
[EOT]
15:10:08 vRemote(ikeEnable.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ikeEnable.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 ''


*** Target initialization phase ***
15:10:08Start Capturing Packets (Link0)
15:10:08 vRecv(Link0,rs_from_nut rs_from_nut_wsll) timeout:15 cntLimit:0 seektime:0
vRecv() return status=1

*** Target pre-test seaquence ***
15:10:23Clear Captured Packets (Link0)

*** Phase-1 1st message recv ***
HOST1(NUT) send ICMP to HOST2(TN)
15:10:23 vRemoteAsync(ping6.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ping6.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 count=12 interval=6 if=rl0 addr=3ffe:501:ffff:101::11''

Link to remote control log
15:10:23 vRecv(Link0,isakmp_phase1_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:10 cntLimit:0 seektime:0
Receive Neighbor Solicitation from HOST-1(NUT)
15:10:27 vSend(Link0,na_llt)
Send Neighbor Advertisement(TN)
15:10:27 vRecv(Link0,isakmp_phase1_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:10 cntLimit:0 seektime:0
Recv 1st message from HOST1(NUT)

OK payload_check
*** Phase-1 2nd message send ***
15:10:27Clear Captured Packets (Link0)
15:10:27 vSend(Link0,isakmp_phase1_send_2nd)
Send 2nd message from HOST2(TN)

*** Phase-1 3rd message recv ***
15:10:27 vRecv(Link0,isakmp_phase1_recv_3rd ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:5 cntLimit:0 seektime:0
Recv 3rd message from HOST1(NUT)

OK payload_check
*** Phase-1 4th message send ***
15:10:27Clear Captured Packets (Link0)
15:10:27 vSend(Link0,isakmp_phase1_send_4th)
Send 4th message from HOST2(TN)

*** Phase-1 5th message recv ***
15:10:28 vRecv(Link0,isakmp_phase1_recv_5th ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:5 cntLimit:0 seektime:0
Recv 5th message from HOST1(NUT)

OK payload_check
*** Phase-1 6th message send ***
15:10:28Clear Captured Packets (Link0)
15:10:28 vSend(Link0,isakmp_phase1_send_6th)
Send 6th message from HOST2(TN)

*** Target testing phase start ***
*** Phase-2 1st message recv ***
15:10:28 vRecv(Link0,isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:5 cntLimit:0 seektime:0
recv unexpect packet at 15:10:28
Recv Phase-2 1st message (HDR*, HASH(1), SA, Ni, *, *) from HOST1(NUT)

OK payload_check
*** Phase-2 2nd message send ***
15:10:29Clear Captured Packets (Link0)
15:10:29 vSend(Link0,isakmp_phase2_send_2nd)
Send Phase-2 2nd message (HDR*, HASH(2), SA, Nr) from HOST2(TN)

*** Phase-2 3rd message recv ***
15:10:29 vRecv(Link0,isakmp_phase2_recv_3rd ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:5 cntLimit:0 seektime:0
Recv Phase-2 3rd message HDR*, HASH(3) from HOST1(NUT)

OK payload_check
*** IPsec SA is esatblished ***
*** The first IPsec transmission ***
## 1st SA elapsed time: 0 ##
15:10:29 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:0 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 1 ***
*** Re-key testing phase start ***
## 1st SA elapsed time: 4 ##
15:10:33 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 2 ***
## 1st SA elapsed time: 10 ##
15:10:39 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 3 ***
## 1st SA elapsed time: 16 ##
15:10:45 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 4 ***
## 1st SA elapsed time: 22 ##
15:10:51 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 5 ***
## 1st SA elapsed time: 28 ##
15:10:57 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Neighbor Solicitation from HOST-1(NUT)
15:11:02 vSend(Link0,na_ll_llt)
Send Neighbor Advertisement(TN)
15:11:02 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 6 ***
## 1st SA elapsed time: 34 ##
15:11:03 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 7 ***
## 1st SA elapsed time: 40 ##
15:11:09 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
Receive Encrypted Echo Request from HOST-1(NUT)

*** Encrypted Echo Reply message recv 8 ***
## 1st SA elapsed time: 46 ##
15:11:15 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 isakmp_phase2_recv ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
!!! ISAKMP PayloadLength decode(1258) over remain size(88)
Recv Phase-2 1st message (HDR*, HASH(1), SA, Ni, *, *) from HOST1(NUT)

OK payload_check
*** Re-Key 1st message recv ***
*** Re-Key 2nd message send ***
15:11:18Clear Captured Packets (Link0)
15:11:18 vSend(Link0,isakmp_phase2_send_2nd)
Send Phase-2 2nd message (HDR*, HASH(2), SA, Nr) from HOST2(TN)

*** Re-Key 3rd message recv ***
15:11:18 vRecv(Link0,isakmp_phase2_recv_3rd ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:5 cntLimit:0 seektime:0
Recv Phase-2 3rd message HDR*, HASH(3) from HOST1(NUT)

OK payload_check
*** 2nd IPsec SA is esatblished ***
*** Encrypted Echo Request message recv using 2nd IPsec SA ***
15:11:18 vRecv(Link0,echo_request_recv_esp_trans_net0host1_net1host2 ns_uni rs_from_nut rs_from_nut_wsll ns_uni_tll_sll ns_uni_sll ns_multi_llt ns_multi) timeout:6 cntLimit:1 seektime:0
!!! ESP Padding size(242) over remain size(14)
recv unexpect packet at 15:11:21
vRecv() return status=2

## 1st SA elapsed time: 52 ##
## 2nd SA elapsed time: 3 ##
15:11:21 vRemoteAsyncWait()

Link to remote control start point
sleep 3 [sec] for escaping critical point of asynchronous remoteconf.

Connected

dell# 
dell# /sbin/ping6 -n -c 12 -i 6 -h 64 -s 2 -p 00 -I rl0 3ffe:501:ffff:101::11
PATTERN: 0x00
PING6(50=40+8+2 bytes) 3ffe:501:ffff:100:290:99ff:fe7e:3e52 --> 3ffe:501:ffff:101::11

~
[EOT]

Target: Reset IKE SA entries: saddump
15:11:21 vRemote(ikeResetSA.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ikeResetSA.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 saddump ''
Connected




--- 3ffe:501:ffff:101::11 ping6 statistics ---
12 packets transmitted, 0 packets received, 100.0% packet loss

dell# 
dell# 
dell# 
dell# 
dell# 
/usr/local/sbin/setkey -c <<EOD
dump;
flush;
EOD

dell# /usr/local/sbin/setkey -c <<EOD
dump;
flush;
EOD

? dump;
? flush;
? EOD
3ffe:501:ffff:100:290:99ff:fe7e:3e52 3ffe:501:ffff:101::11 
        esp mode=transport spi=4097(0x00001001) reqid=0(0x00000000)
        E: 3des-cbc  a8d226f6 01f2d60b 98d26139 8ec93258 d173a73a 5bd56b22
        A: hmac-sha1  6ac95e98 6a4e135d 0f2f34da e97ae047 466ca5ca
        seq=0x00000001 replay=4 flags=0x00000000 state=mature 
        created: Mar 16 06:18:33 2006   current: Mar 16 06:19:04 2006
        diff: 31(s)     hard: 60(s)     soft: 48(s)
        last: Mar 16 06:18:47 2006      hard: 0(s)      soft: 0(s)
        current: 84(bytes)      hard: 0(bytes)  soft: 0(bytes)
        allocated: 1    hard: 0 soft: 0
        sadb_seq=1 pid=1579 refcnt=2
3ffe:501:ffff:101::11 3ffe:501:ffff:100:290:99ff:fe7e:3e52 
        esp mode=transport spi=61011498(0x03a2f62a) reqid=0(0x00000000)
        E: 3des-cbc  ee195061 0efda07c 3ee29b97 cdd0bcbb 2486d9eb 9c880ce4
        A: hmac-sha1  2a4b393c c7bc2ddc e37b3b02 61cfb665 6dcd070b
        seq=0x00000000 replay=4 flags=0x00000000 state=mature 
        created: Mar 16 06:18:33 2006   current: Mar 16 06:19:04 2006
        diff: 31(s)     hard: 60(s)     soft: 48(s)
        last:                           hard: 0(s)      soft: 0(s)
        current: 0(bytes)       hard: 0(bytes)  soft: 0(bytes)
        allocated: 0    hard: 0 soft: 0
        sadb_seq=0 pid=1579 refcnt=1
dell# 
dell# sendMessagesSync: never got /usr/local/sbin/setkey -c <<EODdump;flush;EOD
echo $status
0
dell# kill -TERM `head -1 /var/run/racoon.pid`

dell# 
echo $status
dell# echo $status
0
dell# /bin/rm -f /var/run/racoon.pid

dell# 
dell# echo $status
0~
[EOT]

Target: Clear SPD entries: spddump
15:11:56 vRemote(ipsecResetSPD.rmt) ``/usr/local/v6eval//bin/freebsd-i386//ipsecResetSPD.rmt -t freebsd-i386 -u root -p v6eval -d ucom0 -o 1 spddump ''
Connected

dell# 
dell# /usr/local/sbin/setkey -c <<EOD
spddump;
spdflush;
? spddump;
? spdflush;
EOD

? EOD
3ffe:501:ffff:100:290:99ff:fe7e:3e52[any] 3ffe:501:ffff:101::11[any] any
        out ipsec
        esp/transport/3ffe:501:ffff:100:290:99ff:fe7e:3e52-3ffe:501:ffff:101::11/require
        created: Mar 16 06:17:02 2006  lastused: Mar 16 06:18:47 2006
        lifetime: 0(s) validtime: 0(s)
        spid=17790 seq=0 pid=1582
        refcnt=1

dell# 
dell# sendMessagesSync: never got /usr/local/sbin/setkey -c <<EODspddump;spdflush;EOD
echo $status
0~
[EOT]
15:12:04End

Packet Reverse Log