[Swan] no (wildcard) connection has been configured with policy PSK+AGGRESSIVE+IKEV1_ALLOW (fwd)

1one.w01f dev.1one.w01f at gmail.com
Wed Mar 16 20:45:28 EET 2022


In case it'd be useful, here's a much longer snippet of the libreswan 
log file. After complaining about malformed payload, it then goes into 
re-transmitting the ModeCfg 8 times:

    | pstats #1 ikev1.isakmp established
    "xauth-psk"[1] 192.168.12.87 #1: IKE SA established
    {auth=PRESHARED_KEY cipher=3DES_CBC_192 integ=HMAC_MD5 group=MODP1536}
    | DPD: dpd_init() called on ISAKMP SA
    | DPD: Peer supports Dead Peer Detection
    | modecfg pull: quirk-poll policy:push not-client
    | parent state #1: AGGR_R2(established IKE SA) =>
    MODE_CFG_R1(established IKE SA)
    "xauth-psk"[1] 192.168.12.87 #1: Sending MODE CONFIG set
    | opening output PBS ModecfgR1
    | **emit ISAKMP Message:
    |    initiator SPI: 69 8b 70 ee  12 04 ce 2c
    |    responder SPI: 60 9a f2 9c  09 af c4 11
    |    next payload type: ISAKMP_NEXT_NONE (0x0)
    |    ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
    |    exchange type: ISAKMP_XCHG_MODE_CFG (0x6)
    |    flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
    |    Message ID: 3406270730 (cb 07 91 0a)
    | next payload chain: saving message location 'ISAKMP Message'.'next
    payload type'
    | ***emit ISAKMP Hash Payload:
    |    next payload type: ISAKMP_NEXT_NONE (0x0)
    | next payload chain: setting previous 'ISAKMP Message'.'next
    payload type' to current ISAKMP Hash Payload (8:ISAKMP_NEXT_HASH)
    | next payload chain: saving location 'ISAKMP Hash Payload'.'next
    payload type' in 'ModecfgR1'
    | emitting 16 zero bytes of HASH DATA into ISAKMP Hash Payload
    | emitting length of ISAKMP Hash Payload: 20
    | ***emit ISAKMP Mode Attribute:
    |    next payload type: ISAKMP_NEXT_NONE (0x0)
    |    Attr Msg Type: ISAKMP_CFG_SET (0x3)
    |    Identifier: 0 (00 00)
    | next payload chain: setting previous 'ISAKMP Hash Payload'.'next
    payload type' to current ISAKMP Mode Attribute (14:ISAKMP_NEXT_MODECFG)
    | next payload chain: saving location 'ISAKMP Mode Attribute'.'next
    payload type' in 'ModecfgR1'
    | pool 10.231.247.10-10.231.247.254: requesting one-time lease for
    connection "xauth-psk"[1] 192.168.12.87 with '192.168.12.87' and old
    address 192.168.12.87/32
    | pool 10.231.247.10-10.231.247.254: growing address pool from 0 to 1
    | entry spd_route hash_table_entries.remote_client at 0x55da52b90918
    "xauth-psk"[1] 192.168.12.87 0.0.0.0/0 -<all>-> 10.231.247.10/32
    deleted from hash table
    | entry spd_route hash_table_entries.remote_client at 0x55da52b90918
    "xauth-psk"[1] 192.168.12.87 0.0.0.0/0 -<all>-> 10.231.247.10/32
    added to hash table bucket 0x55da514ba7c0
    | pool 10.231.247.10-10.231.247.254 lease 10.231.247.10 $2: assign
    unused one-time lease to "xauth-psk"[1] 192.168.12.87 $2 with ID
    '192.168.12.87' and that.client 10.231.247.10/32; leases 1 in-use 1
    free 0 reusable 0
    | a lease 10.231.247.10
    | ****emit ISAKMP ModeCfg attribute:
    |    ModeCfg attr type: INTERNAL_IP4_ADDRESS (0x1)
    | emitting 4 raw bytes of IP_addr into ISAKMP ModeCfg attribute
    | IP_addr: 0a e7 f7 0a
    | emitting length of ISAKMP ModeCfg attribute: 4
    | ****emit ISAKMP ModeCfg attribute:
    |    ModeCfg attr type: INTERNAL_IP4_SUBNET (0xd)
    | emitting 4 raw bytes of IP4_subnet into ISAKMP ModeCfg attribute
    | IP4_subnet: 00 00 00 00
    | emitting 4 raw bytes of IP4_submsk into ISAKMP ModeCfg attribute
    | IP4_submsk: 00 00 00 00
    | emitting length of ISAKMP ModeCfg attribute: 8
    | we are not sending a domain
    | We are not sending a banner
    | We are 0.0.0.0/0 so not sending CISCO_SPLIT_INC
    | no IKEv1 message padding required
    | emitting length of ISAKMP Mode Attribute: 28
    | HASH(1): addref key-key at 0x55da52b81be0
    |     result: newref trimmed key-key at 0x55da52b97270 (64-bytes,
    EXTRACT_KEY_FROM_KEY)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    | append_symkey_bytes: delref lhs-key at 0x55da52b81be0
    |     result: newref result-key at 0x55da52b7b250 (64-bytes,
    CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    |     result: newref M-ID-key at 0x55da52b7cac0 (68-bytes,
    CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    | append_symkey_bytes: delref lhs-key at 0x55da52b7b250
    |     result: newref payload-key at 0x55da52b7b250 (96-bytes,
    CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    | append_symkey_bytes: delref lhs-key at 0x55da52b7cac0
    |     result: newref PRF HMAC inner hash-key at 0x55da52b9a350
    (32-bytes, EXTRACT_KEY_FROM_KEY)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    |     result: newref PRF HMAC inner hash-key at 0x55da52b7cac0
    (16-bytes, EXTRACT_KEY_FROM_KEY)(symkey_from_bytes() +400
    lib/libswan/crypt_symkey.c)
    | PRF HMAC inner hash: delref tmp-key at 0x55da52b9a350
    | HASH(1): delref inner-key at 0x55da52b7b250
    |     result: newref result-key at 0x55da52b7b250 (64-bytes,
    CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224
    lib/libswan/crypt_symkey.c)
    |     result: newref result-key at 0x55da52b9a350 (80-bytes,
    CONCATENATE_BASE_AND_DATA)(merge_symkey_symkey() +251
    lib/libswan/crypt_symkey.c)
    | append_symkey_symkey: delref lhs-key at 0x55da52b7b250
    | HASH(1): delref hashed-inner-key at 0x55da52b7cac0
    | HASH(1): delref key-key at 0x55da52b97270
    | HASH(1): delref outer-key at 0x55da52b9a350
    | XAUTH: mode config response HASH(1):
    |   b2 26 79 e4  2f 41 88 d7  25 f5 cd 84  b7 46 c5 97 .&y./A..%....F..
    | no IKEv1 message padding required
    | emitting length of ISAKMP Message: 76
    | no IKEv1 message padding required
    | emitting length of ISAKMP Message: 76
    | sending 80 bytes for ModeCfg set through vipnet from
    <server.address.redacted>:4500 to 192.168.12.87:4500 using UDP (for #1)
    |   00 00 00 00  69 8b 70 ee  12 04 ce 2c  60 9a f2 9c ....i.p....,`...
    |   09 af c4 11  08 10 06 01  cb 07 91 0a  00 00 00 4c ...............L
    |   eb de 33 51  6b ba b5 cc  d0 0f 39 d5  90 29 25 6a ..3Qk.....9..)%j
    |   41 b4 57 c3  c8 6c ad d4  38 08 67 93  84 d0 e3 aa A.W..l..8.g.....
    |   92 91 ea 78  46 44 6f 14  f6 3d f6 14  32 f1 17 ce ...xFDo..=..2...
    | #1 deleting EVENT_SA_EXPIRE
    | delref tt at 0x55da52b9cf38(1->0) (destroy_timeout() +585
    programs/pluto/server.c)
    | delref state-event at 0x55da52b91c58(1->0) (delete_event() +507
    programs/pluto/timer.c)
    | #1 STATE_MODE_CFG_R1: retransmits: cleared
    | event_schedule_where: newref EVENT_RETRANSMIT-pe at 0x55da52b88ba8
    timeout in 0.5 seconds for #1
    | newref tt at 0x55da52b9d098(0->1) (schedule_timeout() +567
    programs/pluto/server.c)
    | #1 STATE_MODE_CFG_R1: retransmits: first event in 0.5 seconds;
    timeout in 60 seconds; limit of 12 retransmits; current time is
    44714.269123
    | #1 spent 3.34 (3.34) milliseconds in process_packet_tail()
    | IKEv1 packet dropped
    | delref struct msg_digest at 0x55da52b8ed38(1->0)
    (process_iface_packet() +306 programs/pluto/demux.c)
    | delref logger at 0x55da52b8c708(1->0) (process_iface_packet() +306
    programs/pluto/demux.c)
    | delref fd at NULL (process_iface_packet() +306 programs/pluto/demux.c)
    | delref fd at NULL (process_iface_packet() +306 programs/pluto/demux.c)
    | delref struct iface_endpoint at 0x55da52b8db88(3->2)
    (process_iface_packet() +306 programs/pluto/demux.c)
    | spent 4.07 (4.07) milliseconds in process_iface_packet() reading
    and processing packet
    | spent 0.0105 (0.0104) milliseconds in udp_read_packet() calling
    check_incoming_msg_errqueue()
    | newref struct msg_digest at 0x55da52b8ed38(0->1) (udp_read_packet()
    +386 programs/pluto/iface_udp.c)
    | addref struct iface_endpoint at 0x55da52b8db88(2->3)
    (udp_read_packet() +386 programs/pluto/iface_udp.c)
    | newref alloc logger at 0x55da52b8c708(0->1) (udp_read_packet() +386
    programs/pluto/iface_udp.c)
    | *received 92 bytes from 192.168.12.87:4500 on vipnet
    <server.address.redacted>:4500 using UDP
    |   69 8b 70 ee  12 04 ce 2c  60 9a f2 9c  09 af c4 11 i.p....,`.......
    |   08 10 05 01  b4 81 67 9e  00 00 00 5c  d3 8e 5d 3b ......g....\..];
    |   b5 79 ce 8f  91 fa a9 fb  b3 ff 32 2b  21 9c 3f 22 .y........2+!.?"
    |   e7 b8 49 2d  2d b5 c3 38  db 54 5c 76  58 2b a9 fb ..I--..8.T\vX+..
    |   eb 16 e6 2f  f2 a4 10 45  e0 1b ec 0e  ca a0 0e 6f .../...E.......o
    |   69 5d 0e 92  3a 71 24 0b  19 2c 35 75 i]..:q$..,5u
    | **parse ISAKMP Message:
    |    initiator SPI: 69 8b 70 ee  12 04 ce 2c
    |    responder SPI: 60 9a f2 9c  09 af c4 11
    |    next payload type: ISAKMP_NEXT_HASH (0x8)
    |    ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
    |    exchange type: ISAKMP_XCHG_INFO (0x5)
    |    flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
    |    Message ID: 3028379550 (b4 81 67 9e)
    |    length: 92 (00 00 00 5c)
    |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
    | peer and cookies match on #1; msgid=00000000 st_msgid=00000000
    st_v1_msgid.phase15=cb07910a
    | p15 state object #1 found, in STATE_MODE_CFG_R1
    | State DB: found IKEv1 state #1 in MODE_CFG_R1 (find_v1_info_state)
    | #1 is idle
    | #1 idle
    | received encrypted packet from 192.168.12.87:4500
    | got payload 0x100  (ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
    | byte at offset 1 (29) of 'ISAKMP Hash Payload'.'reserved' is 0xf7
    but should have been zero (ignored)
    "xauth-psk"[1] 192.168.12.87 #1: 9063-byte length of ISAKMP Hash
    Payload is larger than can fit
    "xauth-psk"[1] 192.168.12.87 #1: malformed payload in packet
    | IKEv1 packet dropped
    | delref struct msg_digest at 0x55da52b8ed38(1->0)
    (process_iface_packet() +306 programs/pluto/demux.c)
    | delref logger at 0x55da52b8c708(1->0) (process_iface_packet() +306
    programs/pluto/demux.c)
    | delref fd at NULL (process_iface_packet() +306 programs/pluto/demux.c)
    | delref fd at NULL (process_iface_packet() +306 programs/pluto/demux.c)
    | delref struct iface_endpoint at 0x55da52b8db88(3->2)
    (process_iface_packet() +306 programs/pluto/demux.c)
    | spent 0.715 (0.714) milliseconds in process_iface_packet() reading
    and processing packet
    | timer_event_cb: processing EVENT_RETRANSMIT-event at 0x55da52b88ba8
    for IKE SA #1 in state MODE_CFG_R1
    | #1 deleting EVENT_RETRANSMIT
    | delref tt at 0x55da52b9d098(1->0) (destroy_timeout() +585
    programs/pluto/server.c)
    | delref state-event at 0x55da52b88ba8(1->0) (timer_event_cb() +227
    programs/pluto/timer.c)
    | IKEv1 retransmit event
    | handling event EVENT_RETRANSMIT for 192.168.12.87 "xauth-psk"[1]
    192.168.12.87 #1 keying attempt 0 of 0; retransmit 1
    | #1 STATE_MODE_CFG_R1: retransmits: current time 44714.767407
    | #1 STATE_MODE_CFG_R1: retransmits: retransmit count 0 exceeds
    limit? NO
    | #1 STATE_MODE_CFG_R1: retransmits: deltatime 0.5 exceeds limit? NO
    | #1 STATE_MODE_CFG_R1: retransmits: monotime 0.498284 exceeds limit? NO
    | event_schedule_where: newref EVENT_RETRANSMIT-pe at 0x55da52b88ba8
    timeout in 0.5 seconds for #1
    | newref tt at 0x55da52b9d408(0->1) (schedule_timeout() +567
    programs/pluto/server.c)
    "xauth-psk"[1] 192.168.12.87 #1: STATE_MODE_CFG_R1: retransmission;
    will wait 0.5 seconds for response
    | sending 80 bytes for EVENT_RETRANSMIT through vipnet from
    <server.address.redacted>:4500 to 192.168.12.87:4500 using UDP (for #1)
    |   00 00 00 00  69 8b 70 ee  12 04 ce 2c  60 9a f2 9c ....i.p....,`...
    |   09 af c4 11  08 10 06 01  cb 07 91 0a  00 00 00 4c ...............L
    |   eb de 33 51  6b ba b5 cc  d0 0f 39 d5  90 29 25 6a ..3Qk.....9..)%j
    |   41 b4 57 c3  c8 6c ad d4  38 08 67 93  84 d0 e3 aa A.W..l..8.g.....
    |   92 91 ea 78  46 44 6f 14  f6 3d f6 14  32 f1 17 ce ...xFDo..=..2...
    | #1 spent 0.504 (0.502) milliseconds in timer_event_cb()
    EVENT_RETRANSMIT
    | timer_event_cb: processing EVENT_RETRANSMIT-event at 0x55da52b88ba8
    for IKE SA #1 in state MODE_CFG_R1
    | #1 deleting EVENT_RETRANSMIT
    | delref tt at 0x55da52b9d408(1->0) (destroy_timeout() +585
    programs/pluto/server.c)
    | delref state-event at 0x55da52b88ba8(1->0) (timer_event_cb() +227
    programs/pluto/timer.c)
    | IKEv1 retransmit event
    | handling event EVENT_RETRANSMIT for 192.168.12.87 "xauth-psk"[1]
    192.168.12.87 #1 keying attempt 0 of 0; retransmit 2

And then finally gives up and moves on to sending the delete notification:

    | handling event EVENT_RETRANSMIT for 192.168.12.87 "xauth-psk"[1]
    192.168.12.87 #1 keying attempt 0 of 0; retransmit 8
    | #1 STATE_MODE_CFG_R1: retransmits: current time 44778.295539
    | #1 STATE_MODE_CFG_R1: retransmits: retransmit count 7 exceeds
    limit? NO
    | #1 STATE_MODE_CFG_R1: retransmits: deltatime 64 exceeds limit? YES
    | #1 STATE_MODE_CFG_R1: retransmits: monotime 64.026416 exceeds
    limit? YES
    "xauth-psk"[1] 192.168.12.87 #1: STATE_MODE_CFG_R1: 60 second
    timeout exceeded after 7 retransmits.  No response (or no acceptable
    response) to our IKEv1 message
    | pstats #1 ikev1.isakmp re-failed too-many-retransmits
    | FOR_EACH_STATE_... in (find_phase1_state() +1898
    programs/pluto/state.c)
    |   found "xauth-psk"[1] 192.168.12.87 #1
    |   matches: 1
    | should_send_delete: yes
    "xauth-psk"[1] 192.168.12.87 #1: deleting state (STATE_MODE_CFG_R1)
    aged 64.077151s and sending notification
    | pstats #1 ikev1.isakmp deleted completed
    | #1 main thread spent 10.1 (10.1) milliseconds helper thread spent
    1.06 (1.06) milliseconds in total
    | suspend: no MD saved in state #1 (delete_state_tail() +1013
    programs/pluto/state.c)
    | FOR_EACH_STATE_... in (find_phase1_state() +1898
    programs/pluto/state.c)
    |   found "xauth-psk"[1] 192.168.12.87 #1
    |   matches: 1
    | should_send_delete: yes
    | #1 send IKEv1 delete notification for STATE_MODE_CFG_R1
    | opening output PBS delete msg
    ... ...

And in any case it doesn't seem like the client did any any further 
"login" after the PSK authenitcation, which seems quite odd as the 
client android app claims to be doing XAUTH and asks for username and 
password each time it connects. Any thoughts on what's happening would 
be greatly appreciated.

Thank you very much.

Wolf

On 17/03/2022 02:26, 1one.w01f wrote:
> Dear Andrew,
>
> Thanks for the analysis and suggestion. Now I have these options 
> commented out in ipsec.conf:
>
>         # leftxauthserver=yes
>         # rightxauthclient=yes
>         # xauthby=file
>
> And it is indeed making some more progress. I can see in the log that 
> it says "IKE SA established", and then libreswan proceeds to 
> generating and sending a ModeCfg, but then later it says in the log:
>
>     | received encrypted packet from 192.168.12.87:4500
>     | got payload 0x100  (ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
>     | byte at offset 1 (29) of 'ISAKMP Hash Payload'.'reserved' is
>     0xf7 but should have been zero (ignored)
>     "xauth-psk"[1] 192.168.12.87 #1: 9063-byte length of ISAKMP Hash
>     Payload is larger than can fit
>     "xauth-psk"[1] 192.168.12.87 #1: malformed payload in packet
>     | IKEv1 packet dropped
>
> And this is what the android client app printed to logcat:
>
>     I FORTIKE : 2022-03-16 16:39:28.916 Adding remote and local NAT-D
>     payloads.
>     I FORTIKE : 2022-03-16 16:39:28.916 Hashing
>     <server.address.redacted>[4500] with algo #1 (NAT-T forced)
>     I FORTIKE : 2022-03-16 16:39:28.916 Hashing 192.168.12.87[4500]
>     with algo #1 (NAT-T forced)
>     I FORTIKE : 2022-03-16 16:39:28.916 Rekey life time: 28500
>     I FORTIKE : 2022-03-16 16:39:28.917 ISAKMP-SA established
>     192.168.12.87-<server.address.redacted>
>     spi:d2ef9e98883a5b6e:9521bbd1fdc60297
>     W FORTIKE : 2022-03-16 16:39:28.930 Short payload
>     W FORTIKE : 2022-03-16 16:39:29.425 Short payload
>     W FORTIKE : 2022-03-16 16:39:29.929 Short payload
>     W FORTIKE : 2022-03-16 16:39:30.932 Short payload
>     W FORTIKE : 2022-03-16 16:39:32.929 Short payload
>     W FORTIKE : 2022-03-16 16:39:36.936 Short payload
>     W FORTIKE : 2022-03-16 16:39:44.979 Short payload
>     I FortiClient VPN: Could not establish session on the IPsec daemon
>     I FORTIKE : 2022-03-16 16:39:53.994 FortiIKE daemon exiting...
>     I FortiClient VPN: Connection failed: Could not establish session
>     on the IPsec daemon
>
> I'm not sure what is happening there. Is the client trying some sort 
> of phase-2 but somehow the libreswan setup is not expecting it?
>
> Thanks.
>
> Wolf
>
> On 16/03/2022 07:25, Andrew Cagney wrote:
>>>          if ((req_policy ^ c->policy) & policy_exact_mask) continue
>>>
>>> (PSK+AGGRESSIVE+IKEV1_ALLOW) ^
>>> (PSK+ENCRYPT+TUNNEL+DONT_REKEY+XAUTH+AGGRESSIVE+IKEV1_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO)
>>> & (XAUTH+AGGRESSIVE+IKEV1_ALLOW)
>>>
>>> If my math is right, this lacks XAUTH, which should have come from
>>> preparse_isakmp_sa_body(sa_pd->pbs); is something missing in the
>>> payload?
>> It looks like:
>>
>> Mar 13 16:19:32.346676: | ******parse ISAKMP Oakley attribute:
>> Mar 13 16:19:32.346688: |    af+type: AF+OAKLEY_AUTHENTICATION_METHOD (0x8003)
>> Mar 13 16:19:32.346699: |    length/value: 1 (0x1)
>>
>> which is:
>>
>> enum ikev1_auth_method {
>> OAKLEY_PRESHARED_KEY = 1,
>>
>> but to get XAUTH, I'm guessing it needs to see something like:
>>
>> | ******parse ISAKMP Oakley attribute:
>> |    af+type: AF+OAKLEY_AUTHENTICATION_METHOD (0x8003)
>> |    length/value: 65001 (fd e9)
>> |    [65001 is XAUTHInitPreShared]
>>
>> https://testing.libreswan.org/v4.6-409-g0dd023c306-main/xauth-pluto-04/OUTPUT/east.pluto.log.gz
>>
>> if the xauth parts of the config are dropped, does it get further?
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20220317/8600903c/attachment-0001.htm>


More information about the Swan mailing list