[gelöst] ssh läßt mich 10 s warten, später dann Timeout ...

[tapferesschneiderlein]

Hallo,

1. Wenn ich mich von zuhause (Debian Sarge) per ssh mit einem weiteren Sarge-PC über Internet verbinden will, klappt alles sofort: Nach zwei Sekunden kommt die Paßwortabfrage. Nach längerer Inaktivität (ich schätze zehn Minuten) wird die Verbindung aber beendet: »reset by peer«.
Verbinde ich mich innerhalb des LANs (von putty), bricht die Verbindung nie ab.

2. Verbinde ich mich zu einem ubuntu-Rechner, geht das *erste* Anmelden auch total schnell, bei späteren Anmeldeversuchen entsteht aber immer eine Kunstpause von zehn Sekunden, bevor die Paßwortabfrage erscheint:

Code: Alles auswählen

22:08:28 OpenSSH_3.8.1p1 Debian-8.sarge.4, OpenSSL 0.9.7e 25 Oct 2004
22:08:28 debug1: Reading configuration data /etc/ssh/ssh_config
22:08:28 debug1: Connecting to xxxx [xx.xx.xx.xx] port 22102.
22:08:29 debug1: Connection established.
22:08:29 debug1: identity file /home/xx/.ssh/identity type -1
22:08:29 debug1: identity file /home/xx/.ssh/id_rsa type -1
22:08:29 debug1: identity file /home/xx/.ssh/id_dsa type -1
22:08:29 debug1: Remote protocol version 2.0, remote software version OpenSSH_4.1p1 Debian-7ubuntu4.1
22:08:29 debug1: match: OpenSSH_4.1p1 Debian-7ubuntu4.1 pat OpenSSH*
22:08:29 debug1: Enabling compatibility mode for protocol 2.0
22:08:29 debug1: Local version string SSH-2.0-OpenSSH_3.8.1p1 Debian-8.sarge.4
22:08:29 debug1: SSH2_MSG_KEXINIT sent
22:08:29 debug1: SSH2_MSG_KEXINIT received
22:08:30 debug1: kex: server->client aes128-cbc hmac-md5 none
22:08:30 debug1: kex: client->server aes128-cbc hmac-md5 none
22:08:30 debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
22:08:30 debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
22:08:30 debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
22:08:30 debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
22:08:30 debug1: Host 'xxxx' is known and matches the RSA host key.
22:08:30 debug1: Found key in /home/xx/.ssh/known_hosts:1
22:08:30 debug1: ssh_rsa_verify: signature correct
22:08:30 debug1: SSH2_MSG_NEWKEYS sent
22:08:30 debug1: expecting SSH2_MSG_NEWKEYS
22:08:30 debug1: SSH2_MSG_NEWKEYS received
22:08:30 debug1: SSH2_MSG_SERVICE_REQUEST sent
22:08:30 debug1: SSH2_MSG_SERVICE_ACCEPT received
xx@xxxx's password: 
22:08:40 debug1: Authentications that can continue: publickey,password
22:08:40 debug1: Next authentication method: publickey
22:08:40 debug1: Trying private key: /home/xx/.ssh/identity
22:08:40 debug1: Trying private key: /home/xx/.ssh/id_rsa
22:08:40 debug1: Trying private key: /home/xx/.ssh/id_dsa
22:08:40 debug1: Next authentication method: password

Bei diesem Server habe ich den selben Timeout-Effekt, so daß ich jetzt eher eine Client-Einstellung bei mir vermute.

Also: Wer wartet hier worauf zwischen 22:08:30 und 22:08:40 und wo könnte ein Zehn-Minuten-Timeout festgelegt sein?

[Faultier]

Der Timeout könnte von einem Namensauflösungsproblem her rühren? Sind auf beiden Rechnern korrekte /etc/host Dateien? Wenn nicht, dann trag auf beiden die jeweiligen Rechnernamen ein und probier das noch einmal.

[tapferesschneiderlein]

Ich habe noch ein bißchen probiert: Das Problem mit dem Warten entsteht auf allen (drei) von mir getesteten Clients, muß also was serverseitiges sein.
Und siehe da: Die /etc/hosts enthielt tatsächlich einen Fehler: Dort stand eine falsche eigene IP. Dies ist jetzt korrigiert; trotzdem wird es nicht besser.
Verbindungen aus dem selben Subnetz (192.168.0.0/24) werden sofort aufgebaut, bei Verbindungen »außen rum« wird die jeweils erste Verbindung (nach IP-Wechsel) ohne Verzögerung aufgebaut, alle weiteren legen diese Pause ein.
Und jetzt kommt's: Dieses Verhalten tritt sogar bei Verbindungen vom Server zu sich selbst auf, wenn er den Umweg über den Router und dessen Port-Forwarding (siehe Skizze) nimmt. Aber auch erst ab beim zweiten mal ...




