IPSec tunnel to Avaya 4620sw phone unstable



  • I'm testing the pfSense 2.0beta5 IPSec implementation with an Avaya 4620sw IP/vpn phone in hopes of eventually replacing a Netgear FVS336G vpn gateway a customer is now using for their VOIP traffic.  The phones have the latest firmware.  Even though pfSense 2.0 is still in beta, I think it's worth it if I can demonstrate a working phone to my customer and/or help get 2.0 to a place where it will work with Avaya IP phones.

    The phone currently establishes an vpn connection and can contact its TFTP server and logs into its callserver (the analog of the old PBX).  However, after only 5 seconds or so, it loses the vpn and tries to re-establish it.  It appears to get it back for a second and then loses it again.  This continues on ad infinitum.  The IPSec log shows something funky is going on.  It looks as though the tunnel is established, but then the incoming association is immediately deleted because of a "fatal INVALID-PAYLOAD-TYPE notify messsage".  The SPDs remain in place and are correct.  I breadboarded the IPSec parameters with a Shrew Soft client and this doesn't happen with it.  Is this a bug or maybe some incompatibility with the IPSec implementation on the phone?  Does anyone have an idea of what is happening or am I just hooped?

    Here are some details, including the IPSec log:

    • pfSense 2.0beta5 i386 Mon Jan 31 07:16:37 EST 2011 build running on a Dell PE2550 (dual 1GHz Pentium 3 CPUs with 1 GB RAM)
    • Avaya 4620sw IP phone with a20bvpn23252 firmware

    SADs:
    Source Destination Protocol SPI Enc. alg. Auth. alg.
    75.152.250.47[4500] 70.74.185.113[56558] ESP-UDP 08ce20b9 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0fa35830 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 074b3dad 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0986f72c 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 06a05efa 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0633762e 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 048a8a7d 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0fb46d27 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0b9a67db 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0b1d0ad8 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0ed22e2e 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 07f6b4a2 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0765a131 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 07c41c7f 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0ec4ebda 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 08564b99 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0bd74b83 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0ea18432 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 08ad6702 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 01595222 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 0b530947 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 041b2c44 3des-cbc hmac-sha1
    70.74.185.113[56558] 75.152.250.47[4500] ESP-UDP 019ea506 3des-cbc hmac-sha1

    SPDs:
    Source Destination  Direction Protocol Tunnel endpoints
    10.10.90.1  192.168.43.0/24 ->    ESP  70.74.185.113 -> 75.152.250.47
    192.168.43.0/24 10.10.90.1  <-         ESP  75.152.250.47 -> 70.74.185.113

    pfSense IPSec log:  (I added the blank lines for ease of reading.)
    Jan 31 22:10:10 gw2 racoon: INFO: @(#)ipsec-tools 0.7.3 (http://ipsec-tools.sourceforge.net)
    Jan 31 22:10:10 gw2 racoon: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
    Jan 31 22:10:10 gw2 racoon: INFO: Reading configuration from "/var/etc/racoon.conf"
    Jan 31 22:10:10 gw2 racoon: INFO: Resize address pool from 0 to 253
    Jan 31 22:10:10 gw2 racoon: INFO: 75.152.250.47[4500] used as isakmp port (fd=16)
    Jan 31 22:10:10 gw2 racoon: INFO: 75.152.250.47[4500] used for NAT-T
    Jan 31 22:10:10 gw2 racoon: INFO: 75.152.250.47[500] used as isakmp port (fd=17)
    Jan 31 22:10:10 gw2 racoon: INFO: 75.152.250.47[500] used for NAT-T
    Jan 31 22:10:10 gw2 racoon: INFO: unsupported PF_KEY message REGISTER

    Jan 31 22:13:29 gw2 racoon: INFO: respond new phase 1 negotiation: 75.152.250.47[500]<=>70.74.185.113[28853]
    Jan 31 22:13:29 gw2 racoon: INFO: begin Aggressive mode.
    Jan 31 22:13:29 gw2 racoon: INFO: received Vendor ID: RFC 3947
    Jan 31 22:13:29 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:13:29 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:13:29 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
    Jan 31 22:13:29 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
    Jan 31 22:13:29 gw2 racoon: INFO: Selected NAT-T version: RFC 3947
    Jan 31 22:13:29 gw2 racoon: INFO: Adding remote and local NAT-D payloads.
    Jan 31 22:13:29 gw2 racoon: INFO: Hashing 70.74.185.113[28853] with algo #2
    Jan 31 22:13:29 gw2 racoon: INFO: Hashing 75.152.250.47[500] with algo #2
    Jan 31 22:13:29 gw2 racoon: INFO: Adding xauth VID payload.
    Jan 31 22:13:30 gw2 racoon: INFO: NAT-T: ports changed to: 70.74.185.113[56558]<->75.152.250.47[4500]
    Jan 31 22:13:30 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:13:30 gw2 racoon: INFO: NAT-D payload #0 verified
    Jan 31 22:13:30 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:13:30 gw2 racoon: INFO: NAT-D payload #1 doesn't match
    Jan 31 22:13:30 gw2 racoon: INFO: NAT detected: PEER
    Jan 31 22:13:30 gw2 racoon: INFO: ISAKMP-SA established 75.152.250.47[4500]-70.74.185.113[56558] spi:4ca48209ecfd0466:c9cda9929397a173
    Jan 31 22:13:30 gw2 racoon: INFO: Using port 0
    Jan 31 22:13:30 gw2 racoon: WARNING: Ignored attribute INTERNAL_ADDRESS_EXPIRY
    Jan 31 22:13:30 gw2 racoon: WARNING: Ignored attribute INTERNAL_IP4_DHCP
    Jan 31 22:13:32 gw2 racoon: INFO: respond new phase 2 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:13:32 gw2 racoon: WARNING: ignore INITIAL-CONTACT notification, because it is only accepted after phase1.
    Jan 31 22:13:32 gw2 racoon: INFO: no policy found, try to generate the policy : 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Jan 31 22:13:32 gw2 racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
    Jan 31 22:13:32 gw2 racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
    Jan 31 22:13:32 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:13:34 gw2 racoon: INFO: IPsec-SA established: ESP 70.74.185.113[56558]->75.152.250.47[4500] spi=27174150(0x19ea506)
    Jan 31 22:13:34 gw2 racoon: INFO: IPsec-SA established: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=223920552(0xd58c1a8)
    Jan 31 22:13:34 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Jan 31 22:13:34 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"
    Jan 31 22:13:34 gw2 racoon: ERROR: fatal INVALID-PAYLOAD-TYPE notify messsage, phase1 should be deleted.
    Jan 31 22:13:34 gw2 racoon: ERROR: Message: '! ^ 4I /Z zB C 8 , qe /U8f4 T ,_ 6 < 9 >< C8 wm , @Vd2; M F #K G r * G Kw N O AG 9"A Z r g d d|8 jL . d { { Z + '.

    Jan 31 22:15:07 gw2 racoon: INFO: respond new phase 1 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:07 gw2 racoon: INFO: begin Aggressive mode.
    Jan 31 22:15:07 gw2 racoon: INFO: received Vendor ID: RFC 3947
    Jan 31 22:15:07 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:07 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:07 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
    Jan 31 22:15:07 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
    Jan 31 22:15:07 gw2 racoon: INFO: Selected NAT-T version: RFC 3947
    Jan 31 22:15:08 gw2 racoon: INFO: Adding remote and local NAT-D payloads.
    Jan 31 22:15:08 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:08 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:08 gw2 racoon: INFO: Adding xauth VID payload.
    Jan 31 22:15:08 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:09 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:09 gw2 racoon: INFO: NAT-D payload #0 verified
    Jan 31 22:15:09 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:09 gw2 racoon: INFO: NAT-D payload #1 doesn't match
    Jan 31 22:15:09 gw2 racoon: INFO: NAT detected: PEER
    Jan 31 22:15:09 gw2 racoon: INFO: ISAKMP-SA established 75.152.250.47[4500]-70.74.185.113[56558] spi:2c361e1763e41848:4076f844da9e4afa
    Jan 31 22:15:10 gw2 racoon: INFO: respond new phase 2 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:10 gw2 racoon: WARNING: ignore INITIAL-CONTACT notification, because it is only accepted after phase1.
    Jan 31 22:15:10 gw2 racoon: INFO: Update the generated policy : 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Jan 31 22:15:10 gw2 racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
    Jan 31 22:15:10 gw2 racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
    Jan 31 22:15:10 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:11 gw2 racoon: ERROR: wrong state 8.
    Jan 31 22:15:11 gw2 racoon: ERROR: failed to pre-process packet.
    Jan 31 22:15:11 gw2 racoon: INFO: IPsec-SA established: ESP 70.74.185.113[56558]->75.152.250.47[4500] spi=68889668(0x41b2c44)
    Jan 31 22:15:11 gw2 racoon: INFO: IPsec-SA established: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=358742086(0x1561f846)
    Jan 31 22:15:11 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Jan 31 22:15:11 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"
    Jan 31 22:15:15 gw2 racoon: ERROR: pfkey DELETE received: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=223920552(0xd58c1a8)

    Jan 31 22:15:19 gw2 racoon: INFO: respond new phase 1 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:19 gw2 racoon: INFO: begin Aggressive mode.
    Jan 31 22:15:19 gw2 racoon: INFO: received Vendor ID: RFC 3947
    Jan 31 22:15:19 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:19 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:19 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
    Jan 31 22:15:19 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
    Jan 31 22:15:19 gw2 racoon: INFO: Selected NAT-T version: RFC 3947
    Jan 31 22:15:19 gw2 racoon: INFO: Adding remote and local NAT-D payloads.
    Jan 31 22:15:19 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:19 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:19 gw2 racoon: INFO: Adding xauth VID payload.
    Jan 31 22:15:19 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:20 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:20 gw2 racoon: INFO: NAT-D payload #0 verified
    Jan 31 22:15:20 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:20 gw2 racoon: INFO: NAT-D payload #1 doesn't match
    Jan 31 22:15:20 gw2 racoon: INFO: NAT detected: PEER
    Jan 31 22:15:20 gw2 racoon: INFO: ISAKMP-SA established 75.152.250.47[4500]-70.74.185.113[56558] spi:6c76da2925c6d60c:2960092706a14cd0
    Jan 31 22:15:21 gw2 racoon: INFO: respond new phase 2 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:21 gw2 racoon: WARNING: ignore INITIAL-CONTACT notification, because it is only accepted after phase1.
    Jan 31 22:15:21 gw2 racoon: INFO: Update the generated policy : 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Jan 31 22:15:21 gw2 racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
    Jan 31 22:15:21 gw2 racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
    Jan 31 22:15:21 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:23 gw2 racoon: ERROR: wrong state 8.
    Jan 31 22:15:23 gw2 racoon: ERROR: failed to pre-process packet.
    Jan 31 22:15:23 gw2 racoon: INFO: IPsec-SA established: ESP 70.74.185.113[56558]->75.152.250.47[4500] spi=189991239(0xb530947)
    Jan 31 22:15:23 gw2 racoon: INFO: IPsec-SA established: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=1549605146(0x5c5d191a)
    Jan 31 22:15:23 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Jan 31 22:15:23 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"
    Jan 31 22:15:27 gw2 racoon: ERROR: pfkey DELETE received: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=358742086(0x1561f846)

    Jan 31 22:15:30 gw2 racoon: INFO: respond new phase 1 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:30 gw2 racoon: INFO: begin Aggressive mode.
    Jan 31 22:15:30 gw2 racoon: INFO: received Vendor ID: RFC 3947
    Jan 31 22:15:30 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:30 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
    Jan 31 22:15:30 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
    Jan 31 22:15:30 gw2 racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
    Jan 31 22:15:30 gw2 racoon: INFO: Selected NAT-T version: RFC 3947
    Jan 31 22:15:31 gw2 racoon: INFO: Adding remote and local NAT-D payloads.
    Jan 31 22:15:31 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:31 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:31 gw2 racoon: INFO: Adding xauth VID payload.
    Jan 31 22:15:31 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:32 gw2 racoon: INFO: Hashing 75.152.250.47[4500] with algo #2
    Jan 31 22:15:32 gw2 racoon: INFO: NAT-D payload #0 verified
    Jan 31 22:15:32 gw2 racoon: INFO: Hashing 70.74.185.113[56558] with algo #2
    Jan 31 22:15:32 gw2 racoon: INFO: NAT-D payload #1 doesn't match
    Jan 31 22:15:32 gw2 racoon: INFO: NAT detected: PEER
    Jan 31 22:15:32 gw2 racoon: INFO: ISAKMP-SA established 75.152.250.47[4500]-70.74.185.113[56558] spi:82e7fb1ce659b3d3:edba98ae9dea1e88
    Jan 31 22:15:33 gw2 racoon: INFO: respond new phase 2 negotiation: 75.152.250.47[4500]<=>70.74.185.113[56558]
    Jan 31 22:15:33 gw2 racoon: WARNING: ignore INITIAL-CONTACT notification, because it is only accepted after phase1.
    Jan 31 22:15:33 gw2 racoon: INFO: Update the generated policy : 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Jan 31 22:15:33 gw2 racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
    Jan 31 22:15:33 gw2 racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
    Jan 31 22:15:33 gw2 racoon: NOTIFY: the packet is retransmitted by 70.74.185.113[56558] (1).
    Jan 31 22:15:34 gw2 racoon: ERROR: wrong state 8.
    Jan 31 22:15:34 gw2 racoon: ERROR: failed to pre-process packet.
    Jan 31 22:15:34 gw2 racoon: INFO: IPsec-SA established: ESP 70.74.185.113[56558]->75.152.250.47[4500] spi=22630946(0x1595222)
    Jan 31 22:15:34 gw2 racoon: INFO: IPsec-SA established: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=1335753046(0x4f9df956)
    Jan 31 22:15:34 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Jan 31 22:15:34 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"
    Jan 31 22:15:38 gw2 racoon: ERROR: pfkey DELETE received: ESP 75.152.250.47[4500]->70.74.185.113[56558] spi=1549605146(0x5c5d191a)

    ==============
    The above continues to recycle starting from the initial phase 1 negotiation.



  • UPDATE
    Well, I really don't know what is going on.  I changed the phone's IPSec parameters to negotiate everything possible itself, just in case.  The server is set to P1- 3DES/MD5, P2 - all/MD5.  The dh group is the same on both ends.  PFS is off on both ends.  Here's what happens through some excerpts from the IPSec debug log:

    Feb  2 00:22:38 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Feb  2 00:22:38 gw2 racoon: DEBUG: pk_recv: retry[0] recv()
    Feb  2 00:22:38 gw2 racoon: DEBUG: get pfkey X_SPDUPDATE message
    Feb  2 00:22:38 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:22:38 gw2 racoon: DEBUG: db :0x28548148: 192.168.43.0/24[0] 192.168.43.1/32[0] proto=any dir=in
    Feb  2 00:22:38 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:22:38 gw2 racoon: DEBUG: db :0x28548288: 192.168.43.1/32[0] 192.168.43.0/24[0] proto=any dir=out
    Feb  2 00:22:38 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:22:38 gw2 racoon: DEBUG: db :0x28548648: 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Feb  2 00:22:38 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"

    -> Here the TFTP files download through the tunnel and the call server is contacted.  The phone apparently logs into the call server.  As soon as what appears to be the first data is sent from the phone, the tunnel is suddenly renegotiated with no error in the log:

    Feb  2 00:24:01 gw2 racoon: DEBUG: ===
    Feb  2 00:24:01 gw2 racoon: DEBUG: 722 bytes message received from 70.74.185.113[6767] to 75.152.250.47[4500]
    Feb  2 00:24:01 gw2 racoon: DEBUG:  e9496040 d098d033 00000000 00000000 01100400 00000000 000002d2 04000194 00000001 00000001 00000188 0a01000a 03000028 01010000 80010007 800e0080 80020002 80040002 80030001 800b0001 000c0004 00069780 03000028 02010000 80010007 800e0080 80020001 80040002 80030001 800b0001 000c0004 00069780 03000024 03010000 80010005 80020002 80040002 80030001 800b0001 000c0004 00069780 03000024 04010000 80010005 80020001 80040002 80030001 800b0001 000c0004 00069780 03000024 05010000 80010001 80020002 80040002 80030001 800b0001 000c0004 00069780 03000024 06010000 80010001 80020001 80040002 80030001 800b0001 000c0004 00069780 03000028 07010000 80010007 800e00c0 80020002 80040002 80030001 800b0001 000c0004 00069780 03000028 08010000 80010007 800e00c0 80020001 80040002 80030001 800b0001 000c0004 00069780 03000028 09010000 80010007 800e0100 80020002 80040002 80030001 800b0001 000c0004 00069780 00000028 0a010000 80010007 800e0100 80020001 80040002 80030001 800b0001 000c0004 00069780 0a000084 0bf87a
    Feb  2 00:24:01 gw2 racoon: DEBUG: anonymous configuration selected for 70.74.185.113.
    Feb  2 00:24:01 gw2 racoon: DEBUG: Marking ports as changed
    Feb  2 00:24:01 gw2 racoon: DEBUG: ===
    Feb  2 00:24:01 gw2 racoon: INFO: respond new phase 1 negotiation: 75.152.250.47[4500]<=>70.74.185.113[6767]
    Feb  2 00:24:01 gw2 racoon: INFO: begin Aggressive mode.

    -> The second attempt also appears to be successful, but ends as follows with a pfkey_DELETE.  The tunnel is rebuilt, the phone resends its first data packet and it all falls apart again.  Every following attempt follows the same pattern:

    ...
    Feb  2 00:24:03 gw2 racoon: ERROR: such policy does not already exist: "10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in"
    Feb  2 00:24:03 gw2 racoon: DEBUG: pk_recv: retry[0] recv()
    Feb  2 00:24:03 gw2 racoon: DEBUG: get pfkey X_SPDUPDATE message
    Feb  2 00:24:03 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:24:03 gw2 racoon: DEBUG: db :0x28548148: 192.168.43.0/24[0] 192.168.43.1/32[0] proto=any dir=in
    Feb  2 00:24:03 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:24:03 gw2 racoon: DEBUG: db :0x28548288: 192.168.43.1/32[0] 192.168.43.0/24[0] proto=any dir=out
    Feb  2 00:24:03 gw2 racoon: DEBUG: sub:0xbfbfe6a4: 192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out
    Feb  2 00:24:03 gw2 racoon: DEBUG: db :0x28548648: 10.10.90.1/32[0] 192.168.43.0/24[0] proto=any dir=in
    Feb  2 00:24:03 gw2 racoon: ERROR: such policy does not already exist: "192.168.43.0/24[0] 10.10.90.1/32[0] proto=any dir=out"
    Feb  2 00:24:09 gw2 racoon: DEBUG: pk_recv: retry[0] recv()
    Feb  2 00:24:09 gw2 racoon: DEBUG: get pfkey DELETE message
    Feb  2 00:24:09 gw2 racoon: ERROR: pfkey DELETE received: ESP 75.152.250.47[4500]->70.74.185.113[6767] spi=1671308013(0x639e22ed)

    If anyone can interpret this as to why it might be happening, I'd sure appreciate it.


Log in to reply