I am trying to debug a serial connection on a BeagleBone running Debian 8.7. To do this I have written a test program in go. I wasn't getting the results I was expecting, so I fired up strace on the test program.
Sure enough, the write system calls I was expecting to see weren't there. I checked my source code and they definitely should be there. The test program is essentially this:
loop:
write a log message to stderr
write a buffer of binary 0x00 to the serial port
write a different log message to stderr
write a buffer of binary 0xff to the serial port
The program produces output on stderr that looks like this:
2015/11/12 21:28:45 111...
2015/11/12 21:28:46 000...
2015/11/12 21:28:48 111...
2015/11/12 21:28:49 000...
2015/11/12 21:28:51 111...
2015/11/12 21:28:52 000...
2015/11/12 21:28:54 111...
2015/11/12 21:28:55 000...
2015/11/12 21:28:57 111...
2015/11/12 21:28:58 000...
2015/11/12 21:29:00 111...
2015/11/12 21:29:01 000...
2015/11/12 21:29:03 111...
2015/11/12 21:29:04 000...
2015/11/12 21:29:06 111...
2015/11/12 21:29:07 000...
2015/11/12 21:29:09 111...
2015/11/12 21:29:10 000...
2015/11/12 21:29:12 111...
2015/11/12 21:29:13 000...
2015/11/12 21:29:15 111...
2015/11/12 21:29:16 000...
2015/11/12 21:29:18 111...
2015/11/12 21:29:19 000...
2015/11/12 21:29:21 111...
I then observed that not all the writes to stderr were appearing in the strace output. There would be runs of the first log message without any of the second, which can't happen with the algorithm above. Here is an extract of the output, filtered by grepping trace.log for write. As you can see there are far fewer strace entries than lines in stderr, indicating that strace isn't logging all the system calls that are actually being made.
write(2, "2015/11/12 21:28:46 000...\n", 27) = 27
write(2, "2015/11/12 21:28:49 000...\n", 27) = 27
write(2, "2015/11/12 21:28:52 000...\n", 27) = 27
write(2, "2015/11/12 21:28:55 000...\n", 27) = 27
write(2, "2015/11/12 21:28:58 000...\n", 27) = 27
write(2, "2015/11/12 21:29:01 000...\n", 27) = 27
write(2, "2015/11/12 21:29:04 000...\n", 27) = 27
write(2, "2015/11/12 21:29:07 000...\n", 27) = 27
write(2, "2015/11/12 21:29:12 111...\n", 27) = 27
write(2, "2015/11/12 21:29:15 111...\n", 27) = 27
write(2, "2015/11/12 21:29:18 111...\n", 27) = 27
write(2, "2015/11/12 21:29:21 111...\n", 27) = 27
There is no concurrency in my source or any of the go libraries I am using, there is no forking of any child processes.
I checked the strace man page and there doesn't appear to be any way to specify statistical sampling of system calls and no indication that it doesn't log all of them unless you specify a filtering expression (which I haven't).
I have no idea if the write system calls directed at the serial ports are actually occurring, but right now I can't trust the strace output because it isn't showing me all the system calls that I know are being made.
Can anyone explain what is going on?
My command line is:
strace -o trace.log -v ./serial-test --device /dev/ttyO2 --oscillator --delay 500
update: a friend suggested adding a -f flag which did seem to help. what isn't clear is why, since the documentation suggests -f is only useful in the presence of calls to fork() and there are none of those in my program (or, indeed, in the strace output).
Ok, so, the manpage also refers to clone() and Linux threads are created with clone(). go uses Linux threads, so this explains the issue.
