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 <[email protected]> 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@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@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@0x55da52b81be0 > | result: newref trimmed key-key@0x55da52b97270 (64-bytes, > EXTRACT_KEY_FROM_KEY)(merge_symkey_bytes() +224 lib/libswan/crypt_symkey.c) > | append_symkey_bytes: delref lhs-key@0x55da52b81be0 > | result: newref result-key@0x55da52b7b250 (64-bytes, > CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224 > lib/libswan/crypt_symkey.c) > | result: newref M-ID-key@0x55da52b7cac0 (68-bytes, > CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224 > lib/libswan/crypt_symkey.c) > | append_symkey_bytes: delref lhs-key@0x55da52b7b250 > | result: newref payload-key@0x55da52b7b250 (96-bytes, > CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224 > lib/libswan/crypt_symkey.c) > | append_symkey_bytes: delref lhs-key@0x55da52b7cac0 > | result: newref PRF HMAC inner hash-key@0x55da52b9a350 (32-bytes, > EXTRACT_KEY_FROM_KEY)(merge_symkey_bytes() +224 lib/libswan/crypt_symkey.c) > | result: newref PRF HMAC inner hash-key@0x55da52b7cac0 (16-bytes, > EXTRACT_KEY_FROM_KEY)(symkey_from_bytes() +400 lib/libswan/crypt_symkey.c) > | PRF HMAC inner hash: delref tmp-key@0x55da52b9a350 > | HASH(1): delref inner-key@0x55da52b7b250 > | result: newref result-key@0x55da52b7b250 (64-bytes, > CONCATENATE_BASE_AND_DATA)(merge_symkey_bytes() +224 > lib/libswan/crypt_symkey.c) > | result: newref result-key@0x55da52b9a350 (80-bytes, > CONCATENATE_BASE_AND_DATA)(merge_symkey_symkey() +251 > lib/libswan/crypt_symkey.c) > | append_symkey_symkey: delref lhs-key@0x55da52b7b250 > | HASH(1): delref hashed-inner-key@0x55da52b7cac0 > | HASH(1): delref key-key@0x55da52b97270 > | HASH(1): delref outer-key@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@0x55da52b9cf38(1->0) (destroy_timeout() +585 > programs/pluto/server.c) > | delref state-event@0x55da52b91c58(1->0) (delete_event() +507 > programs/pluto/timer.c) > | #1 STATE_MODE_CFG_R1: retransmits: cleared > | event_schedule_where: newref EVENT_RETRANSMIT-pe@0x55da52b88ba8 timeout in > 0.5 seconds for #1 > | newref tt@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@0x55da52b8ed38(1->0) (process_iface_packet() +306 > programs/pluto/demux.c) > | delref logger@0x55da52b8c708(1->0) (process_iface_packet() +306 > programs/pluto/demux.c) > | delref fd@NULL (process_iface_packet() +306 programs/pluto/demux.c) > | delref fd@NULL (process_iface_packet() +306 programs/pluto/demux.c) > | delref struct iface_endpoint@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@0x55da52b8ed38(0->1) (udp_read_packet() +386 > programs/pluto/iface_udp.c) > | addref struct iface_endpoint@0x55da52b8db88(2->3) (udp_read_packet() +386 > programs/pluto/iface_udp.c) > | newref alloc logger@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@0x55da52b8ed38(1->0) (process_iface_packet() +306 > programs/pluto/demux.c) > | delref logger@0x55da52b8c708(1->0) (process_iface_packet() +306 > programs/pluto/demux.c) > | delref fd@NULL (process_iface_packet() +306 programs/pluto/demux.c) > | delref fd@NULL (process_iface_packet() +306 programs/pluto/demux.c) > | delref struct iface_endpoint@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@0x55da52b88ba8 for IKE SA > #1 in state MODE_CFG_R1 > | #1 deleting EVENT_RETRANSMIT > | delref tt@0x55da52b9d098(1->0) (destroy_timeout() +585 > programs/pluto/server.c) > | delref state-event@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@0x55da52b88ba8 timeout in > 0.5 seconds for #1 > | newref tt@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@0x55da52b88ba8 for IKE SA > #1 in state MODE_CFG_R1 > | #1 deleting EVENT_RETRANSMIT > | delref tt@0x55da52b9d408(1->0) (destroy_timeout() +585 > programs/pluto/server.c) > | delref state-event@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? > > > _______________________________________________ Swan mailing list [email protected] https://lists.libreswan.org/mailman/listinfo/swan
