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