tricky site-to-site IPsec VPNs / phase1 timeout

dmnc · August 7, 2015, 11:04am

Hi, I’ve 3 sites with RB951G and I’m using IPsec tunnels. Sometimes the tunnel is broken and some disable/enable/flush/restart process can solve the problem. But now, it’s almost a month when I’m not able to connect one of two tunnels. Configuration is completely the same, all 3 routers are v.6.30.2. There is no NAT in front of RBs.
I also have NAT bypass rule but it’s not important because I can’t go thru phase1. And I also I’m accepting esp and udp500,4500 on input. But as I said one tunnel is working and second (copy of 1st one) not.

site A: wan A.A.127.192, lan 192.168.13.0/24
site B: wan B.B.7.52, lan 192.168.11.0/24
site C: wan C.C.220.6, lan 192.168.101.0/24

A–B is ok
C–B is ok
C–A is broken

I’ve tried reboots, even change to another public address on site A, but with no progress. Please what can be wrong?

[admin@MikroTik_site_C] > /ip ipsec policy print 
Flags: T - template, X - disabled, D - dynamic, I - inactive, * - default 
 0 TX* group=default src-address=::/0 dst-address=::/0 protocol=all proposal=default template=yes 

 1     ;;; site_B
       src-address=192.168.101.0/24 src-port=any dst-address=192.168.11.0/24 dst-port=any protocol=all action=encrypt level=require ipsec-protocols=esp tunnel=yes 
       sa-src-address=C.C.220.6 sa-dst-address=B.B.7.52 proposal=CeLuNet-high priority=2 

 2     ;;; site_A
       src-address=192.168.101.0/24 src-port=any dst-address=192.168.13.0/24 dst-port=any protocol=all action=encrypt level=require ipsec-protocols=esp tunnel=yes 
       sa-src-address=C.C.220.6 sa-dst-address=A.A.127.192 proposal=CeLuNet-high priority=0 

[admin@MikroTik_site_C] > /ip ipsec peer print  
Flags: X - disabled, D - dynamic 
 0    ;;; site_B
      address=B.B.7.52/32 local-address=0.0.0.0 passive=no port=500 auth-method=pre-shared-key secret="XXX" generate-policy=no
      policy-template-group=default exchange-mode=main send-initial-contact=yes nat-traversal=no proposal-check=obey hash-algorithm=sha1 enc-algorithm=aes-256
      dh-group=modp4096 lifetime=1d lifebytes=0 dpd-interval=2m dpd-maximum-failures=5 

 1    ;;; site_A
      address=A.A.127.192/32 local-address=0.0.0.0 passive=no port=500 auth-method=pre-shared-key secret="XXX" generate-policy=no 
      policy-template-group=default exchange-mode=main send-initial-contact=yes nat-traversal=no proposal-check=obey hash-algorithm=sha1 enc-algorithm=aes-256 
      dh-group=modp4096 lifetime=1d lifebytes=0 dpd-interval=2m dpd-maximum-failures=5 



--- OLM ---

[admin@MikroTik_site_A] > /ip ipsec policy print
Flags: T - template, X - disabled, D - dynamic, I - inactive, * - default 
 0 TX* group=default src-address=::/0 dst-address=::/0 protocol=all proposal=default template=yes 

 1     ;;; site_B
       src-address=192.168.13.0/24 src-port=any dst-address=192.168.11.0/24 dst-port=any protocol=all action=encrypt level=require ipsec-protocols=esp tunnel=yes 
       sa-src-address=A.A.127.192 sa-dst-address=B.B.7.52 proposal=CeLuNet-high priority=0 

 2     ;;; site_C
       src-address=192.168.13.0/24 src-port=any dst-address=192.168.101.0/24 dst-port=any protocol=all action=encrypt level=require ipsec-protocols=esp tunnel=yes 
       sa-src-address=A.A.127.192 sa-dst-address=C.C.220.6 proposal=CeLuNet-high priority=0

