So, es hat zwar etwas gedauert, aber jetzt habe ich die Zeit gefunden, mir das Protokoll mal etwas näher anzusehen.
Der Beginn sieht ja noch gut aus, nach dem Aufbau der Verbindung wird jetzt - und zwar nur seitens der FRITZ!Box - im Abstand von 30 Sekunden ein DPD-Paket gesendet, um das Fortbestehen der (UDP-)Verbindung zu überprüfen.
Dann aber kommt etwas, was ich so absolut nicht verstehe:
Rich (BBCode):
May 21 22:59:06 04[NET] sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500]
May 22 05:08:50 03[NET] received packet: from 93.133.172.168[500] to 192.168.3.19[500]
Nun ist das ja offensichtlich auch gerade noch eine Stelle, an der Du (was an sich nicht zu beanstanden wäre) das Protokoll gekürzt hast. Aber warum um alles in der Welt erreicht da plötzlich wieder ein Paket auf UDP-Port 500 die StrongSwan-Instanz, wenn Du doch die zuvor sicherlich bestehende Portfreigabe für diesen Port entfernt hast? Ich hatte jedenfalls schon zweimal (#16 und #20) darauf hingewiesen, daß diese vollkommen umsonst und in diesem Fall ganz offensichtlich sogar eher hinderlich ist.
Denn ohne diese Weiterleitung hätte das Paket um 05:08:50 die StrongSwan-Instanz gar nicht erreichen dürfen und für die FRITZ!Box sollten das nun mal zwei unterschiedliche Endpoints (so ein Endpunkt besteht bekanntlich immer aus der Kombination von IP-Adresse und Portnummer) sein, was sich irgendwie auch darin zeigt, daß das offenbar ja eine neue "aggressive"-Message ist. Das kann aber irgendwie auch nicht das erste Rekeying für Phase 1 sein, denn die Gültigkeit des Sitzungsschlüssels wurde ja eingangs folgendermaßen festgelegt:
Rich (BBCode):
May 21 22:51:16 11[IKE] <fritzbox|1> scheduling rekeying in 13996s
May 21 22:51:16 11[IKE] <fritzbox|1> maximum IKE_SA lifetime 15436s
und weder für 13996 Sekunden noch für 15436 Sekunden käme ich da auf 05:08 Uhr.
Also wird das vermutlich (hier fehlt eben wieder das dazu passende Protokoll der Gegenseite) eine weitere, zusätzliche SA sein, die da ausgehandelt wird/wurde. Das macht es halt nicht übersichtlicher, wobei die ausgehandelten Verbindungen ja auf jeder Seite auch deswegen einen "Index" erhalten, WEIL es eben mehr als eine gleichzeitig geben kann, solange beim Aufbau nicht "alles andere zuvor vergessen" angesagt wurde durch eine "initial contact"-Option in der Nachricht:
Rich (BBCode):
May 22 05:08:50 15[ENC] <fritzbox|16> parsed AGGRESSIVE request 0 [ HASH NAT-D NAT-D N(INITIAL_CONTACT) ]
Auch die Tatsache, daß jetzt die XFRM-Regeln alle mit
refcount 2 gehandelt werden:
Rich (BBCode):
May 22 05:08:50 09[KNL] <fritzbox|16> policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in already exists, increasing refcount
May 22 05:08:50 09[KNL] <fritzbox|16> updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in [priority 375423, refcount 2]
May 22 05:08:50 09[KNL] <fritzbox|16> policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd already exists, increasing refcount
May 22 05:08:50 09[KNL] <fritzbox|16> updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd [priority 375423, refcount 2]
May 22 05:08:50 09[KNL] <fritzbox|16> policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out already exists, increasing refcount
May 22 05:08:50 09[KNL] <fritzbox|16> updating policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out [priority 375423, refcount 2]
spricht für die Annahme, daß da eben KEIN "initial contact" stattfindet und eine weitere SA aufgebaut wird, ebenso wie das hier:
Rich (BBCode):
May 22 05:23:32 12[KNL] <fritzbox|16> deleting policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out
May 22 05:23:32 12[KNL] <fritzbox|16> policy still used by another CHILD_SA, not removed
May 22 05:23:32 12[KNL] <fritzbox|16> not updating policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out [priority 375423, refcount 1]
May 22 05:23:32 12[KNL] <fritzbox|16> deleting policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in
May 22 05:23:32 12[KNL] <fritzbox|16> policy still used by another CHILD_SA, not removed
May 22 05:23:32 12[KNL] <fritzbox|16> not updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in [priority 375423, refcount 1]
May 22 05:23:32 12[KNL] <fritzbox|16> deleting policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd
May 22 05:23:32 12[KNL] <fritzbox|16> policy still used by another CHILD_SA, not removed
May 22 05:23:32 12[KNL] <fritzbox|16> not updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd [priority 375423, refcount 1
Das hier:
Rich (BBCode):
May 22 05:14:44 03[NET] received packet: from 146.88.241.153[41421] to 192.168.3.19[500]
May 22 05:14:44 03[ENC] parsing header of message
May 22 05:14:44 03[ENC] parsing HEADER payload, 46 bytes left
May 22 05:14:44 03[ENC] parsing rule 0 IKE_SPI
May 22 05:14:44 03[ENC] parsing rule 1 IKE_SPI
May 22 05:14:44 03[ENC] parsing rule 2 U_INT_8
May 22 05:14:44 03[ENC] parsing rule 3 U_INT_4
May 22 05:14:44 03[ENC] parsing rule 4 U_INT_4
May 22 05:14:44 03[ENC] parsing rule 5 U_INT_8
May 22 05:14:44 03[ENC] parsing rule 6 RESERVED_BIT
May 22 05:14:44 03[ENC] parsing rule 7 RESERVED_BIT
May 22 05:14:44 03[ENC] parsing rule 8 FLAG
May 22 05:14:44 03[ENC] parsing rule 9 FLAG
May 22 05:14:44 03[ENC] parsing rule 10 FLAG
May 22 05:14:44 03[ENC] parsing rule 11 FLAG
May 22 05:14:44 03[ENC] parsing rule 12 FLAG
May 22 05:14:44 03[ENC] parsing rule 13 FLAG
May 22 05:14:44 03[ENC] parsing rule 14 U_INT_32
May 22 05:14:44 03[ENC] parsing rule 15 HEADER_LENGTH
May 22 05:14:44 03[ENC] parsing HEADER payload finished
May 22 05:14:44 03[ENC] parsed a (0) request header
May 22 05:14:44 03[ENC] added payload of type NOTIFY to message
May 22 05:14:44 03[ENC] no message rules specified for this message type
May 22 05:14:44 03[NET] received unsupported IKE version 0.0 from 146.88.241.153, sending INVALID_MAJOR_VERSION
May 22 05:14:44 03[NET] waiting for data on sockets
ist dann ein schönes Beispiel dafür, daß eben auch die Ports für VPN-Verbindungen nicht davor gefeit sind, daß da ungültige Pakete eintreffen, ob nun versehentlich oder als "Angriff", spielt dabei gar keine Rolle. Eine ordentlich gehärtete Implementierung kann auch mit solchen ungültigen Paketen umgehen und verwirft sie einfach, nachdem die Gültigkeit (bzw. das Fehlen ebenjener) festgestellt wurde.
Was jetzt den plötzlichen Wechsel des Verhaltens um 05:08 Uhr ausgelöst haben könnte, kann man (mit dem vorhandenen Material) aber nicht sehen ... und diese Zeit paßt auch zu keiner Angabe, die Du in #21 gemacht hast.
Aber irgendetwas muß da geschehen sein, denn plötzlich ändert sich ja auch der Rhythmus der DPD-Messages - aus 30 Sekunden zwischen 22:51 Uhr und 05:08 Uhr werden auf einmal 5 Minuten und 4 Sekunden:
Rich (BBCode):
May 22 05:16:52 04[NET] sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500]
May 22 05:21:56 03[NET] received packet: from 93.133.172.168[4500] to 192.168.3.19[4500]
Danach soll bis 05:45 Uhr gar nichts mehr passiert sein? Das kann ich irgendwie auch nicht glauben - wenn Du in der nächsten Runde Zeilen entfernst, kennzeichne das doch bitte so, daß man es nachvollziehen kann.
Um 05:57 Uhr kommt dann wieder eine DPD-Message von der FRITZ!Box:
Rich (BBCode):
May 22 05:57:22 11[ENC] <fritzbox|16> parsed INFORMATIONAL_V1 request 2275246658 [ HASH N(DPD) ]
[...]
May 22 05:57:22 11[ENC] <fritzbox|16> generating INFORMATIONAL_V1 request 1363242085 [ HASH N(DPD_ACK) ]
und wie sich diese Nachrichten erklären lassen, weiß ich auch nicht:
Rich (BBCode):
May 22 05:57:22 04[NET] sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500]
May 22 06:02:25 03[NET] received packet: from 93.133.172.168[4500] to 192.168.3.19[4500]
Wenn dazwischen auf der StrongSwan-Seite eine Zwangstrennung erfolgte und der Anschluß dabei eine neue (öffentliche) IP-Adresse erhalten hat, dann dürfte die FRITZ!Box ja nur dann in der Lage sein, an diese neue Adresse ein Paket zu senden, wenn sie die neue Adresse NACH der Aktualisierung im DynDNS ERNEUT aufgelöst hat und das Paket dann an diese neue Adresse gesendet wurde. Ansonsten kann ich mir absolut nicht vorstellen, wie da der StrongSwan-Server das Paket um 06:02:25 empfangen könnte - also muß es DOCH WIEDER irgendwelchen anderen Traffic gegeben haben, der zur "Umschaltung" der Adresse des NAT-Gateway im IPSec der FRITZ!Box geführt hat - genau deshalb braucht es auch die (synchronen) Protokolle von beiden Seiten.
Die FRITZ!Box hat jedenfalls ihrerseits gar keine Veranlassung, die Verbindung zu kappen und neu aufzubauen, denn der StrongSwan-Server meldet sich ja noch ganz normal per DPD:
Rich (BBCode):
May 22 06:02:25 12[ENC] <fritzbox|16> parsed INFORMATIONAL_V1 request 1719834483 [ HASH N(DPD) ]
[...]
May 22 06:02:25 12[ENC] <fritzbox|16> generating INFORMATIONAL_V1 request 947734980 [ HASH N(DPD_ACK) ]
und um 06:04:16 werden sogar noch einmal die Keys in P2 erneuert:
Rich (BBCode):
May 22 06:04:16 07[CHD] <fritzbox|16> CHILD_SA net{9} state change: CREATED => INSTALLING
May 22 06:04:16 07[CHD] <fritzbox|16> using AES_CBC for encryption
May 22 06:04:16 07[CHD] <fritzbox|16> using HMAC_SHA2_512_256 for integrity
May 22 06:04:16 07[CHD] <fritzbox|16> adding inbound ESP SA
May 22 06:04:16 07[CHD] <fritzbox|16> SPI 0xc2d91561, src 93.133.172.168 dst 192.168.3.19
May 22 06:04:16 07[KNL] <fritzbox|16> adding SAD entry with SPI c2d91561 and reqid {1}
May 22 06:04:16 07[KNL] <fritzbox|16> using encryption algorithm AES_CBC with key size 256
May 22 06:04:16 07[KNL] <fritzbox|16> using integrity algorithm HMAC_SHA2_512_256 with key size 512
May 22 06:04:16 07[KNL] <fritzbox|16> using replay window of 32 packets
May 22 06:04:16 07[KNL] <fritzbox|16> HW offload: no
May 22 06:04:16 07[CHD] <fritzbox|16> adding outbound ESP SA
May 22 06:04:16 07[CHD] <fritzbox|16> SPI 0xeaf3612b, src 192.168.3.19 dst 93.133.172.168
May 22 06:04:16 07[KNL] <fritzbox|16> adding SAD entry with SPI eaf3612b and reqid {1}
May 22 06:04:16 07[KNL] <fritzbox|16> using encryption algorithm AES_CBC with key size 256
May 22 06:04:16 07[KNL] <fritzbox|16> using integrity algorithm HMAC_SHA2_512_256 with key size 512
May 22 06:04:16 07[KNL] <fritzbox|16> using replay window of 0 packets
May 22 06:04:16 07[KNL] <fritzbox|16> HW offload: no
May 22 06:04:16 07[KNL] <fritzbox|16> policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in already exists, increasing refcount
May 22 06:04:16 07[KNL] <fritzbox|16> updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 in [priority 375423, refcount 2]
May 22 06:04:16 07[KNL] <fritzbox|16> policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd already exists, increasing refcount
May 22 06:04:16 07[KNL] <fritzbox|16> updating policy 192.168.5.0/24 === 192.168.3.1..192.168.3.255 fwd [priority 375423, refcount 2]
May 22 06:04:16 07[KNL] <fritzbox|16> policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out already exists, increasing refcount
May 22 06:04:16 07[KNL] <fritzbox|16> updating policy 192.168.3.1..192.168.3.255 === 192.168.5.0/24 out [priority 375423, refcount 2]
May 22 06:04:16 07[KNL] <fritzbox|16> getting a local address in traffic selector 192.168.3.1..192.168.3.255
May 22 06:04:16 07[KNL] <fritzbox|16> using host 192.168.3.19
May 22 06:04:16 07[KNL] <fritzbox|16> getting iface name for index 2
May 22 06:04:16 07[KNL] <fritzbox|16> using 192.168.3.1 as nexthop and eth0 as dev to reach 93.133.172.168/32
May 22 06:04:16 07[IKE] <fritzbox|16> CHILD_SA net{9} established with SPIs c2d91561_i eaf3612b_o and TS 192.168.3.1..192.168.3.255 === 192.168.5.0/24
May 22 06:04:16 07[CHD] <fritzbox|16> CHILD_SA net{9} state change: INSTALLING => INSTALLED
May 22 06:04:16 07[CHD] <fritzbox|16> CHILD_SA net{8} state change: REKEYING => REKEYED
May 22 06:04:16 07[IKE] <fritzbox|16> reinitiating already active tasks
womit dann wieder zwei unterschiedliche Schlüssel aktiv sind, die wechselseitig falsch verschlüsseln, weil sich die SAs unterscheiden.
Um 06:08:06 Uhr gibt es dann noch einmal eine (erfolgreiche) DPD-Message:
Rich (BBCode):
May 22 06:08:06 11[ENC] <fritzbox|16> parsed INFORMATIONAL_V1 request 2186422233 [ HASH N(DPD) ]
[...]
May 22 06:08:06 11[ENC] <fritzbox|16> generating INFORMATIONAL_V1 request 3925932221 [ HASH N(DPD_ACK) ]
und was die FRITZ!Box jetzt veranlaßt haben könnte, um 06:13:32 Uhr wieder mit einem neuen Verbindungsaufbau zu beginnen:
Rich (BBCode):
May 22 06:13:32 03[NET] received packet: from 93.133.172.168[500] to 192.168.3.19[500]
[...]
May 22 06:13:32 03[ENC] parsed a AGGRESSIVE message header
steht sicherlich im (zeitgleichen) Protokoll der Box (das war dann der Index 17 im StrongSwan). Ich wage mal die These, daß das immer noch nicht funktioniert hätte, wenn nicht zeitnah im StrongSwan die zweite SA für diese Transformation gelöscht worden wäre (das war die mit Index 16):
Rich (BBCode):
May 22 06:13:33 09[CHD] <fritzbox|17> CHILD_SA net{9} state change: REKEYING => REKEYED
[...]
May 22 06:13:42 13[IKE] <fritzbox|16> queueing ISAKMP_DELETE task
May 22 06:13:42 13[IKE] <fritzbox|16> activating new tasks
May 22 06:13:42 13[IKE] <fritzbox|16> activating ISAKMP_DELETE task
May 22 06:13:42 13[IKE] <fritzbox|16> deleting IKE_SA fritzbox[16] between 192.168.3.19[strongswan.ddnss.de]...93.133.172.168[fritzbox.ddnss.de]
May 22 06:13:42 13[ENC] <fritzbox|16> added payload of type DELETE_V1 to message
May 22 06:13:42 13[IKE] <fritzbox|16> sending DELETE for IKE_SA fritzbox[16]
May 22 06:13:42 13[IKE] <fritzbox|16> IKE_SA fritzbox[16] state change: ESTABLISHED => DELETING
[...]
May 22 06:13:42 13[NET] <fritzbox|16> sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500] (140 bytes)
[...]
May 22 06:13:42 13[IKE] <fritzbox|16> IKE_SA fritzbox[16] state change: DELETING => DESTROYING
Der Timer für die DPD-Messages bleibt aber jetzt offenbar bei 5 Minuten:
Rich (BBCode):
May 22 06:44:01 04[NET] sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500]
May 22 06:49:01 03[NET] received packet: from 93.133.172.168[4500] to 192.168.3.19[4500]
[...]
May 22 06:49:01 04[NET] sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500]
bis dann offenbar nichts mehr ankommt, denn eigentlich müßte um 06:54 Uhr herum ja die nächste DPD-Kommunikation erfolgen. Die SAs für Index 17 sind jedenfalls weiterhin aktiv und erst um 07:07 Uhr (das sind immerhin 18 Minuten nach der letzten erfolgreichen "dead peer detection") entschließt sich dann die FRITZ!Box, erneut eine komplett neue Verbindung aufzubauen (die kriegt dann den Index 18 im StrongSwan):
Rich (BBCode):
May 22 07:07:33 14[IKE] <18> 93.133.172.168 is initiating a Aggressive Mode IKE_SA
May 22 07:07:33 14[IKE] <18> IKE_SA (unnamed)[18] state change: CREATED => CONNECTING
wobei sie die Antwort des StrongSwan gar nicht erst abwartet und sofort noch eine weitere Verbindung (bzw. eine AGGRESSIVE-Message) nachschiebt - die kriegt dann im StrongSwan den Index 19. Witzigerweise erwartet aber der StrongSwan-Server dann erst einmal eine Reaktion auf seine Antwort für den Index 18:
Rich (BBCode):
May 22 07:07:37 06[IKE] <fritzbox|18> sending retransmit 1 of response message ID 0, seq 1
May 22 07:07:37 06[NET] <fritzbox|18> sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500] (530 bytes)
[...]
May 22 07:07:44 08[IKE] <fritzbox|18> sending retransmit 2 of response message ID 0, seq 1
May 22 07:07:44 08[NET] <fritzbox|18> sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500] (530 bytes)
[...]
May 22 07:07:57 05[IKE] <fritzbox|18> sending retransmit 3 of response message ID 0, seq 1
May 22 07:07:57 05[NET] <fritzbox|18> sending packet: from 192.168.3.19[4500] to 93.133.172.168[4500] (530 bytes)
[...]
May 22 07:08:03 07[JOB] <fritzbox|18> deleting half open IKE_SA with 93.133.172.168 after timeout
[...]
May 22 07:08:03 07[IKE] <fritzbox|18> IKE_SA fritzbox[18] state change: CONNECTING => DESTROYING
Zwischendrin wird aber die SA mit Index 17 noch abgräumt:
Rich (BBCode):
May 22 07:07:43 05[IKE] <fritzbox|17> queueing ISAKMP_DELETE task
[...]
May 22 07:07:43 05[IKE] <fritzbox|17> activating ISAKMP_DELETE task
May 22 07:07:43 05[IKE] <fritzbox|17> deleting IKE_SA fritzbox[17] between 192.168.3.19[strongswan.ddnss.de]...93.133.172.168[fritzbox.ddnss.de]
[...]
May 22 07:07:43 05[IKE] <fritzbox|17> sending DELETE for IKE_SA fritzbox[17]
May 22 07:07:43 05[IKE] <fritzbox|17> IKE_SA fritzbox[17] state change: ESTABLISHED => DELETING
Danach geht es dann einigermaßen kreuz und quer (ich würde mich sehr wundern, wenn in dieser Zeitspanne tatsächlich Daten übertragen werden konnten - ab 07:24 gibt es auch keine DPD-Pakete mehr), bis um 07:48 Uhr dann die FRITZ!Box mit ihrer neuen IP-Adresse eine vollkommen neue Verbindung initiiert (die kriegt dann Index 20), die aber kurz danach wieder durch eine weitere (Index 21) ersetzt wird.
Ich empfehle Dir wirklich DRINGEND, die Weiterleitung für UDP 500 abzuschalten ... erhält die FRITZ!Box aus irgendeinem Grund eine Antwort über ein abweichendes NAT-Gateway, korrigiert sie bei sich die Adresse des Absenders (z.B. hier:
Code:
2024-05-09 05:57:49 avmike:StrongSwan: nat_t_port changed from 2.243.250.254:4500 to 93.131.32.132:4500
), wenn das Paket zu einer vorhandenen Verbindung paßt. Das wird noch lange nicht alles lösen, aber es vermeidet zusätzliche Probleme, denn das Ziel ist es ja, die FRITZ!Box dazu zu bringen, daß sie nach dem Wechsel der IP-Adresse auf der Seite des StrongSwan-Servers ebendiesen Wechsel auch erkennt und ihrerseits die Verbindung (zur neuen Adresse des Routers vor dem StrongSwan-Server) neu aufbaut. Offensichtlich klappt das aber nur, wenn sie eben KEINE Pakete von der neuen IP-Adresse erhält und wenn sie die neue IP-Adresse des Unifi-Routers nicht kennt, sollte es ihr schwerfallen, dorthin DPD-Pakete zu senden.
Ansonsten verstehe ich die Zeiten in den Protokollen irgendwie auch nicht ... kann es event. sein, daß bei Dir der Container noch mit Winterzeit protokolliert und damit 05:08 Uhr eigentlich schon 06:08 Uhr ist und zu diesem Zeitpunkt die Zwangstrennung für den Unifi-Router schon erfolgt war? Das wären dann ja nur ca. 8 Minuten, bevor die FRITZ!Box neu aufgebaut hat. Andererseits passen dann ja auch die anderen Zeitangaben wieder nicht, denn da geschieht ja tatsächlich etwas gegen 06:00 Uhr und um 07:48 Uhr. Die Gretchen-Frage wäre für mich also, was da um 05:08 Uhr (oder in den 10 Minuten davor, denn DPD-Timeout wäre nach 3 Versuchen und bei 30 Sekunden Abstand sollte das eigentlich nach 90 Sekunden erkannt werden) genau passiert ist - aber eben mit den Protokollen von BEIDEN Seiten, sonst macht das immer noch keinen Sinn.
