[Openswan Users] Mode Config packets answered with CERTIFICATE_UNAVAILABLE

Sascha.Grau at Stud.Tu-Ilmenau.De Sascha.Grau at Stud.Tu-Ilmenau.De
Thu Jan 13 18:44:18 CET 2005 

Hello,

I am using Openswan 2.3.0 and i am trying to get XAuth + Mode Config working with a Netscreen 208
appliance. Openswan initiates the connection and acts as a client. With pure XAuth everything is
working quite fine. 
Now i activate Mode Config on the Netscreen and the problems begin. Phase 1 IKE works, the Netscreen
requests XAuth username and password and it is sent to her. Pluto now prints "awaiting CFG_set". The
appliance reacts with the Mode Config message containing the IP address and all that stuff. Pluto
answers this with a CERTIFICATE_UNAVAILABLE message (which certificate ? seems more like a standard
error message ?!). Every following message from the Netscreen is replied with a PAYLOAD_MALFORMED.

In the logs this looks like:

Jan 13 17:22:19 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: XAUTH: Answering XAUTH challenge
with user='xauthUser'
Jan 13 17:22:19 piii700 pluto[2850]: | emitting 3 zero bytes of message padding into ISAKMP Message
Jan 13 17:22:19 piii700 pluto[2850]: | emitting length of ISAKMP Message: 92
Jan 13 17:22:19 piii700 pluto[2850]: | emitting length of ISAKMP Message: 92
Jan 13 17:22:19 piii700 pluto[2850]: | complete state transition with STF_OK
Jan 13 17:22:19 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: transition from state
STATE_XAUTH_I0 to state STATE_XAUTH_I1
Jan 13 17:22:19 piii700 pluto[2850]: | sending reply packet
Jan 13 17:22:19 piii700 pluto[2850]: | inserting event EVENT_SA_REPLACE, timeout in 28530 seconds for #1
Jan 13 17:22:19 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: XAUTH client - awaiting CFG_set
Jan 13 17:22:19 piii700 pluto[2850]: | XAUTH client is not yet authenticated
Jan 13 17:22:19 piii700 pluto[2850]: | next event EVENT_REINIT_SECRET in 3583 seconds
Jan 13 17:22:19 piii700 pluto[2850]: |  
Jan 13 17:22:19 piii700 pluto[2850]: | *received 76 bytes from 10.1.1.1:500 on eth0:1
Jan 13 17:22:19 piii700 pluto[2850]: | **parse ISAKMP Message:
Jan 13 17:22:19 piii700 pluto[2850]: |    initiator cookie:
Jan 13 17:22:19 piii700 pluto[2850]: |   6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: |    responder cookie:
Jan 13 17:22:19 piii700 pluto[2850]: |   6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:22:19 piii700 pluto[2850]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:22:19 piii700 pluto[2850]: |    exchange type: ISAKMP_XCHG_MODE_CFG
Jan 13 17:22:19 piii700 pluto[2850]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:22:19 piii700 pluto[2850]: |    message ID:  29 c8 6c 07
Jan 13 17:22:19 piii700 pluto[2850]: |    length: 76
Jan 13 17:22:19 piii700 pluto[2850]: | ICOOKIE:  6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: | RCOOKIE:  6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: | peer:  0a 01 01 01
Jan 13 17:22:19 piii700 pluto[2850]: | state hash entry 9
Jan 13 17:22:19 piii700 pluto[2850]: | peer and cookies match on #1, provided msgid 29c86c07 vs 00000000
Jan 13 17:22:19 piii700 pluto[2850]: | state object not found
Jan 13 17:22:19 piii700 pluto[2850]: | ICOOKIE:  6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: | RCOOKIE:  6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: | peer:  0a 01 01 01
Jan 13 17:22:19 piii700 pluto[2850]: | state hash entry 9
Jan 13 17:22:19 piii700 pluto[2850]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 13 17:22:19 piii700 pluto[2850]: | state object #1 found, in STATE_XAUTH_I1
Jan 13 17:22:19 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: discarding duplicate packet;
already STATE_XAUTH_I1
Jan 13 17:22:19 piii700 pluto[2850]: | next event EVENT_REINIT_SECRET in 3583 seconds
Jan 13 17:22:19 piii700 pluto[2850]: |  
Jan 13 17:22:19 piii700 pluto[2850]: | *received 100 bytes from 10.1.1.1:500 on eth0:1
Jan 13 17:22:19 piii700 pluto[2850]: | **parse ISAKMP Message:
Jan 13 17:22:19 piii700 pluto[2850]: |    initiator cookie:
Jan 13 17:22:19 piii700 pluto[2850]: |   6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: |    responder cookie:
Jan 13 17:22:19 piii700 pluto[2850]: |   6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:22:19 piii700 pluto[2850]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:22:19 piii700 pluto[2850]: |    exchange type: ISAKMP_XCHG_MODE_CFG
Jan 13 17:22:19 piii700 pluto[2850]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:22:19 piii700 pluto[2850]: |    message ID:  1a 48 e8 5b
Jan 13 17:22:19 piii700 pluto[2850]: |    length: 100
Jan 13 17:22:19 piii700 pluto[2850]: | ICOOKIE:  6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: | RCOOKIE:  6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: | peer:  0a 01 01 01
Jan 13 17:22:19 piii700 pluto[2850]: | state hash entry 9
Jan 13 17:22:19 piii700 pluto[2850]: | peer and cookies match on #1, provided msgid 1a48e85b vs 00000000
Jan 13 17:22:19 piii700 pluto[2850]: | state object not found
Jan 13 17:22:19 piii700 pluto[2850]: | ICOOKIE:  6b e4 17 6c  0a 00 83 72
Jan 13 17:22:19 piii700 pluto[2850]: | RCOOKIE:  6e f7 45 99  fb 74 82 29
Jan 13 17:22:19 piii700 pluto[2850]: | peer:  0a 01 01 01
Jan 13 17:22:19 piii700 pluto[2850]: | state hash entry 9
Jan 13 17:22:19 piii700 pluto[2850]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 13 17:22:19 piii700 pluto[2850]: | state object #1 found, in STATE_XAUTH_I1
Jan 13 17:22:19 piii700 pluto[2850]: | ***parse ISAKMP Hash Payload:
Jan 13 17:22:19 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_MODECFG
Jan 13 17:22:19 piii700 pluto[2850]: |    length: 24
Jan 13 17:22:19 piii700 pluto[2850]: | ***parse ISAKMP Mode Attribute:
Jan 13 17:22:20 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_NONE
Jan 13 17:22:20 piii700 pluto[2850]: |    length: 40
Jan 13 17:22:20 piii700 pluto[2850]: |    Attr Msg Type: ISAKMP_CFG_SET
Jan 13 17:22:20 piii700 pluto[2850]: |    Identifier: 999
Jan 13 17:22:20 piii700 pluto[2850]: | removing 8 bytes of padding
Jan 13 17:22:20 piii700 pluto[2850]: | **emit ISAKMP Message:
Jan 13 17:22:20 piii700 pluto[2850]: |    initiator cookie:
Jan 13 17:22:20 piii700 pluto[2850]: |   6b e4 17 6c  0a 00 83 72
Jan 13 17:22:20 piii700 pluto[2850]: |    responder cookie:
Jan 13 17:22:20 piii700 pluto[2850]: |   6e f7 45 99  fb 74 82 29
Jan 13 17:22:20 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:22:20 piii700 pluto[2850]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:22:20 piii700 pluto[2850]: |    exchange type: ISAKMP_XCHG_MODE_CFG
Jan 13 17:22:20 piii700 pluto[2850]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:22:20 piii700 pluto[2850]: |    message ID:  1a 48 e8 5b
Jan 13 17:22:20 piii700 pluto[2850]: | ****parse ISAKMP ModeCfg attribute:
Jan 13 17:22:20 piii700 pluto[2850]: |    ModeCfg attr type: INTERNAL_IP4_ADDRESS
Jan 13 17:22:20 piii700 pluto[2850]: |    length/value: 4
Jan 13 17:22:20 piii700 pluto[2850]: | ****parse ISAKMP ModeCfg attribute:
Jan 13 17:22:20 piii700 pluto[2850]: |    ModeCfg attr type: INTERNAL_IP4_NETMASK
Jan 13 17:22:20 piii700 pluto[2850]: |    length/value: 4
Jan 13 17:22:20 piii700 pluto[2850]: | ****parse ISAKMP ModeCfg attribute:
Jan 13 17:22:20 piii700 pluto[2850]: |    ModeCfg attr type: INTERNAL_IP4_DNS
Jan 13 17:22:20 piii700 pluto[2850]: |    length/value: 4
Jan 13 17:22:20 piii700 pluto[2850]: | ****parse ISAKMP ModeCfg attribute:
Jan 13 17:22:20 piii700 pluto[2850]: |    ModeCfg attr type: INTERNAL_IP4_NBNS
Jan 13 17:22:20 piii700 pluto[2850]: |    length/value: 4
Jan 13 17:22:20 piii700 pluto[2850]: | complete state transition with STF_FAIL
Jan 13 17:22:20 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: sending encrypted notification
CERTIFICATE_UNAVAILABLE to 10.1.1.1:500
Jan 13 17:22:20 piii700 pluto[2850]: | **emit ISAKMP Message:
Jan 13 17:22:20 piii700 pluto[2850]: |    initiator cookie:
Jan 13 17:22:20 piii700 pluto[2850]: |   6b e4 17 6c  0a 00 83 72
Jan 13 17:22:20 piii700 pluto[2850]: |    responder cookie:
Jan 13 17:22:20 piii700 pluto[2850]: |   6e f7 45 99  fb 74 82 29
Jan 13 17:22:20 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:22:20 piii700 pluto[2850]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:22:20 piii700 pluto[2850]: |    exchange type: ISAKMP_XCHG_INFO
Jan 13 17:22:20 piii700 pluto[2850]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:22:20 piii700 pluto[2850]: |    message ID:  33 32 79 c6
Jan 13 17:22:20 piii700 pluto[2850]: | ***emit ISAKMP Hash Payload:
Jan 13 17:22:20 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_N
Jan 13 17:22:20 piii700 pluto[2850]: | emitting 20 zero bytes of HASH(1) into ISAKMP Hash Payload
Jan 13 17:22:20 piii700 pluto[2850]: | emitting length of ISAKMP Hash Payload: 24
Jan 13 17:22:20 piii700 pluto[2850]: | ***emit ISAKMP Notification Payload:
Jan 13 17:22:20 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_NONE
Jan 13 17:22:20 piii700 pluto[2850]: |    DOI: ISAKMP_DOI_IPSEC
Jan 13 17:22:20 piii700 pluto[2850]: |    protocol ID: 1
Jan 13 17:22:20 piii700 pluto[2850]: |    SPI size: 0
Jan 13 17:22:20 piii700 pluto[2850]: |    Notify Message Type: CERTIFICATE_UNAVAILABLE
Jan 13 17:22:20 piii700 pluto[2850]: | emitting 0 raw bytes of spi into ISAKMP Notification Payload
Jan 13 17:22:20 piii700 pluto[2850]: | spi
Jan 13 17:22:20 piii700 pluto[2850]: | emitting length of ISAKMP Notification Payload: 12
Jan 13 17:22:20 piii700 pluto[2850]: | emitting 4 zero bytes of encryption padding into ISAKMP Message
Jan 13 17:22:20 piii700 pluto[2850]: | emitting length of ISAKMP Message: 68
Jan 13 17:22:20 piii700 pluto[2850]: | state transition function for STATE_XAUTH_I0 failed:
CERTIFICATE_UNAVAILABLE
Jan 13 17:22:20 piii700 pluto[2850]: | next event EVENT_REINIT_SECRET in 3582 seconds
Jan 13 17:22:25 piii700 pluto[2850]: |  
Jan 13 17:22:25 piii700 pluto[2850]: | *received 100 bytes from 10.1.1.1:500 on eth0:1
Jan 13 17:22:25 piii700 pluto[2850]: | **parse ISAKMP Message:
Jan 13 17:22:25 piii700 pluto[2850]: |    initiator cookie:
Jan 13 17:22:25 piii700 pluto[2850]: |   6b e4 17 6c  0a 00 83 72
Jan 13 17:22:25 piii700 pluto[2850]: |    responder cookie:
Jan 13 17:22:25 piii700 pluto[2850]: |   6e f7 45 99  fb 74 82 29
Jan 13 17:22:25 piii700 pluto[2850]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:22:25 piii700 pluto[2850]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:22:25 piii700 pluto[2850]: |    exchange type: ISAKMP_XCHG_MODE_CFG
Jan 13 17:22:25 piii700 pluto[2850]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:22:25 piii700 pluto[2850]: |    message ID:  1a 48 e8 5b
Jan 13 17:22:25 piii700 pluto[2850]: |    length: 100
Jan 13 17:22:25 piii700 pluto[2850]: | ICOOKIE:  6b e4 17 6c  0a 00 83 72
Jan 13 17:22:25 piii700 pluto[2850]: | RCOOKIE:  6e f7 45 99  fb 74 82 29
Jan 13 17:22:25 piii700 pluto[2850]: | peer:  0a 01 01 01
Jan 13 17:22:25 piii700 pluto[2850]: | state hash entry 9
Jan 13 17:22:25 piii700 pluto[2850]: | peer and cookies match on #1, provided msgid 1a48e85b vs 1a48e85b
Jan 13 17:22:25 piii700 pluto[2850]: | state object #1 found, in STATE_XAUTH_I1
Jan 13 17:22:25 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: next payload type of ISAKMP Hash
Payload has an unknown value: 17
Jan 13 17:22:25 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: malformed payload in packet
Jan 13 17:22:25 piii700 pluto[2850]: "main-rsa-xauth-modecfg" #1: sending notification
PAYLOAD_MALFORMED to 10.1.1.1:500

