really odd 0.45 startup behavior

Paul Fox pgf at brightstareng.com
Fri Apr 22 07:02:32 WST 2005


has anyone else seen this?  we recently switched from 0.43 to 0.45
on an embedded PPC platform.  call that platform "ppc"

if during the first couple of minutes after boot, an scp is done to copy
a file off of the embedded device, performance is very slow.  i.e.,
this command executed from a different host:
    scp root at ppc:/bin/busybox /tmp
will take upwards of 30 seconds to complete, but only for the first
couple of minutes of uptime.  after that, it runs very quickly.

i know, this doesn't sound like a dropbear problem, except that
    a) release 0.43 doesn't show this behavior, and
    b) if i strace the 0.45 dropbear server while this is happening,
     i see the following suspicious behavior -- continuous
     writes of 0 bytes from a null buffer.  this can't be right.

i'll excerpt the "interesting" parts of the strace below.  this was obtained
with:  
    strace -tt -f -o /tmp/st -p $(pidof dropbear)
before the client had started.  during the long periods of odd
write() calls, there is no extraneous network traffic going on.
i confess i'm at a loss as to what might change a minute or two
after the box boots which makes this problem go away.  hmmm --
i take that back -- i just straced a "successful" run.  the
bad writes are still happening, but the long delays aren't there.
so there may be too problems.  i'll look into the long delays
separately.

i spent some time trying to turn on TRACE(), but either the tracing
fd gets closed during all the duping/forking, or i didn't try hard
enough, because i didn't get all that much output...

paul
=---------------------
 paul fox, pgf at brightstareng.com