Edit: Bild verkleinert.

[tapferesschneiderlein]

Weitere Tests:
Das Problem mit der Wartezeit ab dem »zweiten« Einloggen entsteht auch bei Login per publickey:

Code: Alles auswählen

10:57:48 OpenSSH_3.8.1p1 Debian-8.sarge.4, OpenSSL 0.9.7e 25 Oct 2004
10:57:48 debug1: Reading configuration data /etc/ssh/ssh_config
10:57:48 debug1: Connecting to xxxx [xx.xx.xx.xx] port 22102.
10:57:48 debug1: Connection established.
10:57:48 debug1: identity file /root/.ssh/identity type -1
10:57:48 debug1: identity file /root/.ssh/id_rsa type 1
10:57:48 debug1: identity file /root/.ssh/id_dsa type -1
10:57:48 debug1: Remote protocol version 2.0, remote software version OpenSSH_4.1p1 Debian-7ubuntu4.1
10:57:48 debug1: match: OpenSSH_4.1p1 Debian-7ubuntu4.1 pat OpenSSH*
10:57:48 debug1: Enabling compatibility mode for protocol 2.0
10:57:48 debug1: Local version string SSH-2.0-OpenSSH_3.8.1p1 Debian-8.sarge.4
10:57:48 debug1: SSH2_MSG_KEXINIT sent
10:57:48 debug1: SSH2_MSG_KEXINIT received
10:57:48 debug1: kex: server->client aes128-cbc hmac-md5 none
10:57:48 debug1: kex: client->server aes128-cbc hmac-md5 none
10:57:48 debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
10:57:48 debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
10:57:48 debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
10:57:48 debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
10:57:48 debug1: Host 'xxxx' is known and matches the RSA host key.
10:57:48 debug1: Found key in /root/.ssh/known_hosts:8
10:57:48 debug1: ssh_rsa_verify: signature correct
10:57:48 debug1: SSH2_MSG_NEWKEYS sent
10:57:48 debug1: expecting SSH2_MSG_NEWKEYS
10:57:48 debug1: SSH2_MSG_NEWKEYS received
10:57:48 debug1: SSH2_MSG_SERVICE_REQUEST sent
10:57:48 debug1: SSH2_MSG_SERVICE_ACCEPT received
10:57:58 debug1: Authentications that can continue: publickey,password
10:57:58 debug1: Next authentication method: publickey
10:57:58 debug1: Trying private key: /root/.ssh/identity
10:57:58 debug1: Offering public key: /root/.ssh/id_rsa
10:57:58 debug1: Server accepts key: pkalg ssh-rsa blen 149
10:57:58 debug1: read PEM private key done: type RSA
10:57:58 debug1: Authentication succeeded (publickey).
10:57:58 debug1: channel 0: new [client-session]
10:57:58 debug1: Entering interactive session.
10:57:58 Last login: Thu May 18 10:57:37 2006 from xx.xx.xx.xx
10:57:58 ...

Außerdem habe ich festgestellt, daß es auch schon vor dem nächsten IP-Wechsel wieder »erste« Male geben kann. Ich habe aber den Zeitraum (ca. eine Stunde) noch nicht genau eingrenzen können.

Daß es immer so genau 10 Sekunden sind, klingt schon nach 'nem Timeout ... aber wessen?

[nil]

Ich würde vielleicht versuchen die Möglichkeit des DNS-Problems weiter zu verfolgen. Zum Abbruch der Sitzung nach 10 Minuten kann man sowohl am Client (putty, mindterm, shell) also auch am Server (sshd) Einstellungen vornehmen.

Um den Abbruch zu erkennen, würde ich mich mit strace sowohl an den Client als auch an den Serverprozess dranhängen. Vielleicht solltest du diese Ausgaben entsprechend hier posten.
Was passiert ferner, wenn du versuchst SSH zu einer IP und nicht zu einem Namen zu machen, ist das identisch?

[tapferesschneiderlein]

Zum Abbruch der Sitzung nach 10 Minuten kann man sowohl am Client (putty, mindterm, shell) also auch am Server (sshd) Einstellungen vornehmen.

Ich habe jetzt auch von anderen gehört, daß ihre ssh-Logins nach einer bestimmten Zeit zurückgesetzt werden, wenn sie sich »von außen« irgendwo einwählen. Ich würde dieses Problem erstmal zurückstellen ...

