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