[admin@MikroTik_site_A] > /ip ipsec peer print 
Flags: X - disabled, D - dynamic 
 0    ;;; site_B
      address=B.B.7.52/32 local-address=0.0.0.0 passive=no port=500 auth-method=pre-shared-key secret="XXX" generate-policy=no 
      policy-template-group=default exchange-mode=main send-initial-contact=yes nat-traversal=no proposal-check=obey hash-algorithm=sha1 enc-algorithm=aes-256 
      dh-group=modp4096 lifetime=1h lifebytes=0 dpd-interval=30s dpd-maximum-failures=5 

 1    ;;; site_C
      address=C.C.220.6/32 local-address=0.0.0.0 passive=no port=500 auth-method=pre-shared-key secret="XXX" generate-policy=no
      policy-template-group=default exchange-mode=main send-initial-contact=yes nat-traversal=no proposal-check=obey hash-algorithm=sha1 enc-algorithm=aes-256
      dh-group=modp4096 lifetime=1d lifebytes=0 dpd-interval=2m dpd-maximum-failures=5

I’ve enabled IPsec logging …

/system logging add topics=ipsec action=memory

[admin@MikroTik_site_C] > /log print 
12:50:50 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:50:50 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 0c34366bdfd41fba:0000000000000000 
12:51:00 ipsec,error phase1 negotiation failed due to time up C.C.220.6[500]<=>A.A.127.192[500] 0c34366bdfd41fba:0000000000000000 
12:51:10 ipsec,debug,packet === 
12:51:10 ipsec,debug initiate new phase 1 negotiation: C.C.220.6[500]<=>A.A.127.192[500] 
12:51:10 ipsec,debug begin Identity Protection mode. 
12:51:10 ipsec,debug,packet new cookie: 
12:51:10 ipsec,debug,packet 8a990b5939959895  
12:51:10 ipsec,debug,packet add payload of len 56, next type 13 
12:51:10 ipsec,debug,packet add payload of len 16, next type 13 
12:51:10 ipsec,debug,packet add payload of len 16, next type 0 
12:51:10 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:51:10 ipsec,debug,packet sockname C.C.220.6[500] 
12:51:10 ipsec,debug,packet send packet from C.C.220.6[500] 
12:51:10 ipsec,debug,packet send packet to A.A.127.192[500] 
12:51:10 ipsec,debug,packet src4 C.C.220.6[500] 
12:51:10 ipsec,debug,packet dst4 A.A.127.192[500] 
12:51:10 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:51:10 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:51:10 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:51:10 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:51:10 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:51:10 ipsec,debug sent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 
12:51:13 ipsec,debug phase2 negotiation failed due to time up waiting for phase1. ESP A.A.127.192[0]->C.C.220.6[0]  
12:51:13 ipsec,debug delete phase 2 handler. 
12:51:15 ipsec,debug new acquire C.C.220.6[0]<=>A.A.127.192[0] 
12:51:15 ipsec,debug suitable outbound SP found: 192.168.101.0/24[0] 192.168.13.0/24[0] proto=any dir=out 
12:51:15 ipsec,debug suitable inbound SP found: 192.168.13.0/24[0] 192.168.101.0/24[0] proto=any dir=in 
12:51:15 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:51:15 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:51:15 ipsec,debug request for establishing IPsec-SA was queued due to no phase1 found. 
12:51:20 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:51:20 ipsec,debug,packet sockname C.C.220.6[500] 
12:51:20 ipsec,debug,packet send packet from C.C.220.6[500] 
12:51:20 ipsec,debug,packet send packet to A.A.127.192[500] 
12:51:20 ipsec,debug,packet src4 C.C.220.6[500] 
12:51:20 ipsec,debug,packet dst4 A.A.127.192[500] 
12:51:20 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:51:20 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:51:20 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:51:20 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:51:20 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:51:20 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 
12:51:30 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:51:30 ipsec,debug,packet sockname C.C.220.6[500] 
12:51:30 ipsec,debug,packet send packet from C.C.220.6[500] 
12:51:30 ipsec,debug,packet send packet to A.A.127.192[500] 
12:51:30 ipsec,debug,packet src4 C.C.220.6[500] 
12:51:30 ipsec,debug,packet dst4 A.A.127.192[500] 
12:51:30 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:51:30 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:51:30 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:51:30 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:51:30 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:51:30 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 
12:51:40 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:51:40 ipsec,debug,packet sockname C.C.220.6[500] 
12:51:40 ipsec,debug,packet send packet from C.C.220.6[500] 
12:51:40 ipsec,debug,packet send packet to A.A.127.192[500] 
12:51:40 ipsec,debug,packet src4 C.C.220.6[500] 
12:51:40 ipsec,debug,packet dst4 A.A.127.192[500] 
12:51:40 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:51:40 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:51:40 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:51:40 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:51:40 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:51:40 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 
12:51:46 ipsec,debug phase2 negotiation failed due to time up waiting for phase1. ESP A.A.127.192[0]->C.C.220.6[0]  
12:51:46 ipsec,debug delete phase 2 handler. 
12:51:48 ipsec,debug new acquire C.C.220.6[0]<=>A.A.127.192[0] 
12:51:48 ipsec,debug suitable outbound SP found: 192.168.101.0/24[0] 192.168.13.0/24[0] proto=any dir=out 
12:51:48 ipsec,debug suitable inbound SP found: 192.168.13.0/24[0] 192.168.101.0/24[0] proto=any dir=in 
12:51:48 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:51:48 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:51:48 ipsec,debug request for establishing IPsec-SA was queued due to no phase1 found. 
12:51:50 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:51:50 ipsec,debug,packet sockname C.C.220.6[500] 
12:51:50 ipsec,debug,packet send packet from C.C.220.6[500] 
12:51:50 ipsec,debug,packet send packet to A.A.127.192[500] 
12:51:50 ipsec,debug,packet src4 C.C.220.6[500] 
12:51:50 ipsec,debug,packet dst4 A.A.127.192[500] 
12:51:50 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:51:50 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:51:50 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:51:50 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:51:50 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:51:50 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 
12:51:59 system,info,account user admin logged in from 192.168.101.110 via telnet 
12:52:00 ipsec,debug,packet 128 bytes from C.C.220.6[500] to A.A.127.192[500] 
12:52:00 ipsec,debug,packet sockname C.C.220.6[500] 
12:52:00 ipsec,debug,packet send packet from C.C.220.6[500] 
12:52:00 ipsec,debug,packet send packet to A.A.127.192[500] 
12:52:00 ipsec,debug,packet src4 C.C.220.6[500] 
12:52:00 ipsec,debug,packet dst4 A.A.127.192[500] 
12:52:00 ipsec,debug,packet 1 times of 128 bytes message will be sent to A.A.127.192[500] 
12:52:00 ipsec,debug,packet 8a990b59 39959895 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:52:00 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:52:00 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:52:00 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:52:00 ipsec,debug resent phase1 packet C.C.220.6[500]<=>A.A.127.192[500] 8a990b5939959895:0000000000000000 




