Die VPN-Funktion ist - in meinen Augen - eine Katastrophe bei dieser Version.
Eine gut beschäftigte VPN-Verbindung (5 MBit/s im Upload am Anschlag über Stunden) bricht in unregelmäßigen Abständen immer mal wieder zusammen beim Erneuern eines Session-Keys:
Code:
Dec 13 16:48:36 avmike[10387]: 2015-12-13 16:48:36(1) [Bus error] avmike([10387]) CRASHED at timercb_del+0x84 (/lib/libavmcsock.so.2 at 0005c8d0) accessing 00000000
Dec 13 16:48:36 avmike[10387]: SIGNO 10 ERRNO 0 CODE 128
Dec 13 16:48:36 avmike[10387]: Version: 06.50
Dec 13 16:48:36 avmike[10387]: No bugmsg
Dec 13 16:48:36 avmike[10387]: ze: 00000000 at: 1810202c v0: 774784c0 v1: 80000001
Dec 13 16:48:36 avmike[10387]: a0: 00000001 a1: 00000001 a2: 76fbd000 a3: 00000001
Dec 13 16:48:36 avmike[10387]: t0: 00000000 t1: 00000000 t2: 80054360 t3: fffffff0
Dec 13 16:48:36 avmike[10387]: t4: 019eed00 t5: 9507b740 t6: 00000000 t7: f10f94d9
Dec 13 16:48:36 avmike[10387]: s0: 80018002 s1: 00000000 s2: 76fc5410 s3: 7fa8dee4
Dec 13 16:48:36 avmike[10387]: s4: 7fa8df6c s5: 00000000 s6: 00000000 s7: 77473000
Dec 13 16:48:36 avmike[10387]: t8: 00000000 t9: 770dc2d0 k0: 00000000 k1: 00000000
Dec 13 16:48:36 avmike[10387]: gp: 77317be0 sp: 7fa8de20 fp: 772c2000 ra: 772ee8b4
Dec 13 16:48:36 avmike[10387]: FA 00000000
Dec 13 16:48:36 avmike[10387]: PC 772ee8d0 timercb_del+0x84 (/lib/libavmcsock.so.2 at 0005c8d0)
Dec 13 16:48:36 avmike[10387]: RA 772ee8b4 timercb_del+0x68 (/lib/libavmcsock.so.2 at 0005c8b4)
Dec 13 16:48:36 avmike[10387]: PC Code: 3c038000 24630001 02038026 <8e030008> 10600038 2411ffff 8e030020 14620034 8f918030
Dec 13 16:48:36 avmike[10387]: RA Code: 2739bdec 0320f809 00000000 <8fbc0010> 32030001 50600005 8e030008 3c038000 24630001
Dec 13 16:48:36 avmike[10387]: [bt] 772ee8d0 timercb_del+0x84 (/lib/libavmcsock.so.2 at 0005c84c/0x5c8d0)
Dec 13 16:48:36 avmike[10387]: Code: 3c038000 24630001 02038026 <8e030008> 10600038 2411ffff 8e030020 14620034 8f918030
Dec 13 16:48:36 avmike[10387]: [bt] 0040f750 [0040f724] <0+0x40f724>+0x2c (/bin/avmike at 0040f724/0x40f750)
Dec 13 16:48:36 avmike[10387]: Code: 8c840000 18800003 8f9984e0 <0320f809> 00000000 ae000000 8fbf001c 8fb00018 03e00008
Dec 13 16:48:36 avmike[10387]: [bt] 00424ab0 _Z15FinishQuickModePP20tIKE_ExchangeContext+0x98 (/bin/avmike at 00424a18/0x424ab0)
Dec 13 16:48:36 avmike[10387]: Code: afa20020 8fbc0018 8f9981cc <0320f809> 02002021 8fa20020 8fbf002c 8fb00028 03e00008
Dec 13 16:48:36 avmike[10387]: [bt] 004266cc _Z17QuickModeExchangePP20tIKE_ExchangeContext+0x6dc (/bin/avmike at 00425ff0/0x4266cc)
Dec 13 16:48:36 avmike[10387]: Code: 2402001a 14620011 27b30044 <0c109286> 02802021 00409021 10400004 8fbc0028 24020019
Dec 13 16:48:36 avmike[10387]: [bt] 00408948 [00407c94] <0+0x407c94>+0xcb4 (/bin/avmike at 00407c94/0x408948)
Dec 13 16:48:36 avmike[10387]: Code: ac5605bc ac53001c a4510020 <0320f809> 27a40064 8fa20064 104001e7 8fbc0020 08102336
Dec 13 16:48:36 avmike[10387]: [bt] 00409210 [004091c0] <0+0x4091c0>+0x50 (/bin/avmike at 004091c0/0x409210)
Dec 13 16:48:36 avmike[10387]: Code: 8fa40024 8fa70050 afa00010 <0c101f25> 02003021 8fbf003c 8fb00038 03e00008 27bd0040
Dec 13 16:48:36 avmike[10387]: [bt] 772cd680 [772cd338] <0+0x772cd338>+0x348 (/lib/libavmcsock.so.2 at 0003b338/0x3b680)
Dec 13 16:48:36 avmike[10387]: Code: 8ed902b4 afb70010 02c02021 <0320f809> 00000000 1000ffa4 8fbc0018 0242102a 5440ffa5
Dec 13 16:48:36 avmike[10387]: [bt] 772cfd54 csock_select_with_msecs+0x3a0 (/lib/libavmcsock.so.2 at 0003d9b4/0x3dd54)
Dec 13 16:48:36 avmike[10387]: Code: 10400010 02002021 8e1901bc <0320f809> 02002021 8fbc0010 8f99898c 0320f809 02802021
Dec 13 16:48:36 avmike[10387]: [bt] 00409734 [00409228] <0+0x409228>+0x50c (/bin/avmike at 00409228/0x409734)
Dec 13 16:48:36 avmike[10387]: Code: 8e82490c 10400005 8f998674 <0320f809> 00000000 081025be 8fbc0020 8f99854c 3c040043
Dec 13 16:48:36 avmike[10387]: [bt] 0040681c main+0x21c (/bin/avmike at 00406600/0x40681c)
Dec 13 16:48:36 avmike[10387]: Code: 8f99846c 0320f809 26057bd8 <0c10248a> 00000000 8fbf0024 8fb10020 8fb0001c 03e00008
Dec 13 16:48:36 avmike[10387]: [bt] finished.
Das ist jetzt der dritte Absturz an genau derselben Stelle. Die Fehlerbehandlung startet den avmike zwar wieder, aber eine über die VPN-Verbindung laufende NFS-Verbindung ist dann erst einmal "hängend", bis die Fehlerkondition "nach oben" durchgereicht wird.
Offenbar ist auch nicht jede neue Schlüsselaushandlung betroffen, der letzte Absturz davor war um 12:35 Uhr.
Es wird ein P2-Proposal mit 3600 Sekunden "life-time" verwendet (esp-all-all/ah-none/comp-all/pfs).
Die VPN-Protokolldatei sieht aus wie ein Hühnerhof und das Eventlog genauso, dort wechseln sich (obwohl die Verbindung im Hintergrund fleißig Daten überträgt, die auch tatsächlich am anderen Ende ankommen) die Meldungen
Code:
13.12.15 11:29:21 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:29:20 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
in loser Folge immer wieder ab (die Stunde von 11-12 Uhr sieht z.B. so aus:
Code:
13.12.15 11:58:05 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:58:04 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:56:03 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:56:01 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:55:10 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:55:09 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:47:00 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:46:59 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:43:45 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:43:44 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:43:15 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:43:14 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:40:43 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:40:42 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:38:33 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:38:32 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:37:19 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:37:18 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:36:21 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:36:20 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:35:32 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:35:31 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:34:56 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:34:55 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:33:27 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:33:25 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:29:21 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:29:20 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:25:10 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:25:09 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:24:04 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:24:03 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:23:53 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:23:52 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:23:39 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:23:38 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:18:20 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:18:20 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:13:27 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:13:26 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:13:16 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:13:15 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:12:36 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:12:35 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:12:20 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:12:19 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:11:53 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:11:52 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:11:26 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:11:25 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:11:01 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:11:00 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:08:07 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:08:06 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:05:03 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:05:02 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:04:53 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:04:52 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:01:52 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:01:51 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
13.12.15 11:00:15 VPN-Verbindung zu Peer1 wurde erfolgreich hergestellt.
13.12.15 11:00:13 VPN-Verbindung zu Peer1 wurde getrennt. Ursache: 3 IKE server
), obwohl seit heute sehr früh am Morgen ununterbrochen Daten übertragen werden (inzwischen insg. 31,5 GB).
Das VPN-Log spiegelt genau dieses auch wieder, es werden ständig irgendwelche SAs ausgehandelt und nach kürzester Zeit wieder verworfen (FreeIPsecSA):
Code:
2015-12-13 16:57:08 avmike:Peer1: Phase 2 ready
2015-12-13 16:57:08 avmike:< cb_sa_created(name=Peer1,id=6,...,flags=0x00002103)
2015-12-13 16:57:08 avmike:Peer1 stop_vpn_keepalive to 192.168.49.1
2015-12-13 16:57:08 avmike:Peer1 restart keepalive_timer timer_id 1994010880
2015-12-13 16:57:08 avmike:Peer1: start waiting connections
2015-12-13 16:57:08 avmike:Peer1: NO waiting connections
2015-12-13 17:01:00 avmike:FreeIPsecSA: spi=d6b1f436 protocol=3 iotype=2
2015-12-13 17:01:00 avmike:< cb_sa_deleted(name=Peer1,id=6,what=2)
2015-12-13 17:01:00 avmike:FreeIPsecSA: spi=4588 protocol=4 iotype=2
2015-12-13 17:01:00 avmike:< cb_sa_deleted(name=Peer1,id=6,what=2)
2015-12-13 17:01:00 avmike:FreeIPsecSA: spi=4a0d113e protocol=3 iotype=1
2015-12-13 17:01:00 avmike:< cb_sa_deleted(name=Peer1,id=6,what=1)
2015-12-13 17:01:00 avmike:FreeIPsecSA: spi=e5c9 protocol=4 iotype=1
2015-12-13 17:01:01 avmike:Peer1: Phase 2 ready
2015-12-13 17:01:01 avmike:< cb_sa_created(name=Peer1,id=7,...,flags=0x00002103)
2015-12-13 17:01:01 avmike:Peer1 stop_vpn_keepalive to 192.168.49.1
2015-12-13 17:01:01 avmike:Peer1 restart keepalive_timer timer_id 1994010880
2015-12-13 17:01:01 avmike:Peer1: start waiting connections
2015-12-13 17:01:01 avmike:Peer1: NO waiting connections
2015-12-13 17:03:23 avmike:FreeIPsecSA: spi=4b33f39 protocol=3 iotype=2
2015-12-13 17:03:23 avmike:< cb_sa_deleted(name=Peer1,id=7,what=2)
2015-12-13 17:03:23 avmike:FreeIPsecSA: spi=722b9c3d protocol=3 iotype=1
2015-12-13 17:03:23 avmike:FreeIPsecSA: spi=c218 protocol=4 iotype=1
2015-12-13 17:03:23 avmike:FreeIPsecSA: spi=e015 protocol=4 iotype=2
2015-12-13 17:03:23 avmike:< cb_sa_deleted(name=Peer1,id=7,what=2)
2015-12-13 17:03:24 avmike:Peer1: Phase 2 ready
Das "NO waiting connections" läßt mich ja eigentlich daran glauben, daß da parallel zu einer laufenden TCP-Verbindung (wir erinnern uns, daß - abgesehen von Pausen bei den Abstürzen des avmike - die ganze Zeit eine Datenübertragung stattfindet, egal was da beim IKE passiert) neue SAs ausgehandelt werden, während eine alte SA weiterhin in Benutzung ist und ja offenbar auch noch für beide Seiten funktioniert. Bei der Gegenstelle handelt es sich - nur der Ordnung halber - um eine 7390 mit 06.20 und genau denselben P2-Proposals (P1SS ist auf beiden Seiten "all/all/all") ... was die Boxen untereinander dann tatsächlich benutzen, ist ja naturgemäß nicht zu ermitteln, solange AVM dazu nichts in die ike.log schreibt. Die andere Seite protokolliert jedenfalls fleißig "decapsulation errors" - immer dann, wenn bei mir eine neue SA ausgehandelt wurde.
Dieses ganze Geraffel mit den ständigen Erneuerungen tritt allerdings gar nicht erst auf, solange keine Daten übertragen werden. Ich habe bisher auch noch nicht mit einem Mitschnitt geprüft, ob da tatsächlich noch eine alte SA verwendet wird (das sieht man ja zumindest einem ESP-Paket anhand des SPI noch an, welche SA benutzt wurde) - im Moment ist mir die Datenübertragung wichtiger und die muß erst einmal zum Abschluß kommen.
Denkbar wäre aber natürlich auch, daß da wirklich immer für kurze Zeit eine neue SA auch benutzt wird (obwohl das "NO waiting connections" eigentlich dagegen sprechen würde in meinen Augen), weil das Erneuern ja immer nur eine Sekunde braucht. Bei den übertragenen Datenmengen kann man einzelne Wiederholungen aufgrund verschwundener TCP-Pakete auch nicht mehr sauber erkennen, schon ein Paket-Mitschnitt macht in diesem Kontext nur noch begrenzten Sinn - ich weiß nicht, wie sich Wireshark bei 1 GB-Dateien benimmt - und auch der Durchsatz wird davon ja nur marginal beeinflußt, da hat unterschiedliche Latenz viel größere Auswirkungen.
Aber egal, was die Ursache ist ... das ist jedenfalls kein tragbarer Zustand - schon weil damit das Eventlog zugemüllt wird und die wirklich wichtigen Einträge aus dem Protokoll verdrängt werden.
Damit wird die tägliche Push-Mail auch zu Makulatur ... selbst wenn ich nicht genau getestet habe, was bei einem Überlauf des Eventlogs mit der Push-Mail passiert. Die von heute nacht 0 Uhr zeigt jedenfalls nur das Eventlog von gestern bis 16:00 Uhr an, dafür aber 120 Zeilen mit den VPN-Fehlern von 09:41 Uhr bis 16:04 Uhr. Das sieht dann wieder mehr danach aus, daß da gar kein Rollover für die Push-Mail erfolgt bzw. dieser Zustand vor dem Rollover irgendwo anders gespeichert wird. Die Mail wurde jedenfalls auch erst nach 0:00 Uhr verschickt und nicht schon um 16 Uhr irgendwas am gestrigen Nachmittag, was der letzte Eventlog-Eintrag nahelegen würde.
Benutzt hier noch jemand eine VPN-Verbindung zwischen zwei FRITZ!Boxen, um darüber große Datenmengen zu übertragen?
Ich kann mich auch noch erinnern, daß ich den Absturz in "timercb_del" schon mal bei einer Fehlermeldung eines anderen Forenteilnehmers
hier gesehen hatte, da war das aber eine 7390 mit 06.30 (und ebenfalls gut ausgelasteter VPN-Verbindung) und mit der 06.30 hatte ich auf meiner 7490 gar kein Problem in dieser Richtung ... aber ich habe bei den Labor-Versionen dann "versäumt", die regelmäßig bei mir stattfindenden umfangreichen Datenübertragungen mit der Labor-Version zu testen, das war von Beginn an viel zu instabil und genau deswegen bin ich ja nach jedem kurzen Test einer 06.36 immer wieder auf die 06.30 zurück. Die Quittung gibt es jetzt ... wobei das offenbar der Bastelei am VPN an sich geschuldet ist und nicht der neuen Firmware-Version. Andererseits tritt es bei mir eben erst mit der 06.50 reproduzierbar auf und so postuliere ich einfach (für mich) einen direkten Zusammenhang mit dieser Firmware-Version.
Wieso diese Firmware allerdings tatsächlich den "release"-Status erringen konnte, verstehe ich auch nicht so ganz ... ich glaube auch nicht daran, daß irgendjemand bei AVM vor Weihnachten noch Überstunden schieben wird, um wenigstens die gröbsten Schnitzer trotzdem noch zu beseitigen, das zieht sich jetzt sicherlich mit dem / bis zum nächsten Release noch eine Weile hin.
Das sieht für mich jedenfalls eher nach einem vorgegebenen Release-Termin aus (der vielleicht auch noch 2 Wochen erhöhten Support-Aufwand "bei der Einführung" vor den Feiertagen berücksichtigte) und der mußte eingehalten werden, egal ob man nun wirklich fertig ist/war oder eben nicht (vermutlich hing man ja ohnehin schon hinterher, wenn man die früheren Ankündigungen - selbst wenn sie unbestimmt waren - berücksichtigt und auch die bei den COMET-Reglern gemachten Aussagen bzgl. des Erscheinens passender Firmware).
Selbst "last minute changes" wie die "erweiterten Support-Daten" haben es - obwohl sie unvollständig bis falsch sind - noch in diese Release-Version geschafft, obwohl man damit auch bis zur nächsten Version hätte warten können, wenn man es gerade mal 1,5 Wochen vor dem Release erst angefangen hat einzubauen.
Ich würde ja hoffen, daß die Entwicklung bei der 7490 gleich mit der nächsten Labor-Reihe weitergeht und die anderen Modelle tatsächlich parallel zu dieser weiteren Entwicklung mit demselben Stand wie beim Release für die 7490 versehen werden, aber das glaube ich angesichts der jetzt schon höheren Build-Nummer der Labor-Version für die 7390 eigentlich nicht so richtig ... damit werden wir vermutlich ähnliche Effekte wie bei der 06.05 für die 7270-Reihe kriegen, wo auch schon lange vor dem Herbst 2014 einige Änderungen, die bei den anderen Boxen erst mit 06.20 Einzug hielten, zu finden waren. Wenn jetzt bei der 7390 noch Fehler aus der 7490 beseitigt werden und bei den Versionen für weitere Modelle dann nochmals andere, dann wird es wohl Zeit für eine Liste der Unterschiede zwischen den Versionen mit gleichen Nummern bei verschiedenen Boxen ... das macht das Chaos dann perfekt. Bisher hatten zumindest die Release-Versionen für die 7490 und die 7390 eine identische Build-Nummer (30889 bei der 06.30) - das macht ja das VPN-Problem so mysteriös für mich, wenn es bei dem einen schon mit der 06.30 auftritt und beim anderen erst mit der 06.50.