corrupted strace output

[Jiri Horky]

Dear developers,

I've recently started to heavily use strace in order to investigate some 
physicist applications. The application's execution is quite 
complicated, resulting in a chain of ~12 processes ( a lot of wrapper 
scripts around, pipes, etc).

I have noticed several strange things with resulting output. In all 
examples below I didn't strip any lines, so they are always consecutive 
lines from output file.

Strace is run with following parameters:

/usr/bin/strace -q -a1 -s0 -f -tttT -o//tmp/strace.file.2010-05-19.19339 
-e 
trace=open,creat,close,read,write,unlink,lseek,_llseek,dup,dup2,pipe,clone,fork,mkdir,clone,access,socket,stat,fstat 
<application>

The strace version is strace-4.5.16-1.el5.1, on Scientific Linux SL 
release 5.2 (Boron), kernel version is 2.6.18-164.15.1.el5, 64bit.

Please let me know if you need more information. I am also able to 
provide the output file (500MB).

Best regards
Jiri Horky

1. Sometimes, (quite rarely, but still), interrupted system call from 
process A is not followed (not counting calls for other processes) by 
same resumed call in this process, but by another (sometimes even 
interrupted) system call in the same process. This seems quite strange 
to me, as I lived in impression, this is simply not possible. See example:

5299  1274263536.157783 _llseek(10, 0, <unfinished ...>
5301  1274263536.157805 write(1, ""..., 4096) = 4096 <0.000021>
5299  1274263536.157871 read(10, ""..., 4096) = 4096 <0.000006>
5301  1274263536.157903 write(1, ""..., 4096 <unfinished ...>
5299  1274263536.157916 read(10, ""..., 4096) = 4096 <0.000014>

2. Sometimes output for reads is corrupted, see example (missing 
parameters).
1436  1274263414.645307 open("/proc/meminfo", O_RDONLY) = 7 <0.000063>
1436  1274263414.645534 read(7, ) = 777 <0.000030>
1436  1274263414.645620 close(7) = 0 <0.000010>

3. _llseeks output is not consistent if it ends up with ESPIPE. Notice 
0xffce0520 instead of number in square brackets as usual. This is not a 
big problem, but makes processing of strace output more difficult.
5299  1274263536.129730 _llseek(10, 0, 0xffce0520, SEEK_CUR) = -1 ESPIPE 
(Illegal seek) <0.000005>

4.  resumed _llseek is not marked as resumed, when ending with error.
5299  1274263536.157783 _llseek(10, 0, <unfinished ...>
5301  1274263536.157805 write(1, ""..., 4096) = 4096 <0.000021>
5299  1274263536.157871 read(10, ""..., 4096) = 4096 <0.000006>
5301  1274263536.157903 write(1, ""..., 4096 <unfinished ...>
5299  1274263536.157916 read(10, ""..., 4096) = 4096 <0.000014>
5299  1274263536.157960 _llseek(10, 0, 0xffce0520, SEEK_CUR) = -1 ESPIPE 
(Illegal seek) <0.000003>

or:
5424  1274263555.912261 _llseek(39, 0, <unfinished ...>
5425  1274263555.912390 
open("/storage/atlas/software/local/lib64/libglobus_gssapi_gsi_gcc32dbgpthr.so", 
O_RDONLY <unfinished ...>
5424  1274263555.912418 _llseek(41, 0, 0xfff3e21c, SEEK_CUR) = -1 ESPIPE 
(Illegal seek) <0.000004>

5. Comletely strange lines + parameters for writes:
5430  1274263558.275721 write(42, ""..., 131072) = 131072 <0.000268>
5430  1274263558.276869 write(42, ""..., 131072) = 131072 <0.000251>
5430  1274263558.278807 write(42, ""..., 131072) = 131072 <0.000306>
) = 0x12dc8 <0.000677>
5430  1274263558.279525 write(42, ""..., 
131072{st_mode=S_IFIFO|S_ISUID|S_ISGID|S_ISVTX|013066600562, 
st_size=8787907233347735880, ...}) = 131072 <0.000261>
5430  1274263558.281039 write(42, ""..., 131072) = 131072 <0.000251>
5430  1274263558.282405 write(42, ""..., 131072) = 131072 <0.000263>
5430  1274263558.283511 write(42, ""..., 131072) = 131072 <0.000248>
5430  1274263558.284693 write(42, ""..., 131072) = 131072 <0.000260>
5430  1274263558.285756 write(42, ""..., 131072) = 131072 <0.000269>
5430  1274263558.286859 write(42, ""..., 131072) = 131072 <0.000234>
5430  1274263558.287985 write(42, ""..., 131072) = 131072 <0.000275>
) = 0xb510 <0.000366>
) = 0x43e0 <0.000513>
5430  1274263558.289094 write(42, ""..., 131072) = 131072 <0.000252>
5430  1274263558.290229 write(42, ""..., 131072) = 131072 <0.000278>
5430  1274263558.291322 write(42, ""..., 131072) = 131072 <0.000237>