corrupted strace output

[Jiri Horky]

Dear all,

I tried to use the newest version available (strace -- version 4.5.20) 
with exactly same results.

Regards
Jiri Horky

On 05/19/2010 05:35 PM, Jiri Horky wrote:
> 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>