# [solved]SSH: Login dauert von extern lange (ca. 20 Sekunden)

## rcmc_ronny

Hallo,

Ich habe ein Problem mit dem SSH Login, welcher jedoch NICHT auf DSN Probleme zurückzuführen ist.

Lokal geht ein Login an der Konsole wie gewohnt schnell. Per SSH jedoch dauert es nach der Eingabe des Passwortes 20 Sekunden.

Ich habe mit strace etws geforscht, konnte jedoch keine Ursache finden. 

Die 20 Skeunden Wartezeit treten nach folgenden Zeilen auf:

```

debug3: mm_share_sync: Share sync end

debug1: PAM: establishing credentials

debug3: PAM: opening session

debug3: PAM: sshpam_store_conv called with 1 messages

```

... Nach den 20 Sekunden Wartezeit geht es normal weiter ... und die Shell ist nutzbar ...

```

debug3: PAM: sshpam_store_conv called with 1 messages

debug2: set_newkeys: mode 0

debug2: set_newkeys: mode 1

debug1: Entering interactive session for SSH2.

debug2: fd 6 setting O_NONBLOCK

debug2: fd 7 setting O_NONBLOCK

debug1: server_init_dispatch_20

debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384

debug1: input_session_request

```

Folgend noch ein strace bis zum Punkt der Wartezeit:

