Sorry for the long details here. It may be relevant or related to some comment I have seen in regards to DHCP client killing traffic in the last few days on tech@ I have seen and that may be it might be useful.
If not just ignore as i am still digging why iked session are unstable long term. But what is sure and seen n the logs is that somehow a perfectly stable iked session with somehow after running well try for no reason to switch to NAT-T when at the same time I see DHCP renewal or request on the originating side of the iked session. The only thing I can think of is that somehow because of the timing of the dhcp renewal, one side of the iked didn't receive a confirmation back and then initiate a NAT-T instead, then it was receive after the DHCP renewal process was completed and then somehow the iked session never recover from tit because it try to do nat from this point and there isn;t any NAT in the path. Logs appear to show this is the common elements I have seen a few times so far and it appear to always be the common factor on an otherwise perfectly stable and running iked session. So, I think I may have found why my IKEDv2 doesn't stay up long term, but i am not sure how to go around it yet. Somehow the remote IKED node, even if program for passive mode, down the road it will send a request for NAT-T to the originating side of the session on a perfectly stable session. I can't fugue out why it would even do that, but I see it in the logs. Then form that point on, the session will never recover at all until I actually simply restart the session on the active side of the session. Log from remote session. Look at teh last two lines from the extract here. <snip> Dec 9 14:28:24 tunnel iked[15183]: ikev2_recv: IKE_SA_INIT request from initiator 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' id 0, 534 bytes Dec 9 14:28:24 tunnel iked[15183]: ikev2_msg_send: IKE_SA_INIT response from 66.63.5.250:500 to 108.56.142.37:500 msgid 0, 437 bytes Dec 9 14:28:24 tunnel iked[15183]: ikev2_recv: IKE_AUTH request from initiator 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' id 1, 800 bytes Dec 9 14:28:24 tunnel iked[15183]: ikev2_msg_send: IKE_AUTH response from 66.63.5.250:500 to 108.56.142.37:500 msgid 1, 768 bytes Dec 9 14:28:24 tunnel iked[15183]: sa_state: VALID -> ESTABLISHED from 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' Dec 9 15:21:05 tunnel iked[15183]: ikev2_recv: CREATE_CHILD_SA request from initiator 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' id 2, 288 bytes Dec 9 15:21:05 tunnel iked[15183]: ikev2_msg_send: CREATE_CHILD_SA response from 66.63.5.250:500 to 108.56.142.37:500 msgid 2, 240 bytes Dec 9 15:21:05 tunnel iked[15183]: ikev2_recv: INFORMATIONAL request from initiator 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' id 3, 80 bytes Dec 9 15:21:05 tunnel iked[15183]: ikev2_pld_delete: deleted 1 spis Dec 9 15:21:05 tunnel iked[15183]: ikev2_msg_send: INFORMATIONAL response from 66.63.5.250:500 to 108.56.142.37:500 msgid 3, 80 bytes Dec 9 16:16:25 tunnel iked[15183]: ikev2_msg_send: INFORMATIONAL request from 66.63.5.250:500 to 108.56.142.37:500 msgid 0, 80 bytes Dec 9 16:16:25 tunnel iked[15183]: ikev2_recv: INFORMATIONAL response from initiator 108.56.142.37:500 to 66.63.5.250:500 policy 'Ouellet' id 0, 80 bytes Dec 9 16:20:25 tunnel iked[15183]: ikev2_msg_send: INFORMATIONAL request from 66.63.5.250:4500 to 108.56.142.37:4500 msgid 1, 80 bytes, NAT-T Dec 9 16:20:25 tunnel iked[15183]: ikev2_recv: INFORMATIONAL response from initiator 108.56.142.37:4500 to 66.63.5.250:4500 policy 'Ouellet' id 1, 80 bytes Dec 9 16:31:25 tunnel iked[15183]: ikev2_msg_send: INFORMATIONAL request from 66.63.5.250:4500 to 108.56.142.37:4500 msgid 2, 80 bytes, NAT-T <snip> And then from that point on, it will ONLY try to use NAT-T and never go back to the normal setup, not even try it as the original side somehow see it as good. and if you do ipsecctl -sa, you see that it appear to be up. But from that point on, no matter what traffic is not flowing anymore and stop exactly from that point forward and never recover until done manually. Now this may be a coincidence, but it appear to happen when there is a DHCP renewal on the source side, even if that's NOT on the interface where the session is on. Looks like a message was receive to but may be not reply to, then a NAT-T message arrive after that point and then all went dead until manually reset. Strange thing is why a DHCP renewal on a different interface affect traffic on an other interface that also operate with DHCP, BUT is not in the process of renewal at that point? Is it possible that all interface that are configure with DHCP are affected when one of them is in a renewal cycle. I saw a few DHCP commit in the last few days and one comment form Bob@ regarding DHCP session dying etc. Tjois may not have anything to do with it, but I thought that may be it may have, or becasue of the events I see and the cvs commits message and the exchange on tech@, that may be it may be relevant information to help that, or not. But I see it in the logs however: Originating side of iked session at the time of communication lost, specially at 16:19:11 below: <snip> Dec 9 14:25:24 gateway iked[18024]: ikev2_msg_send: IKE_SA_INIT request from 0.0.0.0:500 to 66.63.5.250:500 msgid 0, 534 bytes Dec 9 14:27:43 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 14:27:43 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 14:28:24 gateway iked[18024]: ikev2_msg_send: IKE_SA_INIT request from 0.0.0.0:500 to 66.63.5.250:500 msgid 0, 534 bytes Dec 9 14:28:24 gateway iked[18024]: ikev2_recv: IKE_SA_INIT response from responder 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' id 0, 437 bytes Dec 9 14:28:24 gateway iked[18024]: ikev2_msg_send: IKE_AUTH request from 108.56.142.37:500 to 66.63.5.250:500 msgid 1, 800 bytes Dec 9 14:28:24 gateway iked[18024]: ikev2_recv: IKE_AUTH response from responder 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' id 1, 768 bytes Dec 9 14:28:24 gateway iked[18024]: sa_state: VALID -> ESTABLISHED from 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' Dec 9 14:34:12 gateway dhclient[21993]: DHCPREQUEST on re0 to 108.56.142.1 Dec 9 14:34:12 gateway dhclient[21993]: DHCPACK from 108.56.142.1 (54:e0:32:be:cf:c9) Dec 9 14:34:12 gateway dhclient[21993]: bound to 108.56.142.37 -- renewal in 3600 seconds. Dec 9 14:55:34 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 14:55:34 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 14:55:49 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.76 from e4:ce:8f:66:58:9e via re2 Dec 9 14:55:49 gateway dhcpd[19889]: DHCPACK on 66.63.44.76 to e4:ce:8f:66:58:9e via re2 Dec 9 15:21:05 gateway iked[18024]: ikev2_msg_send: CREATE_CHILD_SA request from 108.56.142.37:500 to 66.63.5.250:500 msgid 2, 288 bytes Dec 9 15:21:05 gateway iked[18024]: ikev2_recv: CREATE_CHILD_SA response from responder 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' id 2, 240 bytes Dec 9 15:21:05 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL request from 108.56.142.37:500 to 66.63.5.250:500 msgid 3, 80 bytes Dec 9 15:21:05 gateway iked[18024]: ikev2_recv: INFORMATIONAL response from responder 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' id 3, 80 bytes Dec 9 15:23:26 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 15:23:26 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 15:34:13 gateway dhclient[21993]: DHCPREQUEST on re0 to 108.56.142.1 Dec 9 15:34:13 gateway dhclient[21993]: DHCPACK from 108.56.142.1 (54:e0:32:be:cf:c9) Dec 9 15:34:13 gateway dhclient[21993]: bound to 108.56.142.37 -- renewal in 3600 seconds. Dec 9 15:51:19 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 15:51:19 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 16:16:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:500 to 108.56.142.37:500 policy 'Ouellet' id 0, 80 bytes Dec 9 16:16:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:500 to 66.63.5.250:500 msgid 0, 80 bytes Dec 9 16:19:11 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 16:19:11 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 16:20:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:4500 to 108.56.142.37:4500 policy 'Ouellet' id 1, 80 bytes Dec 9 16:20:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:4500 to 66.63.5.250:4500 msgid 1, 80 bytes, NAT-T Dec 9 16:31:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:4500 to 108.56.142.37:4500 policy 'Ouellet' id 2, 80 bytes Dec 9 16:31:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:4500 to 66.63.5.250:4500 msgid 2, 80 bytes, NAT-T Dec 9 16:32:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:4500 to 108.56.142.37:4500 policy 'Ouellet' id 3, 80 bytes Dec 9 16:32:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:4500 to 66.63.5.250:4500 msgid 3, 80 bytes, NAT-T Dec 9 16:34:13 gateway dhclient[21993]: DHCPREQUEST on re0 to 108.56.142.1 Dec 9 16:34:13 gateway dhclient[21993]: DHCPACK from 108.56.142.1 (54:e0:32:be:cf:c9) Dec 9 16:34:13 gateway dhclient[21993]: bound to 108.56.142.37 -- renewal in 3600 seconds. Dec 9 16:44:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:4500 to 108.56.142.37:4500 policy 'Ouellet' id 4, 80 bytes Dec 9 16:44:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:4500 to 66.63.5.250:4500 msgid 4, 80 bytes, NAT-T Dec 9 16:47:01 gateway dhcpd[19889]: DHCPREQUEST for 66.63.44.84 from 68:09:27:73:5a:d7 via re2 Dec 9 16:47:01 gateway dhcpd[19889]: DHCPACK on 66.63.44.84 to 68:09:27:73:5a:d7 via re2 Dec 9 16:55:25 gateway iked[18024]: ikev2_recv: INFORMATIONAL request from responder 66.63.5.250:4500 to 108.56.142.37:4500 policy 'Ouellet' id 5, 80 bytes Dec 9 16:55:25 gateway iked[18024]: ikev2_msg_send: INFORMATIONAL response from 108.56.142.37:4500 to 66.63.5.250:4500 msgid 5, 80 bytes, NAT-T <snip>
