Attachment 299867 Details for Bug 439985 – log from eal5 (initiator)

log from eal5 (initiator)

eal5.secure.log (text/plain), 28.73 KB, created by IBM Bug Proxy on 2008-04-01 08:24:42 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: IBM Bug Proxy

Created: 2008-04-01 08:24:42 UTC

Size: 28.73 KB

patch

obsolete

>
>Mar 31 15:24:43 eal5 ipsec__plutorun: Starting Pluto subsystem...
>Mar 31 15:24:43 eal5 pluto[22910]: Starting Pluto (Openswan Version 2.6.09; Vendor ID OEZD~MT}mAnl) pid:22910
>Mar 31 15:24:43 eal5 pluto[22910]: Setting NAT-Traversal port-4500 floating to on
>Mar 31 15:24:43 eal5 pluto[22910]:    port floating activation criteria nat_t=1/port_float=1
>Mar 31 15:24:43 eal5 pluto[22910]:    including NAT-Traversal patch (Version 0.6c)
>Mar 31 15:24:43 eal5 pluto[22910]: | opening /dev/urandom
>Mar 31 15:24:43 eal5 pluto[22910]: using /dev/urandom as source of random entropy
>Mar 31 15:24:43 eal5 pluto[22910]: | inserting event EVENT_REINIT_SECRET, timeout in 3600 seconds
>Mar 31 15:24:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC_SSH: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_enc(): Activating OAKLEY_TWOFISH_CBC: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_enc(): Activating OAKLEY_SERPENT_CBC: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_enc(): Activating OAKLEY_BLOWFISH_CBC: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_hash(): Activating OAKLEY_SHA2_512: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: ike_alg_register_hash(): Activating OAKLEY_SHA2_256: Ok (ret=0)
>Mar 31 15:24:43 eal5 pluto[22910]: starting up 3 cryptographic helpers
>Mar 31 15:24:43 eal5 pluto[22921]: | opening /dev/urandom
>Mar 31 15:24:43 eal5 pluto[22910]: started helper pid=22921 (fd:7)
>Mar 31 15:24:43 eal5 pluto[22921]: using /dev/urandom as source of random entropy
>Mar 31 15:24:43 eal5 pluto[22923]: | opening /dev/urandom
>Mar 31 15:24:43 eal5 pluto[22910]: started helper pid=22923 (fd:8)
>Mar 31 15:24:44 eal5 pluto[22921]: ! helper 0 waiting on fd: 8
>Mar 31 15:24:44 eal5 pluto[22923]: using /dev/urandom as source of random entropy
>Mar 31 15:24:44 eal5 pluto[22924]: | opening /dev/urandom
>Mar 31 15:24:44 eal5 pluto[22910]: started helper pid=22924 (fd:9)
>Mar 31 15:24:44 eal5 pluto[22923]: ! helper 1 waiting on fd: 9
>Mar 31 15:24:44 eal5 pluto[22924]: using /dev/urandom as source of random entropy
>Mar 31 15:24:44 eal5 pluto[22910]: Using Linux 2.6 IPsec interface code on 2.6.18-86.el5 (experimental code)
>Mar 31 15:24:44 eal5 pluto[22924]: ! helper 2 waiting on fd: 10
>Mar 31 15:24:44 eal5 pluto[22910]: | process 22910 listening for PF_KEY_V2 on file descriptor 12
>Mar 31 15:24:44 eal5 pluto[22910]: | finish_pfkey_msg: SADB_REGISTER message 1 for AH 
>Mar 31 15:24:44 eal5 pluto[22910]: |   02 07 00 02  02 00 00 00  01 00 00 00  7e 59 00 00
>Mar 31 15:24:44 eal5 pluto[22910]: | pfkey_get: SADB_REGISTER message 1
>Mar 31 15:24:44 eal5 pluto[22910]: | AH registered with kernel.
>Mar 31 15:24:44 eal5 pluto[22910]: | finish_pfkey_msg: SADB_REGISTER message 2 for ESP 
>Mar 31 15:24:44 eal5 pluto[22910]: |   02 07 00 03  02 00 00 00  02 00 00 00  7e 59 00 00
>Mar 31 15:24:44 eal5 pluto[22910]: | pfkey_get: SADB_REGISTER message 2
>Mar 31 15:24:44 eal5 pluto[22910]: | alg_init():memset(0x822ec0, 0, 2016) memset(0x8236a0, 0, 2048) 
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: sadb_msg_len=19 sadb_supported_len=56
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=251
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[0], exttype=14, satype=3, alg_id=251, alg_ivlen=0, alg_minbits=0, alg_maxbits=0, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=2
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[1], exttype=14, satype=3, alg_id=2, alg_ivlen=0, alg_minbits=128, alg_maxbits=128, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=3
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[2], exttype=14, satype=3, alg_id=3, alg_ivlen=0, alg_minbits=160, alg_maxbits=160, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=5
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[3], exttype=14, satype=3, alg_id=5, alg_ivlen=0, alg_minbits=256, alg_maxbits=256, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=8
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[4], exttype=14, satype=3, alg_id=8, alg_ivlen=0, alg_minbits=160, alg_maxbits=160, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=14, alg_id=9
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[5], exttype=14, satype=3, alg_id=9, alg_ivlen=0, alg_minbits=128, alg_maxbits=128, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: sadb_msg_len=19 sadb_supported_len=80
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=11
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[6], exttype=15, satype=3, alg_id=11, alg_ivlen=0, alg_minbits=0, alg_maxbits=0, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=2
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[7], exttype=15, satype=3, alg_id=2, alg_ivlen=8, alg_minbits=64, alg_maxbits=64, res=0, ret=1
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=3
>Mar 31 15:24:44 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[8], exttype=15, satype=3, alg_id=3, alg_ivlen=8, alg_minbits=192, alg_maxbits=192, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=6
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[9], exttype=15, satype=3, alg_id=6, alg_ivlen=8, alg_minbits=40, alg_maxbits=128, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=7
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[10], exttype=15, satype=3, alg_id=7, alg_ivlen=8, alg_minbits=40, alg_maxbits=448, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=12
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[11], exttype=15, satype=3, alg_id=12, alg_ivlen=8, alg_minbits=128, alg_maxbits=256, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=252
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[12], exttype=15, satype=3, alg_id=252, alg_ivlen=8, alg_minbits=128, alg_maxbits=256, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=253
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[13], exttype=15, satype=3, alg_id=253, alg_ivlen=8, alg_minbits=128, alg_maxbits=256, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_add():satype=3, exttype=15, alg_id=13
>Mar 31 15:24:45 eal5 pluto[22910]: | kernel_alg_register_pfkey(): SADB_SATYPE_ESP: alg[14], exttype=15, satype=3, alg_id=13, alg_ivlen=8, alg_minbits=128, alg_maxbits=256, res=0, ret=1
>Mar 31 15:24:45 eal5 pluto[22910]: | ESP registered with kernel.
>Mar 31 15:24:45 eal5 pluto[22910]: | finish_pfkey_msg: SADB_REGISTER message 3 for IPCOMP 
>Mar 31 15:24:45 eal5 pluto[22910]: |   02 07 00 09  02 00 00 00  03 00 00 00  7e 59 00 00
>Mar 31 15:24:45 eal5 pluto[22910]: | pfkey_get: SADB_REGISTER message 3
>Mar 31 15:24:45 eal5 pluto[22910]: | IPCOMP registered with kernel.
>Mar 31 15:24:45 eal5 pluto[22910]: Could not change to directory '/etc/ipsec.d/cacerts': /
>Mar 31 15:24:45 eal5 pluto[22910]: Could not change to directory '/etc/ipsec.d/aacerts': /
>Mar 31 15:24:45 eal5 pluto[22910]: Could not change to directory '/etc/ipsec.d/ocspcerts': /
>Mar 31 15:24:45 eal5 pluto[22910]: Could not change to directory '/etc/ipsec.d/crls'
>Mar 31 15:24:45 eal5 pluto[22910]: | inserting event EVENT_LOG_DAILY, timeout in 30915 seconds
>Mar 31 15:24:45 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 118 seconds
>Mar 31 15:24:45 eal5 pluto[22910]: |  
>Mar 31 15:24:45 eal5 pluto[22910]: | *received whack message
>Mar 31 15:24:45 eal5 pluto[22910]: | alg_info_parse_str() ealg_buf=aes aalg_buf=md5eklen=0  aklen=0
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094a0, "OAKLEY_AES")
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_ppfixi () calling enum_search(0x8094a0, "OAKLEY_AES_CBC")
>Mar 31 15:24:45 eal5 pluto[22910]: | parser_alg_info_add() ealg_getbyname("aes")=7
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094b0, "OAKLEY_MD5")
>Mar 31 15:24:45 eal5 pluto[22910]: | parser_alg_info_add() aalg_getbyname("md5")=1
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094c0, "OAKLEY_GROUP_MODP1024")
>Mar 31 15:24:45 eal5 pluto[22910]: | parser_alg_info_add() modp_getbyname("modp1024")=2
>Mar 31 15:24:45 eal5 pluto[22910]: | __alg_info_ike_add() ealg=7 aalg=1 modp_id=2, cnt=1
>Mar 31 15:24:45 eal5 pluto[22910]: | alg_info_parse_str() ealg_buf=aes aalg_buf=sha1eklen=0  aklen=0
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094a0, "OAKLEY_AES")
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_ppfixi () calling enum_search(0x8094a0, "OAKLEY_AES_CBC")
>Mar 31 15:24:45 eal5 pluto[22910]: | parser_alg_info_add() ealg_getbyname("aes")=7
>Mar 31 15:24:45 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094b0, "OAKLEY_SHA1")
>Mar 31 15:24:45 eal5 pluto[22910]: | parser_alg_info_add() aalg_getbyname("sha1")=2
>Mar 31 15:24:46 eal5 pluto[22910]: | enum_search_prefix () calling enum_search(0x8094c0, "OAKLEY_GROUP_MODP1024")
>Mar 31 15:24:46 eal5 pluto[22910]: | parser_alg_info_add() modp_getbyname("modp1024")=2
>Mar 31 15:24:46 eal5 pluto[22910]: | __alg_info_ike_add() ealg=7 aalg=2 modp_id=2, cnt=2
>Mar 31 15:24:46 eal5 pluto[22910]: | Added new connection aes-modp1024 with policy PSK+ENCRYPT+TUNNEL+PFS+!IKEv1+IKEv2ALLOW+IKEv2Init
>Mar 31 15:24:46 eal5 pluto[22910]: | ike (phase1) algorihtm values: AES_CBC(7)_000-MD5(1)-MODP1024(2), AES_CBC(7)_000-SHA1(2)-MODP1024(2); flags=-strict
>Mar 31 15:24:46 eal5 pluto[22910]: | counting wild cards for 9.3.190.198 is 0
>Mar 31 15:24:46 eal5 pluto[22910]: | counting wild cards for 9.47.66.58 is 0
>Mar 31 15:24:46 eal5 pluto[22910]: | alg_info_addref() alg_info->ref_cnt=1
>Mar 31 15:24:46 eal5 pluto[22910]: | alg_info_addref() alg_info->ref_cnt=2
>Mar 31 15:24:46 eal5 pluto[22910]: added connection description "aes-modp1024"
>Mar 31 15:24:46 eal5 pluto[22910]: | 9.3.190.198<9.3.190.198>[S=C]...9.47.66.58<9.47.66.58>[S=C]
>Mar 31 15:24:46 eal5 pluto[22910]: | ike_life: 3600s; ipsec_life: 28800s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 3; policy: PSK+ENCRYPT+TUNNEL+PFS+!IKEv1+IKEv2ALLOW+IKEv2Init
>Mar 31 15:24:46 eal5 pluto[22910]: | * processed 0 messages from cryptographic helpers 
>Mar 31 15:24:46 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 117 seconds
>Mar 31 15:24:46 eal5 pluto[22910]: |  
>Mar 31 15:24:46 eal5 pluto[22910]: | *received whack message
>Mar 31 15:24:46 eal5 pluto[22910]: listening for IKE messages
>Mar 31 15:24:46 eal5 pluto[22910]: | found lo with address 127.0.0.1
>Mar 31 15:24:46 eal5 pluto[22910]: | found eth0 with address 9.3.190.198
>Mar 31 15:24:46 eal5 pluto[22910]: adding interface eth0/eth0 9.3.190.198:500
>Mar 31 15:24:46 eal5 pluto[22910]: adding interface eth0/eth0 9.3.190.198:4500
>Mar 31 15:24:46 eal5 pluto[22910]: adding interface lo/lo 127.0.0.1:500
>Mar 31 15:24:46 eal5 pluto[22910]: adding interface lo/lo 127.0.0.1:4500
>Mar 31 15:24:46 eal5 pluto[22910]: | found lo with address 0000:0000:0000:0000:0000:0000:0000:0001
>Mar 31 15:24:46 eal5 pluto[22910]: adding interface lo/lo ::1:500
>Mar 31 15:24:46 eal5 pluto[22910]: | connect_to_host_pair: 9.3.190.198:500 9.47.66.58:500 -> hp:none 
>Mar 31 15:24:46 eal5 pluto[22910]: loading secrets from "/etc/ipsec.secrets"
>Mar 31 15:24:46 eal5 pluto[22910]: | id type added to secret(0x8b09250) 1: 9.3.190.198
>Mar 31 15:24:46 eal5 pluto[22910]: | id type added to secret(0x8b09250) 1: 9.47.66.58
>Mar 31 15:24:46 eal5 pluto[22910]: | Processing PSK at line 1: passed
>Mar 31 15:24:46 eal5 pluto[22910]: | * processed 0 messages from cryptographic helpers 
>Mar 31 15:24:46 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 117 seconds
>Mar 31 15:25:06 eal5 pluto[22910]: |  
>Mar 31 15:25:06 eal5 pluto[22910]: | *received whack message
>Mar 31 15:25:06 eal5 pluto[22910]: | processing connection aes-modp1024
>Mar 31 15:25:06 eal5 pluto[22910]: | empty esp_info, returning defaults
>Mar 31 15:25:06 eal5 pluto[22910]: | creating state object #1 at 0x8b09af0
>Mar 31 15:25:06 eal5 pluto[22910]: | processing connection aes-modp1024
>Mar 31 15:25:06 eal5 pluto[22910]: | ICOOKIE:  14 b6 24 e5  8a 5e 9b 19
>Mar 31 15:25:06 eal5 pluto[22910]: | RCOOKIE:  00 00 00 00  00 00 00 00
>Mar 31 15:25:06 eal5 pluto[22910]: | state hash entry 13
>Mar 31 15:25:06 eal5 pluto[22910]: | inserting state object #1 on chain 13
>Mar 31 15:25:06 eal5 pluto[22910]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1
>Mar 31 15:25:06 eal5 pluto[22910]: | processing connection aes-modp1024
>Mar 31 15:25:06 eal5 pluto[22910]: | Queuing pending Quick Mode with 9.47.66.58 "aes-modp1024"
>Mar 31 15:25:06 eal5 pluto[22910]: "aes-modp1024" #1: initiating v2 parent SA
>Mar 31 15:25:06 eal5 pluto[22910]: | 1: w->pcw_dead: 0 w->pcw_work: 0 cnt: 3
>Mar 31 15:25:06 eal5 pluto[22910]: | asking helper 1 to do build_kenonce op on seq: 1 (len=2668, pcw_work=1)
>Mar 31 15:25:06 eal5 pluto[22910]: | crypto helper write of request: cnt=2668<wlen=2668.  
>Mar 31 15:25:06 eal5 pluto[22923]: ! helper 1 read 2664+4/2668 bytesfd: 9
>Mar 31 15:25:06 eal5 pluto[22910]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
>Mar 31 15:25:06 eal5 pluto[22923]: ! helper 1 doing build_kenonce op id: 1
>Mar 31 15:25:06 eal5 pluto[22910]: | * processed 0 messages from cryptographic helpers 
>Mar 31 15:25:06 eal5 pluto[22923]: ! Local DH secret:
>Mar 31 15:25:06 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 97 seconds
>Mar 31 15:25:06 eal5 pluto[22923]: !   ec 10 15 70  59 f0 f2 71  88 60 d3 71  2e 40 08 ff
>Mar 31 15:25:06 eal5 pluto[22923]: !   32 58 db 11  a9 cb 33 b0  d3 1d e5 96  48 c6 a7 41
>Mar 31 15:25:06 eal5 pluto[22923]: ! Public DH value sent:
>Mar 31 15:25:06 eal5 pluto[22923]: !   32 bb f7 ad  48 a0 c5 dc  ef 2e 6e ab  91 bd 54 87
>Mar 31 15:25:06 eal5 pluto[22923]: !   1a b5 9a 55  7a 19 19 18  90 69 0a 4c  89 46 46 6c
>Mar 31 15:25:06 eal5 pluto[22923]: !   b2 0a 6b 26  cd 35 98 51  b8 d1 b4 c5  6c 4a 26 0a
>Mar 31 15:25:06 eal5 pluto[22923]: !   c1 86 69 aa  01 d2 25 4a  ed 8d c3 c1  bb eb 9a aa
>Mar 31 15:25:06 eal5 pluto[22923]: !   19 56 22 0d  73 a7 4a ca  c1 c4 11 3f  00 0f a3 51
>Mar 31 15:25:06 eal5 pluto[22923]: !   93 e3 fb 5a  09 bf fa 65  c1 1c 79 9b  fe 37 9b c9
>Mar 31 15:25:06 eal5 pluto[22923]: !   ab 43 23 c4  4c 68 eb a6  03 3d 07 2b  45 d3 ca 8f
>Mar 31 15:25:06 eal5 pluto[22923]: !   0b e9 56 8c  c8 a8 42 cc  8c ca 73 53  5e f6 2c 47
>Mar 31 15:25:06 eal5 pluto[22923]: ! Generated nonce:
>Mar 31 15:25:06 eal5 pluto[22923]: !   5e c3 e1 3f  56 fc a5 0e  80 c9 31 36  14 0b 07 e3
>Mar 31 15:25:06 eal5 pluto[22910]: |  
>Mar 31 15:25:06 eal5 pluto[22910]: | helper 1 has finished work (cnt now 1)
>Mar 31 15:25:06 eal5 pluto[22910]: | helper 1 replies to id: q#1
>Mar 31 15:25:06 eal5 pluto[22910]: | calling callback function 0x758960
>Mar 31 15:25:06 eal5 pluto[22910]: | ikev2 parent outI1: calculated ke+nonce, sending I1
>Mar 31 15:25:06 eal5 pluto[22910]: | processing connection aes-modp1024
>Mar 31 15:25:06 eal5 pluto[22910]: | **emit ISAKMP Message:
>Mar 31 15:25:07 eal5 pluto[22910]: |    initiator cookie:
>Mar 31 15:25:07 eal5 pluto[22910]: |   14 b6 24 e5  8a 5e 9b 19
>Mar 31 15:25:07 eal5 pluto[22910]: |    responder cookie:
>Mar 31 15:25:07 eal5 pluto[22910]: |   00 00 00 00  00 00 00 00
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_v2SA
>Mar 31 15:25:07 eal5 pluto[22910]: |    ISAKMP version: IKEv2 version 2.0 (rfc4306)
>Mar 31 15:25:07 eal5 pluto[22910]: |    exchange type: ISAKMP_v2_SA_INIT
>Mar 31 15:25:07 eal5 pluto[22910]: |    flags: ISAKMP_FLAG_INIT
>Mar 31 15:25:07 eal5 pluto[22910]: |    message ID:  00 00 00 00
>Mar 31 15:25:07 eal5 pluto[22910]: | ***emit IKEv2 Security Association Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_v2KE
>Mar 31 15:25:07 eal5 pluto[22910]: |    critical bit: Payload-Critical
>Mar 31 15:25:07 eal5 pluto[22910]: | ****emit IKEv2 Proposal Substructure Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_P
>Mar 31 15:25:07 eal5 pluto[22910]: |    prop #: 1
>Mar 31 15:25:07 eal5 pluto[22910]: |    proto ID: 1
>Mar 31 15:25:07 eal5 pluto[22910]: |    spi size: 0
>Mar 31 15:25:07 eal5 pluto[22910]: |    # transforms: 4
>Mar 31 15:25:07 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform type: 1
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform ID: 12
>Mar 31 15:25:07 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:07 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform type: 3
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform ID: 2
>Mar 31 15:25:07 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:07 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform type: 2
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform ID: 1
>Mar 31 15:25:07 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:07 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:07 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_NONE
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform type: 4
>Mar 31 15:25:07 eal5 pluto[22910]: |    transform ID: 2
>Mar 31 15:25:07 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Proposal Substructure Payload: 40
>Mar 31 15:25:08 eal5 pluto[22910]: | ****emit IKEv2 Proposal Substructure Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_NONE
>Mar 31 15:25:08 eal5 pluto[22910]: |    prop #: 2
>Mar 31 15:25:08 eal5 pluto[22910]: |    proto ID: 1
>Mar 31 15:25:08 eal5 pluto[22910]: |    spi size: 0
>Mar 31 15:25:08 eal5 pluto[22910]: |    # transforms: 4
>Mar 31 15:25:08 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform type: 1
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform ID: 12
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:08 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform type: 3
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform ID: 2
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:08 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_T
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform type: 2
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform ID: 2
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:08 eal5 pluto[22910]: | *****emit IKEv2 Transform Substructure Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_NONE
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform type: 4
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform ID: 2
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Transform Substructure Payload: 8
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Proposal Substructure Payload: 40
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting length of IKEv2 Security Association Payload: 84
>Mar 31 15:25:08 eal5 pluto[22910]: | ***emit IKEv2 Key Exchange Payload:
>Mar 31 15:25:08 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_v2Ni
>Mar 31 15:25:08 eal5 pluto[22910]: |    transform type: 2
>Mar 31 15:25:08 eal5 pluto[22910]: | emitting 128 raw bytes of ikev2 g^x into IKEv2 Key Exchange Payload
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  32 bb f7 ad  48 a0 c5 dc  ef 2e 6e ab  91 bd 54 87
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  1a b5 9a 55  7a 19 19 18  90 69 0a 4c  89 46 46 6c
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  b2 0a 6b 26  cd 35 98 51  b8 d1 b4 c5  6c 4a 26 0a
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  c1 86 69 aa  01 d2 25 4a  ed 8d c3 c1  bb eb 9a aa
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  19 56 22 0d  73 a7 4a ca  c1 c4 11 3f  00 0f a3 51
>Mar 31 15:25:08 eal5 pluto[22910]: | ikev2 g^x  93 e3 fb 5a  09 bf fa 65  c1 1c 79 9b  fe 37 9b c9
>Mar 31 15:25:09 eal5 pluto[22910]: | ikev2 g^x  ab 43 23 c4  4c 68 eb a6  03 3d 07 2b  45 d3 ca 8f
>Mar 31 15:25:09 eal5 pluto[22910]: | ikev2 g^x  0b e9 56 8c  c8 a8 42 cc  8c ca 73 53  5e f6 2c 47
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting length of IKEv2 Key Exchange Payload: 136
>Mar 31 15:25:09 eal5 pluto[22910]: | ***emit IKEv2 Nonce Payload:
>Mar 31 15:25:09 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_v2V
>Mar 31 15:25:09 eal5 pluto[22910]: |    critical bit: Payload-Critical
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting 16 raw bytes of IKEv2 nonce into IKEv2 Nonce Payload
>Mar 31 15:25:09 eal5 pluto[22910]: | IKEv2 nonce  5e c3 e1 3f  56 fc a5 0e  80 c9 31 36  14 0b 07 e3
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting length of IKEv2 Nonce Payload: 20
>Mar 31 15:25:09 eal5 pluto[22910]: | ***emit ISAKMP Vendor ID Payload:
>Mar 31 15:25:09 eal5 pluto[22910]: |    next payload type: ISAKMP_NEXT_NONE
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting 12 raw bytes of Vendor ID into ISAKMP Vendor ID Payload
>Mar 31 15:25:09 eal5 pluto[22910]: | Vendor ID  4f 45 5a 44  7e 4d 54 7d  6d 41 6e 6c
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting length of ISAKMP Vendor ID Payload: 16
>Mar 31 15:25:09 eal5 pluto[22910]: | emitting length of ISAKMP Message: 284
>Mar 31 15:25:09 eal5 pluto[22910]: | sending 284 bytes for ikev2_parent_outI1_common through eth0:500 to 9.47.66.58:500 (using #1)
>Mar 31 15:25:09 eal5 pluto[22910]: |   14 b6 24 e5  8a 5e 9b 19  00 00 00 00  00 00 00 00
>Mar 31 15:25:09 eal5 pluto[22910]: |   21 20 22 08  00 00 00 00  00 00 01 1c  22 80 00 54
>Mar 31 15:25:09 eal5 pluto[22910]: |   02 00 00 28  01 01 00 04  03 00 00 08  01 00 00 0c
>Mar 31 15:25:09 eal5 pluto[22910]: |   03 00 00 08  03 00 00 02  03 00 00 08  02 00 00 01
>Mar 31 15:25:09 eal5 pluto[22910]: |   00 00 00 08  04 00 00 02  00 00 00 28  02 01 00 04
>Mar 31 15:25:09 eal5 pluto[22910]: |   03 00 00 08  01 00 00 0c  03 00 00 08  03 00 00 02
>Mar 31 15:25:09 eal5 pluto[22910]: |   03 00 00 08  02 00 00 02  00 00 00 08  04 00 00 02
>Mar 31 15:25:09 eal5 pluto[22910]: |   28 00 00 88  00 02 00 00  32 bb f7 ad  48 a0 c5 dc
>Mar 31 15:25:09 eal5 pluto[22910]: |   ef 2e 6e ab  91 bd 54 87  1a b5 9a 55  7a 19 19 18
>Mar 31 15:25:09 eal5 pluto[22910]: |   90 69 0a 4c  89 46 46 6c  b2 0a 6b 26  cd 35 98 51
>Mar 31 15:25:09 eal5 pluto[22910]: |   b8 d1 b4 c5  6c 4a 26 0a  c1 86 69 aa  01 d2 25 4a
>Mar 31 15:25:09 eal5 pluto[22910]: |   ed 8d c3 c1  bb eb 9a aa  19 56 22 0d  73 a7 4a ca
>Mar 31 15:25:09 eal5 pluto[22910]: |   c1 c4 11 3f  00 0f a3 51  93 e3 fb 5a  09 bf fa 65
>Mar 31 15:25:09 eal5 pluto[22910]: |   c1 1c 79 9b  fe 37 9b c9  ab 43 23 c4  4c 68 eb a6
>Mar 31 15:25:09 eal5 pluto[22910]: |   03 3d 07 2b  45 d3 ca 8f  0b e9 56 8c  c8 a8 42 cc
>Mar 31 15:25:09 eal5 pluto[22910]: |   8c ca 73 53  5e f6 2c 47  2b 80 00 14  5e c3 e1 3f
>Mar 31 15:25:09 eal5 pluto[22910]: |   56 fc a5 0e  80 c9 31 36  14 0b 07 e3  00 00 00 10
>Mar 31 15:25:09 eal5 pluto[22910]: |   4f 45 5a 44  7e 4d 54 7d  6d 41 6e 6c
>Mar 31 15:25:09 eal5 pluto[22910]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
>Mar 31 15:25:09 eal5 pluto[22910]: | complete v2 state transition with STF_OK
>Mar 31 15:25:09 eal5 pluto[22910]: "aes-modp1024" #1: transition from state STATE_IKEv2_START to state STATE_PARENT_I1
>Mar 31 15:25:09 eal5 pluto[22910]: "aes-modp1024" #1: STATE_PARENT_I1: sent v2I1, expected v2R1
>Mar 31 15:25:09 eal5 pluto[22910]: | * processed 1 messages from cryptographic helpers 
>Mar 31 15:25:10 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 93 seconds
>Mar 31 15:26:43 eal5 pluto[22910]: |  
>Mar 31 15:26:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:26:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:26:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 3480 seconds
>Mar 31 15:26:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:26:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:26:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:28:42 eal5 pluto[22910]: |  
>Mar 31 15:28:42 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:28:42 eal5 pluto[22910]: | called while no event expired (1206995322/1206995323, EVENT_PENDING_PHASE2)
>Mar 31 15:28:42 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 1 seconds
>Mar 31 15:28:43 eal5 pluto[22910]: |  
>Mar 31 15:28:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:28:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:28:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 3360 seconds
>Mar 31 15:28:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:28:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:28:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:30:43 eal5 pluto[22910]: |  
>Mar 31 15:30:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:30:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:30:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 3240 seconds
>Mar 31 15:30:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:30:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:30:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:32:43 eal5 pluto[22910]: |  
>Mar 31 15:32:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:32:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:32:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 3120 seconds
>Mar 31 15:32:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:32:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:32:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:34:43 eal5 pluto[22910]: |  
>Mar 31 15:34:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:34:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:34:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 3000 seconds
>Mar 31 15:34:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:34:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:34:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:36:43 eal5 pluto[22910]: |  
>Mar 31 15:36:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:36:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:36:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 2880 seconds
>Mar 31 15:36:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:36:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:36:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds
>Mar 31 15:38:43 eal5 pluto[22910]: |  
>Mar 31 15:38:43 eal5 pluto[22910]: | *time to handle event
>Mar 31 15:38:43 eal5 pluto[22910]: | handling event EVENT_PENDING_PHASE2
>Mar 31 15:38:43 eal5 pluto[22910]: | event after this is EVENT_REINIT_SECRET in 2760 seconds
>Mar 31 15:38:43 eal5 pluto[22910]: | inserting event EVENT_PENDING_PHASE2, timeout in 120 seconds
>Mar 31 15:38:43 eal5 pluto[22910]: | pending review: connection "aes-modp1024" checked
>Mar 31 15:38:43 eal5 pluto[22910]: | next event EVENT_PENDING_PHASE2 in 120 seconds

Actions: View

Attachments on bug 439985: 299867 | 299868