Bug 1342669

Summary: strace "-eread=<fd list>" / "-ewrite=<fd list>" are mutually exclusive but likely shouldn't be
Product: Red Hat Enterprise Linux 6 Reporter: Frank Hirtz <fhirtz>
Component: straceAssignee: DJ Delorie <dj>
Status: CLOSED ERRATA QA Contact: Michal Kolar <mkolar>
Severity: medium Docs Contact:
Priority: medium    
Version: 6.7CC: bgollahe, cww, dj, law, ldv, mcermak, mkolar, mnewsome, nobody+bgollahe, ohudlick
Target Milestone: rcFlags: bgollahe: needinfo+
Target Release: ---   
Hardware: All   
OS: All   
Whiteboard:
Fixed In Version: strace-4.8-11.el6 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-03-21 10:24:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1269194    

Description Frank Hirtz 2016-06-03 20:21:33 UTC
Description of problem:
For strace, the documentation says:

OPTIONS
[ ... ]
       -eread=set  Perform a full hexidecimal and ascii dump of all the
                   data read from file descriptors listed in the speci-
                   fied set.  For example, to see all input activity on
                   file descriptors 3 and 5 use read=3,5.

       -ewrite=set Perform a full hexidecimal and ascii dump of all the
                   data written to file descriptors listed in the spec-
                   ified set.  For example, to see all output  activity
                   on file descriptors 3 and 5 use read=3,5.

