[Swan] Help needed: STATE_MAIN_I3: 60 second timeout exceeded after 7 retransmits. Possible authentication failure: no acceptable response to our first encrypted message

Mathieu Rossignol mathieu.rossignol at hurence.com
Tue Apr 16 16:10:07 UTC 2019


Hi there,

I'm aVPN noob and i'm stuck with this problem:

---------------------------------------------------------------------

[root at xxxxxx ipsec.d]# ipsec auto --verbose --up mysubnet
002 "mysubnet" #6: initiating Main Mode
104 "mysubnet" #6: STATE_MAIN_I1: initiate
003 "mysubnet" #6: ignoring unknown Vendor ID payload 
[92d37bd4c2ddfdacbbc732ccaaccedba]
106 "mysubnet" #6: STATE_MAIN_I2: sent MI2, expecting MR2
108 "mysubnet" #6: STATE_MAIN_I3: sent MI3, expecting MR3
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 0.5 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 1 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 2 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 4 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 8 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 16 seconds 
for response
010 "mysubnet" #6: STATE_MAIN_I3: retransmission; will wait 32 seconds 
for response
031 "mysubnet" #6: STATE_MAIN_I3: 60 second timeout exceeded after 7 
retransmits.  Possible authentication failure: no acceptable response to 
our first encrypted message
000 "mysubnet" #6: starting keying attempt 2 of an unlimited number, but 
releasing whack

-------------------------------------------------------------------

configuration (xxx.conf file):

config setup
     protostack=netkey
     nat_traversal=no

conn mysubnet
     also=mytunnel
     leftsubnet=10.100.105.0/24
     leftsourceip=10.100.105.254
     rightsubnet=192.168.41.0/24
     rightsourceip=192.168.41.254
     auto=start

conn mytunnel
     type=tunnel
     authby=secret
     ike=aes128-sha1;modp1024
     salifetime=3600s
     ikelifetime=21600s
     phase2alg=aes128-sha1;modp1024
     left=149.202.66.102
     right=92.103.11.11

-------------------------------------------------------------------

xxx.secrets file:

92.103.11.11 149.202.66.102 : PSK "OfCourseNotTheRealOne"

-------------------------------------------------------------------

tail -f /var/log/secure|grep mysbunet:

Apr 16 17:53:13 ns3007941 pluto[12687]: |  conn mysubnet mark 
0/00000000, 0/00000000
Apr 16 17:53:13 ns3007941 pluto[12687]: |  conn mysubnet mark 
0/00000000, 0/00000000
Apr 16 17:53:19 ns3007941 pluto[12687]: "mysubnet" #6: initiating Main Mode
Apr 16 17:53:19 ns3007941 pluto[12687]: "mysubnet" #6: ignoring unknown 
Vendor ID payload [92d37bd4c2ddfdacbbc732ccaaccedba]
Apr 16 17:53:19 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I2: 
sent MI2, expecting MR2
Apr 16 17:53:19 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
sent MI3, expecting MR3
Apr 16 17:53:19 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 0.5 seconds for response
Apr 16 17:53:20 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 1 seconds for response
Apr 16 17:53:21 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 2 seconds for response
Apr 16 17:53:23 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 4 seconds for response
Apr 16 17:53:27 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 8 seconds for response
Apr 16 17:53:29 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in process_v1_packet() at ikev1.c:1096)
Apr 16 17:53:29 ns3007941 pluto[12687]: | "mysubnet" #6: discarding 
duplicate packet; already STATE_MAIN_I3
Apr 16 17:53:29 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in process_md() at demux.c:396)
Apr 16 17:53:35 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in timer_event_cb() at timer.c:319)
Apr 16 17:53:35 ns3007941 pluto[12687]: | processing: [RE]START state #6 
connection "mysubnet" 92.103.11.11 (in retransmit_v1_msg() at retry.c:60)
Apr 16 17:53:35 ns3007941 pluto[12687]: | handling event 
EVENT_v1_RETRANSMIT for 92.103.11.11 "mysubnet" #6 keying attempt 1 of 
0; retransmit 6
Apr 16 17:53:35 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 16 seconds for response
Apr 16 17:53:35 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in timer_event_cb() at timer.c:664)
Apr 16 17:53:39 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in process_v1_packet() at ikev1.c:1096)
Apr 16 17:53:39 ns3007941 pluto[12687]: | "mysubnet" #6: discarding 
duplicate packet; already STATE_MAIN_I3
Apr 16 17:53:39 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in process_md() at demux.c:396)
Apr 16 17:53:39 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in for_each_state() at state.c:1614)
Apr 16 17:53:39 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in for_each_state() at state.c:1614)
Apr 16 17:53:49 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in process_v1_packet() at ikev1.c:1096)
Apr 16 17:53:49 ns3007941 pluto[12687]: | "mysubnet" #6: discarding 
duplicate packet; already STATE_MAIN_I3
Apr 16 17:53:49 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in process_md() at demux.c:396)
Apr 16 17:53:51 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in timer_event_cb() at timer.c:319)
Apr 16 17:53:51 ns3007941 pluto[12687]: | processing: [RE]START state #6 
connection "mysubnet" 92.103.11.11 (in retransmit_v1_msg() at retry.c:60)
Apr 16 17:53:51 ns3007941 pluto[12687]: | handling event 
EVENT_v1_RETRANSMIT for 92.103.11.11 "mysubnet" #6 keying attempt 1 of 
0; retransmit 7
Apr 16 17:53:51 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 
retransmission; will wait 32 seconds for response
Apr 16 17:53:51 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in timer_event_cb() at timer.c:664)
Apr 16 17:53:59 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in process_v1_packet() at ikev1.c:1096)
Apr 16 17:53:59 ns3007941 pluto[12687]: | "mysubnet" #6: discarding 
duplicate packet; already STATE_MAIN_I3
Apr 16 17:53:59 ns3007941 pluto[12687]: | processing: stop state #6 
connection "mysubnet" 92.103.11.11 (in process_md() at demux.c:396)
Apr 16 17:54:23 ns3007941 pluto[12687]: | processing: start state #6 
connection "mysubnet" 92.103.11.11 (in timer_event_cb() at timer.c:319)
Apr 16 17:54:23 ns3007941 pluto[12687]: | processing: [RE]START state #6 
connection "mysubnet" 92.103.11.11 (in retransmit_v1_msg() at retry.c:60)
Apr 16 17:54:23 ns3007941 pluto[12687]: | handling event 
EVENT_v1_RETRANSMIT for 92.103.11.11 "mysubnet" #6 keying attempt 1 of 
0; retransmit 8
Apr 16 17:54:23 ns3007941 pluto[12687]: "mysubnet" #6: STATE_MAIN_I3: 60 
second timeout exceeded after 7 retransmits. Possible authentication 
failure: no acceptable response to our first encrypted message
Apr 16 17:54:23 ns3007941 pluto[12687]: "mysubnet" #6: starting keying 
attempt 2 of an unlimited number, but releasing whack
Apr 16 17:54:23 ns3007941 pluto[12687]: | processing: suspend state #6 
connection "mysubnet" 92.103.11.11 (in initialize_new_state() at 
ipsec_doi.c:490)
Apr 16 17:54:23 ns3007941 pluto[12687]: | processing: start state #7 
connection "mysubnet" 92.103.11.11 (in initialize_new_state() at 
ipsec_doi.c:490)
Apr 16 17:54:23 ns3007941 pluto[12687]: | processing: [RE]START state #7 
connection "mysubnet" 92.103.11.11 (in initialize_new_state() at 
ipsec_doi.c:510)
Apr 16 17:54:23 ns3007941 pluto[12687]: "mysubnet" #7: initiating Main 
Mode to replace #6

-------------------------------------------------------------------

iptables:

ACCEPT     udp  --  92.103.11.11         0.0.0.0/0            udp 
dpt:500 ctstate NEW,RELATED,ESTABLISHED
ACCEPT     ah   --  92.103.11.11         0.0.0.0/0 ctstate 
NEW,RELATED,ESTABLISHED
ACCEPT     esp  --  92.103.11.11         0.0.0.0/0 ctstate 
NEW,RELATED,ESTABLISHED

-------------------------------------------------------------------

ifconfig:

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
         inet 149.202.66.102  netmask 255.255.255.0  broadcast 
149.202.66.255
         ether 0c:c4:7a:55:84:32  txqueuelen 1000  (Ethernet)
         RX packets 24435652157  bytes 21473727284485 (19.5 TiB)
         RX errors 0  dropped 0  overruns 2755  frame 0
         TX packets 22028813578  bytes 19416650994448 (17.6 TiB)
         TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
         device memory 0xdf920000-df93ffff

-------------------------------------------------------------------

ipsec version:

Linux Libreswan 3.25 (netkey) on 3.14.32-xxxx-grs-ipv6-64

-------------------------------------------------------------------

It's like the PSK authentication (I guess) is was valid but in fact if I 
remove the xxx.secrets file, the same problem occurs...

Thanks for any help!



More information about the Swan mailing list