Dropbear Verbindung bricht alle 2.5 Stunden ab

[dunki]

Hi,

ich benutze Dropbear auf einer 7490 um von dort mittels rsync über ssh Dateien ins Internet (strato hidrive) zu synchronisieren. Mir ist aufgefallen, dass die Verbindung exakt alle 2.5h abbricht. An Strato liegt das nicht, weil es bei einer Verbindung vom PC nicht passiert.
Fällt jemandem was dazu ein?

Gruss
dunki

 

[oliver.ertl]

Lass halt einfach den Rsync in einer screen-Session laufen und gut ist

 

[dunki]

Mir ist nicht klar warum das helfen sollte? Der Prozess läuft bereits im Hintergrund mit Outputredirection auf eine Datei. Gibt es einen bekannten Bug/Feature, der durch die Screen-Session umgangen würde?

ssh läuft als Childprozess von rsync und das als Child von einem Script, das ich per ssh auf der Fritzbox starte. Das Script läuft weiter nur der rsync Prozess bricht mit der folgenden Fehlermeldung ab:
rsync: writefd_unbuffered failed to write 4092 bytes to socket [sender]: Broken pipe (32)
rsync: connection unexpectedly closed (2449 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [sender=3.0.9]

Und zwar auf die Minute genau alle 2.5h. Das kann doch kein Zufall sein...

Script:

#!/bin/sh

# script rsyncs to strato hidrive
# using ssh with an public key

# retry until rsync error code == 0 and upload successfull
# in order to work around DSL zwangstrennung

exec &> /var/media/ftp/uStor00/hidrive_mac/rsync.log

echo rsync start, first attempt
echo starting to rsync /var/media/ftp/uStor00/hidrive_mac/mac_encrypted_backup.sparsebundle
date
until rsync -av --delete -e "ssh -i /var/mod/root/.ssh/id_rsa_hidrive.db" /var/media/ftp/uStor00/hidrive_mac/mac_encrypted_backup.sparsebundle [email protected]:/users/user1/backup;
do
    echo Tansfer disrupted, retrying in 10 seconds...
    sleep 10
    date
    echo rsync restart
done

echo rsync successfull, all done

Aufgerufen wird es auf der Mac Konsole mit:

ssh -l root fritz.box "/var/media/ftp/uStor00/user1/hidrive_backup.sh &"

 

[RalfFriedl]

Es gibt zwei mögliche Ursachen. Entweder wird die Verbindung vom Server beendet, oder es gibt einen Timeout und deswegen ist die Verbindung weg. Letzteres kann speziell bei Verbindungen über einen NAT Router passieren, normalerweise aber nur dann, wenn die Verbindung nicht aktiv ist.
Die kannst versuchen, mit tcpdump herauszufinden, welche Pakete am Ende der Verbindung gesendet und empfangen werden. Wenn es zweieinhalb Stunden lang Daten transferiert werden, kommt dabei aber eine ganze Menge zusammen.

Verwendest Du am PC auch dropbear, oder openssh?

 

[dunki]

Genau genommen habe ich vorher nicht vom PC sondern von einem Linkstation NAS mit dem gleichen Skript gearbeitet, dort war aber openssh installiert. Außer der DSL Zwangstrennung habe ich nie ein Problem gehabt. Die Verbindung ist auch sicher nicht idle und im syslog finde ich auch nichts.

Kann es sein, dass die Fritzbox selbst die Verbindung trennt? Gibt es irgendeinen Fritzbox Prozess, der alle 2.5h das System so belastet, dass rsync keine Daten mehr liefert und die Verbindung idle wird?

Ich werde nochmal mit der Linkstation gegen testen um sicher zu sein, dass der Server die Verbindung nicht trennt.

Macht es Sinn dropbear gegen ssh zu tauschen?

 

[RalfFriedl]

Es gibt keinen Grund, warum die Box die Verbindung trennen sollte, aber dass heißt nicht, dass sie es nicht tut.
Dass ein Prozess genau 2,5h oder 150m nach dem Start von Dropbear läuft ist ebenfalls unwahrscheinlich.
Kannst Du eine SSH Verbindung ohne rsync aufbauen? Das hätte den Vorteil, dass man tcpdump laufen lassen kann, ohne dass ein hohes Datenvolumen gespeichert wird.
Ein Tausch von openssh statt dropbear zeigt nicht die Ursache, aber vielleicht hilft er, und es macht nicht viel Arbeit.

 

[dunki]

Ich habe leider kein Ziel außerhalb meines LAN auf dem ich mich mit nur ssh einloggen könnte. Strato hidrive hat nur einen rsync Zugang, keine ssh Konsole, das gleiche gilt für meinen Webserver.

Was auch noch sein könnte ist, das es an der 7490 liegt. Ich hatte bis vor 1 Monat eine 7390 (ohne Freetz) und damit war es kein Problem. Die 7490 habe ich mit der Linkstation noch nicht getestet aber das mache ich gerade. Das sollte zeigen, ob die Abbrüche auf Fritzbox und Linkstation beide da sind und ob sie gleichzeitig sind.

 

[dunki]

Also: Linkstation an LAN1 läuft jetzt schon 3h ohne Abbruch.

Es muss also entweder daran liegen, dass der dropbear Prozess auf der Fritzbox läuft oder an Dropbear selber. Vielleicht versuche ich mal Dropbear gegen openssh auszutauschen.

 

[dunki]

Ich habe jetzt Dropbear gegen openssh getauscht und damit ist das Problem weg.

Es muss also an Dropbear liegen! Außerdem habe ich beobachtet, dass
-2:30h mit 1Mbit/s Upload genau 1.04GByte ergeben, das ist verdächtig nahe an der 1GB Grenze dran
-sich die 2:30h zu 2:45h verlängern, wenn ich noch einen 2. Upload habe, sich also die Bandbreite verringert und damit die in 2:30h übertragene Datenmenge kleiner wird

Daher vermute ich, dass Dropbear einen Bug hat, der nach 1GByte übertragenem Datenvolumen die Verbindung abbrechen lässt. Bei der 1GB Grenze würde genau das 30. Bit in einem Byte Zähler auf 1 gesetzt werden, mit der Benutzung eines signed 32 Bit integers kann es also eigentlich nichts zu tun habe.

Vielleicht hilft es ja jemandem der ein ähnliches Problem mit Dropbear hat. Ansonsten sollte man lieber openssh statt Dropbear nehmen, wenn man mit rsync Daten über ssh übertragen will.

 

[RalfFriedl]

Aus sysoptions.h:
/* Spec recommends after one hour or 1 gigabyte of data
#define KEX_REKEY_DATA (1<<20) /* 2^30 == 1GB, this value must be < INT_MAX */

Kannst Du mal am Dropbear Debug-Ausgaben aktivieren?

--- debug.h
+++ debug.h
@@ -39,7 +39,7 @@
  * Caution: Don't use this in an unfriendly environment (ie unfirewalled),
  * since the printing may not sanitise strings etc. This will add a reasonable
  * amount to your executable size. */
-/* #define DEBUG_TRACE */
+#define DEBUG_TRACE
 
 /* All functions writing to the cleartext payload buffer call
  * CHECKCLEARTOWRITE() before writing. This is only really useful if you're
@@ -57,7 +57,7 @@
 
 /* A couple of flags, not usually useful, and mightn't do anything */
 
-/*#define DEBUG_KEXHASH*/
+#define DEBUG_KEXHASH
 /*#define DEBUG_RSA*/
 
 /* you don't need to touch this block */

Danach kann man dropbear auch mit der Option -v aufrufen, dies produziert einiges an Ausgaben.
Um nicht so viele Daten senden zu müssen, bis das Problem auftritt, kannst Du noch die Grenze verkleinern:

--- sysoptions.h
+++ sysoptions.h
@@ -16,7 +16,7 @@
 #define KEX_REKEY_TIMEOUT (3600 * 8)
 #endif
 #ifndef KEX_REKEY_DATA
-#define KEX_REKEY_DATA (1<<30) /* 2^30 == 1GB, this value must be < INT_MAX */
+#define KEX_REKEY_DATA (1<<16) /* 2^16 == 64kB, this value must be < INT_MAX */
 #endif
 /* Close connections to clients which haven't authorised after AUTH_TIMEOUT */
 #ifndef AUTH_TIMEOUT

 

[dunki]

Aha, daran wird's wohl liegen, dann passiert der Fehler anscheinend beim rekeying. Danke!

Ich müsste meine Box nochmal komplett plattmachen, um das auszuprobieren. Besteht berechtigte Hoffnung, dass dabei was rauskommt, das du beheben kannst?

 

[RalfFriedl]

Du musst die Box nicht komplett platt machen, es reicht, einen dropbear client mit dem Patch zu erstellen und diesen auf die Box zu kopieren. Wenn Du schon 1GB an Daten transferierst, ist wohl auch ein Massenspeicher an der Box angeschlossen, wo ein dropbear abgelegt werden kann. Wenn dort die Berechtigungen nicht passen, kannst Du den dropbear auch nach /tmp kopieren und dort ausführbar machen.
Bei rsync verwendest Du sowieso schon die Option -e, also kannst Du an der Stelle auch den Dropbear und die Option -v angeben.

rsync -e '/tmp/dbclient -v -i ...' ...

Ob ich damit den Fehler beheben kann, weiß ich nicht, aber man könnte das Protokoll an den Autor von dropbear schicken, der kennt sich damit sicher besser aus.

 

[dunki]

Ok, muss ich nur das Client Binary kopieren oder brauche ich auch noch irgendwelche Bibliotheken?

 

[RalfFriedl]

Die Bibliotheken, die das Programm braucht, sind vermutlich sowieso schon im Image.

 

[dunki]

Habe gerade gesehen, dass man dropbear auch als statisches binary compilieren kann. Das mache ich jetzt.

 

[dunki]

Ich bekomme es nicht hin.

Ich habe jetzt nach einem vollständigen make Lauf die Dateien sysoptions.h und debug.h in source/target-mips_gcc-4.6.4_uClibc-0.9.32.1/dropbear-2013.62 geändert und danach nochmal make aufgerufen: dann werden die beiden Dateien aber nicht neu übersetzt und das binary dropbearmulti wird nicht geändert.

Wenn ich vor dem 2. make ein make dropbear-clean mache, wird beim make danach zwar dropbearmulti übersetzt aber vorher werden die geänderten Dateien überschrieben.

Wo muss ich das ändern damit es funktioniert?

 

[RalfFriedl]

Die einfache Variante ist:

make dropbear-dirclean
make dropbear-source

Dann Dateien ändern, dann make dropbear-precompiled.

Der elegantere Weg ist, die beiden Änderung aus #10 als Patch in der Datei make/dropbear/patches/999-debug.patch abzulegen, dann braucht man nur noch dropbear-dirclean und dropbear-precompiled aufzurufen. Vielleicht greift auch die Automatik und man kann auf das dropbear-dirclean verzichten.

Freetz sollte schon alle Libraries für dropbear haben.

        libcrypt.so.0 => /lib/libcrypt.so.0 (0x2aabe000)
        libutil.so.0 => /lib/libutil.so.0 (0x2aae2000)
        libz.so.1 => /usr/lib/freetz/libz.so.1 (0x2aaf3000)
        libgcc_s.so.1 => /lib/libgcc_s.so.1 (0x2ab15000)
        libc.so.0 => /lib/libc.so.0 (0x2ab33000)
        ld-uClibc.so.0 => /lib/ld-uClibc.so.0 (0x2aaa8000)

 

[dunki]

Übersetzt werden die Dateien jetzt (Methode 1). Das binary dropbearmulti habe ich direkt nach make dropbear-precompiled rauskopiert.

Wenn ich auf der Fritzbox das binary dropbearmulti ausführe, bekomme ich aber jetzt nur noch einen segmentation fault. Vorher konnte ich es starten. Geändert habe ich nur folgendes:

debug.h:
#define DEBUG_TRACE
#define DEBUG_KEXHASH

sysoptions.h:
#define KEX_REKEY_DATA (1<<21)

In menuconfig hatte ich für dropbear das statische binary gewählt.

Hast du noch eine Idee?

 

[RalfFriedl]

Versuch es mal nicht statisch.

 

[dunki]

Ok, nicht statisch hat es funktioniert. Sollte man für die statische Option ein Ticket auf freetz.org aufmachen?

Hier ist der Teil des Logs mit dem Abbruch:


...
TRACE (5619) 1389521630.365826: send_msg_channel_data: len 16375 fd 0
TRACE (5619) 1389521630.372597: leave send_msg_channel_data
TRACE (5619) 1389521630.373003: send normal readfd
TRACE (5619) 1389521630.373316: enter send_msg_channel_data
TRACE (5619) 1389521630.373707: enter send_msg_channel_data isextended 0 fd 0
TRACE (5619) 1389521630.374120: maxlen 16375
TRACE (5619) 1389521630.374595: send_msg_channel_data: len 16375 fd 0
TRACE (5619) 1389521630.381393: leave send_msg_channel_data
TRACE (5619) 1389521630.381798: rekeying after timeout or max data reached
TRACE (5619) 1389521630.382441: send_msg_kexdh_init()
TRACE (5619) 1389521630.391507: DATAALLOWED=0
TRACE (5619) 1389521630.391861: -> KEXINIT
TRACE (5619) 1389521630.392163: maybe_empty_reply_queue - no data allowed
TRACE (5619) 1389521630.769376: empty queue dequeing
TRACE (5619) 1389521630.769747: maybe_empty_reply_queue - no data allowed
TRACE (5619) 1389521631.234696: process_packet: packet type = 93, len 9
TRACE (5619) 1389521631.235255: enter session_cleanup
TRACE (5619) 1389521631.235565: enter cli_tty_cleanup
TRACE (5619) 1389521631.235865: leave cli_tty_cleanup: not in raw mode
TRACE (5619) 1389521631.236376: enter chancleanup
TRACE (5619) 1389521631.236683: channel 0 closing
TRACE (5619) 1389521631.237056: enter remove_channel
TRACE (5619) 1389521631.237352: channel index is 0
TRACE (5619) 1389521631.238302: CLOSE writefd 1
TRACE (5619) 1389521631.238677: CLOSE readfd 0
TRACE (5619) 1389521631.239089: CLOSE errfd 2
rsync: writefd_unbuffered failed to write 4092 bytes to socket [sender]: Broken pipe (32)
rsync: connection unexpectedly closed (34 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [sender=3.0.9]

#define KEX_REKEY_DATA (1<<21) hat den Abbruch wie erwartet schon viel früher stattfinden lassen, es liegt also definitiv am Volumenlimit.
Wie man sieht macht dropbear anscheinend einfach die IO-Pipes zu, wenn das Volumenlimit erreicht ist...

Wenns was hilft hätte ich auch noch den Rest des Logfiles.