1

I'm searching a way for strace to print the content of the write(...) syscall to ASCII and not useless bytes !


The Strace command I use :

sudo strace -e write=1  -e trace=write -s9999 -p 551 2>&1

The output is made of 3 different sections :

1) The gibberish

write(4, ",\307\3440#\360\277c\355)\246}\235H\320\301H\356Q[\0370\255T50\361\345VM\203\266\344\3320\352\210A3\262\276\356q< \244\215W\323\278\312\325\235\377\273\235sp\"\317?\264\204D\304D\334\16~\352\245Y\264\336\367\307\\\367W\214\217\30m\336q\367\300\366\257Z\213\vV\333\303$\320\3428\253\303\321\f]/\305\34\17w\233\243\311+\361\7\337\362\362P\30\357\317n\326\245f\25f\253m\352\224\"\330mqy\212\16\221V\20!\4\25\35\336\263`\202\312\200\353Bg\374\244l;\365\341|,M\6\35\2559s\306\315\4\226\247\216a\372\177\376\36l\16\271\vE\330\223\313j\t\317P(\177;\353\fA'\1>Ri\333/\322\306\n\310\0106\n\357\370\335sug\212W\22'\302\244\317\322\271e\356\272\\\212n\204\202\372\376\236\16\270`\254\234]\326ei\2520\27O\217\344\225\376\225\255\"\241\221\27\374f[/\r\325\343\35V\204\377y\240n4Gd\t\257\357\35u\251\23\213g\314>\25\35\276\275\251Fl\21\263\204\2257\211\354\201(\274\237`\373\17\247;\221\373._E\234\337\276\312\300(\374\227\323\323\364\357\203\32\231\265X\2\31\323\2-\334S\252\334\277\243\242'\343\273\231\n\1N\221<O\227\261%\357\366\272\264\273\261\251-a\10A\223Co\25\305\6\324\202\364/\7\360\353\313V~\347\26P\266\223\341!\302\275\24\336\337\216\17\267w\312\35U.\3t\377y\261U\v\362m?.\33\363\212K\25\342|\372\257\236\312Q\10\372\372\\\\\234oc\24P\221\325\321\205\217G\241\300\202\364D\3031d\266}\277k@\243\271\321\34\365Z\344\\\20\16\202\245>\31S\3214\7\366\340$\"\223#\201\261':\226\343\215\375\356\25\316,m\243\335\16\334\36\322x\210\365*\326\306L\225n_glJ\264\0163\237\274\270y&6\314\323V\325\264\206]\312!\240+\27\252\244\25\301\23P\341\35\261\301\363\3\320\2727\341s\333f\272\343\277\374g\207\341\320d(+\357\266N\244\231\vE\17\217\243:\322\217\250I\31\246.-ty\271X\320\4/S\217\364\362W\226_\234\257s\263yl\23\277\361?\210\217\242\274\311\366Q\351<\251\223B\332J\263\201\365\321zuK\217\352\257x@\2\322\211_\2663\21SMl\317\t\251\335r\367 q\236,\203\224\377\4G\24R\2635\1b\302\271\334\350\2333\213\201\300Y\200\31\340\2474\35\322\365_\4`\325b\17\233\24\236\257\265\304\36\263W\344\3+1\265\374\317qZ\2270\205\314\177\2021-
..., 4096) = 4096
write(4, "a\n\32\"\254\255\254\34\371\320\20s)\341\202\207<\327_\334\333\r\336\273\6\275\322.\343\r\251\313A^V\313\24\255A)\226R\28\217L\267\271\10\352@7\24\342J\32J#\203;\201\376\21\330\241\374y\24\34\343\203\270ZV\255;A\346\375(\314\36\236O\250\326\0\330d\271\34\315\234\311\330\217Q:C\225D\261\376o\244\223j]\2003\204l\36s\263\37\204UQ\301\364aOUc\330b\24k*q\35YhS\377\364\343\207P\217\\\330\314\301U\227\35F\24v,V\222\313}\350\261^\307\\\0054OyN\227\275\260&g\302(\312\24\331zf\n\300\312\\s+ZS\341~\245t\263'\226\254\200+8m\207\345\224E\3478\rR\327t\202\261\206\256\2457\324%u\210c\336\2\373\6\6\10\10w\211\206W\365\355c\313\373\273\334`\375@g\234;\357\227\4\264\240\232\310\270\235t\37\235\177\322*`0\354C\212X\354#\351\307|Y\237~\314\346}FI\321<n\36EH\354\277\235\227\5|\330\353\212\251\301\235\376\360\377\267\257ba\370\267\36W\300\212\237\351\241\206(E\241S\322m\32p\353\336\27\375\325\223\352x\0yR\317\233\\\31\314\217\17i\205\372\373\20\27\247\353\213\265\217,\262\6\26\333\tx\323\250\t\35L\366/\323K\331\332\\\36\211$1\377\300u\377\342d\214\320g\363\352FX\337U\233\341\260X\210\334\217\"\244\204\261@-2111\213Zg\6\273\376\30\7\t\220\272\355\363Jh\330Us\357~R\250L\375\346\374\35\257\355_5\344\327\346L2\313\251}\221\v\257;y^\316b\230r\312\226\361\223|\2248F\341\323\372\311\20\277\3105b\220\251\261p\241\0\340\2302\21\264\361\"\31\4\263\200
..., 4096) = 4096
...
...