```

write(2, "debug3: PAM: sshpam_store_conv c"..., 55debug3: PAM: sshpam_store_conv called with 1 messages

) = 55

_llseek(4, 0, [0], SEEK_SET)            = 0

time(NULL)                              = 1285057107

fcntl64(4, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=0, len=292}, 0xbf9b0410) = 0

write(4, "Sj\230Lssh\0\0\0\0\0\0\0\0\0\0\0\0\267 \3\233\277n|H\267'\260O\267"..., 292) = 292

fcntl64(4, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=0, len=292}, 0xbf9b0410) = 0

gettimeofday({1285057107, 744165}, NULL) = 0

access("/var/log/wtmpx", F_OK)          = -1 ENOENT (No such file or directory)

open("/var/log/wtmp", O_WRONLY|O_LARGEFILE) = 5

alarm(0)                                = 0

rt_sigaction(SIGALRM, {0xb751b8b0, [], 0}, {SIG_DFL, [], SA_INTERRUPT}, 8) = 0

alarm(10)                               = 0

fcntl64(5, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0

_llseek(5, 0, [132480], SEEK_END)       = 0

write(5, "\7\0\0\0008,\0\0ssh\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

fcntl64(5, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0

alarm(0)                                = 10

rt_sigaction(SIGALRM, {SIG_DFL, [], SA_INTERRUPT}, NULL, 8) = 0

close(5)                                = 0

close(4)                                = 0

open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4

_llseek(4, 0, [0], SEEK_CUR)            = 0

fstat64(4, {st_mode=S_IFREG|0644, st_size=3225, ...}) = 0

mmap2(NULL, 3225, PROT_READ, MAP_SHARED, 4, 0) = 0xb773b000

_llseek(4, 3225, [3225], SEEK_SET)      = 0

munmap(0xb773b000, 3225)                = 0

close(4)                                = 0

getrlimit(RLIMIT_CPU, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_FSIZE, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_DATA, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_CORE, {rlim_cur=0, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_RSS, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_NPROC, {rlim_cur=14046, rlim_max=14046}) = 0

getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=1024}) = 0

getrlimit(RLIMIT_MEMLOCK, {rlim_cur=64*1024, rlim_max=64*1024}) = 0

getrlimit(RLIMIT_AS, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_LOCKS, {rlim_cur=RLIM_INFINITY, rlim_max=RLIM_INFINITY}) = 0

getrlimit(RLIMIT_SIGPENDING, {rlim_cur=14046, rlim_max=14046}) = 0

getrlimit(RLIMIT_MSGQUEUE, {rlim_cur=800*1024, rlim_max=800*1024}) = 0

getrlimit(RLIMIT_NICE, {rlim_cur=0, rlim_max=0}) = 0

getrlimit(RLIMIT_RTPRIO, {rlim_cur=0, rlim_max=0}) = 0

getpriority(PRIO_PROCESS, 0)            = 20

open("/etc/security/limits.conf", O_RDONLY|O_LARGEFILE) = 4

fstat64(4, {st_mode=S_IFREG|0644, st_size=1825, ...}) = 0

mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773b000

read(4, "# /etc/security/limits.conf\n#\n#E"..., 4096) = 1825

read(4, "", 4096)                       = 0

close(4)                                = 0

munmap(0xb773b000, 4096)                = 0

open("/etc/security/limits.d", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 4

brk(0x80f7000)                          = 0x80f7000

getdents64(4, /* 3 entries */, 32768)   = 80

getdents64(4, /* 0 entries */, 32768)   = 0

brk(0x80ef000)                          = 0x80ef000

close(4)                                = 0

open("/etc/security/limits.d/tor.conf", O_RDONLY|O_LARGEFILE) = 4

fstat64(4, {st_mode=S_IFREG|0644, st_size=89, ...}) = 0

mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773b000

read(4, "tor           hard    nofile    "..., 4096) = 89

read(4, "", 4096)                       = 0

close(4)                                = 0

munmap(0xb773b000, 4096)                = 0

setpriority(PRIO_PROCESS, 0, 0)         = 0

open("/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 4

fstat64(4, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0

mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773b000

read(4, "#\n# This is the configuration fi"..., 4096) = 2980

read(4, "", 4096)                       = 0

close(4)                                = 0

munmap(0xb773b000, 4096)                = 0

open("/etc/environment", O_RDONLY|O_LARGEFILE) = 4

fstat64(4, {st_mode=S_IFREG|0644, st_size=97, ...}) = 0

mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773b000

read(4, "#\n# This file is parsed by pam_e"..., 4096) = 97

read(4, "", 4096)                       = 0

close(4)                                = 0

munmap(0xb773b000, 4096)                = 0

open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4

_llseek(4, 0, [0], SEEK_CUR)            = 0

fstat64(4, {st_mode=S_IFREG|0644, st_size=3225, ...}) = 0

mmap2(NULL, 3225, PROT_READ, MAP_SHARED, 4, 0) = 0xb773b000

_llseek(4, 3225, [3225], SEEK_SET)      = 0

munmap(0xb773b000, 3225)                = 0

close(4)                                = 0

stat64("/root/.pam_environment", 0xbf9b008c) = -1 ENOENT (No such file or directory)

getuid32()                              = 0

access("/var/run/utmpx", F_OK)          = -1 ENOENT (No such file or directory)

open("/var/run/utmp", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 4

_llseek(4, 0, [0], SEEK_SET)            = 0

alarm(0)                                = 0

rt_sigaction(SIGALRM, {0xb751b8b0, [], 0}, {SIG_DFL, [], SA_INTERRUPT}, 8) = 0

alarm(10)                               = 0

fcntl64(4, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0

read(4, "\10\0\0\0\27 \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\2\0\0\0\0\0\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\10\0\0\0\201\"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\1\0\0\0003N\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\10\0\0\0f%\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\345<\0\0tty1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\346<\0\0tty2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\347<\0\0tty3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\350<\0\0tty4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\351<\0\0tty5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\6\0\0\0\352<\0\0tty6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\7\0\0\0;)\0\0pts/0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\10\0\0\0\312+\0\0pts/1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "\10\0\0\0\350+\0\0pts/2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384

read(4, "", 384)                        = 0

fcntl64(4, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0

alarm(0)                                = 10

rt_sigaction(SIGALRM, {SIG_DFL, [], SA_INTERRUPT}, NULL, 8) = 0

close(4)                                = 0

getuid32()                              = 0

time(NULL)                              = 1285057107

socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4

connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0

send(4, "<86>Sep 21 10:18:27 sshd: pam_un"..., 89, MSG_NOSIGNAL) = 89

open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5

_llseek(5, 0, [0], SEEK_CUR)            = 0

fstat64(5, {st_mode=S_IFREG|0644, st_size=3225, ...}) = 0

mmap2(NULL, 3225, PROT_READ, MAP_SHARED, 5, 0) = 0xb773b000

_llseek(5, 3225, [3225], SEEK_SET)      = 0

munmap(0xb773b000, 3225)                = 0

close(5)                                = 0

socket(PF_FILE, SOCK_STREAM, 0)         = 5

connect(5, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) = 0

fcntl64(5, F_GETFL)                     = 0x2 (flags O_RDWR)

fcntl64(5, F_SETFL, O_RDWR|O_NONBLOCK)  = 0

fcntl64(5, F_GETFD)                     = 0

fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0

geteuid32()                             = 0

poll([{fd=5, events=POLLOUT}], 1, 0)    = 1 ([{fd=5, revents=POLLOUT}])

write(5, "\0", 1)                       = 1

write(5, "AUTH EXTERNAL 30\r\n", 18)    = 18

poll([{fd=5, events=POLLIN}], 1, -1)    = 1 ([{fd=5, revents=POLLIN}])

read(5, "OK bf5a9bbaea42ae7f6e5b015d00000"..., 2048) = 37

poll([{fd=5, events=POLLOUT}], 1, -1)   = 1 ([{fd=5, revents=POLLOUT}])

write(5, "BEGIN\r\n", 7)                = 7

poll([{fd=5, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=5, revents=POLLOUT}])

writev(5, [{"l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}, {"", 0}], 2) = 128

clock_gettime(CLOCK_MONOTONIC, {258330, 757727674}) = 0

poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])

read(5, "l\2\1\1\n\0\0\0\1\0\0\0=\0\0\0\6\1s\0\5\0\0\0:1.12\0\0\0"..., 2048) = 260

read(5, 0x80d02e0, 2048)                = -1 EAGAIN (Resource temporarily unavailable)

writev(5, [{"l\1\0\1\324\0\0\0\2\0\0\0\273\0\0\0\1\1o\0#\0\0\0/org/fre"..., 208}, {"\314\0\0\0\0\0\0\0\t\0\0\0unix-user\0\1i\0\0\0\0\0\0\0\0"..., 212}], 2) = 420

clock_gettime(CLOCK_MONOTONIC, {258330, 760993215}) = 0

poll([{fd=5, events=POLLIN}], 1, 25000

```

