Ich hoffe du kannst mit den Infos etwas anfangen.
Ich komme mir zwar auch langsam blöd vor, weil ich immer wieder nach weiteren Infos fragen müßte, aber vielleicht liest Du ja einfach mal mit, was in Deinen Protokollen so steht.
Abgesehen davon fehlt einfach Kontext ... ich mache das gleich mal an einem konkreten Punkt fest.
Die ersten 138 Zeilen Deiner Protokolldatei zeigen erst einmal nur, daß da von 12:27:09 bis 14:38:00 keine "Security Association" (SA, das ist ein Satz von Einstellungen, bestehend u.a. aus der entfernten und der lokalen IP-Adresse und dem verwendeten Schlüssel und anderen Parametern, wie der vereinbarten Lebensdauer) existiert, mit der die trotzdem in regelmäßigen Abständen eintreffenden Daten (anfangs alle 16 Sekunden, später werden es 17, ich tippe mal auf DPD-Pakete seitens des Shrewsoft-Clients) entschlüsselt werden können.
Da Du bestimmt einen guten Grund hattest, die Bitte um den Neustart auf beiden Seiten vor dem zu protokollierenden Versuch zu ignorieren, würde mich schon interessieren, welcher das war. Die ersten 138 Zeilen hättest Du uns damit schon mal erspart.
Außerdem würde sich die Frage, was denn nun um 14:38:00 plötzlich passierte, daß da seitens des Clients eine neue Verbindung aufgebaut wurde, dann auch erübrigen, das würde ich dann indirekt daraus schließen, daß Du offenbar ein Protokoll erstellen lassen wolltest.
Das meine ich aber mit "Kontext" ... wenn das alles ohne Eingriffe durch Dich so automatisch abgelaufen sein sollte (selbst dann fehlt die Angabe, ob denn nun die empfohlenen regelmäßigen Datenübertragungen stattgefunden haben und was diese für Ergebnisse lieferten), dann sind das schon vollkommen unerklärliche Intervalle, die da zu beobachten sind.
Als Einschub ganz kurz noch etwas zu der Konfiguration ... die sieht vollkommen normal aus, mit dem GUI-Assistenten eingerichtet, die Zeilenumbrüche in der vpn.cfg sind hoffentlich nur auf das Kopieren aus einem ungeeigneten Terminalprogramm zurückzuführen?
Gibt es einen bestimmten Grund, da das Netz 10.4.2.0/24 zu verwenden? Es muß kein Problem sein, andererseits fummelt AVM für mein Empfinden bei allen anderen privaten Adressbereichen auch mal gerne dazwischen und wenn da irgendwelche ganz alten Routinen noch am Werkeln sind, dann kennen die vielleicht noch gar kein CIDR. Wenn ich Probleme suchen wollte, würde ich erst einmal alles vermeiden, was von "Standardeinstellungen" abweicht und zwar mindestens so lange, bis ich sicher weiß, daß es daran nicht liegen kann. Wie gesagt, wird es eher nicht sein ... ist nur eine Frage des Prinzips, daß man nicht alles auf einmal ändert und sich hinterher wundert, daß nichts funktioniert. Dann sollte man tatsächlich Schritt für Schritt vorwärts gehen und ggf. auch unabhängige Änderungen erst einmal wieder rückgängig machen, um das Problem auf das Wesentliche zu reduzieren.
Zurück zum Log ... um 14:38:00 startet ja nun aus heiterem Himmel der Shrewsoft-Client eine neue Verbindung (offenbar war der seit 13:04:54 ja tot, da kam das letzte nicht zu entschlüsselnde Paket bei der FRITZ!Box an) und nachdem Phase1 dann geklappt hat, funktioniert auch um 14:38:04 irgendwann Phase2, damit steht die Verbindung. Auch die Feststellung der FRITZ!Box, daß sich der Absenderport des Shrewsoft-Clients geändert hat (von 61120 auf 61141) ist ein überdeutliches Zeichen dafür (neben den Nachrichten seit dem frühen Morgen), daß da auch in der FRITZ!Box schon länger der avmike lief und die letzte Verbindung des Clients (die muß ja irgendwann vor 12:27:09 mal aufgebaut worden sein, denn zu diesem Zeitpunkt war sie dann schon tot) von einem anderen Port aus erfolgte. Wieso der Shrewsoft-Client jetzt nach mindestens 130 Minuten plötzlich wieder aktiv wird, ist schon komisch ...
Für die Verbindung seit 14:38:04 (Phase1 schon 4 Sekunden früher, falls das nochmal wichtig wird), wird dann um 15:26:04 Uhr offenbar ein Rekeying ausgeführt. Da in der FRITZ!Box sämtliche Nachrichten dazu fehlen, kann das eigentlich nur eine Anforderung des Shrewsoft-Clients sein. Hast Du da irgendwas eingestellt, daß der nach 48 Minuten einen neuen Schlüssel benutzt? Das paßt so überhaupt nicht zu irgendwelchen bekannten Macken der FRITZ!Box. :gruebel:
Aber das klappt ja offenbar sogar noch ... denn es wird ja eine neue SA erzeugt, leider wird bei der FRITZ!Box der SPI der neuen SA nicht angezeigt, daher sieht man nicht, wann die mit FreeIPsecSA wieder freigegeben wird. Und spätestens hier bräuchte man jetzt wieder die Information, ob mit dieser neuen SA die Verbindung noch funktioniert, auch wenn man Daten darüber überträgt ... da wäre ein regelmäßiges Ping jetzt hilfreich. Wenn das doch nur mal jemand vorgeschlagen hätte ...
Egal ... um 15:38:00 wird dann jedenfalls die FRITZ!Box selbst aktiv (3600 Sekunden nach Phase1) und will die SA 2 (um 14:38:00 erzeugt, wie im Log steht) löschen. Nun weiß ich nicht, wie der avmike da zählt und was für ihn eine SA tatsächlich ist ... bei IPSec wird in der Regel für jede Richtung ein eigener Schlüssel verwendet (kann man in meinem 'racoon'-Log genauer sehen). Ich vermute mal, bei AVM laufen die beiden Schlüssel unter einer gemeinsamen SA-"Nummer". Jedenfalls werden um 15:38:03 ja dann genau zwei SPI (Security Parameter Index, eine Art Selektor für eine SA, in Kombination mit der IP-Adresse) gelöscht. Aus dem unterschiedlichen iotyp-Parameter würde ich auch auf "ausgehend" und "eingehend" tippen, keine Ahnung, wer wer ist.
Damit ist - nach meinem Verständnis - die Verbindung tot ... der avmike hat wohl die aktive SA gelöscht. Eigentlich gibt es ja tatsächlich zwei SA für eine IPSec-VPN-Verbindung ... eine für das Absichern von Phase2 (ISAKMP), die in Phase1 (IKE) ausgehandelt wurde und eine für den tatsächlichen Datenverkehr (ESP), die in Phase2 (eben ISAKMP) ausgekegelt wird. Im AVM-Log wird die ISAKMP-SA wohl über die "avmike:mainmode [verbindung]: add SA [n]"-Meldungen protokolliert und die für die Verschlüsselung des Payloads mit den "cb_sa_created"-Meldungen. Der AVM-Daemon löscht also nach 3600 Sekunden die SA für ISAKMP ... und ich würde fast wetten, implizit eben auch die SA für den Datentransfer.
Ab hier wird es aber erst richtig merkwürdig, wenn man Deine früheren Beschreibungen zugrunde legt. Denn offenbar kriegt es jetzt der Shrewsoft-Client per DPD (wir hatten am Beginn dafür 16-17 Sekunden-Intervalle, jetzt sind es schon 26 Sekunden?) mit, daß da nichts mehr geht und startet jetzt von sich aus erneut Phase1 (um 15:38:29), dabei bleibt aber der Port identisch, was mit einiger Sicherheit darauf hinweist, daß das tatsächlich automatisch erfolgte. Phase2 braucht dann wieder die schon bekannten 4 Sekunden (sind ja auch elend viele Vorschläge, die da zu untersuchen sind) und dann steht tatsächlich wieder eine Verbindung (SA id=5). Und nun wird nach weiteren 26 Sekunden dann ein Paket empfangen, das nicht entschlüsselt werden kann (das "fehlerhafte Paketlänge" resultiert mit einiger Sicherheit daraus) und dann löscht der avmike von sich aus sofort wieder die frische SA (ebenfalls id=5, wie man am Log-Eintrag der Callback-Funktion erkennen kann). Dann schmeißt er die ISAKMP-SA (Nr. 3) auch gleich noch weg und entsorgt - so interpretiere ich das "del_neighbour" - die komplette Verbindung, weil keine SA für ISAKMP mehr existiert ("set canceld = TRUE"). Jedenfalls fliegen jetzt auch die ESP-SAs mit den IDs 4 (von 15:26:04, noch mit der ISAKMP-SA Nr. 2 ausgehandelt) und 5 (von 15:38:33, mit ISAKMP-SA 3) wieder weg und damit ist erst mal Schicht im Schacht.
Für mich wird das Paket um 15:38:59 von der FRITZ!Box fälschlicherweise mit der SA 4 entschlüsselt, was schief geht, weil der Shrewsoft-Client wahrscheinlich schon mit der SA 5 von 15:38:33 verschlüsselt. Das würde allerdings wieder heißen, daß da tatsächlich zu einem Zeitpunkt zwei ESP-SA auch auf der FRITZ!Box existieren. Allerdings sollte nach meinem Verständnis die FRITZ!Box dann auch beide "probieren", wenn es mit der ersten nicht klappt. Stattdessen werden die Bürgersteige hochgeklappt und wohl einseitig die Freundschaft aufgekündigt. Hier stellt sich für mich dann der Shrewsoft-Client aber etwas glatt an ... der ist jetzt offenbar eingeschnappt. Ansonsten sollte er ja (DPD ist doch hoffentlich immer noch an?) feststellen, daß da keine Daten mehr drüber gehen und tatsächlich noch einmal mit Phase1 beginnen.
Das einzig Spannende ist es da für mich, was denn nun mit Traffic in den 26 Sekunden zwischen 15:38:33 und 15:38:59 passieren würde ... theoretisch sollte da jedes Paket ebenfalls schon für "ungültige Länge"-Fehler sorgen. Dann wäre die Frage, ob die Reaktion der FRITZ!Box (alles einreißen, was da noch steht) auch erst nach 26 Sekunden (Wie kommt es überhaupt von 16-17 Sekunden zu 26 Sekunden? Wäre das doch bloß ein Neustart des Shrewsoft-Clients gewesen, mit dem da begonnen wurde ...) eintritt oder schon früher bei anderen Paketen. Hätte Dich doch bloß jemand gebeten, da auch Traffic über die VPN-Verbindung zu schicken, wenn der Zeitpunkt des Fehlers sich nähert ... ich komme mir - eingangs schon bemerkt - etwas blöd vor, wenn ich immer wieder an solchen Stellen darauf verweisen muß, wie es besser gewesen wäre. Das hat schon seinen Grund, wenn ich solche Vorschläge mache ... das ist keine Beschäftigungstherapie. Es mag zwar sein, daß sich am Ende für Dein Problem keine Lösung fndet, aber pure Neugierde ist es eben auch nicht und ich wende mich nach solchen Bitten auch nicht schulterzuckend ab nach dem Motto: "Na wenn das so ist, kann man da auch nicht helfen.". Es kann und wird nicht immer klappen, aber ich schreibe mir ja bei so einer langen Antwort auch nicht nur einen Wolf, weil ich mit der Zeit nichts anderes anzufangen wüßte. Da gibt es definitiv spannendere Themen, wenn mich die Schreibwut packt ...
Das ist es jedenfalls in etwa, was man dem Log (mit Halbwissen und ein paar Annahmen zum avmike, da gibt es von AVM keine echten Infos) entnehmen kann ... zu einer ordentlichen Analyse gehört aber eben auch das Protokoll der Gegenseite. Hast Du überhaupt danach gesucht und es nur nicht gefunden oder hast Du den Hinweis genauso ignoriert, wie den zum Neustart für einen definierten Ausgangszustand?
In jedem Falle ist es sonderbar, was da nach 48 Minuten zum Erstellen der ESP-SA mit der ID 4 führt ... ich weiß auch, daß Du irgendwo schon mal eine Armada von Screenshots aufgefahren hattest ... ich fände allerdings eine verbale Beschreibung der wichtigen IPSec-Settings wesentlich besser als wenn ich mich da durch unscharfe Grafiken kämpfen muß. Mal sehen, ob ich das trotzdem schaffe ... Du kannst ja derweil mal klären, wo denn die 48 Minuten eingestellt sein könnten - denn das mit den Screenshots tue ich mir nur an, wenn Du definitiv versicherst, daß das 1:1 auch die Einstellungen sind, die zu dem gesamten Zeitraum des AVM-Protokolls (das wäre Sonntag 12:27 bis 18:15 Uhr) bestanden haben. Ansonsten macht das einfach keinen Sinn, wenn ich erst raten müßte, was da im oben betrachteten Zeitraum aktiv war. Das war ja noch vor #70 und insofern verstehe ich eigentlich auch überhaupt nicht, wie ein Protokoll, von dem ich Dir erst 19:40 erklärt habe, wie Du da rankommst, schon um 18:15 Uhr endet und warum Du nicht wirklich einfach mal eine saubere Umgebung zum Testen und zur anschließenden Auswertung der Ergebnisse geschaffen hast.
Fazit:
Die FRITZ!Box verhält sich sicherlich ab und an mal seltsam ... das Verhalten des Shrewsoft-Clients ist bei Dir aber eher noch seltsamer (die 48 Minuten sollten dem AVM-Log nach auf der Shrewsoft-Seite ihre Ursache haben). Mehr kann ich aus dem Log auch nicht ersehen ... ich habe mir schon etwas dabei gedacht, als ich Dich darum bat, auch nach dem Shrewsoft-Log zu suchen ... auch wenn ich nicht sicher weiß, ob es eines gibt und wenn ja, ob das erst noch irgendwo eingeschaltet werden muß. Aber dafür müßte man ja dann ohnehin wieder einen "frischen" Versuch starten und hier drehe ich mich jetzt im Kreis, die Gegend kommt mir jedenfalls bekannt vor.
Auch der AVM-Daemon dürfte seinen Anteil an der entstehenden Verwirrung haben ... ich würde ihm unterstellen, daß er die SAs für ISAKMP und ESP nicht wirklich getrennt verwaltet und mit der ISAKMP-SA auch immer die ESP-SAs entsorgt. Auch das ist geraten, aber es würde zu den Symptomen passen. So ein Zusammenhang ist nach meinem Verständnis aber eigentlich nicht gegeben und auch nicht erforderlich, wenn eine ESP-SA erst einmal existiert, braucht es die ISAKMP-SA nicht mehr, die diesen Prozess abgesichert hat - oder ich verstehe da etwas fundamental falsch. Vielleicht geht ja ohne ISAKMP-SA auch kein DPD (das läuft ja als Notify-Message im Gegensatz zu irgendwelchen anderen Keepalive-Mechanismen, aber nach meinem Verständnis auch mit der ESP-SA verschlüsselt) mehr? Selbst dann sollte es aber eigentlich möglich sein, eine neue IKE-Phase einzuläuten und wirklich von vorne zu beginnen. Blöd ist es am Ende nur, wenn da beide Seiten jeweils einen unterschiedlichen Zustand einer Verbindung annehmen, weil z.B. für die eine Seite es nur eine einzige Verbindung zur Gegenseite geben kann, während diese Gegenseite munter mehrere parallele Verbindungen und Verbindungsversuche verwaltet, die dann auf der ersten Seite alles durcheinander bringen.
Ich weiß nicht, ob es tatsächlich etwas bringt, weil der Parameter dem Namen nach auch unterschiedliche Bedeutungen haben kann ... aber ich würde es zumindest mal mit dem "always_renew" auf Seiten des avmike probieren, vielleicht kann der ja damit überredet werden, anstelle des brutalen Abbruchs einen zusätzlichen Versuch des Rekeyings zu starten? Die genaue Bedeutung ist meines Wissens nicht bekannt, es gibt nur alle möglichen Spekulationen.
