Project

General

Profile

Issue #3478

Periodic missing output from swanctl during initiate / terminate with updown plugin

Added by Malte Øhlers 5 months ago. Updated 28 days ago.

Status:
Closed
Priority:
Normal
Category:
swanctl
Affected version:
5.8.0
Resolution:
No change required

Description

Hi,

I have a periodic but persistent issue using swanctl initiate and terminate command.
In our setup we have a script to do additional per tunnel configuration that runs via the updown plugin ("updown=/path/to/script").
This works as expected.

However often we use swanctl to initiate and terminate the tunnels manually, and we have noticed that often the output from the updown script is missing.
Here is what we expect to see when initiating a child sa (and often see) - Notice the [CHD] lines:

 ubuntu@server-1:~$ swanctl -i --child herrekvarn-test1
[IKE] initiating IKE_SA herrekvarn-test[126421] to y.y.y.y
[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
[NET] sending packet: from x.x.x.x[500] to y.y.y.y[500] (400 bytes)
[NET] received packet: from y.y.y.y[500] to x.x.x.x[500] (521 bytes)
[ENC] parsed IKE_SA_INIT response 0 [ SA KE No V V V N(NATD_S_IP) N(NATD_D_IP) V ]
[IKE] received Cisco Delete Reason vendor ID
[IKE] received Cisco Copyright (c) 2009 vendor ID
[ENC] received unknown vendor ID: 43:49:53:43:4f:2d:47:52:45:2d:4d:4f:44:45:02
[IKE] received FRAGMENTATION vendor ID
[CFG] selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1536
[IKE] local host is behind NAT, sending keep alives
[IKE] remote host is behind NAT
[IKE] authentication of 'xp.xp.xp.xp' (myself) with pre-shared key
[IKE] establishing CHILD_SA herrekvarn-test1{122719}
[ENC] generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
[NET] sending packet: from x.x.x.x[4500] to y.y.y.y[4500] (352 bytes)
[NET] received packet: from y.y.y.y[4500] to x.x.x.x[4500] (256 bytes)
[ENC] parsed IKE_AUTH response 1 [ V IDr AUTH SA TSi TSr N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) ]
[IKE] authentication of 'herrekvarn254' with pre-shared key successful
[IKE] IKE_SA herrekvarn-test[126421] established between x.x.x.x[xp.xp.xp.xp]...y.y.y.y[herrekvarn254]
[IKE] scheduling reauthentication in 83523s
[IKE] maximum IKE_SA lifetime 92163s
[IKE] received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding
[CFG] selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
[IKE] CHILD_SA herrekvarn-test1{122719} established with SPIs ca5f668f_i 5cad15b5_o and TS x.x.x.x/32 === z.z.z.z/32
[CHD] updown: 2020-06-08 10:37:36,288 INFO     herrekvarn-test1: Starting updown configuration for tunnel: herrekvarn-test1
[CHD] updown: 2020-06-08 10:37:36,411 INFO     herrekvarn-test1: Created VTI interface: vti_herrekv_231
[CHD] updown: 2020-06-08 10:37:36,472 INFO     herrekvarn-test1: VTI interface 'vti_herrekv_231' is up
[CHD] updown: 2020-06-08 10:37:36,475 INFO     herrekvarn-test1: Adding iptables rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,480 INFO     herrekvarn-test1: Adding iptables rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,483 INFO     herrekvarn-test1: Adding iptables rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,485 INFO     herrekvarn-test1: Adding iptables rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,489 INFO     herrekvarn-test1: Adding iptables rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,491 INFO     herrekvarn-test1: Added iptables endpoint rule: XXXX
[CHD] updown: 2020-06-08 10:37:36,556 INFO     herrekvarn-test1: Added route 'z.z.z.z/32' table '231' interface 'vti_herrekv_231'.
[CHD] updown: 2020-06-08 10:37:37,056 INFO     herrekvarn-test1: Finished setup of updown configuration for tunnel: herrekvarn-test1
initiate completed successfully

However it is also periodically all the updown script ([CHD]) output will be missing - even though the script has been run and triggered.
In those cases we just see:

ubuntu@server-1:~$ swanctl -i --child herrekvarn-test1
[IKE] establishing CHILD_SA herrekvarn-test1{122732}
[ENC] generating CREATE_CHILD_SA request 5 [ SA No KE TSi TSr ]
[NET] sending packet: from x.x.x.x[4500] to y.y.y.y[4500] (416 bytes)
[NET] received packet: from y.y.y.y[4500] to x.x.x.x[4500] (448 bytes)
[ENC] parsed CREATE_CHILD_SA response 5 [ SA No KE TSi TSr ]
[CFG] selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ
[IKE] CHILD_SA herrekvarn-test1{122732} established with SPIs c52917d8_i a82718fa_o and TS x.x.x.x/32 === z.z.z.z/32
initiate completed successfully

I have tried to subscribe to the vici socket from a python script and listen to the messages - and there I do see all the messages as expected.
So it seems to be related to how swanctl is selecting / displaying messages.

Is this a bug / know issue - or I'm a missing something?

Thank you in advance!

/Malte

History

#1 Updated by Tobias Brunner 5 months ago

  • Status changed from New to Feedback

There is no guarantee you see any of these messages in the output of --initiate. After the CHILD_SA has been established (when the state switches to CHILD_INSTALLED), the thread that started the initiation will unregister as listener/logger. But since that happens asynchronously any messages triggered by the child_updown() event (used by the updown plugin), which happens concurrently after the above, might or might not be seen in the output.

#2 Updated by Tobias Brunner 28 days ago

  • Status changed from Feedback to Closed
  • Assignee set to Tobias Brunner
  • Resolution set to No change required

Also available in: Atom PDF