[Openswan Users] STATE_MAIN_I3: sent MI3, expecting MR3, 002 #1: received 1 malformed payload notifies

Tue Jun 12 16:47:20 EDT 2012

Paul, thank you, here you go:

| sending 84 bytes for STATE_MAIN_I2 through eth0:500 to PUBLIC-IP:500 
(using #1)
|   7f 1f f7 06  0c dd df d9  fa 17 e3 73  cf a0 22 56
|   05 10 02 01  00 00 00 00  00 00 00 54  fa 7c ac 19
|   24 70 c4 52  df 8b b5 3d  1c 58 c7 0e  85 61 98 cc
|   dc 8f 84 05  7f 29 ed 19  d5 ba bc 91  a0 25 66 34
|   3e c7 82 14  f6 58 94 00  01 21 af dd  de 44 5c ee
|   58 62 33 b0
| inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
| event added at head of queue
"telefonica/2x0" #1: STATE_MAIN_I3: sent MI3, expecting MR3
| modecfg pull: noquirk policy:push not-client
| phase 1 is done, looking for phase 2 to unpend
| * processed 1 messages from cryptographic helpers
| next event EVENT_RETRANSMIT in 10 seconds for #1
| next event EVENT_RETRANSMIT in 10 seconds for #1
|
| *received 40 bytes from PUBLIC-IP:500 on eth0 (port=500)
|   7f 1f f7 06  0c dd df d9  fa 17 e3 73  cf a0 22 56
|   0b 10 05 00  ee 2f c1 77  00 00 00 28  00 00 00 0c
|   00 00 00 00  01 00 00 10
| **parse ISAKMP Message:
|    initiator cookie:
|   7f 1f f7 06  0c dd df d9
|    responder cookie:
|   fa 17 e3 73  cf a0 22 56
|    next payload type: ISAKMP_NEXT_N
|    ISAKMP version: ISAKMP Version 1.0 (rfc2407)
|    exchange type: ISAKMP_XCHG_INFO
|    flags: none
|    message ID:  ee 2f c1 77
|    length: 40
|  processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
| ICOOKIE:  7f 1f f7 06  0c dd df d9
| RCOOKIE:  fa 17 e3 73  cf a0 22 56
| state hash entry 4
| peer and cookies match on #1, provided msgid 00000000 vs 00000000/00000000
| p15 state object #1 found, in STATE_MAIN_I3
| processing connection telefonica/2x0
| got payload 0x800(ISAKMP_NEXT_N) needed: 0x0 opt: 0x0
| ***parse ISAKMP Notification Payload:
|    next payload type: ISAKMP_NEXT_NONE
|    length: 12
|    DOI: ISAKMP_DOI_ISAKMP
|    protocol ID: 1
|    SPI size: 0
|    Notify Message Type: PAYLOAD_MALFORMED
| info:
| processing informational PAYLOAD_MALFORMED (16)
"telefonica/2x0" #1: received 1 malformed payload notifies
| complete state transition with STF_IGNORE
| * processed 0 messages from cryptographic helpers
| next event EVENT_RETRANSMIT in 10 seconds for #1
| next event EVENT_RETRANSMIT in 10 seconds for #1
|
| next event EVENT_RETRANSMIT in 0 seconds for #1
| *time to handle event
| handling event EVENT_RETRANSMIT
| event after this is EVENT_PENDING_DDNS in 44 seconds
| processing connection telefonica/2x0
| handling event EVENT_RETRANSMIT for <invalid> "telefonica/2x0" #1
| sending 84 bytes for EVENT_RETRANSMIT through eth0:500 to 
PUBLIC-IP:500 (using #1)
|   7f 1f f7 06  0c dd df d9  fa 17 e3 73  cf a0 22 56
|   05 10 02 01  00 00 00 00  00 00 00 54  fa 7c ac 19
|   24 70 c4 52  df 8b b5 3d  1c 58 c7 0e  85 61 98 cc
|   dc 8f 84 05  7f 29 ed 19  d5 ba bc 91  a0 25 66 34
|   3e c7 82 14  f6 58 94 00  01 21 af dd  de 44 5c ee
|   58 62 33 b0
| inserting event EVENT_RETRANSMIT, timeout in 20 seconds for #1
| event added at head of queue
| next event EVENT_RETRANSMIT in 20 seconds for #1
|
| *received whack message
terminating all conns with alias='telefonica'
| processing connection telefonica/2x0
"telefonica/2x0": terminating SAs using this connection
| removing pending policy for "none" {0x10c9120}
| processing connection telefonica/2x0
"telefonica/2x0" #1: deleting state (STATE_MAIN_I3)
| deleting event for #1
| deleting state #1
| deleting event for #1
| removing pending policy for "telefonica/1x0" {0x10caa20}
| no suspended cryptographic state for 1
| ICOOKIE:  7f 1f f7 06  0c dd df d9
| RCOOKIE:  fa 17 e3 73  cf a0 22 56
| state hash entry 4
| processing connection telefonica/1x0
"telefonica/1x0": terminating SAs using this connection
| * processed 0 messages from cryptographic helpers
| next event EVENT_PENDING_DDNS in 39 seconds
| next event EVENT_PENDING_DDNS in 39 seconds
|
| *received whack message
shutting down
forgetting secrets
| processing connection telefonica/2x0
"telefonica/2x0": deleting connection
| alg_info_delref(0x10c8000) alg_info->ref_cnt=1
| alg_info_delref(0x10c8000) freeing alg_info
| alg_info_delref(0x10c7390) alg_info->ref_cnt=1
| alg_info_delref(0x10c7390) freeing alg_info
| processing connection telefonica/1x0
"telefonica/1x0": deleting connection
| alg_info_delref(0x10c6e70) alg_info->ref_cnt=1
| alg_info_delref(0x10c6e70) freeing alg_info
| alg_info_delref(0x10c6200) alg_info->ref_cnt=1
| alg_info_delref(0x10c6200) freeing alg_info
| crl fetch request list locked by 'free_crl_fetch'
| crl fetch request list unlocked by 'free_crl_fetch'
| crl list locked by 'free_crls'
| crl list unlocked by 'free_crls'
| ocsp cache locked by 'free_ocsp_cache'
| ocsp cache unlocked by 'free_ocsp_cache'
shutting down interface lo/lo ::1:500
shutting down interface lo/lo 127.0.0.1:500

El 12/06/12 13:17, Paul Wouters escribió:
> On Tue, 12 Jun 2012, Luis Fernando Gramajo wrote:
>
>> 108 "telefonica/2x0" #1: STATE_MAIN_I3: sent MI3, expecting MR3
>> 002 "telefonica/2x0" #1: received 1 malformed payload notifies
>
> Post a plutodebug=all log output of that MR3 packet coming in so someone
> can check out what's happening.
>
> Paul

-- 
Luis Fernando Gramajo P.
Redes y Telecomunicaciones
Sistemas de Información EMPAGUA