Specifying -ewrite=... alone:

 strace -etrace=read,write -ewrite=0,1 dd if=/dev/urandom of=/dev/zero bs=256 count=1
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\6\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240!\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\356\1\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000^\0\0\0\0\0\0"..., 832) = 832
read(0, "\200&\31\314\354\204\233\31\257\337\220\36\2248\177Kd\6\0\2152\266\376\274J\032242\355\316\302"..., 256) = 256
write(1, "\200&\31\314\354\204\233\31\257\337\220\36\2248\177Kd\6\0\2152\266\376\274J\032242\355\316\302"..., 256) = 256
 | 00000  80 26 19 cc ec 84 9b 19  af df 90 1e 94 38 7f 4b  .&...........8.K |
 | 00010  64 06 00 8d 32 b6 fe bc  4a 1a 32 34 32 ed ce c2  d...2...J.242... |
 | 00020  75 e8 76 e5 72 f6 12 8e  85 e2 3e 32 33 42 ad e9  u.v.r.....>23B.. |
 | 00030  5c 90 40 48 0b dc 38 fb  2c a1 4a c4 f9 a7 04 65  \.@H..8.,.J....e |
 | 00040  e2 91 75 6f 27 95 65 29  61 2d 33 5e c7 a3 81 a0  ..uo'.e)a-3^.... |
 | 00050  e8 9d aa ae 3d 86 15 04  11 16 01 1f 91 b8 d3 bb  ....=........... |
 | 00060  3a 36 d7 e6 29 f2 de 46  e7 28 bf 57 0d 8a 39 73  :6..)..F.(.W..9s |
 | 00070  9b 05 b1 13 85 d4 dc a9  2d 4a 55 44 63 fe cc 3b  ........-JUDc..; |
 | 00080  11 1b 8e 87 5f 64 bc 7d  16 e7 f1 f0 2c e5 61 0e  ...._d.}....,.a. |
 | 00090  d7 64 4e b4 23 ee a4 2b  41 bc 3e f8 40 74 c1 c4  .dN.#..+A.>.@t.. |
 | 000a0  98 fe 73 3e 3e 95 9d 97  5c f3 fd 25 37 f1 3d dc  ..s>>...\..%7.=. |
 | 000b0  91 ee bb 60 d5 c0 43 24  76 16 60 4b 4a 43 eb f4  ...`..C$v.`KJC.. |
 | 000c0  ba 28 b9 c9 cd d8 ae 58  03 ec d9 fa d5 d9 d3 de  .(.....X........ |
 | 000d0  08 08 c8 f7 7d b1 2f 5b  5c 00 10 be 5b 71 31 b0  ....}./[\...[q1. |
 | 000e0  31 48 58 b1 6b b7 ca 0c  fa 93 ee 6d de 28 f0 1e  1HX.k......m.(.. |
 | 000f0  68 09 03 6f 10 ca 4e e1  94 92 5f e2 4d 28 70 1d  h..o..N..._.M(p. |
[ ... ]

Specifying _both_ -eread=.../-ewrite=... "swallows" the -ewrite=... though:

$ strace -etrace=read,write -ewrite=0,1 -eread=0,1 dd if=/dev/urandom of=/dev/zero bs=256 count=1
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\6\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240!\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\356\1\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000^\0\0\0\0\0\0"..., 832) = 832
read(0, "@ D\215>%P\253\351\251\365T\336\360t\203\346R\323\346\312\310P\266\6\241\332\1\353\346>\265"..., 256) = 256
 | 00000  40 20 44 8d 3e 25 50 ab  e9 a9 f5 54 de f0 74 83  @ D.>%P....T..t. |
 | 00010  e6 52 d3 e6 ca c8 50 b6  06 a1 da 01 eb e6 3e b5  .R....P.......>. |
 | 00020  45 d2 eb 7d 5f 97 50 60  74 c8 e0 34 ce f4 23 e7  E..}_.P`t..4..#. |
 | 00030  6f ad 4a ec 16 c0 4e 1f  96 aa 32 48 50 cd 03 62  o.J...N...2HP..b |
 | 00040  7f 9b 1f 57 20 e1 e0 41  87 e7 42 82 6c 32 2e 69  ...W ..A..B.l2.i |
 | 00050  f3 c0 fb 9a 4b d1 27 c2  b8 2c c3 df 18 02 65 eb  ....K.'..,....e. |
 | 00060  37 5a 02 57 b4 0f 87 b3  dc 9b fa 03 c5 2a 6d a7  7Z.W.........*m. |
 | 00070  bb 2c d0 af 1e 6b f8 14  18 48 a3 4a 7e fa 59 a3  .,...k...H.J~.Y. |
 | 00080  50 2d 39 8e a1 7b 71 3d  9b 71 6e e4 07 6f 24 6b  P-9..{q=.qn..o$k |
 | 00090  3f 87 38 de 86 bd d7 4a  3a 19 a2 45 8d 09 08 07  ?.8....J:..E.... |
 | 000a0  10 db f1 5f fe 5a 09 d1  bd fd 94 0f 06 66 70 70  ..._.Z.......fpp |
 | 000b0  ad f1 df 08 21 65 15 0e  f4 b2 26 26 c0 df 1e 75  ....!e....&&...u |
 | 000c0  98 86 3f 1c bf b8 64 aa  48 5f b0 f1 9c 3c 3b 21  ..?...d.H_...<;! |
 | 000d0  b2 11 71 ea e9 70 79 a3  79 02 d5 ce 25 c3 6f 44  ..q..py.y...%.oD |
 | 000e0  00 4b 09 97 b0 0b 52 5b  6c 8a 3f 98 13 20 dd 5a  .K....R[l.?.. .Z |
 | 000f0  44 ba 27 aa 39 5f 18 b1  43 13 aa 1c 59 3e f5 d8  D.'.9_..C...Y>.. |
write(1, "@ D\215>%P\253\351\251\365T\336\360t\203\346R\323\346\312\310P\266\6\241\332\1\353\346>\265"..., 256) = 256
[ ... ]

When specifying both a verbose read/write fd list to strace, I expect to see full output for both reads and writes.

Where are you experiencing the behavior?  What environment?

RHEL6.

When does the behavior occur? Frequently?  Repeatedly?   At certain times?

100% repeatable.

What information can you provide around timeframes and urgency?

<snip>
The bug is in syscall.c, function dumpio():

   2459 static void
   2460 dumpio(struct tcb *tcp)
   2461 {
   2462     int (*func)();
   2463 
   2464     if (syserror(tcp))
   2465         return;
   2466     if ((unsigned long) tcp->u_arg[0] >= num_quals)
   2467         return;
   2468     func = tcp->s_ent->sys_func;
   2469     if (func == printargs)
   2470         return;
   2471     if (qual_flags[tcp->u_arg[0]] & QUAL_READ) {
   2472         if (func == sys_read ||
   2473             func == sys_pread ||
   2474             func == sys_recv ||
   2475             func == sys_recvfrom)
   2476             dumpstr(tcp, tcp->u_arg[1], tcp->u_rval);
   2477         else if (func == sys_readv)
   2478             dumpiov(tcp, tcp->u_arg[2], tcp->u_arg[1]);
   2479         return;
   2480     }
   2481     if (qual_flags[tcp->u_arg[0]] & QUAL_WRITE) {
   2482         if (func == sys_write ||
   2483             func == sys_pwrite ||
   2484             func == sys_send ||
   2485             func == sys_sendto)
   2486             dumpstr(tcp, tcp->u_arg[1], tcp->u_arg[2]);
   2487         else if (func == sys_writev)
   2488             dumpiov(tcp, tcp->u_arg[2], tcp->u_arg[1]);
   2489         return;
   2490     }
   2491 }
</snip>

Remove these two "return" instructions and it'll do the right thing.

The parsing was changed a bit in newer strace versions, and this case is handled properly so we're good on that front:

<snip>
[fmhirtz@x1 ~]$ strace -etrace=read,write -ewrite=0,1 -eread=0,1 dd if=/dev/urandom of=/dev/zero bs=256 count=1
read(4, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\6\2\0\0\0\0\0"..., 832) = 832
read(0, "\245\264\375\0278\256r\16\r\253L\373I\223\251\265\334\203\341\347\1\21\351)\33{\276!hI+\244"..., 256) = 256
 | 00000  a5 b4 fd 17 38 ae 72 0e  0d ab 4c fb 49 93 a9 b5  ....8.r...L.I... |
 | 00010  dc 83 e1 e7 01 11 e9 29  1b 7b be 21 68 49 2b a4  .......).{.!hI+. |
 | 00020  1a fe 23 78 ca f6 ad c1  4c 36 90 1a 12 c6 aa ec  ..#x....L6...... |
<snip>
 | 000d0  4c e5 d0 79 17 bc 9f a8  74 64 52 4d ab 9d 30 c6  L..y....tdRM..0. |
 | 000e0  c0 f5 9a 0c 9e bf 73 e1  c6 a0 7f 22 c4 a4 eb d0  ......s....".... |
 | 000f0  fb 81 9b 06 81 aa a3 19  9c 66 f1 69 17 c7 88 99  .........f.i.... |
write(1, "\245\264\375\0278\256r\16\r\253L\373I\223\251\265\334\203\341\347\1\21\351)\33{\276!hI+\244"..., 256) = 256
 | 00000  a5 b4 fd 17 38 ae 72 0e  0d ab 4c fb 49 93 a9 b5  ....8.r...L.I... |
 | 00010  dc 83 e1 e7 01 11 e9 29  1b 7b be 21 68 49 2b a4  .......).{.!hI+. |
 | 00020  1a fe 23 78 ca f6 ad c1  4c 36 90 1a 12 c6 aa ec  ..#x....L6...... |
<snip>
 | 00b90  36 32 30 0a 74 75 72 6b  69 73 68 20 20 20 20 20  620.turkish      |
 | 00ba0  20 20 20 20 74 72 5f 54  52 2e 49 53 4f 2d 38 38      tr_TR.ISO-88 |
 | 00bb0  35 39 2d 39 0a                                    59-9.            |
read(0, "", 4096)                       = 0
write(2, "1+0 records in\n1+0 records out\n", 311+0 records in
1+0 records out
) = 31
write(2, "256 bytes (256 B) copied", 24256 bytes (256 B) copied) = 24
write(2, ", 0.000975011 s, 263 kB/s\n", 26, 0.000975011 s, 263 kB/s
) = 26
+++ exited with 0 +++
</snip>

Comment 2 Dmitry V. Levin 2016-07-22 22:17:39 UTC
JFYI, this was fixed upstream by commit v4.10~147.

Comment 11 errata-xmlrpc 2017-03-21 10:24:54 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2017-0668.html