Was passiert ferner, wenn du versuchst SSH zu einer IP und nicht zu einem Namen zu machen, ist das identisch?

Ja, vollkommen. Es entsteht genau dieselbe Wartezeit von 10 Sekunden, wenn ich direkt ssh <IP-Adresse> -p <Port> aufrufe.

Edit: PS: Und auch wieder, bei einer Verbindung vom Server zu sich selbst (über den forwardenden Router -- siehe Skizze).

[tapferesschneiderlein]

Wenn ich auf dem Client ein strace ssh ... ausführe, entsteht (wie auch schon in der Debug-Ausgabe) einfach nur eine Lücke zwischen 12:55:27 und 12:55:38.

Das strace-Protokoll poste ich jetzt mal nicht, hier ein Auszug aus der Debug-Ausgabe:

Code: Alles auswählen

...
12:55:27 debug1: SSH2_MSG_NEWKEYS received
12:55:27 debug1: SSH2_MSG_SERVICE_REQUEST sent
12:55:28 debug1: SSH2_MSG_SERVICE_ACCEPT received
12:55:38 debug1: Authentications that can continue: publickey,password
12:55:38 debug1: Next authentication method: publickey
12:55:38 debug1: Trying private key: /root/.ssh/identity
12:55:38 debug1: Offering public key: /root/.ssh/id_rsa
...

Auf dem Server passiert währenddessen folgendes:
Zwei neue Prozesse entstehen:

Code: Alles auswählen

12:55:27
root     19426  0.0  0.7   4912  1612 ?        Ss   12:55   0:00 sshd: [accepted]
sshd     19427  0.0  0.7   4912  1644 ?        S    12:55   0:00 sshd: [net]

Unmittelbat vor der Pause wird aus [accepted] beim ersten Prozess [priv]:

Code: Alles auswählen

12:55:28
root     19426  0.0  0.8   5096  1832 ?        Ss   12:55   0:00 sshd: root [priv]
sshd     19427  0.0  0.7   4912  1712 ?        S    12:55   0:00 sshd: root [net]

Diese Prozesse bleiben dann so stehen bis zum Login, der zweite verschwindet dann:

Code: Alles auswählen

12:55:38
root     19426  0.0  0.9   6312  2072 ?        Ss   12:55   0:00 sshd: root@pts/5

Das sind die Ausgaben von ps waux im Sekundentakt. Der zweite Prozess [net] scheint also irgendwas zu tun.

[nil]

Hi,
mit strace meinte ich vor allem den Serverprozess und nicht den Client.

Was liefert auf dem Server:

Code: Alles auswählen

strace -p19426
strace -p19427

(Zahlen evtl. austauschen)

[tapferesschneiderlein]

Mmh, es ist (für mich gerade) relativ schwer, einen Prozess zu tracen, den es noch nicht gibt.
Mein Experiment

Code: Alles auswählen

while true; 
  do PID=$(ps wuax | egrep "s+hd: root \[" | awk '{print $2}'); 
  [ "$PID" ] && strace -tp$PID 2> trace_ssh.log;
done

ergab folgendes:

Code: Alles auswählen

14:29:12 Process 24757 attached - interrupt to quit
14:29:12 gettimeofday({1147955352, 808103}, NULL) = 0
14:29:12 gettimeofday({1147955352, 808143}, NULL) = 0
14:29:17 poll([{fd=4, events=POLLIN}], 1, 4942) = 0
14:29:17 gettimeofday({1147955357, 751242}, NULL) = 0
14:29:17 poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
14:29:17 send(4, "yj1001000000003756893678934759002847in-a"..., 44, 0) = 44
14:29:17 poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
14:29:17 ioctl(4, FIONREAD, [88]) = 0

***************************
14:29:17 recvfrom(4, "yj2052006568935760031227"..., 1024, 0, {sa_family=AF_INET, \
    sin_port=htons(53), sin_addr=inet_addr("192.168.0.10")}, [16]) = 88
***************************

14:29:17 gettimeofday({1147955357, 752057}, NULL) = 0
14:29:22 poll([{fd=4, events=POLLIN}], 1, 4999) = 0
14:29:22 close(4) = 0
14:29:22 read(6, "00033", 4) = 4
14:29:22 read(6, "300016ssh-connection00000000", 27) = 27
14:29:22 read(6, "0005", 4) = 4
14:29:22 read(6, "n0000", 5) = 5
14:29:22 write(6, "0005v", 5) = 5
14:29:22 write(6, "0000", 4) = 4
14:29:22 read(6, "000246", 4) = 4
14:29:22 read(6, "240002000000000002250007ssh-rsa0"..., 166) = 166
14:29:22 geteuid32() = 0
14:29:22 getegid32() = 0
14:29:22 getgroups32(0, []) = 0
14:29:22 open("/proc/sys/kernel/ngroups_max", O_RDONLY) = 4
14:29:22 read(4, "65536n", 31) = 6
14:29:22 close(4) = 0
14:29:22 socket(PF_FILE, SOCK_STREAM, 0) = 4
14:29:22 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
14:29:22 fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
...