Disabling Mode Config at the Netscreen but leaving it enabled at the Openswan side looks like:

Jan 13 17:36:48 piii700 pluto[3553]: "main-rsa-xauth-modecfg" #1: transition from state
STATE_XAUTH_I0 to state STATE_XAUTH_I1
Jan 13 17:36:48 piii700 pluto[3553]: | sending reply packet
Jan 13 17:36:48 piii700 pluto[3553]: | inserting event EVENT_SA_REPLACE, timeout in 28530 seconds for #1
Jan 13 17:36:48 piii700 pluto[3553]: "main-rsa-xauth-modecfg" #1: XAUTH client - awaiting CFG_set
Jan 13 17:36:48 piii700 pluto[3553]: | modecfg pull: noquirk policy:pull modecfg-client
Jan 13 17:36:48 piii700 pluto[3553]: | modecfg client is starting due to policy
Jan 13 17:36:48 piii700 pluto[3553]: "main-rsa-xauth-modecfg" #1: modecfg: Sending IP request
(MODECFG_I1)
Jan 13 17:36:48 piii700 pluto[3553]: | **emit ISAKMP Message:
Jan 13 17:36:48 piii700 pluto[3553]: |    initiator cookie:
Jan 13 17:36:48 piii700 pluto[3553]: |   28 eb 54 03  dd c2 e7 87
Jan 13 17:36:48 piii700 pluto[3553]: |    responder cookie:
Jan 13 17:36:48 piii700 pluto[3553]: |   c7 5a 8e a2  a5 92 ac 69
Jan 13 17:36:48 piii700 pluto[3553]: |    next payload type: ISAKMP_NEXT_HASH
Jan 13 17:36:48 piii700 pluto[3553]: |    ISAKMP version: ISAKMP Version 1.0
Jan 13 17:36:48 piii700 pluto[3553]: |    exchange type: ISAKMP_XCHG_MODE_CFG
Jan 13 17:36:48 piii700 pluto[3553]: |    flags: ISAKMP_FLAG_ENCRYPTION
Jan 13 17:36:48 piii700 pluto[3553]: |    message ID:  4e c9 f0 b5
Jan 13 17:36:48 piii700 pluto[3553]: | ***emit ISAKMP Hash Payload:
Jan 13 17:36:48 piii700 pluto[3553]: |    next payload type: ISAKMP_NEXT_MODECFG
Jan 13 17:36:48 piii700 pluto[3553]: | emitting 20 zero bytes of HASH into ISAKMP Hash Payload
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP Hash Payload: 24
Jan 13 17:36:48 piii700 pluto[3553]: | ***emit ISAKMP Mode Attribute:
Jan 13 17:36:48 piii700 pluto[3553]: |    next payload type: ISAKMP_NEXT_NONE
Jan 13 17:36:48 piii700 pluto[3553]: |    Attr Msg Type: ISAKMP_CFG_REQUEST
Jan 13 17:36:48 piii700 pluto[3553]: |    Identifier: 0
Jan 13 17:36:48 piii700 pluto[3553]: | ****emit ISAKMP ModeCfg attribute:
Jan 13 17:36:48 piii700 pluto[3553]: |    ModeCfg attr type: INTERNAL_IP4_ADDRESS
Jan 13 17:36:48 piii700 pluto[3553]: |    length/value: 0
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP ModeCfg attribute: 0
Jan 13 17:36:48 piii700 pluto[3553]: | ****emit ISAKMP ModeCfg attribute:
Jan 13 17:36:48 piii700 pluto[3553]: |    ModeCfg attr type: INTERNAL_IP4_NETMASK
Jan 13 17:36:48 piii700 pluto[3553]: |    length/value: 0
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP ModeCfg attribute: 0
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP Mode Attribute: 16
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP Message: 68
Jan 13 17:36:48 piii700 pluto[3553]: | emitting length of ISAKMP Message: 68
Jan 13 17:36:48 piii700 pluto[3553]: | inserting event EVENT_RETRANSMIT, timeout in 30 seconds for #1
Jan 13 17:36:48 piii700 pluto[3553]: | next event EVENT_RETRANSMIT in 30 seconds for #1

Of course nothing is returned, but here i see these modecfg messages about the modecfgpull option. I
also disabled modecfgpull because the appliance sends the mode config messages without request (as
seen above). Sadly this did not change the error.

For me it looks like some timing issue. 

Here is are the connections from my ipsec.conf:

conn main-rsa-xauth-modecfg
        also=main-rsa-xauth
        leftmodecfgserver=yes
        rightmodecfgclient=yes
	modecfgpull=no

conn main-rsa-xauth
        also=main-rsa
        leftxauthserver=yes
        rightxauthclient=yes

conn main-rsa
	authby=rsasig
	left=10.1.1.1
	leftsubnet=0.0.0.0/0
	right=10.1.99.1
	rightsubnet=0.0.0.0/0
	auto=add
	rightcert=ike.sunrise.net.crt
	leftid=@netscreen.sunrise.net
	leftcert=netscreen.crt

I hope on your helping advises.

Sascha Grau

More information about the Users mailing list