Fedora Users — Re: xinetd delays in in.rshd responses (cluster problem, long)

Here's a strace from both sides of the connection -- server first, thenclient.


I appreciate all of your help so far, this is proving to be very productive.

-Tim

=============== STRACE OFF SERVER XINETD ===============
[15:23:54 - root@xxx:~]strace -T -ttt -p 24001
Process 24001 attached - interrupt to quit

1131578642.371074 select(11, [3 5 6 8 9 10], NULL, NULL, NULL) = 1 (in [9])<0.309762>1131578642.680997 accept(9, {sa_family=AF_INET, sin_port=htons(1023),sin_addr=inet_addr("192.168.101.2")}, [16]) = 11 <0.000045>

1131578642.681189 time(NULL)            = 1131578642 <0.000036>

1131578642.681296 clone(child_stack=0,flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,child_tidptr=0xb7d5a708) = 18935 <0.000554>

1131578642.681935 time([1131578642])    = 1131578642 <0.000033>
1131578642.682073 time([1131578642])    = 1131578642 <0.000095>

1131578642.682247 stat64("/etc/localtime", {st_mode=S_IFREG|0644,st_size=1017, ...}) = 0 <0.000037>1131578642.682408 stat64("/etc/localtime", {st_mode=S_IFREG|0644,st_size=1017, ...}) = 0 <0.000035>1131578642.682540 stat64("/etc/localtime", {st_mode=S_IFREG|0644,st_size=1017, ...}) = 0 <0.000035>1131578642.682682 send(7, "<86>Nov 9 15:24:02 xinetd[24001"..., 76,MSG_NOSIGNAL) = 76 <0.000039>

1131578642.682864 close(11)             = 0 <0.000034>

1131578642.682950 select(11, [3 5 6 8 9 10], NULL, NULL, NULL) = ?ERESTARTNOHAND (To be restarted) <1.209783>

1131578643.892837 --- SIGCHLD (Child exited) @ 0 (0) ---
1131578643.892905 write(4, "\21", 1)    = 1 <0.000038>
1131578643.893010 sigreturn()           = ? (mask now []) <0.000033>

1131578643.893146 select(11, [3 5 6 8 9 10], NULL, NULL, NULL) = 1 (in [3])<0.000038>

1131578643.893257 ioctl(3, FIONREAD, [1]) = 0 <0.000036>
1131578643.893354 read(3, "\21", 1)     = 1 <0.000046>

1131578643.893457 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}],WNOHANG) = 18935 <0.000057>1131578643.893575 close(-1) = -1 EBADF (Bad file descriptor)<0.000042>1131578643.893675 waitpid(-1, 0xbff04aa8, WNOHANG) = -1 ECHILD (No childprocesses) <0.000034>1131578643.893774 select(11, [3 5 6 8 9 10], NULL, NULL, NULL <unfinished...>

Process 24001 detached
================= END SERVER STRACE ====================

================= START CLIENT STRACE ===================
[15:23:55 - root@node2:~]strace -ttt -f rsh master uname -a

1131578641.494993 execve("/usr/bin/rsh", ["rsh", "master", "uname", "-a"],[/* 20 vars */]) = 0

1131578641.495364 brk(0)                = 0x80003000

1131578641.495429 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4b0001131578641.495504 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No suchfile or directory)

1131578641.495577 open("/etc/ld.so.cache", O_RDONLY) = 3
1131578641.495620 fstat64(3, {st_mode=S_IFREG|0644, st_size=57813, ...}) = 0

1131578641.495709 old_mmap(NULL, 57813, PROT_READ, MAP_PRIVATE, 3, 0) =0xb7f3c000

1131578641.495761 close(3)              = 0
1131578641.495810 open("/lib/libcrypt.so.1", O_RDONLY) = 3

1131578641.495857 read(3,"\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\7H"..., 512) = 512

1131578641.495915 fstat64(3, {st_mode=S_IFREG|0755, st_size=27660, ...}) = 0

1131578641.496184 close(3)              = 0
1131578641.496229 open("/lib/libutil.so.1", O_RDONLY) = 3