Ein ähnleicher Shell-Wurm auf den [net]-Prozess angesetzt ergab wieder nur die 10 Sekunden Pause.

Code: Alles auswählen

14:29:12 Process 24758 attached - interrupt to quit
14:29:22 read(4, "0005", 4) = 4
14:29:22 read(4, "v0000", 5) = 5
14:29:22 write(3, "3053263232643673213371737330t-212"..., 64) = 64
14:29:22 select(4, [3], NULL, NULL, NULL) = 1 (in [3])
14:29:22 read(3, "234>342289...201360Su376hu3245c265"..., 8192) = 240
14:29:22 write(4, "00024624", 5) = 5
14:29:22 write(4, "0002000000000002250007ssh-rsa000"..., 165) = 165
14:29:22 read(4, "000t", 4) = 4
...

Ich vermute mal stark, daß die markierte Zeile (***) mit sin_addr=inet_addr("192.168.0.10") das Problem ist. 192.168.0.10 ist die LAN-seitige IP des Routers.



PS: Ich wäre außerdem dankbar, wenn mir a) jemand sagen könnte, wie ich das auch einfacher haben könnte und b) wenn da oben jetzt mein SSH-Key irgendwo steht

[tapferesschneiderlein]

Ich habe mit tcpdump auf dem Server mal überwacht, woher die Pakete kommen, die der Router von außen nach innen weiterleitet. Mein Verdacht, er würde sich selbst als Absender einsetzen und Antwortpakete des Servers dann wieder modifizieren und nach außen schicken, hat sich nicht bestätigt: Die Pakete kommen ganz sauber von der IP des Clients.
Zum Zeitpunkt an dem dieses sin_addr=inet_addr("192.168.0.10") auftaucht, zeigt mir tcpdump folgende Anfrage:

Code: Alles auswählen

// 192.168.0.102: Server
// 192.168.0.10:  Router
// ww.xx.yy.zz:   Client

16:12:03.168211 IP 192.168.0.102.1269 > 192.168.0.10.53:  9205+ PTR? zz.yy.xx.ww.in-addr.arpa. (44)
16:12:03.168645 IP 192.168.0.10.53 > 192.168.0.102.1269:  9205* 1/0/0 (88)
16:12:03.204862 IP 192.168.0.102.22 > ww.xx.yy.zz.49968: . ack 946 win 1752 <nop,nop,timesta...

16:12:08.167226 IP 192.168.0.102.1269 > 192.168.0.10.53:  9205+ PTR? zz.yy.xx.ww.in-addr.arpa. (44)
16:12:08.167663 IP 192.168.0.10.53 > 192.168.0.102.1269:  9205* 1/0/0 (88)

16:12:13.166759 IP 192.168.0.102.22 > ww.xx.yy.zz.49968: P 1345:1409(64) ack 946 win 1752 <no...
16:12:13.260007 IP ww.xx.yy.zz.49968 > 192.168.0.102.22: P 946:1186(240) ack 1409 win 8320 <n...

Er sendet die Anfrage also nach 5 Sekunden nochmal, nach weiteren 5 Sekunden geht's dann weiter.
Mache ich die Anfrage selbst, geht es schneller:

Code: Alles auswählen

~# time nslookup ww.xx.yy.zz
Server:         192.168.0.10
Address:        192.168.0.10#53

ww.xx.yy.zz.in-addr.arpa      name = pCCDDEEFF.dip0.t-ipconnect.de.


real    0m0.008s
user    0m0.004s
sys     0m0.003s

Interessanterweise zeigt er mir aber die IP richtig rum an (ww.xx.yy.zz.in-addr...) und nicht rückwärts wie in der tcpdump-ausgabe (zz.yy.xx.ww.in-addr...). Wandelt das nslookup für mich um? Fragt der ssh-Prozess falsch? ...?

[tapferesschneiderlein]

Ha, gelöst. Der Router ist Mist. Genauer sein DNS.

Link



Ich habe jetzt einfach einen anderen Nameserver in /etc/resolv.conf eingetragen -- dann geht's. *\(^_^)/*