[Swan] no (wildcard) connection has been configured with policy PSK+AGGRESSIVE+IKEV1_ALLOW (fwd)
Andrew Cagney
andrew.cagney at gmail.com
Wed Mar 16 21:53:37 EET 2022
It's looking like a bug in the fortnite client. It should be sending:
| ******parse ISAKMP Oakley attribute:
| af+type: AF+OAKLEY_AUTHENTICATION_METHOD (0x8003)
| length/value: 65001 (fd e9)
| [65001 is XAUTHInitPreShared]
but is instead sending:
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)
either fortnite is fixed (perhaps there's an option controlling
this?), or libreswan is hacked to pretend that PSK is really XAUTH+PSK
:-/
I'm not surprised things didn't get much further (it just helps
confirm the theory that it is the above): fortnite is trying to do
xauth and libreswan is not (with IKEv1 packets that can't be decrypted
is a hint that auth failed).
On Wed, 16 Mar 2022 at 14:45, 1one.w01f <dev.1one.w01f at gmail.com> wrote:
>
> 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?
>
>
>
More information about the Swan
mailing list