timeout problem in ssh sessions

[Andy Spiegl <zsh.Andy@xxxxxxxxx>]

Hi,

every second time or so when I exit zsh in a ssh-session the connection
doesn't close for a very long time (several minutes).  I usually press Ctrl-C then.
I can't figure out what's causing this, but after looking at a strace
output I suspect it's a ssh problem, maybe connected with some zsh feature.
What's confusing me especially is that it doesn't happen every time.

Is anyone experiencing this, too?

To illustrate my problem I'll post the (commented) strace output after
running "ssh root@localhost" and then attaching strace to the running
ssh process:

 condor:~#strace -f -p 12280      
 Process 12280 attached - interrupt to quit
 select(13, [3 4 6 7 9], [], NULL, {4, 608000}) = 0 (Timeout)
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 select(13, [3 4 6 7 9], [3], NULL, {10, 0}) = 1 (out [3], left {10, 0})
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
...

Then I pressed Ctrl-D and got this:
 access("/var/log/wtmpx", F_OK)          = -1 ENOENT (No such file or directory)
 open("/var/log/wtmp", O_WRONLY|O_LARGEFILE) = 8
 alarm(0)                                = 0
 rt_sigaction(SIGALRM, {0xb7c5d590, [], 0}, {SIG_DFL}, 8) = 0
 alarm(1)                                = 0
 fcntl64(8, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
 _llseek(8, 0, [15793920], SEEK_END)     = 0
 write(8, "\10\0\0\0\370/\0\0pts/18\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
 fcntl64(8, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
 alarm(0)                                = 1
 rt_sigaction(SIGALRM, {SIG_DFL}, NULL, 8) = 0
 close(8)                                = 0
 getuid32()                              = 0
 chown32("/dev/pts/18", 0, 0)            = 0
 chmod("/dev/pts/18", 0666)              = 0
 close(10)                               = 0
 waitpid(-1, 0xbf80abe8, WNOHANG)        = -1 ECHILD (No child processes)
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 select(13, [3 4 6 7 11], [3], NULL, {10, 0}) = 2 (in [4], out [3], left {10, 0})
 read(4, "\0", 1)                        = 1
 read(4, 0xbf80abeb, 1)                  = -1 EAGAIN (Resource temporarily unavailable)
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 write(3, "#\252\33b\203\275\33D\1W%`9\223b\315\242u0O\204]\270\265"..., 96) = 96
 select(13, [3 4 6 7 11], [], NULL, {10, 0}) = 1 (in [3], left {10, 0})
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 read(3, "@v\225\241\274 \240\25\213\262\233\373V&\222;\36)7\331"..., 16384) = 32
 shutdown(6, 2 /* send and receive */)   = 0
 close(6)                                = 0
 close(6)                                = -1 EBADF (Bad file descriptor)
 close(6)                                = -1 EBADF (Bad file descriptor)
 select(13, [3 4 7 11], [], NULL, {10, 0}

In this line it hangs for about 5 seconds, then:

                                         ) = 0 (Timeout)
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 select(13, [3 4 7 11], [3], NULL, {10, 0}) = 1 (out [3], left {10, 0})
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 write(3, "u\33\n\206\257 \6QV\233\'\333\t\3501)}\240F\241p>\361%"..., 64) = 64
 select(13, [3 4 7 11], [], NULL, {10, 0}) = 1 (in [3], left {10, 0})
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 read(3, "\32c\202\374\305\244T\4^(\331\205!\200A\226\34\215\253"..., 16384) = 32
 select(13, [3 4 7 11], [], NULL, {10, 0}

and it hangs again.  When I press Ctrl-C this happens:

           ) = 1 (in [3], left {4, 776000})
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 read(3, "", 16384)                      = 0
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 shutdown(7, 2 /* send and receive */)   = 0
 close(7)                                = 0
 close(7)                                = -1 EBADF (Bad file descriptor)
 close(7)                                = -1 EBADF (Bad file descriptor)
 shutdown(11, 2 /* send and receive */)  = 0
 close(11)                               = 0
 close(11)                               = -1 EBADF (Bad file descriptor)
 close(11)                               = -1 EBADF (Bad file descriptor)
 open("/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 6
 fstat64(6, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0
 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f93000
 read(6, "#\n# This is the configuration fi"..., 4096) = 2980
 read(6, "", 4096)                       = 0
 close(6)                                = 0
 munmap(0xb7f93000, 4096)                = 0
 open("/etc/environment", O_RDONLY|O_LARGEFILE) = 6
 fstat64(6, {st_mode=S_IFREG|0644, st_size=18, ...}) = 0
 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f93000
 read(6, "\n#LANG=de_DE@euro\n", 4096)   = 18
 read(6, "", 4096)                       = 0
 close(6)                                = 0
 munmap(0xb7f93000, 4096)                = 0
 open("/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 6
 fstat64(6, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0
 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f93000
 read(6, "#\n# This is the configuration fi"..., 4096) = 2980
 read(6, "", 4096)                       = 0
 close(6)                                = 0
 munmap(0xb7f93000, 4096)                = 0
 open("/etc/default/locale", O_RDONLY|O_LARGEFILE) = 6
 fstat64(6, {st_mode=S_IFREG|0644, st_size=51, ...}) = 0
 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f93000
 read(6, "#  File generated by update-loca"..., 4096) = 51
 read(6, "", 4096)                       = 0
 close(6)                                = 0
 munmap(0xb7f93000, 4096)                = 0
 munmap(0xb7f7f000, 13156)               = 0
 munmap(0xb79cf000, 95396)               = 0
 munmap(0xb7f7d000, 7228)                = 0
 munmap(0xb7f7b000, 6676)                = 0
 munmap(0xb7f78000, 10776)               = 0
 munmap(0xb7f74000, 15120)               = 0
 geteuid32()                             = 0
 getegid32()                             = 0
 getgroups32(0, [])                      = 0
 setgroups32(1, [0])                     = 0
 setresgid32(-1, 0, -1)                  = 0
 setresuid32(-1, 0, -1)                  = 0
 unlink("/tmp/ssh-VHJOx12280/agent.12280") = 0
 rmdir("/tmp/ssh-VHJOx12280")            = 0
 setresuid32(-1, 0, -1)                  = 0
 setresgid32(-1, 0, -1)                  = 0
 setgroups32(0, [])                      = 0
 shutdown(3, 2 /* send and receive */)   = 0
 close(3)                                = 0
 brk(0x800a1000)                         = 0x800a1000
 exit_group(0)                           = ?
 Process 12280 detached

I also attached strace to the zsh process but after my Ctrl-D it terminates
right away with this output:
...
  [pid 12311] stat64("/etc/zsh/zlogout.zwc", 0xbff77b60) = -1 ENOENT (No such file or directory)
 [pid 12311] stat64("/etc/zsh/zlogout", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0
 [pid 12311] open("/etc/zsh/zlogout", O_RDONLY|O_NOCTTY|O_LARGEFILE) = 3
 [pid 12311] fcntl64(3, F_DUPFD, 10)     = 11
 [pid 12311] close(3)                    = 0
 [pid 12311] fcntl64(11, F_GETFL)        = 0x8000 (flags O_RDONLY|O_LARGEFILE)
 [pid 12311] fstat64(11, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0
 [pid 12311] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fba000
 [pid 12311] _llseek(11, 0, [0], SEEK_CUR) = 0
 [pid 12311] rt_sigaction(SIGINT, {0x80a7400, [], SA_INTERRUPT}, NULL, 8) = 0
 [pid 12311] read(11, "# /etc/zsh/zlogout: system-wide "..., 4096) = 58
 [pid 12311] rt_sigaction(SIGINT, {0x80a7400, [], SA_INTERRUPT}, NULL, 8) = 0
 [pid 12311] read(11, "", 4096)          = 0
 [pid 12311] close(11)                   = 0
 [pid 12311] munmap(0xb7fba000, 4096)    = 0
 [pid 12311] exit_group(0)               = ?
 Process 12311 detached


I hope this is not too off-topic,
 Andy.

-- 
 "Linux is like a Wigwam: No Gates, no Windows, Apache inside."
                                      (Unknown)