#84 ipsec-tools 0.8.0 racoon segfaults after losing connectivity

open
nobody
None
7
2014-08-27
2013-02-08
Todd Blum
No

I just had two racoon core dumps, two nights in a row.

They both seem to coincide with ISP outages, the first night on my side, and the second night an ISP outage that affected at least five remote routers. racoon magically restarted itself twice on the first night, and not at all on the second.

I was using pfSense 2.0.1 (since upgraded to 2.0.2), both of which run on FreeBSD 8.1 and use:

Feb 5 00:13:33 racoon: INFO: @(#)ipsec-tools 0.8.0 (http://ipsec-tools.sourceforge.net)
Feb 5 00:13:33 racoon: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
---
Log exerpts are:

Feb 5 00:09:36 192.168.116.250 racoon: [173.z.z.z] INFO: DPD: remote (ISAKMP-SA spi=2384af4f0ce1ea9c:98e4230c19058a5c) seems to be dea
d.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purging ISAKMP-SA spi=2384af4f0ce1ea9c:98e4230c19058a5c.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purged IPsec-SA spi=194715026.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purged IPsec-SA spi=66256580.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purged ISAKMP-SA spi=2384af4f0ce1ea9c:98e4230c19058a5c.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: ISAKMP-SA deleted 204.x.x.x[500]-173.z.z.z[500] spi:2384af4f0ce1ea9c:98e4230c19058a5c
Feb 5 00:09:36 192.168.116.250 racoon: INFO: IPsec-SA request for 173.z.z.z queued due to no phase1 found.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: initiate new phase 1 negotiation: 204.x.x.x[500]<=>173.z.z.z[500]
Feb 5 00:09:36 192.168.116.250 racoon: INFO: begin Identity Protection mode.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: IPsec-SA request for 108.x.x.x queued due to no phase1 found.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: initiate new phase 1 negotiation: 204.x.x.x[500]<=>108.x.x.x[500]
Feb 5 00:09:36 192.168.116.250 racoon: INFO: begin Identity Protection mode.
Feb 5 00:09:36 192.168.116.250 racoon: [70.x.x.x] INFO: DPD: remote (ISAKMP-SA spi=4723810f85f0bc34:099f2fc12d622f27) seems to be dead.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purging ISAKMP-SA spi=4723810f85f0bc34:099f2fc12d622f27.
Feb 5 00:09:36 192.168.116.250 racoon: INFO: purged IPsec-SA spi=133413478.
Feb 5 00:09:36 192.168.x.x racoon: INFO: purged IPsec-SA spi=74597912.
Feb 5 00:09:36 192.168.x.x racoon: INFO: purged ISAKMP-SA spi=4723810f85f0bc34:099f2fc12d622f27.
Feb 5 00:09:36 192.168.x.x racoon: INFO: IPsec-SA request for 70.z.z.z queued due to no phase1 found.
Feb 5 00:09:42 192.168.x.x pf: 00:00:00.967728 rule 1/0(match): block in on enc0: (tos 0x0, ttl 99, id 168, offset 0, flags [none], proto TCP (6), length 40)
Feb 5 00:09:42 192.168.x.x pf: 192.168.Y.x.80 > 192.168.x.H.58823: Flags [.], cksum 0x8b43 (correct), ack 1, win 0, length 0
Feb 5 00:09:42 192.168.x.x kernel: pid 38566 (racoon), uid 0: exited on signal 11 (core dumped)
--
Feb 5 00:15:12 192.168.x.x racoon: [24.x.x.x] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 24.x.x.x[0]->204.x.x.x[0]
Feb 5 00:15:12 192.168.x.x racoon: INFO: delete phase 2 handler.
Feb 5 00:15:12 192.168.x.x racoon: NOTIFY: the packet is retransmitted by 168.x.x.x[500] (1).
Feb 5 00:15:12 192.168.x.x racoon: NOTIFY: the packet is retransmitted by 72.x.x.x[500] (1).
Feb 5 00:15:12 192.168.x.x racoon: ERROR: phase1 negotiation failed due to time up. 2922ae9fc607afdc:e8795f869a651ef4
Feb 5 00:15:12 192.168.x.x kernel: pid 57409 (racoon), uid 0: exited on signal 11 (core dumped)
--

Feb 6 01:48:43 192.168.116.250 racoon: [107.z.z.z] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
Feb 6 01:48:43 192.168.116.250 racoon: INFO: IPsec-SA request for 209.z.z.z queued due to no phase1 found.
Feb 6 01:48:43 192.168.116.250 racoon: INFO: initiate new phase 1 negotiation: 204.x.x.x[500]<=>209.z.z.z[500]
Feb 6 01:48:43 192.168.116.250 racoon: INFO: begin Identity Protection mode.
Feb 6 01:48:43 192.168.116.250 racoon: INFO: received Vendor ID: DPD
Feb 6 01:48:44 192.168.116.250 racoon: [66.z.z.z] ERROR: unknown Informational exchange received.
Feb 6 01:48:44 192.168.116.250 racoon: [66.z.z.z] ERROR: unknown Informational exchange received.
Feb 6 01:48:44 192.168.116.250 racoon: [71.z.z.z] INFO: DPD: remote (ISAKMP-SA spi=23c4c715caf74e95:73eaf2d5863eb546) seems to be dead.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: purging ISAKMP-SA spi=23c4c715caf74e95:73eaf2d5863eb546.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: purged IPsec-SA spi=83395052.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: purged IPsec-SA spi=12868578.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: purged ISAKMP-SA spi=23c4c715caf74e95:73eaf2d5863eb546.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: ISAKMP-SA deleted 204.x.x.x[500]-71.z.z.z[500] spi:23c4c715caf74e95:73eaf2d5863eb546
Feb 6 01:48:44 192.168.116.250 racoon: INFO: ISAKMP-SA established 204.x.x.x[500]-209.z.z.z[500] spi:c3de808313e44848:6f35e2474512d
cfb
Feb 6 01:48:44 192.168.116.250 racoon: INFO: IPsec-SA request for 64.z.z.z queued due to no phase1 found.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: initiate new phase 1 negotiation: 204.x.x.x[500]<=>64.z.z.z[500]
Feb 6 01:48:44 192.168.116.250 racoon: INFO: begin Identity Protection mode.
Feb 6 01:48:44 192.168.116.250 racoon: [66.z.z.z] ERROR: unknown Informational exchange received.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: respond new phase 1 negotiation: 204.x.x.x[500]<=>66.z.z.z[500]
Feb 6 01:48:44 192.168.116.250 racoon: INFO: begin Identity Protection mode.
Feb 6 01:48:44 192.168.116.250 racoon: INFO: received Vendor ID: DPD
Feb 6 01:48:44 192.168.116.250 racoon: INFO: received Vendor ID: DPD
Feb 6 01:48:44 192.168.116.250 racoon: INFO: ISAKMP-SA established 204.x.x.x[500]-64.z.z.z[500] spi:7271dcd00ea0731f:61f4c99af2710cf5
Feb 6 01:48:44 192.168.116.250 pf: 00:00:00.949496 rule 1/0(match): block in on enc0: (tos 0x0, ttl 99, id 114, offset 0, flags [none], prot
o TCP (6), length 40)
Feb 6 01:48:44 192.168.x.x pf: 192.168.K.x.80 > 192.168.116.8.33150: Flags [.], cksum 0xf662 (correct), ack 1, win 0, length 0
Feb 6 01:48:44 192.168.x.x racoon: INFO: initiate new phase 2 negotiation: 204.x.x.x[500]<=>209.x.x.x[500]
Feb 6 01:48:44 192.168.x.x racoon: INFO: IPsec-SA established: ESP 204.x.x.x[500]->209.x.x.x[500] spi=234527522(0xdfa9b22)
Feb 6 01:48:44 192.168.x.x racoon: INFO: IPsec-SA established: ESP 204.x.x.x[500]->209.x.x.x[500] spi=1266810441(0x4b81fe49)
Feb 6 01:48:45 192.168.x.x racoon: [71.x.x.x] INFO: request for establishing IPsec-SA was queued due to no phase1 found.
Feb 6 01:48:45 192.168.x.x kernel: pid 10622 (racoon), uid 0: exited on signal 11 (core dumped)
--

Found these similar reports here:

http://forum.pfsense.org/index.php/topic,39383.0.html

Discussion

  • Todd Blum
    Todd Blum
    2013-02-08

    • summary: ipsec-tools 0.80 racoon segfaults after losing connectivity --> ipsec-tools 0.8.0 racoon segfaults after losing connectivity
    • priority: 5 --> 7
     
  • Todd Blum
    Todd Blum
    2013-04-10

    It seems like the more Phase1's not establishing, the more likely racoon is to segfault.

     
  • Todd Blum
    Todd Blum
    2013-04-22

    The error message 'failed to get sainfo' is usually appearing in the logs prior to the segfaults, then not at all afterwards:

    Apr 16 09:59:51 192.168.116.250 racoon: [xx.xx.xxx.xx] ERROR: unknown Informational exchange received.
    Apr 16 09:59:55 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 09:59:57 192.168.116.250 racoon: [yy.yy.yy.yyy] ERROR: unknown Informational exchange received.
    Apr 16 10:00:02 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:02 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:16 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:23 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:23 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:41 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:44 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:00:44 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:02 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:06 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:06 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:14 192.168.116.250 racoon: INFO: respond new phase 1 negotiation: zz.zz.zz.zz[500]<=>hh.hh.hh.hh[500]
    Apr 16 10:01:14 192.168.116.250 racoon: INFO: begin Identity Protection mode.
    Apr 16 10:01:17 192.168.116.250 racoon: INFO: ISAKMP-SA established zz.zz.zz.zz[500]-hh.hh.hh.hh[500] spi:baa4c93e8c16198c:482ba6110eeabc0
    c
    Apr 16 10:01:17 192.168.116.250 racoon: INFO: purged IPsec-SA proto_id=ESP spi=2201026904.
    Apr 16 10:01:17 192.168.116.250 racoon: INFO: purged IPsec-SA proto_id=ESP spi=3679806084.
    Apr 16 10:01:18 192.168.116.250 racoon: INFO: respond new phase 2 negotiation: zz.zz.zz.zz[500]<=>hh.hh.hh.hh[500]
    Apr 16 10:01:18 192.168.116.250 racoon: INFO: IPsec-SA established: ESP zz.zz.zz.zz[500]->hh.hh.hh.hh[500] spi=119993144(0x726f338)
    Apr 16 10:01:18 192.168.116.250 racoon: INFO: IPsec-SA established: ESP zz.zz.zz.zz[500]->hh.hh.hh.hh[500] spi=2718404122(0xa2078e1a)
    Apr 16 10:01:19 192.168.116.250 racoon: INFO: ISAKMP-SA expired zz.zz.zz.zz[500]-hh.hh.hh.hh[500] spi:baa4c93e8c16198c:482ba6110eeabc0c
    Apr 16 10:01:19 192.168.116.250 racoon: INFO: ISAKMP-SA deleted zz.zz.zz.zz[500]-hh.hh.hh.hh[500] spi:baa4c93e8c16198c:482ba6110eeabc0c
    Apr 16 10:01:27 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:27 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:30 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:51 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:51 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:01:55 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:13 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:13 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:16 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:37 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:37 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:40 192.168.116.250 racoon: ERROR: failed to get sainfo.
    Apr 16 10:02:41 192.168.116.250 racoon: INFO: respond new phase 1 negotiation: zz.zz.zz.zz[500]<=>hh.hh.hh.hh[500]
    Apr 16 10:02:41 192.168.116.250 racoon: INFO: begin Identity Protection mode.
    Apr 16 10:02:42 192.168.116.250 kernel: pid 45397 (racoon), uid 0: exited on signal 11 (core dumped)

    Is there any relation to this error report?

    https://bugs.launchpad.net/ubuntu/+source/ipsec-tools/+bug/913935

     
  • Todd Blum
    Todd Blum
    2013-04-23

    Today I've found that I had duplicate IPSec tunnels configured in pfSense, one disabled and the other enabled.

    I've moved this tunnel elsewhere, and I've removed both from the pfSense config to see if this improves my racoon stability.

     
  • Todd Blum
    Todd Blum
    2013-05-01

    racoon segfaulted again, but this time without any sainfo messages.

    The crash coincided with an ISP outage that affected at least 6 remote
    endpoints. DPD was enabled on these tunnels:

    ...
    May 1 01:18:27 192.168.116.250 racoon: INFO: ISAKMP-SA deleted
    my.end.poi.nt[500]-x.x.x.x [500] spi:48131b4e56ac24b8:32ef67f65454935e
    May 1 01:18:28 192.168.116.250 racoon: [y.y.y.y ] INFO: DPD: remote
    (ISAKMP-SA spi=622012ee7f51261d:7e39cc0f5ee916a0) seems to be dead.
    May 1 01:18:28 192.168.116.250 racoon: INFO: purging ISAKMP-SA
    spi=622012ee7f51261d:7e39cc0f5ee916a0.
    May 1 01:18:28 192.168.116.250 racoon: INFO: purged IPsec-SA
    spi=2284023606.
    May 1 01:18:28 192.168.116.250 racoon: INFO: purged IPsec-SA spi=187964617.
    May 1 01:18:28 192.168.116.250 racoon: INFO: purged ISAKMP-SA
    spi=622012ee7f51261d:7e39cc0f5ee916a0.
    May 1 01:18:28 192.168.116.250 racoon: INFO: ISAKMP-SA deleted
    my.end.poi.nt[500]-y.y.y.y [500] spi:622012ee7f51261d:7e39cc0f5ee916a0
    May 1 01:18:29 192.168.116.250 racoon: [z.z.z.z ] INFO: DPD: remote
    (ISAKMP-SA spi=3c837090349206bf:1086e896dce5e982) seems to be dead.
    May 1 01:18:29 192.168.116.250 racoon: INFO: purging ISAKMP-SA
    spi=3c837090349206bf:1086e896dce5e982.
    May 1 01:18:29 192.168.116.250 racoon: INFO: purged IPsec-SA
    spi=3531119898.
    May 1 01:18:29 192.168.116.250 racoon: INFO: purged IPsec-SA spi=124488619.
    May 1 01:18:29 192.168.116.250 racoon: INFO: purged ISAKMP-SA
    spi=3c837090349206bf:1086e896dce5e982.

    The segfaults still seem to coinside with connectivity issues.

     
  • Todd Blum
    Todd Blum
    2013-05-29

    Probably seemed to correlate with the outages of a single ISP.

    The ISP replaced/repaired a DSL DSLAM and possibly some core routers as well.

    racoon has been up stable now for several weeks since this change.