[Swan] Bringing up strongSwan+Libreswan transport connection
Pavel Volkov
sailor at lists.xtsubasa.org
Mon Sep 30 16:54:04 UTC 2019
On понедельник, 30 сентября 2019 г. 18:23:57 MSK, Andrew Cagney wrote:
> Hmm, the below still doesn't contain any debug information - its easy
> to spot as those lines are prefixed with '|'. Is the plutodebug=all
> line in the "config setup" section vis:
>
> config setup
> plutodebug=all
>
> (I'd stick with just "all" as should be more than sufficient).
>
My bad, I forgot to set lower log level in journald.
Lots of output, this is the part between successful auth and error message.
Full log available here: https://xtsubasa.org/libreswan_log.txt
"server" #2: IKEv2 mode peer ID is ID_FQDN: '@server.example.com'
| verifying AUTH payload
| required RSA CA is '%any'
| checking RSA keyid '@server.example.com' for match with
'@server.example.com'
| trusted_ca_nss: trustee A = 'CN=Gundam Solutions IPsec CA'
| key issuer CA is 'CN=Gundam Solutions IPsec CA'
| an RSA Sig check passed with *AwEAAcN3k [remote certificates]
| #1 spent 0.0792 milliseconds in try_all_RSA_keys() trying a pubkey
"server" #2: Authenticated using RSA
| #1 spent 0.121 milliseconds in ikev2_verify_rsa_hash()
| parent state #1: PARENT_I2(open IKE SA) => PARENT_I3(established IKE SA)
| #1 will start re-keying in 2607 seconds with margin of 993 seconds
(attempting re-key)
| state #1 requesting EVENT_SA_REPLACE to be deleted
| free_event_entry: release EVENT_SA_REPLACE-pe at 0x55759e626cc8
| event_schedule: new EVENT_SA_REKEY-pe at 0x55759e62efe8
| inserting event EVENT_SA_REKEY, timeout in 2607 seconds for #1
| pstats #1 ikev2.ike established
| FOR_EACH_STATE_... via for_each_state in nat_traversal_ka_event
| FOR_EACH_STATE_... in for_each_state
| processing: [RE]START state #2 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1556)
| processing: stop state #2 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1558)
| processing: resume state #2 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1558)
| processing: suspend state #2 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1556)
| processing: start state #1 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1556)
| NAT-T: keepalive packet not required as recent DPD event used the IKE SA
on conn server
| processing: stop state #1 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1558)
| processing: resume state #2 connection "server" xxx.xxx.149.202 (in
for_each_state() at state.c:1558)
| global one-shot timer EVENT_NAT_T_KEEPALIVE scheduled in 20 seconds
| TSi: parsing 1 traffic selectors
| ***parse IKEv2 Traffic Selector:
| TS type: IKEv2_TS_IPV4_ADDR_RANGE (0x7)
| IP Protocol ID: 0 (0x0)
| length: 16 (0x10)
| start port: 0 (0x0)
| end port: 65535 (0xffff)
| parsing 4 raw bytes of IKEv2 Traffic Selector into ipv4 ts low
| ipv4 ts low b9 2b 5e c8
| parsing 4 raw bytes of IKEv2 Traffic Selector into ipv4 ts high
| ipv4 ts high b9 2b 5e c8
| TSi: parsed 1 traffic selectors
| TSr: parsing 1 traffic selectors
| ***parse IKEv2 Traffic Selector:
| TS type: IKEv2_TS_IPV4_ADDR_RANGE (0x7)
| IP Protocol ID: 0 (0x0)
| length: 16 (0x10)
| start port: 0 (0x0)
| end port: 65535 (0xffff)
| parsing 4 raw bytes of IKEv2 Traffic Selector into ipv4 ts low
| ipv4 ts low 33 9e 95 ca
| parsing 4 raw bytes of IKEv2 Traffic Selector into ipv4 ts high
| ipv4 ts high 33 9e 95 ca
| TSr: parsed 1 traffic selectors
| evaluating our conn="server" I=192.168.1.2/32:0/0
R=xxx.xxx.149.202/32:0/0 to their:
| TSi[0] .net=185.43.94.200-185.43.94.200 .iporotoid=0
.{start,end}port=0..65535
| match address end->client=192.168.1.2/32 ==
TSi[0]net=185.43.94.200-185.43.94.200: NO
| reject responder TSi/TSr Traffic Selector
| #2 spent 2.29 milliseconds in processing: Initiator: process IKE_AUTH
response
| processing: [RE]START state #2 connection "server" xxx.xxx.149.202 (in
complete_v2_state_transition() at ikev2.c:3157)
| #2 complete v2 state transition from PARENT_I2 to V2_IPSEC_I with status
STF_FAIL+v2N_TS_UNACCEPTABLE
| state transition function for STATE_PARENT_I2 failed: v2N_TS_UNACCEPTABLE
| processing: stop from xxx.xxx.149.202:4500 (BACKGROUND) (in process_md()
at demux.c:443)
| processing: stop state #2 connection "server" xxx.xxx.149.202 (in
process_md() at demux.c:445)
| processing: STOP connection NULL (in process_md() at demux.c:446)
| timer_event_cb: processing event at 0x55759e62eaa8
| handling event EVENT_RETRANSMIT for child state #2
| processing: start state #2 connection "server" xxx.xxx.149.202 (in
timer_event_cb() at timer.c:253)
| IKEv2 retransmit event
| processing: [RE]START state #2 connection "server" xxx.xxx.149.202 (in
retransmit_v2_msg() at retry.c:140)
| handling event EVENT_RETRANSMIT for xxx.xxx.149.202 "server" #2 attempt 2
of 0
| and parent for xxx.xxx.149.202 "server" #1 keying attempt 1 of 0;
retransmit 1
| retransmits: current time 87409.976; retransmit count 0 exceeds limit?
NO; deltatime 0.5 exceeds limit? NO; monotime 0.485 exceeds limit? NO
| event_schedule: new EVENT_RETRANSMIT-pe at 0x55759e634128
| inserting event EVENT_RETRANSMIT, timeout in 0.5 seconds for #2
"server" #2: STATE_PARENT_I2: retransmission; will wait 0.5 seconds for
response
| sending fragments ...
| sending 536 bytes for EVENT_RETRANSMIT through eth0:4500 to
xxx.xxx.149.202:4500 (using #1)
| 00 00 00 00 df 18 89 18 50 51 94 4c 64 92 dc cd
<... skipped ...>
| 9b 0a e9 98 66 90 a8 c4
| sending 536 bytes for EVENT_RETRANSMIT through eth0:4500 to
xxx.xxx.149.202:4500 (using #1)
| 00 00 00 00 df 18 89 18 50 51 94 4c 64 92 dc cd
<... skipped ...>
| 16 35 c8 07 06 ce 23 57
| sending 520 bytes for EVENT_RETRANSMIT through eth0:4500 to
xxx.xxx.149.202:4500 (using #1)
| 00 00 00 00 df 18 89 18 50 51 94 4c 64 92 dc cd
| 42 73 7d 39 35 20 23 08 00 00 00 01 00 00 02 04
<... skipped ...>
| a3 0c 99 71 9c 7b 57 b2 73 c3 c0 93 6e a3 de ec
| 98 e2 99 b9 0f f8 a3 77
| sent 3 fragments
| free_event_entry: release EVENT_RETRANSMIT-pe at 0x55759e62eaa8
| processing: stop state #2 connection "server" xxx.xxx.149.202 (in
timer_event_cb() at timer.c:607)
| *received 1236 bytes from xxx.xxx.149.202:4500 on eth0 (port=4500)
| df 18 89 18 50 51 94 4c 64 92 dc cd 42 73 7d 39
<... skipped ...>
| 76 83 bc 18 17 93 89 72 ab 56 a1 a9 d4 30 97 df
| 78 6e c3 90
| processing: start from xxx.xxx.149.202:4500 (in process_md() at
demux.c:441)
| **parse ISAKMP Message:
| initiator cookie:
| df 18 89 18 50 51 94 4c
| responder cookie:
| 64 92 dc cd 42 73 7d 39
| next payload type: ISAKMP_NEXT_v2SKF (0x35)
| ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)
| exchange type: ISAKMP_v2_IKE_AUTH (0x23)
| flags: ISAKMP_FLAG_v2_MSG_RESPONSE (0x20)
| Message ID: 1 (0x1)
| length: 1236 (0x4d4)
| processing version=2.0 packet with exchange type=ISAKMP_v2_IKE_AUTH (35)
| I am receiving an IKEv2 Response ISAKMP_v2_IKE_AUTH
| I am the IKE SA Original Initiator
| State DB: IKEv2 state object #2 found, in STATE_PARENT_I2
(find_v2_sa_by_request_msgid)
| found state #2
| processing: start state #2 connection "server" xxx.xxx.149.202 (in
ikev2_process_packet() at ikev2.c:1774)
| #2 is idle
| #2 idle
| #2 in state PARENT_I2: sent v2I2, expected v2R2
| Unpacking clear payload for svm: Initiator: process INVALID_SYNTAX AUTH
notification
| Now let's proceed with payload (ISAKMP_NEXT_v2SKF)
| ***parse IKEv2 Encrypted Fragment:
| next payload type: ISAKMP_NEXT_v2IDr (0x24)
| flags: none (0x0)
| length: 1208 (0x4b8)
| fragment number: 1 (0x1)
| total fragments: 2 (0x2)
| processing payload: ISAKMP_NEXT_v2SKF (len=1200)
| received IKE encrypted fragment number '1', total number '2', next
payload '36'
| processing: stop from xxx.xxx.149.202:4500 (BACKGROUND) (in process_md()
at demux.c:443)
| processing: stop state #2 connection "server" xxx.xxx.149.202 (in
process_md() at demux.c:445)
| processing: STOP connection NULL (in process_md() at demux.c:446)
| *received 228 bytes from xxx.xxx.149.202:4500 on eth0 (port=4500)
| df 18 89 18 50 51 94 4c 64 92 dc cd 42 73 7d 39
<... skipped ...>
| 99 15 98 ef 8e 57 fa 38 42 a7 4d 44 8e 40 95 e8
| d9 7b 24 a8
| processing: start from xxx.xxx.149.202:4500 (in process_md() at
demux.c:441)
| **parse ISAKMP Message:
| initiator cookie:
| df 18 89 18 50 51 94 4c
| responder cookie:
| 64 92 dc cd 42 73 7d 39
| next payload type: ISAKMP_NEXT_v2SKF (0x35)
| ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)
| exchange type: ISAKMP_v2_IKE_AUTH (0x23)
| flags: ISAKMP_FLAG_v2_MSG_RESPONSE (0x20)
| Message ID: 1 (0x1)
| length: 228 (0xe4)
| processing version=2.0 packet with exchange type=ISAKMP_v2_IKE_AUTH (35)
| I am receiving an IKEv2 Response ISAKMP_v2_IKE_AUTH
| I am the IKE SA Original Initiator
| State DB: IKEv2 state object #2 found, in STATE_PARENT_I2
(find_v2_sa_by_request_msgid)
| found state #2
| processing: start state #2 connection "server" xxx.xxx.149.202 (in
ikev2_process_packet() at ikev2.c:1774)
| #2 is idle
| #2 idle
| #2 in state PARENT_I2: sent v2I2, expected v2R2
| Unpacking clear payload for svm: Initiator: process INVALID_SYNTAX AUTH
notification
| Now let's proceed with payload (ISAKMP_NEXT_v2SKF)
| ***parse IKEv2 Encrypted Fragment:
| next payload type: ISAKMP_NEXT_v2NONE (0x0)
| flags: none (0x0)
| length: 200 (0xc8)
| fragment number: 2 (0x2)
| total fragments: 2 (0x2)
| processing payload: ISAKMP_NEXT_v2SKF (len=192)
| received IKE encrypted fragment number '2', total number '2', next
payload '0'
| data for hmac: df 18 89 18 50 51 94 4c 64 92 dc cd 42 73 7d 39
<... skipped ...>
| data for hmac: ca 80 ea 4e d1 1b d6 74 4c 02 5e 44 58 17 a7 b6
| data for hmac: 95 e4 13 d8 73 1d 31 b3 38 84 b0 86 54 be bc 01
| data for hmac: 76 83 bc 18
| calculated auth: 17 93 89 72 ab 56 a1 a9 d4 30 97 df 78 6e c3 90
| provided auth: 17 93 89 72 ab 56 a1 a9 d4 30 97 df 78 6e c3 90
| authenticator matched
| data for hmac: df 18 89 18 50 51 94 4c 64 92 dc cd 42 73 7d 39
<... skipped ...>
| data for hmac: f4 bb ea ff d4 a1 6f 7c aa fc 3a 0e b7 6d 30 3d
| data for hmac: 99 15 98 ef
| calculated auth: 8e 57 fa 38 42 a7 4d 44 8e 40 95 e8 d9 7b 24 a8
| provided auth: 8e 57 fa 38 42 a7 4d 44 8e 40 95 e8 d9 7b 24 a8
| authenticator matched
| #2 ikev2 ISAKMP_v2_IKE_AUTH decrypt success
| Now let's proceed with payload (ISAKMP_NEXT_v2IDr)
| **parse IKEv2 Identification - Responder - Payload:
| next payload type: ISAKMP_NEXT_v2CERT (0x25)
| flags: none (0x0)
| length: 25 (0x19)
| ID type: ID_FQDN (0x2)
| processing payload: ISAKMP_NEXT_v2IDr (len=17)
| Now let's proceed with payload (ISAKMP_NEXT_v2CERT)
| **parse IKEv2 Certificate Payload:
| next payload type: ISAKMP_NEXT_v2AUTH (0x27)
| flags: none (0x0)
| length: 929 (0x3a1)
| ikev2 cert encoding: CERT_X509_SIGNATURE (0x4)
| processing payload: ISAKMP_NEXT_v2CERT (len=924)
| Now let's proceed with payload (ISAKMP_NEXT_v2AUTH)
| **parse IKEv2 Authentication Payload:
| next payload type: ISAKMP_NEXT_v2N (0x29)
| flags: none (0x0)
| length: 264 (0x108)
| auth method: IKEv2_AUTH_RSA (0x1)
| processing payload: ISAKMP_NEXT_v2AUTH (len=256)
| Now let's proceed with payload (ISAKMP_NEXT_v2N)
| **parse IKEv2 Notify Payload:
| next payload type: ISAKMP_NEXT_v2SA (0x21)
| flags: none (0x0)
| length: 8 (0x8)
| Protocol ID: PROTO_v2_RESERVED (0x0)
| SPI size: 0 (0x0)
| Notify Message Type: v2N_USE_TRANSPORT_MODE (0x4007)
| processing payload: ISAKMP_NEXT_v2N (len=0)
| Now let's proceed with payload (ISAKMP_NEXT_v2SA)
| **parse IKEv2 Security Association Payload:
| next payload type: ISAKMP_NEXT_v2TSi (0x2c)
| flags: none (0x0)
| length: 44 (0x2c)
| processing payload: ISAKMP_NEXT_v2SA (len=40)
| Now let's proceed with payload (ISAKMP_NEXT_v2TSi)
| **parse IKEv2 Traffic Selector - Initiator - Payload:
| next payload type: ISAKMP_NEXT_v2TSr (0x2d)
| flags: none (0x0)
| length: 24 (0x18)
| number of TS: 1 (0x1)
| processing payload: ISAKMP_NEXT_v2TSi (len=16)
| Now let's proceed with payload (ISAKMP_NEXT_v2TSr)
| **parse IKEv2 Traffic Selector - Responder - Payload:
| next payload type: ISAKMP_NEXT_v2NONE (0x0)
| flags: none (0x0)
| length: 24 (0x18)
| number of TS: 1 (0x1)
| processing payload: ISAKMP_NEXT_v2TSr (len=16)
| selected state microcode Initiator: process IKE_AUTH response
| Now let's proceed with state specific processing
| calling processor Initiator: process IKE_AUTH response
| #2 spent 2.16 milliseconds
| Received v2N_USE_TRANSPORT_MODE in IKE_AUTH reply
"server" #2: EXPECTATION FAILED: st->st_remote_certs.verified == NULL (in
decode_certs() at x509.c:696)
"server" #2: EXPECTATION FAILED: ike->sa.st_remote_certs.verified == NULL
(in ikev2_parent_inR2() at ikev2_parent.c:3684)
"server" #2: X509: CERT payload bogus or revoked
More information about the Swan
mailing list