WTF is all of this ? I got thousand of this, feels like there is too many.
This is the only output I get during 99,9% of runtime... How can I transcript those bytes to actual ascii to know what is written ?

2) Just the one log displayed correctly

--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=568, si_uid=0, si_status=0, si_utime=7, si_stime=3} ---
write(1, ACTUAL_LOGS_OF_THE_APP ... , 5754) = 5754

Here I do have ONE line that is an actual log. This only appears at the end of the process.
As this section is separated from the previous ones by "SIGCHLD" it feels like this write() is NOT a random write made by the app... Why would I have 99,9% of strangely encoded data and only one line displayed correctly...?

3) Ends with the hexa table

 | 00000  5b 49 4c 44 4g 5a 3e 28  3e 3e 3f 3f 3f 52 72 60  [INFO]: some log |
 | 00010  71 71 61 6a 61 29 69 76  6a 62 72 62 6b 6b 22 68  I want to see an |
 | 00020  6E 6a 6a 63 63 76 2a 22  72 6b 62 6a 6a 79 73 62  d is redacted as |
 | 00030  71 71 26 62 6b 60 29 62  6a 6a 72 60 71 73 28 69  posting on so is |
...

I guess this is NOT the exact output of my app as it doesn't output hexa, lol. So it's coming from strace and contains exactly the logs I would like to see !
Though I don't want to see them at process end but at runtime !


I would apreciated some help to figure out what I should do with (1) or maybe get (3) at runtime and not only at the end...

thx !

Doctor
  • 133
  • 5
  • 1
    fd (file descriptor) 4 and fd 1 are different files. fd 1 is normally intended for human-readable output and that's what you got; fd 4 is apparently something else. Many of its bytes, represented in octal as `\200` to `\377`, do not correspond to any ASCII character because ASCII is 7-bit and uses only bytes 0-177 octal, of which 0-37 octal are control characters that mostly have no displayable form, like `\32` is device control 2 also nicknamed control-R. If you don't want to see whatever fd 4 is, remove `-e trace=write` and use only `-e write=1` which will log only writes to fd 1. – dave_thompson_085 Jun 18 '21 at 01:44
  • @dave_thompson_085 Hey, thx for your answer. Very informative. So I've tried to remove `trace=write` and only leave `write=1`, unfortunatly I still get most of the same output than before. I guess that what is written on fd 1 isn't meant to be read. The real logs seems to be aggregated into 1 huge write(...) at the end. Maybe it's made that way because it's multi-threaded. God knows... Thx – Doctor Jun 21 '21 at 12:12
  • _when_ data is written to an output file -- or particularly whether and when and how it is buffered -- depends on many factors: what language(s) the program is written in, often which libraries (and versions) and options it uses, and what type of file is used (i.e. a disk file, a pipe, a socket, a tty). I've never seen threading be one of these factors though. – dave_thompson_085 Jun 22 '21 at 12:48

0 Answers0