Also entweder liegt es an PAM oder an DBUS oder an beiden bzw. der Kombination .. ich konnte jedoch kein Unterschied zu anderen Servern finden, wo es einwandfrei funktioniert.

System:  Linux 2.6.35-gentoo-r5 #1 SMP Tue Sep 14 13:42:31 CEST 2010 i686 

```

emerge --info

Portage 2.1.8.3 (default/linux/x86/10.0, gcc-4.4.3, glibc-2.11.2-r0, 2.6.35-gentoo-r5 i686)

=================================================================

System uname: Linux-2.6.35-gentoo-r5-i686-AMD_Duron-tm-_Processor-with-gentoo-1.12.13

Timestamp of tree: Tue, 21 Sep 2010 01:00:01 +0000

distcc 3.1 i686-pc-linux-gnu [disabled]

ccache version 2.4 [disabled]

app-shells/bash:     4.1_p7

dev-java/java-config: 2.1.11

dev-lang/python:     2.4.6, 2.5.4-r4, 2.6.5-r3, 3.1.2-r4

dev-util/ccache:     2.4-r7

dev-util/cmake:      2.8.1-r2

sys-apps/baselayout: 1.12.13

sys-apps/sandbox:    1.6-r2

sys-devel/autoconf:  2.13, 2.65-r1

sys-devel/automake:  1.4_p6, 1.5, 1.6.3, 1.7.9-r1, 1.8.5-r3, 1.9.6-r2, 1.10.2, 1.11.1

sys-devel/binutils:  2.20.1-r1

sys-devel/gcc:       3.4.6-r2, 4.1.2, 4.3.4, 4.4.3-r2

sys-devel/gcc-config: 1.4.1

sys-devel/libtool:   2.2.10

sys-devel/make:      3.81-r2

virtual/os-headers:  2.6.30-r1

ACCEPT_KEYWORDS="x86"

ACCEPT_LICENSE="*"

CBUILD="i686-pc-linux-gnu"

CFLAGS="-march=athlon-tbird -O2 -pipe -fomit-frame-pointer"

CHOST="i686-pc-linux-gnu"

CONFIG_PROTECT="/etc /usr/lib/fax /var/spool/fax/etc"

CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/env.d/java/ /etc/fonts/fonts.conf /etc/gconf /etc/php/apache2-php5/ext-active/ /etc/php/cgi-php5/ext-active/ /etc/php/cli-php5/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo"

CXXFLAGS="-march=athlon-tbird -O2 -pipe -fomit-frame-pointer"

DISTDIR="/usr/portage/distfiles"

FEATURES="assume-digests distlocks fixpackages news parallel-fetch protect-owned sandbox sfperms strict unmerge-logs unmerge-orphans"

GENTOO_MIRRORS="http://distfiles.gentoo.org"

LC_ALL="de_DE.UTF-8"

LDFLAGS="-Wl,-O1 -Wl,--as-needed"

LINGUAS="de en"

MAKEOPTS="-j3"

PKGDIR="/usr/portage/packages"

PORTAGE_CONFIGROOT="/"

PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages"

PORTAGE_TMPDIR="/var/tmp"

PORTDIR="/usr/portage"

PORTDIR_OVERLAY="/usr/local/portage/layman/hollow /usr/local/portage/layman/php-4 /usr/local/portage"

SYNC="rsync://rsync.gentoo.org/gentoo-portage"

USE="3dnow 3dnowext 7zip acl apache2 audiofile bash-completion berkdb bluetooth bzip2 cli cracklib crypt cups curl cxx dbus dri expat extensions flac fortran gd gdbm gif gmp gpm iconv idn ipv6 jpeg lcms libwww logrotate lua mad mhash mmx mmxext mng modules mudflap mysql ncurses nls nptl nptlonly ogg openmp pam pcre perl php png pppd python qt readline recode reflection samba sdl session slang snmp speex ssl sysfs tcpd tiff truetype udev unicode usb vorbis x86 xinetd xml2 xorg zlib" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1 emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="access auth auth_dbm auth_anon auth_digest alias file-cache echo charset-lite cache disk-cache mem-cache ext-filter case_filter case-filter-in deflate mime-magic cern-meta expires headers usertrack unique-id proxy proxy-connect proxy-ftp proxy-http info include cgi cgid dav dav-fs vhost-alias speling rewrite log_config logio env setenvif mime status autoindex asis negotiation dir imap actions userdir so unique_id filter authz_host auth_basic authn_default auth_basic authn_default authn_file authz_default authz_groupfile authz_host authz_owner authz_user autoindex speling unique_id" APACHE2_MPMS="prefork" ELIBC="glibc" FRITZCAPI_CARDS="fxusb_CZ" INPUT_DEVICES="keyboard mouse" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="de en" RUBY_TARGETS="ruby18" USERLAND="GNU" VIDEO_CARDS="vesa fbdev" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" 

Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, FFLAGS, INSTALL_MASK, LANG, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS

```