1131578641.496273 read(3,"\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260|\310"..., 512) = 512

1131578641.496328 fstat64(3, {st_mode=S_IFREG|0755, st_size=15080, ...}) = 0

1131578641.496531 close(3)              = 0
1131578641.496571 open("/lib/libc.so.6", O_RDONLY) = 3

1131578641.496613 read(3,"\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\n_B\000"..., 512) = 5121131578641.496668 fstat64(3, {st_mode=S_IFREG|0755, st_size=1489572, ...}) =01131578641.496742 old_mmap(NULL, 1219548, PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7de00001131578641.496800 old_mmap(0xb7f04000, 16384, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x124000) = 0xb7f040001131578641.496870 old_mmap(0xb7f08000, 7132, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f08000

1131578641.496934 close(3)              = 0

1131578641.496986 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ddf0001131578641.497049 set_thread_area({entry_number:-1 -> 6,base_addr:0xb7ddf9e0, limit:1048575, seg_32bit:1, contents:0,read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0

1131578641.497205 mprotect(0xb7f04000, 8192, PROT_READ) = 0
1131578641.497247 mprotect(0xb7f0c000, 4096, PROT_READ) = 0
1131578641.497285 mprotect(0xb7f13000, 4096, PROT_READ) = 0
1131578641.497332 mprotect(0x409000, 4096, PROT_READ) = 0
1131578641.497368 munmap(0xb7f3c000, 57813) = 0
1131578641.497447 getuid32()            = 0
1131578641.497523 brk(0)                = 0x80003000
1131578641.497555 brk(0x80024000)       = 0x80024000
1131578641.497611 socket(PF_FILE, SOCK_STREAM, 0) = 3
1131578641.497652 fcntl64(3, F_GETFL)   = 0x2 (flags O_RDWR)
1131578641.497688 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0

1131578641.497729 connect(3, {sa_family=AF_FILE,path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

1131578641.497811 close(3)              = 0
1131578641.497856 socket(PF_FILE, SOCK_STREAM, 0) = 3
1131578641.497891 fcntl64(3, F_GETFL)   = 0x2 (flags O_RDWR)
1131578641.497926 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0

1131578641.497966 connect(3, {sa_family=AF_FILE,path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

1131578641.498043 close(3)              = 0
1131578641.498091 open("/etc/nsswitch.conf", O_RDONLY) = 3
1131578641.498143 fstat64(3, {st_mode=S_IFREG|0644, st_size=1698, ...}) = 0

1131578641.498220 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4a0001131578641.498264 read(3, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) =1698

1131578641.498345 read(3, "", 4096)     = 0
1131578641.498381 close(3)              = 0
1131578641.498413 munmap(0xb7f4a000, 4096) = 0
1131578641.498466 open("/etc/ld.so.cache", O_RDONLY) = 3
1131578641.498509 fstat64(3, {st_mode=S_IFREG|0644, st_size=57813, ...}) = 0

1131578641.498580 old_mmap(NULL, 57813, PROT_READ, MAP_PRIVATE, 3, 0) =0xb7f3c000

1131578641.498639 close(3)              = 0
1131578641.498686 open("/lib/libnss_files.so.2", O_RDONLY) = 3

1131578641.498733 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\33\0\000"..., 512) = 512

1131578641.498789 fstat64(3, {st_mode=S_IFREG|0755, st_size=46552, ...}) = 0

1131578641.498994 close(3)              = 0
1131578641.499041 mprotect(0xb7ddd000, 4096, PROT_READ) = 0
1131578641.499080 munmap(0xb7f3c000, 57813) = 0
1131578641.499126 open("/etc/passwd", O_RDONLY) = 3
1131578641.499173 fcntl64(3, F_GETFD)   = 0
1131578641.499207 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
1131578641.499242 fstat64(3, {st_mode=S_IFREG|0644, st_size=2064, ...}) = 0

1131578641.499316 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4a0001131578641.499354 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) =2064

1131578641.499424 close(3)              = 0
1131578641.499458 munmap(0xb7f4a000, 4096) = 0
1131578641.499515 open("/etc/services", O_RDONLY) = 3
1131578641.499559 fcntl64(3, F_GETFD)   = 0
1131578641.499593 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
1131578641.499627 fstat64(3, {st_mode=S_IFREG|0644, st_size=20385, ...}) = 0

1131578641.499699 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4a0001131578641.499736 read(3, "# /etc/services:\n# $Id: services"..., 4096) =40961131578641.499843 read(3, "otocol\nntp\t\t123/tcp\nntp\t\t123/udp"..., 4096)= 40961131578641.499943 read(3, "67/udp\nrsync\t\t873/tcp\t\t\t\t# rsync"...,4096) = 4096

1131578641.499998 close(3)              = 0
1131578641.500030 munmap(0xb7f4a000, 4096) = 0
1131578641.500072 getpid()              = 16041
1131578641.500136 gettimeofday({1131578641, 500148}, NULL) = 0
1131578641.500177 open("/etc/resolv.conf", O_RDONLY) = 3
1131578641.500221 fstat64(3, {st_mode=S_IFREG|0644, st_size=68, ...}) = 0

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

1131578641.500329 read(3, "search accentopto.com\nnameserver"..., 4096) = 68
1131578641.500384 read(3, "", 4096)     = 0
1131578641.500418 close(3)              = 0
1131578641.500452 munmap(0xb7f4a000, 4096) = 0
1131578641.500497 socket(PF_FILE, SOCK_STREAM, 0) = 3
1131578641.500537 fcntl64(3, F_GETFL)   = 0x2 (flags O_RDWR)
1131578641.500573 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0

1131578641.500613 connect(3, {sa_family=AF_FILE,path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

1131578641.500692 close(3)              = 0
1131578641.500731 socket(PF_FILE, SOCK_STREAM, 0) = 3
1131578641.500768 fcntl64(3, F_GETFL)   = 0x2 (flags O_RDWR)
1131578641.500803 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0

1131578641.500843 connect(3, {sa_family=AF_FILE,path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

1131578641.500925 close(3)              = 0
1131578641.500965 open("/etc/host.conf", O_RDONLY) = 3
1131578641.501010 fstat64(3, {st_mode=S_IFREG|0644, st_size=17, ...}) = 0

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

1131578641.501118 read(3, "order hosts,bind\n", 4096) = 17
1131578641.501169 read(3, "", 4096)     = 0
1131578641.501203 close(3)              = 0
1131578641.501236 munmap(0xb7f4a000, 4096) = 0
1131578641.501273 open("/etc/hosts", O_RDONLY) = 3
1131578641.501314 fcntl64(3, F_GETFD)   = 0
1131578641.501348 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
1131578641.501388 fstat64(3, {st_mode=S_IFREG|0644, st_size=1683, ...}) = 0

1131578641.501459 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4a0001131578641.501496 read(3, "# Do not remove the following li"..., 4096) =1683

1131578641.501556 close(3)              = 0
1131578641.501590 munmap(0xb7f4a000, 4096) = 0
1131578641.501633 open("/etc/hosts", O_RDONLY) = 3
1131578641.501675 fcntl64(3, F_GETFD)   = 0
1131578641.501708 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
1131578641.501741 fstat64(3, {st_mode=S_IFREG|0644, st_size=1683, ...}) = 0

1131578641.501814 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4a0001131578641.501851 read(3, "# Do not remove the following li"..., 4096) =1683

1131578641.501904 close(3)              = 0
1131578641.501938 munmap(0xb7f4a000, 4096) = 0
1131578641.501978 rt_sigprocmask(SIG_BLOCK, [URG], [], 8) = 0
1131578641.502031 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3

1131578641.502075 bind(3, {sa_family=AF_INET, sin_port=htons(1023),sin_addr=inet_addr("0.0.0.0")}, 16) = 0

1131578641.502126 fcntl64(3, F_SETOWN, 16041) = 0

1131578641.502164 connect(3, {sa_family=AF_INET, sin_port=htons(514),sin_addr=inet_addr("192.168.101.1")}, 16) = 0

1131578641.502454 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 4

1131578641.502529 bind(4, {sa_family=AF_INET, sin_port=htons(1022),sin_addr=inet_addr("0.0.0.0")}, 16) = 0

1131578641.502597 listen(4, 1)          = 0
1131578641.502660 write(3, "1022\0", 5) = 5

1131578641.502725 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN,revents=POLLIN}], 2, -1) = 11131578641.505699 accept(4, {sa_family=AF_INET, sin_port=htons(1022),sin_addr=inet_addr("192.168.101.1")}, [16]) = 5

1131578641.505813 close(4)              = 0

1131578641.505870 writev(3, [{"root\0", 5}, {"root\0", 5}, {"uname -a\0",9}], 3) = 19

1131578641.505963 read(3, "\0", 1)      = 1
1131578642.493984 rt_sigprocmask(SIG_SETMASK, [], [URG], 8) = 0
1131578642.494064 setuid32(0)           = 0
1131578642.494113 rt_sigprocmask(SIG_BLOCK, [INT QUIT TERM], [], 8) = 0
1131578642.494174 rt_sigaction(SIGINT, {SIG_IGN}, {SIG_DFL}, 8) = 0

1131578642.494239 rt_sigaction(SIGINT, {0x80000cf4, [INT], SA_RESTART},{SIG_IGN}, 8) = 0

1131578642.494305 rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0

1131578642.494365 rt_sigaction(SIGQUIT, {0x80000cf4, [QUIT], SA_RESTART},{SIG_IGN}, 8) = 0

1131578642.494431 rt_sigaction(SIGTERM, {SIG_IGN}, {SIG_DFL}, 8) = 0

1131578642.494491 rt_sigaction(SIGTERM, {0x80000cf4, [TERM], SA_RESTART},{SIG_IGN}, 8) = 0

1131578642.494561 clone(Process 16042 attached

child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,child_tidptr=0xb7ddfa28) = 16042

[pid 16041] 1131578642.494784 ioctl(5, FIONBIO, [1]) = 0
[pid 16041] 1131578642.494844 ioctl(3, FIONBIO, [1]) = 0

[pid 16041] 1131578642.494903 rt_sigprocmask(SIG_SETMASK, [], [INT QUITTERM], 8) = 0[pid 16041] 1131578642.494965 select(6, [3 5], NULL, NULL, NULL <unfinished...>

[pid 16042] 1131578642.495036 ioctl(5, FIONBIO, [1]) = 0
[pid 16042] 1131578642.495085 ioctl(3, FIONBIO, [1]) = 0
[pid 16042] 1131578642.495138 close(5)  = 0
[pid 16042] 1131578642.495190 read(0,  <unfinished ...>
[pid 16041] 1131578642.507190 <... select resumed> ) = 1 (in [3])

[pid 16041] 1131578642.507233 read(3, "Linux xxx.xxx.com 2.6.1"..., 8192) =101[pid 16041] 1131578642.507315 write(1, "Linux xxx.xxx.com 2.6.1"...,101Linux xxx.xxx.com 2.6.13web100 #1 SMP Fri Oct 28 09:58:58 PDT 2005 i686i686 i386 GNU/Linux

) = 101

[pid 16041] 1131578642.507385 select(6, [3 5], NULL, NULL, NULL) = 2 (in [35])

[pid 16041] 1131578642.507441 read(5, "", 8192) = 0
[pid 16041] 1131578642.507497 read(3, "", 8192) = 0
[pid 16041] 1131578642.507554 kill(16042, SIGKILL) = 0
[pid 16041] 1131578642.507645 exit_group(0) = ?

1131578642.507739 <... read resumed> 0xbf849480, 8192) = ? ERESTARTSYS (Tobe restarted)

1131578642.507834 +++ killed by SIGKILL +++
====================== END CLIENT STRACE ================

----- Original Message -----From: "Les Mikesell" <lesmikesell@xxxxxxxxx>

If it is practical, strace xinetd through accepting a connection
(with -f to see if your rsh is doing any checks of its own
after the connection is up).

--
  Les Mikesell
   lesmikesell@xxxxxxxxx