[Swan] Error: ipv4: Invalid values in header for route get request (bug on script?)

Bruno de Paula Larini bruno.larini at riosoft.com.br
Thu Oct 3 13:40:54 UTC 2019


Hi list.
I've been running libreswan 3.29 on the two ends on Fedora for about a 
week with no problems. Yesterday, however, the tunnel got down and only 
got up after a forced restart on both sites. Today it happened again and 
after searching the logs, they were like this:

<PART 1>
Oct  3 01:17:49.027022: added connection description "foobar/1x0"
Oct  3 01:17:49.027099: added connection description "foobar/2x0"
Oct  3 01:17:49.028710: loading secrets from "/etc/ipsec.d/foobar.secrets"
Oct  3 01:17:49.029648: initiating all conns with alias='foobar'
Oct  3 01:17:49.029695: "foobar/2x0" #3: initiating v2 parent SA
Oct  3 01:17:49.029722: "foobar/2x0": constructed local IKE proposals 
for foobar/2x0 (IKE SA initiator selecting KE): 
1:IKE:ENCR=AES_GCM_C_256,AES_GCM_C_128;PRF=HMAC_SHA2_512;INTEG=NONE;DH=MODP2048
Oct  3 01:17:49.036593: "foobar/2x0" #3: STATE_PARENT_I1: sent v2I1, 
expected v2R1
Oct  3 01:17:49.055340: | Switching Child connection for #6 to 
"foobar/1x0" from "foobar/2x0"
Oct  3 01:17:49.055380: "foobar/1x0": constructed local ESP/AH proposals 
for foobar/1x0 (IKE SA initiator emitting ESP/AH proposals): 
1:ESP:ENCR=AES_GCM_C_128,AES_GCM_C_256;INTEG=NONE;DH=NONE;ESN=DISABLED
Oct  3 01:17:49.055409: "foobar/1x0" #6: STATE_PARENT_I2: sent v2I2, 
expected v2R2 {auth=IKEv2 cipher=AES_GCM_16_256 integ=n/a 
prf=HMAC_SHA2_512 group=MODP2048}
Oct  3 01:17:49.088039: "foobar/1x0" #6: IKEv2 mode peer ID is 
ID_IPV4_ADDR: '<right_ip>'
Oct  3 01:17:49.088134: "foobar/1x0" #6: Authenticated using authby=secret
Oct  3 01:17:49.141648: "foobar/1x0" #6: negotiated connection 
[172.16.0.0-172.16.3.255:0-65535 0] -> 
[192.168.120.0-192.168.120.255:0-65535 0]
Oct  3 01:17:49.141681: "foobar/1x0" #6: STATE_V2_IPSEC_I: IPsec SA 
established tunnel mode {ESP/NAT=>0x3c33205c <0x5a6d3e16 
xfrm=AES_GCM_16_128-NONE NATOA=none NATD=<right_ip>:4500 DPD=passive}
Oct  3 01:17:49.141720: "foobar/2x0": constructed local ESP/AH proposals 
for foobar/2x0 (ESP/AH initiator emitting proposals): 
1:ESP:ENCR=AES_GCM_C_128,AES_GCM_C_256;INTEG=NONE;DH=MODP2048;ESN=DISABLED
Oct  3 01:17:49.143342: "foobar/2x0" #7: STATE_V2_CREATE_I: sent IPsec 
Child req wait response
Oct  3 01:17:49.197757: "foobar/2x0" #7: negotiated connection 
[10.17.1.0-10.17.1.255:0-65535 0] -> 
[192.168.120.0-192.168.120.255:0-65535 0]
Oct  3 01:17:49.197784: "foobar/2x0" #7: STATE_V2_IPSEC_I: IPsec SA 
established tunnel mode {ESP/NAT=>0x36de525f <0x9a3b0da8 
xfrm=AES_GCM_16_128-NONE-MODP2048 NATOA=none NATD=<right_ip>:4500 
DPD=passive}
Oct  3 01:42:18.050187: "foobar/2x0" #7: deleting state 
(STATE_V2_IPSEC_I) aged 1468.908s and sending notification
Oct  3 01:42:18.050224: "foobar/2x0" #7: ESP traffic information: in=0B 
out=943B
Oct  3 01:42:18.068007: "foobar/1x0" #6: deleting state 
(STATE_V2_IPSEC_I) aged 1469.012s and sending notification
Oct  3 01:42:18.068047: "foobar/1x0" #6: ESP traffic information: 
in=123KB out=122KB
Oct  3 01:42:18.081285: "foobar/2x0" #3: deleting state 
(STATE_PARENT_I3) aged 1469.051s and sending notification
Oct  3 01:42:18.081392: "foobar/2x0" #3: deleting IKE SA for connection 
'foobar/2x0' but connection is supposed to remain up; schedule 
EVENT_REVIVE_CONNS
Oct  3 01:42:18.098134: "foobar/1x0": unroute-client output: Error: 
ipv4: Invalid values in header for route get request.
Oct  3 01:42:18.105102: "foobar/1x0": unroute-client output: 
/usr/libexec/ipsec/_updown.netkey: line 449: [: too many arguments
</PART 1>

<PART 2>
Oct  3 01:42:18.809574: added connection description "foobar/1x0"
Oct  3 01:42:18.809675: added connection description "foobar/2x0"
Oct  3 01:42:18.811288: loading secrets from "/etc/ipsec.d/foobar.secrets"
Oct  3 01:42:18.811967: initiating all conns with alias='foobar'
Oct  3 01:42:18.812014: "foobar/2x0" #3: initiating v2 parent SA
Oct  3 01:42:18.812040: "foobar/2x0": constructed local IKE proposals 
for foobar/2x0 (IKE SA initiator selecting KE): 
1:IKE:ENCR=AES_GCM_C_256,AES_GCM_C_128;PRF=HMAC_SHA2_512;INTEG=NONE;DH=MODP2048
Oct  3 01:42:18.818694: "foobar/2x0" #3: STATE_PARENT_I1: sent v2I1, 
expected v2R1
Oct  3 01:42:19.318591: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 0.5 seconds for response
Oct  3 01:42:19.818551: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 1 seconds for response
Oct  3 01:42:20.819064: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 2 seconds for response
Oct  3 01:42:22.820584: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 4 seconds for response
Oct  3 01:42:26.823015: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 8 seconds for response
Oct  3 01:42:34.828368: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 16 seconds for response
Oct  3 01:42:50.829629: "foobar/2x0" #3: STATE_PARENT_I1: 
retransmission; will wait 32 seconds for response
Oct  3 01:42:58.899240: "foobar/2x0" #3: deleting state 
(STATE_PARENT_I1) aged 40.087s and NOT sending notification
Oct  3 01:42:58.899271: "foobar/2x0" #3: deleting IKE SA for connection 
'foobar/2x0' but connection is supposed to remain up; schedule 
EVENT_REVIVE_CONNS
</PART 2>


The obvious error on the end of PART 1 happened about once a hour until 
it failed permanently. That was the moment the tunnel got down. Then 
PART 2 kept repeating.
I went to the script and edited it from
if [ -z $(ip -o route list src ${PLUTO_MY_SOURCEIP}) ]; then
to
if [ -z "$(ip -o route list src ${PLUTO_MY_SOURCEIP})" ]; then

The error message seem to have stopped so far, but I don't know if it is 
really the cause of the problem (of if this is the correct fix).
My configs are like this on both sites:

conn foobar
         authby=secret
         left=<left_ip>
         leftid=<left_ip>
         leftsubnets={172.16.0.0/22,10.17.1.0/24}
         leftsourceip=172.16.0.1
         right=<right_ip>
         rightid=<right_ip>
         rightsubnet=192.168.120.0/24
         ike=aes_gcm-sha2_512;modp2048
         ikelifetime=43200
         salifetime=21600
         esp=aes_gcm-null;modp2048
         pfs=yes
         ikev2=insist
         auto=start

Maybe someone out there knows if it is really a bug on the script?
Thanks!


More information about the Swan mailing list