Ich habe aktuell noch hpn bei openssh aktiviert, aber geändert hat dies nichts und schaden tut es AFAIK auch nicht.

Hoffe jemand hat einen ultimativen Tip für mich  :Smile: 

RonnyLast edited by rcmc_ronny on Wed Sep 22, 2010 12:28 pm; edited 1 time in total

----------

## Necoro

nur n Raten...:

```
poll([{fd=5, events=POLLIN}], 1, 25000)
```

(fd 5 ist DBus)

Warum benutzt dein openssh überhaupt DBus?

----------

## rcmc_ronny

Hi,

gute Frage ...

Ich sehe nirgendswo das USE-Flag ...

[ebuild   R   ] net-misc/openssh-5.5_p1-r2  USE="hpn pam tcpd -X -X509 -kerberos -ldap -libedit (-selinux) -skey -static" 0 kB

[ebuild   R   ] sys-libs/pam-1.1.1-r2  USE="berkdb cracklib nls -audit -debug (-selinux) -test -vim-syntax" 0 kB

[ebuild   R   ] sys-auth/pambase-20100310  USE="consolekit cracklib sha512 -debug -gnome-keyring -mktemp -passwdqc (-selinux) -ssh" 0 kB

Ich habe DBUS schon seit mehreren Jahren in der make.conf in der USE Variable. Wird DBUS für ein Server System (kein Desktop) benötigt, wenn nein, hau ich das Flag raus und schau ob es was bringt. 

Ronny

----------

## Necoro

consolekit ist das, was DBus benötigt

schau mal, dass du auch das Gentoo-Server-Profil ausgewählt hast -- das schmeißt einige sinnlose Desktop-Flags raus. (Und dbus ist auf nem Server eins davon)

----------

## rcmc_ronny

Hi,

danke für die Hinweise ... ich habe dbus erstmal gestoppt und haue Ihn runter, falls in den nächsten Tagen keine Probleme auftreten.

Scheinbar versucht consolekit den DBUS zu nutzen, wenn er gestartet ist, was die Verzögerung hervorruft.

In dem Zug habe ich dann auch gleich die USE Flags nochmal optimiert.

Aktuell geht der Login nun wieder so fix wie es sein soll  :Smile: 

Ronny

----------

## Necoro

 *rcmc_ronny wrote:*   

> Scheinbar versucht consolekit den DBUS zu nutzen, wenn er gestartet ist, was die Verzögerung hervorruft.

 

Uh - wenn ich das richtig sehe, IST consolekit ein DBus-Dienst. Also ohne DBus funktioniert der erst gar nicht ^^. Also vllt auch gleich consolekit runterschmeißen, wenn du es nicht brauchst.

----------

## rcmc_ronny

Hoi,

danke, consolekit brauch ich nicht und ist bereits entfernt, für die Entfernung von dbus ist auch alles vorbereitet.

Damit ist mein Problem gelöst  :Smile: 

Danke Dir für die Hilfe  :Smile: 

Ronny

----------