783   22:16:22.928481 --- SIGSTOP (Stopped (signal)) ---
783   22:16:22.963743 _newselect(0x8, 0x7ffffa98, 0, 0, 0x7ffffbd0) = 1
783   22:16:24.083301 accept(4, {sin_family=AF_INET, sin_port=htons(38831), sin_addr=inet_addr("192.168.1.24")}}, [16]) = 5
783   22:16:24.084002 pipe([6, 8])      = 0
783   22:16:24.084680 fork()            = 1111
783   22:16:24.086040 close(8 <unfinished ...>
1111  22:16:24.087285 time( <unfinished ...>
783   22:16:24.087529 <... close resumed> ) = 0
1111  22:16:24.087710 <... time resumed> [6560184]) = 6560184
783   22:16:24.087948 close(5 <unfinished ...>
1111  22:16:24.088240 getpid( <unfinished ...>
783   22:16:24.088414 <... close resumed> ) = 0
1111  22:16:24.088583 <... getpid resumed> ) = 1111
783   22:16:24.088769 _newselect(0x8, 0x7ffffa98, 0, 0, 0x7ffffbd0 <unfinished ...>
1111  22:16:24.089039 rt_sigaction(SIGPIPE, {0xff170d4, [], 0}, {SIG_IGN}, 8) = 0
1111  22:16:24.089622 send(3, "<86>Mar 17 22:16:24 dropbear[111"..., 76, 0) = 76
1111  22:16:24.090301 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
1111  22:16:24.090684 setsid()          = 1111
1111  22:16:24.091026 close(4)          = 0
1111  22:16:24.091293 close(6)          = 0
1111  22:16:24.091772 gettimeofday({6560184, 91896}, NULL) = 0
1111  22:16:24.092185 brk(0x10032000)   = 0x10032000
1111  22:16:24.092954 brk(0x10033000)   = 0x10033000
1111  22:16:24.093504 rt_sigaction(SIGCHLD, {0x1000ba20, [ABRT KILL SEGV ALRM CHLD CONT IO 35], SA_NOCLDSTOP}, NULL, 8) = 0
1111  22:16:24.093989 gettimeofday({6560184, 94102}, NULL) = 0
1111  22:16:24.094342 write(5, "SSH-2.0-dropbear_0.45\r\n", 23) = 23
1111  22:16:24.094955 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.095595 gettimeofday({6560184, 95711}, NULL) = 0
1111  22:16:24.095905 read(5, "S", 1)   = 1
1111  22:16:24.096495 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.096836 gettimeofday({6560184, 96945}, NULL) = 0
1111  22:16:24.097134 read(5, "S", 1)   = 1
1111  22:16:24.097514 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.097845 gettimeofday({6560184, 97954}, NULL) = 0
1111  22:16:24.098142 read(5, "H", 1)   = 1
1111  22:16:24.098480 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.098849 gettimeofday({6560184, 98962}, NULL) = 0
1111  22:16:24.099150 read(5, "-", 1)   = 1
1111  22:16:24.099486 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.099815 gettimeofday({6560184, 99924}, NULL) = 0
1111  22:16:24.100153 read(5, "2", 1)   = 1
1111  22:16:24.100493 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.100818 gettimeofday({6560184, 100926}, NULL) = 0
1111  22:16:24.101114 read(5, ".", 1)   = 1
1111  22:16:24.101492 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.101821 gettimeofday({6560184, 101930}, NULL) = 0
1111  22:16:24.102117 read(5, "0", 1)   = 1
1111  22:16:24.102452 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.102866 gettimeofday({6560184, 102981}, NULL) = 0
1111  22:16:24.103168 read(5, "-", 1)   = 1
1111  22:16:24.103505 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.103830 gettimeofday({6560184, 103938}, NULL) = 0
1111  22:16:24.104169 read(5, "O", 1)   = 1
1111  22:16:24.104507 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.104832 gettimeofday({6560184, 104940}, NULL) = 0
1111  22:16:24.105128 read(5, "p", 1)   = 1
1111  22:16:24.105502 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.105832 gettimeofday({6560184, 105940}, NULL) = 0
1111  22:16:24.106127 read(5, "e", 1)   = 1
1111  22:16:24.106463 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.106834 gettimeofday({6560184, 106946}, NULL) = 0
1111  22:16:24.107133 read(5, "n", 1)   = 1
1111  22:16:24.107469 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.107797 gettimeofday({6560184, 107905}, NULL) = 0
1111  22:16:24.108135 read(5, "S", 1)   = 1
1111  22:16:24.108475 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.108801 gettimeofday({6560184, 108909}, NULL) = 0
1111  22:16:24.109097 read(5, "S", 1)   = 1
1111  22:16:24.109525 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.109854 gettimeofday({6560184, 109963}, NULL) = 0
1111  22:16:24.110152 read(5, "H", 1)   = 1
1111  22:16:24.110487 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.110851 gettimeofday({6560184, 110962}, NULL) = 0
1111  22:16:24.111149 read(5, "_", 1)   = 1
1111  22:16:24.111484 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.111805 gettimeofday({6560184, 111913}, NULL) = 0
1111  22:16:24.112143 read(5, "3", 1)   = 1
1111  22:16:24.112484 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.112805 gettimeofday({6560184, 112913}, NULL) = 0
1111  22:16:24.113102 read(5, ".", 1)   = 1
1111  22:16:24.113514 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.113842 gettimeofday({6560184, 113949}, NULL) = 0
1111  22:16:24.114137 read(5, "5", 1)   = 1
1111  22:16:24.114473 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.114837 gettimeofday({6560184, 114948}, NULL) = 0
1111  22:16:24.115135 read(5, "p", 1)   = 1
1111  22:16:24.115470 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.115791 gettimeofday({6560184, 115899}, NULL) = 0
1111  22:16:24.116129 read(5, "1", 1)   = 1
1111  22:16:24.116468 _newselect(0x6, 0x7ffff890, 0, 0, 0x7ffff910) = 1
1111  22:16:24.116789 gettimeofday({6560184, 116897}, NULL) = 0
1111  22:16:24.117084 read(5, "\n", 1)  = 1
1111  22:16:24.117501 open("/dev/random", O_RDONLY) = 4
1111  22:16:24.118100 read(4, "\232\231\234s3\346\254\270\243\364Z", 32) = 11
1111  22:16:24.118574 read(4, "\17\206\342\200\360K\346", 21) = 7
1111  22:16:24.119055 read(4, "\222\347_", 14) = 3
1111  22:16:24.119464 read(4, "Y", 11)  = 1
1111  22:16:25.924485 read(4, "\355", 10) = 1
1111  22:16:25.924945 read(4, "\17", 9) = 1
1111  22:16:26.924050 read(4, "\201", 8) = 1
1111  22:16:26.924415 read(4, "\346", 7) = 1
1111  22:16:26.924767 read(4, "\377", 6) = 1
1111  22:16:26.925217 read(4, "\231", 5) = 1
1111  22:16:28.484131 read(4, "g", 4)   = 1
1111  22:16:28.484486 read(4, "2", 3)   = 1
1111  22:16:28.484826 read(4, "\256", 2) = 1
1111  22:16:28.485275 read(4, "!", 1)   = 1
1111  22:16:29.754249 close(4)          = 0
1111  22:16:29.755556 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 2
1111  22:16:29.755922 gettimeofday({6560189, 756030}, NULL) = 0
1111  22:16:29.756228 write(5, "\0\0\0\224\n\24i\27\21\225\325bi(\2131\37G\16\240B&\0\0"..., 152) = 152
1111  22:16:29.756882 read(5, "\0\0\2\34\t\24\36\226", 8) = 8
1111  22:16:29.757348 read(5, "\24k|\6\310\243\5\302\24_f<|\201\0\0\0=diffie-hellman"..., 536) = 536
1111  22:16:29.757872 brk(0x10034000)   = 0x10034000
1111  22:16:29.758511 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:29.774248 gettimeofday({6560189, 774365}, NULL) = 0
1111  22:16:29.774596 read(5, "\0\0\0\214\6\36\0\0", 8) = 8
1111  22:16:29.775006 read(5, "\0\200q\4m\246z=\316/\232\250\340\323X7\315\357\263\201"..., 136) = 136
1111  22:16:29.776048 brk(0x10035000)   = 0x10035000
1111  22:16:29.776541 brk(0x10036000)   = 0x10036000
1111  22:16:29.777691 brk(0x10037000)   = 0x10037000
1111  22:16:29.779257 brk(0x10038000)   = 0x10038000
1111  22:16:29.780657 brk(0x10039000)   = 0x10039000
1111  22:16:29.782329 brk(0x1003a000)   = 0x1003a000
1111  22:16:29.910572 brk(0x1003b000)   = 0x1003b000
1111  22:16:30.065094 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.065502 gettimeofday({6560190, 65611}, NULL) = 0
1111  22:16:30.065809 write(5, "\0\0\2|\5\37\0\0\1\261\0\0\0\7ssh-dss\0\0\0\201\0\350\17"..., 640) = 640
1111  22:16:30.066502 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.066849 gettimeofday({6560190, 66958}, NULL) = 0
1111  22:16:30.067154 write(5, "\0\0\0\f\n\25\323\300\345\224\211\235<\32\331\23", 16) = 16
1111  22:16:30.067690 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.084124 gettimeofday({6560190, 84423}, NULL) = 0
1111  22:16:30.084684 read(5, "\0\0\0\f\n\25\0\0", 8) = 8
1111  22:16:30.085129 read(5, "\0\0\0\0\0\0\0\0", 8) = 8
1111  22:16:30.087066 gettimeofday({6560190, 87198}, NULL) = 0
1111  22:16:30.087421 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.087800 gettimeofday({6560190, 87915}, NULL) = 0
1111  22:16:30.088143 read(5, "A\344f\342\310\364|\324", 8) = 8
1111  22:16:30.088599 read(5, "\232\341\37\\\205\317\347\322\25\353\361\203\331M\216\t"..., 44) = 44
1111  22:16:30.090052 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.090460 gettimeofday({6560190, 90576}, NULL) = 0
1111  22:16:30.090775 write(5, "\330\252\334F;@\275\243c,\262Q\233[~\335\313\313\201\37"..., 52) = 52
1111  22:16:30.091351 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.093377 gettimeofday({6560190, 93493}, NULL) = 0
1111  22:16:30.093720 read(5, "\304\370{\352\250v\343\241", 8) = 8
1111  22:16:30.094173 read(5, "\364$\375\0005\363q\\J\240\277\320\330As\330\242[N\334"..., 60) = 60
1111  22:16:30.095664 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.096073 gettimeofday({6560190, 96182}, NULL) = 0
1111  22:16:30.096381 write(5, "\266\r\3305h\0\332q\34\241\4-\v\313#naa\377\fY7\32\17\371"..., 60) = 60
1111  22:16:30.096960 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.104021 gettimeofday({6560190, 104137}, NULL) = 0
1111  22:16:30.104364 read(5, "\374`86\230\3554\16", 8) = 8
1111  22:16:30.104813 read(5, ")E\\IS\267\10^\vcy\217\330@\20\370\207\347si\"I\10\364"..., 516) = 516
1111  22:16:30.106283 socket(PF_UNIX, SOCK_STREAM, 0) = 4
1111  22:16:30.106759 connect(4, {sin_family=AF_UNIX, path="/var/run/.nscd_socket"}, 110) = -1 ENOENT (No such file or directory)
1111  22:16:30.107256 close(4)          = 0
1111  22:16:30.107660 open("/etc/nsswitch.conf", O_RDONLY) = 4
1111  22:16:30.108145 fstat64(0x4, 0x7ffff668) = 0
1111  22:16:30.108432 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30017000
1111  22:16:30.108749 read(4, "passwd:\t\tfiles\nshadow:\t\tfiles\ngr"..., 4096) = 139
1111  22:16:30.109426 read(4, "", 4096) = 0
1111  22:16:30.109747 close(4)          = 0
1111  22:16:30.110024 munmap(0x30017000, 4096) = 0
1111  22:16:30.110637 open("/lib/libnss_files.so.2", O_RDONLY) = 4
1111  22:16:30.111042 read(4, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\0 \364"..., 1024) = 1024
1111  22:16:30.111541 fstat64(0x4, 0x7fffec68) = 0
1111  22:16:30.111941 mmap(0xfe11000, 108436, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) = 0xfe11000
1111  22:16:30.112265 mprotect(0xfe1c000, 63380, PROT_NONE) = 0
1111  22:16:30.112597 mmap(0xfe21000, 45056, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 4, 0) = 0xfe21000
1111  22:16:30.113222 close(4)          = 0
1111  22:16:30.114205 open("/etc/passwd", O_RDONLY) = 4
1111  22:16:30.114730 fcntl64(0x4, 0x1, 0) = 0
1111  22:16:30.115012 fcntl64(0x4, 0x2, 0x1) = 0
1111  22:16:30.115330 fstat64(0x4, 0x7ffff638) = 0
1111  22:16:30.115614 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30017000
1111  22:16:30.115981 read(4, "root:$1$$FACDTVoJKPHNGdGKbpBr5.:"..., 4096) = 84
1111  22:16:30.116600 close(4)          = 0
1111  22:16:30.116894 munmap(0x30017000, 4096) = 0
1111  22:16:30.117398 open("/etc/shells", O_RDONLY) = -1 ENOENT (No such file or directory)
1111  22:16:30.117979 stat("/root", {st_mode=S_IFDIR|0755, st_size=1024, ...}) = 0
1111  22:16:30.118535 stat("/root/.ssh", 0x7ffff768) = -1 ENOENT (No such file or directory)
1111  22:16:30.119836 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:30.120196 gettimeofday({6560190, 120304}, NULL) = 0
1111  22:16:30.120504 write(5, "\333\276Ku\304vc\205tvg\5\215R\240\272\336\312\254\235"..., 60) = 60
1111  22:16:30.121125 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.664284 gettimeofday({6560192, 664405}, NULL) = 0
1111  22:16:32.664638 read(5, "\vE \325\256\16@\302", 8) = 8
1111  22:16:32.665088 read(5, "\23\275\216\f\205$\356\373\261\'u>\200y\214N~=l\366\343"..., 140) = 140
1111  22:16:32.665947 open("/etc/shells", O_RDONLY) = -1 ENOENT (No such file or directory)
1111  22:16:32.670467 time([6560192])   = 6560192
1111  22:16:32.670921 getpid()          = 1111
1111  22:16:32.671267 rt_sigaction(SIGPIPE, {0xff170d4, [], 0}, {SIG_IGN}, 8) = 0
1111  22:16:32.671687 send(3, "<85>Mar 17 22:16:32 dropbear[111"..., 94, 0) = 94
1111  22:16:32.672358 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
1111  22:16:32.673585 close(8)          = 0
783   22:16:32.673920 <... _newselect resumed> ) = 1
783   22:16:32.674096 close(6)          = 0
783   22:16:32.674411 _newselect(0x8, 0x7ffffa98, 0, 0, 0x7ffffbd0 <unfinished ...>
1111  22:16:32.674731 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.675067 gettimeofday({6560192, 675176}, NULL) = 0
1111  22:16:32.675369 write(5, "\247\233b\234\f\276\213\330=\331\263{l\2241\37\353LAW\10"..., 36) = 36
1111  22:16:32.675991 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.684193 gettimeofday({6560192, 684308}, NULL) = 0
1111  22:16:32.684535 read(5, "\343\\UF\237RO\364", 8) = 8
1111  22:16:32.684974 read(5, "\210^\n\357Fj\250,\363\241\350\243a\350\10b-\31\354\361"..., 52) = 52
1111  22:16:32.686598 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.686965 gettimeofday({6560192, 687074}, NULL) = 0
1111  22:16:32.687269 write(5, "\264\320/\315\207\35 \256\244\244\356\276\270\32i\316W"..., 52) = 52
1111  22:16:32.687854 _newselect(0x6, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.693556 gettimeofday({6560192, 693673}, NULL) = 0
1111  22:16:32.693902 read(5, "6U\305J\230$\206W", 8) = 8
1111  22:16:32.694343 read(5, "\353\314\273\361\31tJ\236 \224\2508&w\212j\240\331Z\326"..., 68) = 68
1111  22:16:32.695085 pipe([4, 6])      = 0
1111  22:16:32.695473 pipe([8, 9])      = 0
1111  22:16:32.695841 pipe([10, 11])    = 0
1111  22:16:32.696283 fork()            = 1123
1111  22:16:32.697624 close(4 <unfinished ...>
1123  22:16:32.698134 dup2(4, 0 <unfinished ...>
1111  22:16:32.698328 <... close resumed> ) = 0
1123  22:16:32.698543 <... dup2 resumed> ) = 0
1111  22:16:32.698729 close(9 <unfinished ...>
1123  22:16:32.698900 dup2(9, 1 <unfinished ...>
1111  22:16:32.699067 <... close resumed> ) = 0
1123  22:16:32.699239 <... dup2 resumed> ) = 1
1111  22:16:32.699412 close(11 <unfinished ...>
1123  22:16:32.699579 dup2(11, 2 <unfinished ...>
1111  22:16:32.699744 <... close resumed> ) = 0
1123  22:16:32.699962 <... dup2 resumed> ) = 2
1111  22:16:32.700230 fcntl64(0x8, 0x4, 0x800 <unfinished ...>
1123  22:16:32.700417 close(6 <unfinished ...>
1111  22:16:32.700585 <... fcntl64 resumed> ) = 0
1123  22:16:32.700759 <... close resumed> ) = 0
1111  22:16:32.700942 fcntl64(0x6, 0x4, 0x800 <unfinished ...>
1123  22:16:32.701119 close(4 <unfinished ...>
1111  22:16:32.701332 <... fcntl64 resumed> ) = 0
1123  22:16:32.701507 <... close resumed> ) = 0
1111  22:16:32.701690 fcntl64(0xa, 0x4, 0x800 <unfinished ...>
1123  22:16:32.701867 close(8 <unfinished ...>
1111  22:16:32.702036 <... fcntl64 resumed> ) = 0
1123  22:16:32.702208 <... close resumed> ) = 0
1111  22:16:32.702607 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38 <unfinished ...>
1123  22:16:32.702817 close(9)          = 0
1123  22:16:32.703159 close(10)         = 0
1123  22:16:32.703425 close(11)         = 0
1123  22:16:32.703968 open("/dev/random", O_RDONLY) = 4
1123  22:16:32.704393 read(4, "\'\202!\375", 32) = 4
1123  22:16:32.704822 read(4,  <unfinished ...>
1111  22:16:32.746682 <... _newselect resumed> ) = 1
1111  22:16:32.746887 gettimeofday({6560192, 746995}, NULL) = 0
1111  22:16:32.747396 read(5, "\220\221\302\0L%\232i", 8) = 8
1111  22:16:32.747914 read(5, "E\333\315|\24\177P\213\346\246\371\35\'\24\304j#\346~\215"..., 36) = 36
1111  22:16:32.748724 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.749133 gettimeofday({6560192, 749249}, NULL) = 0
1111  22:16:32.749453 write(6, "\0", 1) = 1

... here's where the problem starts...

1111  22:16:32.749800 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.750138 gettimeofday({6560192, 750248}, NULL) = 0
1111  22:16:32.750531 write(6, NULL, 0) = 0
1111  22:16:32.750829 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.751173 gettimeofday({6560192, 751284}, NULL) = 0
1111  22:16:32.751480 write(6, NULL, 0) = 0
1111  22:16:32.751810 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.752157 gettimeofday({6560192, 752267}, NULL) = 0
1111  22:16:32.752462 write(6, NULL, 0) = 0
1111  22:16:32.752747 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.753176 gettimeofday({6560192, 753294}, NULL) = 0

..... note the "write(6, NULL, 0) = 0".  unless my strace command
is broken (possible), this is very strange.  time passes, more of
the same gettimeofda/write/select pattern, until the read below
returns for process 1123...

1111  22:16:32.920552 write(6, NULL, 0) = 0
1111  22:16:32.920877 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.921212 gettimeofday({6560192, 921312}, NULL) = 0
1111  22:16:32.921511 write(6, NULL, 0) = 0
1111  22:16:32.921792 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.922168 gettimeofday({6560192, 922270}, NULL) = 0
1111  22:16:32.922469 write(6, NULL, 0) = 0
1111  22:16:32.922751 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.923202 gettimeofday( <unfinished ...>
1123  22:16:32.923539 <... read resumed> "w", 28) = 1
1123  22:16:32.923760 read(4, "\\", 27) = 1
1123  22:16:32.924091 read(4, "\3", 26) = 1
1123  22:16:32.924493 read(4,  <unfinished ...>
1111  22:16:32.924693 <... gettimeofday resumed> {6560192, 923469}, NULL) = 0
1111  22:16:32.924920 write(6, NULL, 0) = 0
1111  22:16:32.925202 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.925537 gettimeofday({6560192, 925637}, NULL) = 0
1111  22:16:32.925837 write(6, NULL, 0) = 0
1111  22:16:32.926166 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.926500 gettimeofday({6560192, 926599}, NULL) = 0
1111  22:16:32.926799 write(6, NULL, 0) = 0
1111  22:16:32.927079 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:32.927453 gettimeofday({6560192, 927555}, NULL) = 0


..... more time passes, more of the same until another read...

1111  22:16:35.120914 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.121294 gettimeofday({6560195, 121399}, NULL) = 0
1111  22:16:35.121599 write(6, NULL, 0) = 0
1111  22:16:35.121933 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.122267 gettimeofday({6560195, 122368}, NULL) = 0
1111  22:16:35.122567 write(6, NULL, 0) = 0
1111  22:16:35.122987 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38 <unfinished ...>
1123  22:16:35.123379 <... read resumed> "b", 25) = 1
1123  22:16:35.123604 read(4, "\271", 24) = 1
1123  22:16:35.123954 read(4, "n", 23)  = 1
1123  22:16:35.124292 read(4, "\263", 22) = 1
1123  22:16:35.124744 read(4,  <unfinished ...>
1111  22:16:35.124906 <... _newselect resumed> ) = 1
1111  22:16:35.125081 gettimeofday({6560195, 125180}, NULL) = 0
1111  22:16:35.125381 write(6, NULL, 0) = 0
1111  22:16:35.125663 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.126040 gettimeofday({6560195, 126143}, NULL) = 0
1111  22:16:35.126343 write(6, NULL, 0) = 0
1111  22:16:35.126624 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.126955 gettimeofday({6560195, 127055}, NULL) = 0
1111  22:16:35.127298 write(6, NULL, 0) = 0
1111  22:16:35.127580 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.127911 gettimeofday({6560195, 128011}, NULL) = 0
1111  22:16:35.128210 write(6, NULL, 0) = 0
1111  22:16:35.128532 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:35.128867 gettimeofday({6560195, 128968}, NULL) = 0
1111  22:16:35.129167 write(6, NULL, 0) = 0


... more time....

1111  22:16:36.308158 gettimeofday({6560196, 308268}, NULL) = 0
1111  22:16:36.308470 write(6, NULL, 0) = 0
1111  22:16:36.308751 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.309081 gettimeofday({6560196, 309180}, NULL) = 0
1111  22:16:36.309379 write(6, NULL, 0) = 0
1111  22:16:36.309706 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.310038 gettimeofday({6560196, 310238}, NULL) = 0
1111  22:16:36.310532 write(6, NULL, 0) = 0
1111  22:16:36.310856 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.311196 gettimeofday({6560196, 311295}, NULL) = 0
1111  22:16:36.311495 write(6, NULL, 0) = 0
1111  22:16:36.311776 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.312103 gettimeofday({6560196, 312245}, NULL) = 0
1111  22:16:36.312447 write(6, NULL, 0) = 0
1111  22:16:36.312729 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.313057 gettimeofday({6560196, 313157}, NULL) = 0
1111  22:16:36.313357 write(6, NULL, 0 <unfinished ...>
1123  22:16:36.313700 <... read resumed> "E", 21) = 1
1123  22:16:36.313921 read(4, "\31", 20) = 1
1123  22:16:36.314270 read(4, "L", 19)  = 1
1123  22:16:36.314609 read(4, "u", 18)  = 1
1123  22:16:36.315050 read(4,  <unfinished ...>
1111  22:16:36.315210 <... write resumed> ) = 0
1111  22:16:36.315406 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.315736 gettimeofday({6560196, 315836}, NULL) = 0
1111  22:16:36.316037 write(6, NULL, 0) = 0
1111  22:16:36.316367 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.316698 gettimeofday({6560196, 316798}, NULL) = 0
1111  22:16:36.316997 write(6, NULL, 0) = 0
1111  22:16:36.317280 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.317650 gettimeofday({6560196, 317752}, NULL) = 0
1111  22:16:36.317951 write(6, NULL, 0) = 0
1111  22:16:36.318232 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:36.318560 gettimeofday({6560196, 318661}, NULL) = 0


.... and on and on and on until finally things sync up again, and
    the transfer completes...



1111  22:16:45.928474 gettimeofday({6560205, 928574}, NULL) = 0
1111  22:16:45.928774 write(6, NULL, 0) = 0
1111  22:16:45.929054 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.929427 gettimeofday({6560205, 929533}, NULL) = 0
1111  22:16:45.929733 write(6, NULL, 0) = 0
1111  22:16:45.930014 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.930347 gettimeofday({6560205, 930447}, NULL) = 0
1111  22:16:45.930647 write(6, NULL, 0) = 0
1111  22:16:45.930972 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.931304 gettimeofday({6560205, 931404}, NULL) = 0
1  22:16:45.931603 write(6, NULL, 0) = 0
1111  22:16:45.931884 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.932260 gettimeofday({6560205, 932362}, NULL) = 0
1111  22:16:45.932561 write(6, NULL, 0) = 0
1111  22:16:45.932842 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.933174 gettimeofday({6560205, 933274}, NULL) = 0
1123  22:16:45.933636 <... read resumed> "n", 1) = 1
1123  22:16:45.933850 close(4)          = 0
1123  22:16:45.934162 close(3)          = 0
1123  22:16:45.934428 close(4)          = -1 EBADF (Bad file descriptor)
1123  22:16:45.934801 getuid()          = 0
1123  22:16:45.935105 setgid(0)         = 0
1123  22:16:45.935811 open("/etc/group", O_RDONLY) = 3
1123  22:16:45.936397 fcntl64(0x3, 0x1, 0) = 0
1123  22:16:45.936681 fcntl64(0x3, 0x2, 0x1) = 0
1123  22:16:45.937002 fstat64(0x3, 0x7ffff598) = 0
1123  22:16:45.937279 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30017000
1123  22:16:45.937640 _llseek(0x3, 0, 0, 0x7ffff5e8, 0x1) = 0
1123  22:16:45.938010 read(3, "root:x:0:\ndaemon:x:1:\nbin:x:2:\ns"..., 4096) = 81
1123  22:16:45.938709 read(3, "", 4096) = 0
1123  22:16:45.939079 close(3)          = 0
1123  22:16:45.939359 munmap(0x30017000, 4096) = 0
1123  22:16:45.939718 setgroups(1, [0]) = 0
1123  22:16:45.940171 setuid(0)         = 0
1123  22:16:45.940577 chdir("/root")    = 0
1123  22:16:45.940993 rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
1123  22:16:45.941540 execve("/bin/sh", ["sh", "-c", "scp -v -f /bin/busybox"], [/* 4 vars */]) = 0
1123  22:16:45.943688 uname({sys="Linux", node="starmobile", ...}) = 0
1123  22:16:45.944413 brk(0)            = 0x101dd1ac
1123  22:16:45.944786 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30016000
1123  22:16:45.945242 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
1123  22:16:45.945748 open("/etc/ld.so.cache", O_RDONLY) = -1 ENOENT (No such file or directory)
1123  22:16:45.946130 open("/lib/libm.so.6", O_RDONLY) = 3
1123  22:16:45.946493 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\0\242"..., 1024) = 1024
1123  22:16:45.947018 fstat64(0x3, 0x7ffff0f8) = 0
1123  22:16:45.947329 mmap(0xff69000, 549372, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xff69000
1123  22:16:45.947641 mprotect(0xffdd000, 74236, PROT_NONE) = 0
1123  22:16:45.948001 mmap(0xffe9000, 24576, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0x70000) = 0xffe9000
1123  22:16:45.948574 mmap(0xffef000, 508, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xffef000
1123  22:16:45.948977 close(3)          = 0
1123  22:16:45.949515 open("/lib/libcrypt.so.1", O_RDONLY) = 3
1123  22:16:45.949909 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\0\f"..., 1024) = 1024
1123  22:16:45.950387 fstat64(0x3, 0x7ffff0d8) = 0
1123  22:16:45.950830 mmap(0xff1d000, 245476, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xff1d000
1123  22:16:45.951156 mprotect(0xff22000, 224996, PROT_NONE) = 0
1123  22:16:45.951485 mmap(0xff2d000, 20480, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xff2d000
1123  22:16:45.952054 mmap(0xff32000, 159460, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xff32000
1123  22:16:45.952455 close(3)          = 0
1123  22:16:45.952822 open("/lib/libc.so.6", O_RDONLY) = 3
1123  22:16:45.953203 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\1\316"..., 1024) = 1024
1123  22:16:45.953846 fstat64(0x3, 0x7ffff0b8) = 0
1123  22:16:45.954161 mmap(0xfdc7000, 1334088, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xfdc7000
1123  22:16:45.954472 mprotect(0xfef5000, 97096, PROT_NONE) = 0
1123  22:16:45.954851 mmap(0xfef7000, 81920, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0x120000) = 0xfef7000
1123  22:16:45.955395 mmap(0xff0b000, 6984, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xff0b000
1123  22:16:45.955792 close(3)          = 0
1123  22:16:45.959349 brk(0)            = 0x101dd1ac
1123  22:16:45.959632 brk(0x101de1ac)   = 0x101de1ac
1123  22:16:45.959918 brk(0x101df000)   = 0x101df000
1123  22:16:45.960553 stat("/etc/busybox.conf", 0x7ffffc28) = -1 ENOENT (No such file or directory)
1123  22:16:45.961106 getuid()          = 0
1123  22:16:45.961466 getgid()          = 0
1123  22:16:45.961762 setgid(0)         = 0
1123  22:16:45.962058 setuid(0)         = 0
1123  22:16:45.962435 getpid()          = 1123
1123  22:16:45.962935 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
1123  22:16:45.963527 getppid()         = 1111
1123  22:16:45.964222 getcwd("/root", 4096) = 6
1123  22:16:45.964726 rt_sigaction(SIGINT, NULL, {SIG_DFL}, 8) = 0
1123  22:16:45.965134 rt_sigaction(SIGINT, {0x1008b4f8, ~[], 0}, NULL, 8) = 0
1123  22:16:45.965579 rt_sigaction(SIGQUIT, NULL, {SIG_DFL}, 8) = 0
1123  22:16:45.965900 rt_sigaction(SIGQUIT, {SIG_DFL}, NULL, 8) = 0
1123  22:16:45.966207 rt_sigaction(SIGTERM, NULL, {SIG_DFL}, 8) = 0
1123  22:16:45.966523 rt_sigaction(SIGTERM, {SIG_DFL}, NULL, 8) = 0
1123  22:16:45.967176 stat("/usr/local/bin/scp", 0x7ffff9b8) = -1 ENOENT (No such file or directory)
1123  22:16:45.967607 stat("/usr/bin/scp", {st_mode=S_IFREG|0755, st_size=21500, ...}) = 0
1123  22:16:45.968499 fork()            = 1157
1111  22:16:45.969452 write(6, NULL, 0) = 0
1111  22:16:45.969762 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.970107 gettimeofday({6560205, 970207}, NULL) = 0
1111  22:16:45.970412 write(6, NULL, 0) = 0
1111  22:16:45.970745 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.971086 gettimeofday({6560205, 971186}, NULL) = 0
1111  22:16:45.971389 write(6, NULL, 0) = 0
1111  22:16:45.971676 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.972056 gettimeofday({6560205, 972160}, NULL) = 0
1111  22:16:45.972363 write(6, NULL, 0) = 0
1111  22:16:45.972648 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.972985 gettimeofday({6560205, 973085}, NULL) = 0
1111  22:16:45.973364 write(6, NULL, 0) = 0
1111  22:16:45.973658 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.973996 gettimeofday({6560205, 974095}, NULL) = 0
1111  22:16:45.974298 write(6, NULL, 0) = 0
1111  22:16:45.974621 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.974969 gettimeofday({6560205, 975068}, NULL) = 0
1111  22:16:45.975270 write(6, NULL, 0) = 0
1111  22:16:45.975555 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.975891 gettimeofday({6560205, 976033}, NULL) = 0
1111  22:16:45.976239 write(6, NULL, 0) = 0
1111  22:16:45.976525 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.976864 gettimeofday({6560205, 976964}, NULL) = 0
1111  22:16:45.977167 write(6, NULL, 0) = 0
1111  22:16:45.977494 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.977835 gettimeofday({6560205, 977935}, NULL) = 0
1111  22:16:45.978138 write(6, NULL, 0) = 0
1111  22:16:45.978423 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.978801 gettimeofday({6560205, 978905}, NULL) = 0
1111  22:16:45.979106 write(6, NULL, 0) = 0
1111  22:16:45.979392 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.979729 gettimeofday({6560205, 979829}, NULL) = 0
1111  22:16:45.980079 write(6, NULL, 0) = 0
1111  22:16:45.980366 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.980704 gettimeofday({6560205, 980804}, NULL) = 0
1111  22:16:45.981007 write(6, NULL, 0) = 0
1111  22:16:45.981335 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.981679 gettimeofday({6560205, 981779}, NULL) = 0
1111  22:16:45.981982 write(6, NULL, 0) = 0
1111  22:16:45.982268 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.982647 gettimeofday({6560205, 982751}, NULL) = 0
1111  22:16:45.982955 write(6, NULL, 0) = 0
1111  22:16:45.983241 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:45.983577 gettimeofday({6560205, 983677}, NULL) = 0
1111  22:16:45.983950 write(6, NULL, 0 <unfinished ...>
1123  22:16:45.984768 wait4(-1,  <unfinished ...>
1111  22:16:45.984919 <... write resumed> ) = 0
1157  22:16:45.985787 execve("/usr/bin/scp", ["scp", "-v", "-f", "/bin/busybox"], [/* 5 vars */] <unfinished ...>
1111  22:16:45.986126 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38 <unfinished ...>
1157  22:16:45.988395 <... execve resumed> ) = 0
1111  22:16:45.988568 <... _newselect resumed> ) = 1
1111  22:16:45.988776 gettimeofday( <unfinished ...>
1157  22:16:45.989130 uname( <unfinished ...>
1111  22:16:45.989327 <... gettimeofday resumed> {6560205, 988878}, NULL) = 0
1157  22:16:45.989567 <... uname resumed> {sys="Linux", node="starmobile", ...}) = 0
1111  22:16:45.990026 write(6, NULL, 0 <unfinished ...>
1157  22:16:45.990213 brk(0 <unfinished ...>
1111  22:16:45.990353 <... write resumed> ) = 0
1157  22:16:45.990587 <... brk resumed> ) = 0x100150d4
1111  22:16:45.990755 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38 <unfinished ...>
1157  22:16:45.991149 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
1111  22:16:45.991326 <... _newselect resumed> ) = 1
1157  22:16:45.991578 <... mmap resumed> ) = 0x30016000
1111  22:16:45.991740 gettimeofday( <unfinished ...>
1157  22:16:45.992089 open("/etc/ld.so.preload", O_RDONLY <unfinished ...>
1111  22:16:45.992291 <... gettimeofday resumed> {6560205, 991837}, NULL) = 0
1157  22:16:45.992565 <... open resumed> ) = -1 ENOENT (No such file or directory)
1111  22:16:45.992730 write(6, NULL, 0 <unfinished ...>
1157  22:16:45.992998 open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
1111  22:16:45.995345 <... write resumed> ) = 0
1157  22:16:45.995572 <... open resumed> ) = -1 ENOENT (No such file or directory)
1157  22:16:45.995772 open("/lib/libc.so.6", O_RDONLY) = 3
1157  22:16:45.996182 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\1\316"..., 1024) = 1024
1157  22:16:45.996657 fstat64(0x3, 0x7ffff0d8) = 0
1157  22:16:45.997061 mmap(0xfeaa000, 1334088, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xfeaa000
1157  22:16:45.997425 mprotect(0xffd8000, 97096, PROT_NONE) = 0
1157  22:16:45.997750 mmap(0xffda000, 81920, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0x120000) = 0xffda000
1157  22:16:45.998312 mmap(0xffee000, 6984, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xffee000
1157  22:16:45.998765 close(3)          = 0
1157  22:16:46.001070 brk(0)            = 0x100150d4
1157  22:16:46.001408 brk(0x100160d4)   = 0x100160d4
1157  22:16:46.001694 brk(0x10017000)   = 0x10017000
1157  22:16:46.002578 getuid()          = 0
1157  22:16:46.003029 socket(PF_UNIX, SOCK_STREAM, 0) = 3
1157  22:16:46.003443 connect(3, {sin_family=AF_UNIX, path="/var/run/.nscd_socket"}, 110) = -1 ENOENT (No such file or directory)
1157  22:16:46.004034 close(3)          = 0
1157  22:16:46.004496 open("/etc/nsswitch.conf", O_RDONLY) = 3
1157  22:16:46.004960 fstat64(0x3, 0x7ffffbd8) = 0
1157  22:16:46.005321 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30017000
1157  22:16:46.005640 read(3, "passwd:\t\tfiles\nshadow:\t\tfiles\ngr"..., 4096) = 139
1157  22:16:46.006261 read(3, "", 4096) = 0
1157  22:16:46.006649 close(3)          = 0
1157  22:16:46.006928 munmap(0x30017000, 4096) = 0
1157  22:16:46.007476 open("/lib/libnss_files.so.2", O_RDONLY) = 3
1157  22:16:46.007922 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\3\0\24\0\0\0\1\0\0 \364"..., 1024) = 1024
1157  22:16:46.008417 fstat64(0x3, 0x7ffff1d8) = 0
1157  22:16:46.008785 mmap(0xfe7f000, 108436, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xfe7f000
1157  22:16:46.009106 mprotect(0xfe8a000, 63380, PROT_NONE) = 0
1157  22:16:46.009478 mmap(0xfe8f000, 45056, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xfe8f000
1157  22:16:46.010016 close(3)          = 0
1157  22:16:46.010837 open("/etc/passwd", O_RDONLY) = 3
1157  22:16:46.011312 fcntl64(0x3, 0x1, 0) = 0
1157  22:16:46.011590 fcntl64(0x3, 0x2, 0x1) = 0
1157  22:16:46.011943 fstat64(0x3, 0x7ffffba8) = 0
1157  22:16:46.012224 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x30017000
1157  22:16:46.012536 read(3, "root:$1$$FACDTVoJKPHNGdGKbpBr5.:"..., 4096) = 84
1157  22:16:46.013127 close(3)          = 0
1157  22:16:46.013505 munmap(0x30017000, 4096) = 0
1157  22:16:46.013971 read(0, "\0", 1)  = 1
1157  22:16:46.014361 open("/bin/busybox", O_RDONLY) = 3
1157  22:16:46.014825 fstat(3, {st_mode=S_IFREG|0755, st_size=877932, ...}) = 0
1157  22:16:46.015473 write(2, "Sending file modes: C0755 877932"..., 41) = 41
1157  22:16:46.015908 write(1, "C0755 877932 busybox\n", 21) = 21
1157  22:16:46.016238 read(0,  <unfinished ...>
1111  22:16:46.016410 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 2
1111  22:16:46.016759 gettimeofday({6560206, 16860}, NULL) = 0
1111  22:16:46.017107 brk(0x10040000)   = 0x10040000
1111  22:16:46.017709 read(8, "C0755 877932 busybox\n", 32759) = 21
1111  22:16:46.019309 read(10, "Sending file modes: C0755 877932"..., 32755) = 41
1111  22:16:46.020633 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:46.021001 gettimeofday({6560206, 21101}, NULL) = 0
1111  22:16:46.021360 write(5, "\360\376Aj\370K\177\303\333\321hx\0326\16\'\7\366\3\\\31"..., 60) = 60
1111  22:16:46.022002 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:46.022614 gettimeofday({6560206, 22732}, NULL) = 0
1111  22:16:46.022945 write(5, "\2335\211\231\257xjfHR,\202\177\231G\263\337/\345L&\376"..., 84) = 84
1111  22:16:46.023516 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:46.023988 gettimeofday({6560206, 24095}, NULL) = 0
1111  22:16:46.024332 read(5, "\201\306%\301\361\20\357\336", 8) = 8
1111  22:16:46.024786 read(5, "x\316\25\367%\f\216\31\226\244l\3\374U\36#\3\27W/\0005"..., 36) = 36
1111  22:16:46.025495 _newselect(0xb, 0x7ffff938, 0x7ffff9b8, 0, 0x7ffffa38) = 1
1111  22:16:46.025849 gettimeofday({6560206, 25949}, NULL) = 0
1111  22:16:46.026160 write(6, "\0", 1 <unfinished ...>
1157  22:16:46.026404 <... read resumed> "\0", 1) = 1
1157  22:16:46.026841 read(3, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\2\0\24\0\0\0\1\20\0G"..., 2048) = 2048
1157  22:16:46.027322 write(1, "\177ELF\1\2\1\0\0\0\0\0\0\0\0\0\0\2\0\24\0\0\0\1\20\0G"..., 2048) = 2048
1157  22:16:46.027749 read(3, "\0\0\0\0\0\0\0\0\0\0\0q\0\0\0o\0\0\0(\0\0\0\0\0\0\0\0\0"..., 2048) = 2048
1157  22:16:46.028264 write(1, "\0\0\0\0\0\0\0\0\0\0\0q\0\0\0o\0\0\0(\0\0\0\0\0\0\0\0\0"..., 2048) = 2048
1157  22:16:46.028697 

...from here on, everything looks normal...


=---------------------
 paul fox, pgf at brightstareng.com



More information about the Dropbear mailing list