[admin@MikroTik_site_A] > /log print
12:47:12 ipsec,debug,packet ========== 
12:47:12 ipsec,debug,packet 124 bytes message received from B.B.7.52[500] to A.A.127.192[500] 
12:47:12 ipsec,debug,packet f148ce86 5a719357 00000000 00000000 01100200 00000000 0000007c 0d000038 
12:47:12 ipsec,debug,packet 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 800c0e10 
12:47:12 ipsec,debug,packet 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 457168a9 
12:47:12 ipsec,debug,packet 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:47:12 ipsec,debug couldn't find configuration. 
12:47:32 ipsec,debug phase2 negotiation failed due to time up waiting for phase1. ESP C.C.220.6[0]->A.A.127.192[0]  
12:47:32 ipsec,debug delete phase 2 handler. 
12:47:36 ipsec,debug new acquire A.A.127.192[0]<=>C.C.220.6[0] 
12:47:36 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.101.0/24[0] proto=any dir=out 
12:47:36 ipsec,debug suitable inbound SP found: 192.168.101.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:47:36 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:47:36 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:47:36 ipsec,debug no configuration found for C.C.220.6. 
12:47:36 ipsec,error failed to begin ipsec sa negotiation. 
12:47:42 ipsec,debug new acquire A.A.127.192[0]<=>B.B.7.52[0] 
12:47:42 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.11.0/24[0] proto=any dir=out 
12:47:42 ipsec,debug suitable inbound SP found: 192.168.11.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:47:42 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:47:42 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:47:42 ipsec,debug no configuration found for B.B.7.52. 
12:47:42 ipsec,error failed to begin ipsec sa negotiation. 
12:47:44 system,info ipsec peer changed by admin 
12:47:44 ipsec,debug,packet === 
12:47:44 ipsec,debug initiate new phase 1 negotiation: A.A.127.192[500]<=>C.C.220.6[500] 
12:47:44 ipsec,debug begin Identity Protection mode. 
12:47:44 ipsec,debug,packet new cookie: 
12:47:44 ipsec,debug,packet 767b51e3394a5394  
12:47:44 ipsec,debug,packet add payload of len 56, next type 13 
12:47:44 ipsec,debug,packet add payload of len 16, next type 13 
12:47:44 ipsec,debug,packet add payload of len 16, next type 0 
12:47:44 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:47:44 ipsec,debug,packet sockname A.A.127.192[500] 
12:47:44 ipsec,debug,packet send packet from A.A.127.192[500] 
12:47:44 ipsec,debug,packet send packet to C.C.220.6[500] 
12:47:44 ipsec,debug,packet src4 A.A.127.192[500] 
12:47:44 ipsec,debug,packet dst4 C.C.220.6[500] 
12:47:44 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:47:44 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:47:44 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:47:44 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:47:44 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:47:44 ipsec,debug sent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:47:54 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:47:54 ipsec,debug,packet sockname A.A.127.192[500] 
12:47:54 ipsec,debug,packet send packet from A.A.127.192[500] 
12:47:54 ipsec,debug,packet send packet to C.C.220.6[500] 
12:47:54 ipsec,debug,packet src4 A.A.127.192[500] 
12:47:54 ipsec,debug,packet dst4 C.C.220.6[500] 
12:47:54 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:47:54 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:47:54 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:47:54 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:47:54 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:47:54 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:04 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:04 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:04 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:04 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:04 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:04 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:04 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:04 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:04 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:04 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:04 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:04 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:11 ipsec,debug new acquire A.A.127.192[0]<=>C.C.220.6[0] 
12:48:11 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.101.0/24[0] proto=any dir=out 
12:48:11 ipsec,debug suitable inbound SP found: 192.168.101.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:48:11 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:48:11 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:48:11 ipsec,debug request for establishing IPsec-SA was queued due to no phase1 found. 
12:48:13 ipsec,debug new acquire A.A.127.192[0]<=>B.B.7.52[0] 
12:48:13 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.11.0/24[0] proto=any dir=out 
12:48:13 ipsec,debug suitable inbound SP found: 192.168.11.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:48:13 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:48:13 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:48:13 ipsec,debug no configuration found for B.B.7.52. 
12:48:13 ipsec,error failed to begin ipsec sa negotiation. 
12:48:14 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:14 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:14 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:14 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:14 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:14 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:14 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:14 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:14 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:14 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:14 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:14 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:24 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:24 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:24 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:24 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:24 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:24 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:24 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:24 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:24 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:24 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:24 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:24 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:34 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:34 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:34 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:34 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:34 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:34 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:34 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:34 ipsec,debug,packet 767b51e3 394a5394 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:34 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:34 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:34 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:34 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:42 ipsec,debug phase2 negotiation failed due to time up waiting for phase1. ESP C.C.220.6[0]->A.A.127.192[0]  
12:48:42 ipsec,debug delete phase 2 handler. 
12:48:44 ipsec,error phase1 negotiation failed due to time up A.A.127.192[500]<=>C.C.220.6[500] 767b51e3394a5394:0000000000000000 
12:48:46 ipsec,debug new acquire A.A.127.192[0]<=>C.C.220.6[0] 
12:48:46 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.101.0/24[0] proto=any dir=out 
12:48:46 ipsec,debug suitable inbound SP found: 192.168.101.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:48:46 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:48:46 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:48:46 ipsec,debug IPsec-SA request for C.C.220.6 queued due to no phase1 found. 
12:48:46 ipsec,debug,packet === 
12:48:46 ipsec,debug initiate new phase 1 negotiation: A.A.127.192[500]<=>C.C.220.6[500] 
12:48:46 ipsec,debug begin Identity Protection mode. 
12:48:46 ipsec,debug,packet new cookie: 
12:48:46 ipsec,debug,packet fed084a474b04158  
12:48:46 ipsec,debug,packet add payload of len 56, next type 13 
12:48:46 ipsec,debug,packet add payload of len 16, next type 13 
12:48:46 ipsec,debug,packet add payload of len 16, next type 0 
12:48:46 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:46 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:46 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:46 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:46 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:46 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:46 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:46 ipsec,debug,packet fed084a4 74b04158 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:46 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:46 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:46 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:46 ipsec,debug sent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] fed084a474b04158:0000000000000000 
12:48:47 ipsec,debug new acquire A.A.127.192[0]<=>B.B.7.52[0] 
12:48:47 ipsec,debug suitable outbound SP found: 192.168.13.0/24[0] 192.168.11.0/24[0] proto=any dir=out 
12:48:47 ipsec,debug suitable inbound SP found: 192.168.11.0/24[0] 192.168.13.0/24[0] proto=any dir=in 
12:48:47 ipsec,debug,packet  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0) 
12:48:47 ipsec,debug,packet   (trns_id=AES-CBC encklen=256 authtype=hmac-sha1) 
12:48:47 ipsec,debug no configuration found for B.B.7.52. 
12:48:47 ipsec,error failed to begin ipsec sa negotiation. 
12:48:56 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:48:56 ipsec,debug,packet sockname A.A.127.192[500] 
12:48:56 ipsec,debug,packet send packet from A.A.127.192[500] 
12:48:56 ipsec,debug,packet send packet to C.C.220.6[500] 
12:48:56 ipsec,debug,packet src4 A.A.127.192[500] 
12:48:56 ipsec,debug,packet dst4 C.C.220.6[500] 
12:48:56 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:48:56 ipsec,debug,packet fed084a4 74b04158 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:48:56 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:48:56 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:48:56 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:48:56 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] fed084a474b04158:0000000000000000 
12:49:05 system,info,account user admin logged out from C.C.220.6 via telnet 
12:49:06 ipsec,debug,packet 128 bytes from A.A.127.192[500] to C.C.220.6[500] 
12:49:06 ipsec,debug,packet sockname A.A.127.192[500] 
12:49:06 ipsec,debug,packet send packet from A.A.127.192[500] 
12:49:06 ipsec,debug,packet send packet to C.C.220.6[500] 
12:49:06 ipsec,debug,packet src4 A.A.127.192[500] 
12:49:06 ipsec,debug,packet dst4 C.C.220.6[500] 
12:49:06 ipsec,debug,packet 1 times of 128 bytes message will be sent to C.C.220.6[500] 
12:49:06 ipsec,debug,packet fed084a4 74b04158 00000000 00000000 01100200 00000000 00000080 0d00003c 
12:49:06 ipsec,debug,packet 00000001 00000001 00000030 01010001 00000028 01010000 800b0001 000c0004 
12:49:06 ipsec,debug,packet 00015180 80010007 800e0100 80030001 80020002 80040010 0d000014 12f5f28c 
12:49:06 ipsec,debug,packet 457168a9 702d9fe2 74cc0100 00000014 afcad713 68a1f1c9 6b8696fc 77570100 
12:49:06 ipsec,debug resent phase1 packet A.A.127.192[500]<=>C.C.220.6[500] fed084a474b04158:0000000000000000

dmnc · August 7, 2015, 12:24pm

okay, I’m tearing my head off, doing some stupid disable/enable/flush/change/change back tricks all the day and I got:

A–B not working
C–B working
C–A working

… still “phase1 negotiation failed due to time up”

dmnc · August 7, 2015, 2:05pm

Since both VPN tunnels are using source port udp 500, can this make problems? I’m wathing udp traffic input udp 500 and I can see just working VPN, no packet from broken remote site …

IntrusDave · August 7, 2015, 2:39pm

what are your firewall rules?
Are you allowing both UDP 500 and IPsec? Plus an Established/Related rule above all others?

dmnc · August 8, 2015, 9:58am

yes please but no packets are incomming

dmnc · August 9, 2015, 9:36am

update, I’m “pinging” my destination routers with nc (

nc -zuvv host 500

) and packets has been received. So problem is (probably) with sending them. When I’m debugging this VPN issue, I can see udp500 packets on output chain (on source router) but none on input chain (on destination router) … what am I missing?

dmnc · August 10, 2015, 11:04am

screw it, I’m going with a SSTP site-to-site now …