Closed ghost closed 5 years ago
brarcher
commented
5 years ago Are you saying that this behavior exists in both Check master and v0.12? Are the logs being reported to stdout, and are there multiple threads in the test that are outputting to stdout besides libcheck? If the output is changed to be a file by adding the following environment variable [link]:
CK_LOG_FILE_NAME=log.txtis the issue still present?
ghost
commented
5 years ago Are you saying that this behavior exists in both Check master and v0.12?
yes
Are the logs being reported to stdout
I think they are created by check but not shown on stdout, I just cat them afterwards.
\ ie. srunner_set_log (sr, "do_cd_command.log");
are there multiple threads in the test that are outputting to stdout besides libcheck?
unsure, should I export CK_FORK=no ? is that enough to ensure 1 thread(s) ?
Did it, but hit the same issue.
If the output is changed to be a file by adding the following environment variable [link]:
I did export CK_LOG_FILE_NAME=log.txt but the issue persists and I can't find any log.txt file via $ find ../../../../ -name log.txt
Looks like those srunner_set_log (sr, "do_cd_command.log"); take precedence also as per mentioned:
If log file is specified with both CK_LOG_FILE_NAME and srunner_set_log(), the name provided to srunner_set_log() will be used.
timestamp of log seems to be up to date with the time that I run make check:
$ cat do_cd_command.log
Running suite /src/filemanager
do_c100%: Checks: 4, Failures: 0, Errors: 0
ome:0: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:1: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:2: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:3: Passed
Results for all suites run:
100%: Checks: 4, Failures: 0, Errors: 0
PASS do_cd_command (exit status: 0)(this is the (unchanged) test from mc )
ghost
commented
5 years ago I just realized something:
the log line from test 1 is overwritten with the penultimate line's contents: 100%: Checks: 4, Failures: 0, Errors: 0 in this:
$ cat compare_directories.log
Running suite /src/filemanager
comp100%: Checks: 4, Failures: 0, Errors: 0
ssed
compare_directories.c:186:P:Core:test2:0: Passed
compare_directories.c:206:P:Core:test3:0: Passed
compare_directories.c:374:P:Core:allinone:0: Passed
Results for all suites run:
100%: Checks: 4, Failures: 0, Errors: 0
PASS compare_directories (exit status: 0)what it should look like (guessed):
$ cat compare_directories.log
Running suite /src/filemanager
compare_directories.c:166:P:Core:test1:0: Passed
compare_directories.c:186:P:Core:test2:0: Passed
compare_directories.c:206:P:Core:test3:0: Passed
compare_directories.c:374:P:Core:allinone:0: Passed
Results for all suites run:
100%: Checks: 4, Failures: 0, Errors: 0
PASS compare_directories (exit status: 0)I just replaced the first occurent of 100%: Checks: 4, Failures: 0, Errors: 0(40 chars with newline) with the missing 40 chars(guessed): are_directories.c:166:P:Core:test1:0: Pa.
Oh look at this, I didn't know this was happening:
$ rm do_cd_command.log
$ ./do_cd_command
Running suite(s): /src/filemanager
100%: Checks: 4, Failures: 0, Errors: 0
$ cat do_cd_command.log
Running suite /src/filemanager
do_cd_command.c:147:P:Core:test_empty_mean_home:0: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:1: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:2: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:3: Passed
Results for all suites run:
100%: Checks: 4, Failures: 0, Errors: 0So, no garblage when run this way. But now I can see where that possible duplication could come from.
ghost
commented
5 years ago If the output is changed to be a file by adding the following environment variable [link]:
CK_LOG_FILE_NAME=log.txtis the issue still present?
I did the opposite and the issue goes away.
I made output be stdout by replacing srunner_set_log (sr, "do_cd_command.log"); with srunner_set_log (sr, "-"); and the output isn't on stdout, it's still inside that log file, but it's not messed up:
$ cat do_cd_command.log
Running suite(s): /src/filemanager
Running suite /src/filemanager
do_cd_command.c:147:P:Core:test_empty_mean_home:0: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:1: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:2: Passed
do_cd_command.c:147:P:Core:test_empty_mean_home:3: Passed
100%: Checks: 4, Failures: 0, Errors: 0
Results for all suites run:
100%: Checks: 4, Failures: 0, Errors: 0
PASS do_cd_command (exit status: 0)I've no idea what's still forcing the output to be inside a .log file for each test, but I'm thinking maybe the Makefile.am ? that check_PROGRAMS line?
ghost
commented
5 years ago I just tested check_money and they don't have a srunner_set_log and the .log file check_money.log is generated. Thus if I add srunner_set_log (sr, "check_money.log"); myself in check_money.c I obviously hit this garbling issue.
$ grep . *.log
check_money.log:Running suite Money
check_money.log:chec100%: Checks: 3, Failures: 0, Errors: 0
check_money.log: Passed
check_money.log:check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.log:check_money.c:56:P:Limits:test_money_create_zero:0: Passed
check_money.log:Results for all suites run:
check_money.log:100%: Checks: 3, Failures: 0, Errors: 0
check_money.log:PASS check_money (exit status: 0)Ergo, the issue is... two writers racing to write to the same log file!! one is implied by the Makefile.am or whatever(unsure what exactly lol), and the other is because I put an explicit srunner_set_log (sr, "check_money.log"); line !
So workaround is to put srunner_set_log (sr, "-"); stdout line!
Or even better, don't put any such line! :D this is not good because there's a difference between logging to stdout/file and not logging:
So, I'm not sure if I should close this or a warning(or doc change) would be nice somewhere ?
Maybe whatever's doing the writing is experiencing an internal race and that's why it overwrites some part of the log. So some function somewhere could be made re-entrant? (I wonder if it's ck_strdup_printf)
ghost
commented
5 years ago oh I found the other writer, apparently:
filename: /test-driver:
...
# Test script is run here.
"$@" >$log_file 2>&1
...
# Report the test outcome and exit status in the logs, so that one can
# know whether the test passed or failed simply by looking at the '.log'
# file, without the need of also peaking into the corresponding '.trs'
# file (automake bug#11814).
echo "$res $test_name (exit status: $estatus)" >>$log_file
...local/autoconf 2.69-5 (base-devel)
A GNU tool for automatically configuring source code
local/autoconf2.13 2.13-5
A GNU tool for automatically configuring source code (Legacy 2.1x version)
local/automake 1.16.1-1 (base-devel)
A GNU tool for automatically creating Makefiles
$ automake --version
automake (GNU automake) 1.16.1
$ autoconf --version
autoconf (GNU Autoconf) 2.69
$ make --version
GNU Make 4.2.1
Built for x86_64-pc-linux-gnu
Ok here's reproduction steps:
mkdir /tmp/1cp -a /usr/share/doc/check/example/ /tmp/1/cd /tmp/1/example/ls -la
drwxr-xr-x 4 user user 4096 15.05.2019 18:37 ./
drwxr-xr-x 3 user user 4096 15.05.2019 20:47 ../
drwxr-xr-x 2 user user 4096 15.05.2019 18:37 src/
drwxr-xr-x 2 user user 4096 15.05.2019 18:37 tests/
-rw-r--r-- 1 user user 868 15.05.2019 18:37 configure.ac
-rw-r--r-- 1 user user 80 15.05.2019 18:37 Makefile.am
-rw-r--r-- 1 user user 2206 15.05.2019 18:37 READMEautoreconf --install./configuremakecd testsmake check
so far all good, no issues here!patch -Np2 -i /tmp/file.patch (assuming you saved it as /tmp/file.patch):
diff --git a/tests/Makefile b/tests/Makefile
index 3dd32e7..67bcf7a 100644
--- a/tests/Makefile
+++ b/tests/Makefile
@@ -796,7 +796,8 @@ recheck: all $(check_PROGRAMS)
TEST_LOGS="$$log_list"; \
exit $$?
check_money.log: check_money$(EXEEXT)
- @p='check_money$(EXEEXT)'; \
+ set -vx; \
+ p='check_money$(EXEEXT)'; \
b='check_money'; \
$(am__check_pre) $(LOG_DRIVER) --test-name "$$f" \
--log-file $$b.log --trs-file $$b.trs \
diff --git a/tests/check_money.c b/tests/check_money.c
index b5a3004..ab3ed0e 100644
--- a/tests/check_money.c
+++ b/tests/check_money.c
@@ -98,6 +98,11 @@ int main(void)
s = money_suite();
sr = srunner_create(s);+#if 1 //set to 1 for bad output, as per: https://github.com/libcheck/check/issues/188
11. `rm check_money.log; make check && { echo '------'; cat check_money.log; }`
notice how the output is _bad_/garbled here! hence, this issue.
12. change the `#if 1` line inside `check_money.c` to `#if 0` (then execute step 11) to see how the _good_ output would look like.Output when #if 0 (aka good) [not everything shown below]:
...
/bin/sh:3+ /bin/sh ../test-driver --test-name check_money --log-file check_money.log --trs-file check_money.trs --color-tests yes --enable-hard-errors yes --expect-failure no -- ./check_money
...
Running suite(s): Money
Running suite Money
check_money.c:42:P:Core:test_money_create:0: Passed
check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.c:56:P:Limits:test_money_create_zero:0: Passed
100%: Checks: 3, Failures: 0, Errors: 0
Results for all suites run:
100%: Checks: 3, Failures: 0, Errors: 0
PASS check_money (exit status: 0)Output when #if 1 (aka bad) [not everything shown below]:
...
/bin/sh:3+ /bin/sh ../test-driver --test-name check_money --log-file check_money.log --trs-file check_money.trs --color-tests yes --enable-hard-errors yes --expect-failure no -- ./check_money
...
------
Running suite Money
chec100%: Checks: 3, Failures: 0, Errors: 0
Passed
check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.c:56:P:Limits:test_money_create_zero:0: Passed
Results for all suites run:
100%: Checks: 3, Failures: 0, Errors: 0
PASS check_money (exit status: 0)Simplified repro steps: 1-10 (same steps as before)
make checkrm check_money.log ; ./check_money >check_money.log 2>&1 && cat check_money.log#if line to 0 or 1, then run step 11 again.bad output:
$ rm check_money.log ; ./check_money >check_money.log 2>&1 && cat check_money.log
Running suite Money
chec100%: Checks: 3, Failures: 0, Errors: 0
Passed
check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.c:56:P:Limits:test_money_create_zero:0: Passed
Results for all suites run:
100%: Checks: 3, Failures: 0, Errors: 0good output:
$ rm check_money.log ; ./check_money >check_money.log 2>&1 && cat check_money.log
Running suite(s): Money
Running suite Money
check_money.c:42:P:Core:test_money_create:0: Passed
check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.c:56:P:Limits:test_money_create_zero:0: Passed
100%: Checks: 3, Failures: 0, Errors: 0
Results for all suites run:
100%: Checks: 3, Failures: 0, Errors: 0non-check reproduction steps:
#include <stdio.h>
int main() {
FILE *f=NULL;
f = fopen("/tmp/a_out_.log", "w");
if (NULL == f) {
fprintf(stderr,"oopsie\n");
} else {
fprintf(stdout, "Something");
fprintf(f," messy ");
fprintf(f," jessy\n");
fprintf(stdout, " or another\n");
fprintf(f,"More stuff\n");
fclose(f);
}
}$ gcc a.c && { ./a.out >/tmp/a_out_.log ; cat /tmp/a_out_.log ; }
Something or another
uffSo, I guess it's not a bug in check right?
I asked on ##linux freenode irc:
\
howaboutsynergy: both the program and the test case write to the same file using different file descriptors and buffered io. it's not obvious what the correct result would be.
then, maybe check can do something about it? to ensure it's not writing to the same file from test-driver ? or, I don't even know how this could be done :D
ghost
commented
5 years ago Hey there is a workaround, thanks to <twkm> and <Learath2> on channel ##C on freenode IRC, looks like check could see that stdout and the log file are both on the same device and same inode, and if so, then use only stdout for outputting.
Check can be done in src/check_log.c in static FILE *srunner_open_file(const char *filename) function. I'll try to do that, for fun.
diff --git a/src/check_log.c b/src/check_log.c
index c785b33..34b3039 100644
--- a/src/check_log.c
+++ b/src/check_log.c
@@ -34,6 +34,8 @@
#include "check_print.h"
#include "check_str.h"
+#include <sys/stat.h> // for fstat() and 'stat' struct
+
/*
* If a log file is specified to be "-", then instead of
* opening a file the log output is printed to stdout.
@@ -457,11 +461,26 @@ static FILE *srunner_open_file(const char *filename)
}
else
{
- f = fopen(filename, "w");
- if(f == NULL)
+ /* Use stdout instead, if it's already redirected to the log file
+ which is usually done by the 'test-driver' script.
+ This avoids corrupted output in the log file. See:
+ https://github.com/libcheck/check/issues/188#issuecomment-492782675
+ */
+ struct stat sb;
+ struct stat osb;
+ if((stat(filename, &sb) != -1) && (fstat(1, &osb) != -1)
+ && (sb.st_dev == osb.st_dev) && (sb.st_ino == osb.st_ino))
+ {
+ f = stdout;
+ }
+ else
{
- eprintf("Error in call to fopen while opening file %s:", __FILE__,
- __LINE__ - 2, filename);
+ f = fopen(filename, "w");
+ if(f == NULL)
+ {
+ eprintf("Error in call to fopen while opening file %s:", __FILE__,
+ __LINE__ - 2, filename);
+ }
}
}
return f;If I'm following along correctly, it seems that autotools is generating a Makefile which is directing stdout to a log file, and the test itself is configured to write to the same log file.
I've not seen that before, maybe it is a newer feature of autotools. I do not think that it warrants having a workaround in libcheck; if one's build system is logging the test output and that is not desirable it should be disabled in the build system rather than compensating in the application. If you figure out how to disable the logging from autotools and you choose to go that route drop a note here, in case someone else runs into the same issue.
I'll close this issue, as there is nothing to do from libcheck. If you disagree, let me know.
ghost
commented
5 years ago While I will be using that patch myself(though limited to Linux(or POSIX?) systems), there is another way to workaround this issue that you might be interested in, thanks to an answer by John Bollinger, and that is: to make a change in both test-driver and in check, such that, when either is opening the log file, they do create it if it does not exist, and if it does exist then they should just open it in append mode.
In other words:
for test-driver:
--- /tmp/test-driver 2018-09-18 15:06:54.000000000 +0200
+++ /usr/share/automake-1.16/test-driver 2019-05-16 17:58:09.690988983 +0200
@@ -104,7 +104,8 @@ trap "st=141; $do_exit" 13
trap "st=143; $do_exit" 15
# Test script is run here.
-"$@" >$log_file 2>&1
+echo -n "" >"$log_file"
+"$@" >>"$log_file" 2>&1
estatus=$?
if test $enable_hard_errors = no && test $estatus -eq 99; thenNote: related https://debbugs.gnu.org/cgi/bugreport.cgi?bug=35762#11
and for check in file src/check_log.c (EDIT: the below seems to work but it's bad):
diff --git a/src/check_log.c b/src/check_log.c
index c785b33..0051f35 100644
--- a/src/check_log.c
+++ b/src/check_log.c
}
else
{
- f = fopen(filename, "w");
+ f = fopen(filename, "a");
+ if(f == NULL)
+ {
+ f = fopen(filename, "w");
+ }
if(f == NULL)
{
eprintf("Error in call to fopen while opening file %s:", __FILE__,This workaround however, won't protect against any other caller redirecting the stdout to a file in write mode(ie. check_money >/tmp/my.log) as opposed to append mode(ie. check_money >>/tmp/my.log) as the first workaround would. It's my main reason why I want to use the first one. Another reason would be that it doesn't require any change in the caller(s) (ie. check_money >/tmp/my.log is a-okay).
I've tested the above patches to work with the check_money repro. steps, so output is correct:
Running suite(s): Money
Running suite Money
check_money.c:42:P:Core:test_money_create:0: Passed
check_money.c:52:P:Limits:test_money_create_neg:0: Passed
check_money.c:56:P:Limits:test_money_create_zero:0: Passed
100%: Checks: 3, Failures: 0, Errors: 0
Results for all suites run:
100%: Checks: 3, Failures: 0, Errors: 0
PASS check_money (exit status: 0)ah, I made a mistake for check_log.c using "a" I assumed it opens it in append mode ONLY if it exists! but man 3 fopen says:
aOpen for appending (writing at end of file). The file is created if it does not exist. The stream is positioned at the end of the file.
EDIT: and even if the above assumption were true, using "w" was wrong there. So two mistakes:)
So, feel free to fix that so that it does the same thing that test-driver does: create file if it doesn't exist, then open in append mode.
My job is done here(sorry for teh spam xD)
ok I caved and did it myself:
diff --git a/src/check_log.c b/src/check_log.c
index c785b33..a10efb2 100644
--- a/src/check_log.c
+++ b/src/check_log.c
@@ -34,6 +34,8 @@
#include "check_print.h"
#include "check_str.h"
+#include <stdio.h> // for fdopen()
+#include <fcntl.h> // for O_APPEND | O_WRONLY | O_CREAT | O_TRUNC
/*
* If a log file is specified to be "-", then instead of
* opening a file the log output is printed to stdout.
@@ -457,7 +461,17 @@ static FILE *srunner_open_file(const char *filename)
}
else
{
- f = fopen(filename, "w");
+ int fd = open(filename, O_APPEND | O_WRONLY | O_CREAT | O_TRUNC, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH);
+ if(fd != -1) {
+ f = fdopen(fd, "a"); // XXX implicit declaration of function 'fdopen' is invalid in C99 [-Wimplicit-function-declaration], wtf shellcheck?!
+ //note: "Modes "w" or "w+" do not cause truncation of the file." (man 3 fdopen)
+ //note: 'The file descriptor is not dup'ed, and will be closed when the stream created by fdopen() is closed.'
+ } else {
+ eprintf("Error in call to open while opening file %s (but we'll retry the normal way - overwrites can ensue)):", __FILE__,
+ __LINE__ - 2, filename);
+ /* one last try the normal, overwrity, way - https://github.com/libcheck/check/issues/188 */
+ f = fopen(filename, "w");
+ }
if(f == NULL)
{
eprintf("Error in call to fopen while opening file %s:", __FILE__,Ok, so the above is the only patch needed IFF bash would get this O_APPEND patch (and thus assuming /bin/sh(which test-driver uses) is bash):
diff --git a/make_cmd.c b/make_cmd.c
index ecbbfd6e..5db799f2 100644
--- a/make_cmd.c
+++ b/make_cmd.c
@@ -700,7 +700,7 @@ make_redirection (source, instruction, dest_and_filename, flags)
case r_output_direction: /* >foo */
case r_output_force: /* >| foo */
case r_err_and_out: /* &>filename */
- temp->flags = O_TRUNC | O_WRONLY | O_CREAT;
+ temp->flags = O_APPEND | O_TRUNC | O_WRONLY | O_CREAT;
break;
case r_appending_to: /* >>foo */(testing why this bash patch is bad/good here)
For actual real life output with the above (4 variants), see here: https://gist.github.com/howaboutsynergy/4dc0c41d6244d91a7dfd07159b905fe9#gistcomment-2919998
ghost
commented
5 years ago So, in conclusion, I would argue that, in general(ie. any program), opening logs as well as redirection, should both be done with O_APPEND | O_TRUNC | O_WRONLY | O_CREAT (Note:O_TRUNC being optional for log files of course, see EDIT below - but O_TRUNC is still required for this > redirection(note: not talking about >>)), and in case fopen() is wanted instead of open() then always use it like:
FILE *f=NULL;
int fd = open(filename, O_APPEND | O_WRONLY | O_CREAT | O_TRUNC, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH); // this is a log file so O_TRUNC is actually optional here!!!!
if(fd != -1) {
f = fdopen(fd, "a");
}
if(f == NULL)
{
//failed
} else { //succeeded
}
//... eventually
fclose(f); // close(fd) not neededHowever, while that may seem to work(so far), I hear that some form or locking would be required, assuming that concurrent write(2)(aka man 2 write) are not running synchronously! If they do run synchronously, system-wide (or at least, per file), then nothing more would be needed, no locks! The above way to open log&redirection would be enough, as long as both are open this way. Only one is not enough!
If you ask me, it seems that the latter is the case(ergo, hooray!):
For a seekable file (i.e., one to which lseek(2) may be applied, for example, a regular file) writing takes place at the file offset, and the file offset is incremented by the number of bytes actually written. If the file was open(2)ed with O_APPEND, the file offset is first set to the end of the file before writing. The adjustment of the file offset and the write operation are performed as an atomic step.
So, thoughts?
EDIT: Ah, I agree with John Bollinger that not all programs may want the log truncation on open(so the O_TRUNC is of course optional - it's just in this particular case of test-driver and check that they were both doing it so I kept it):
I strongly disagree that it should be standard practice for programs to truncate their log files at startup. No doubt it makes sense for some programs to do so, but it makes at least as much sense for other programs to avoid doing so.
ghost
commented
5 years ago Great news: I was using open() with O_CREAT wrongly (above, and in any other places thus far) by not supplying the mode argument! and thus random mode flags would be set on the file!!!!!!!! It amazes me that you can get away with this with like no errors (or warnings) :D EDIT: A way to futureproof against this, is to always compile the .c code with gcc(gnu c compiler, not clang!) and give it these args: -D_FORTIFY_SOURCE=2 -O1 (or -O2 etc., just not: -O0 or ommiting it altogether because _FORTIFY_SOURCE requires compiling with optimization (-O)) this will make gcc error if the mode arg isn't passed when it's required!(this is due to _FORTIFY_SOURCE + gcc)
from man 2 open:
The mode argument specifies the file mode bits be applied when a new file is created. This argument must be supplied when O_CREAT or O_TMPFILE is specified in flags; if neither O_CREAT nor O_TMPFILE is specified, then mode is ignored. The effective mode is modified by the process's umask in the usual way: in the absence of a default ACL, the mode of the created file is (mode & ~umask). Note that this mode applies only to future accesses of the newly created file; the open() call that creates a read-only file may well return a read/write file descriptor.
/* Open FILE with access OFLAG. If O_CREAT or O_TMPFILE is in OFLAG,
a third argument is the file protection. */
int
__libc_open (const char *file, int oflag)
{
-- int mode;
if (file == NULL)
{
>> __set_errno (EINVAL);
return -1;
}
if (__OPEN_NEEDS_MODE (oflag))
{
va_list arg;
>> va_start(arg, oflag);
mode = va_arg(arg, int);
va_end(arg);
}
>> __set_errno (ENOSYS);
return -1;
}# define __OPEN_NEEDS_MODE(oflag) \
(((oflag) & O_CREAT) != 0 || ((oflag) & __O_TMPFILE) == __O_TMPFILE)So a sideeffect of this was that make check inside check would fail.
brarcher
commented
5 years ago Let me try to catch up.
I'm not sure I agree with the need for making test logging append. Conceptually a Check unit testing program is an independent run through various tests, and keeping the results independent from other results seems reasonable. Appending to an existing log may actually be a surprise rather than a feature. In the situation you ran into two streams were being written to the same file, correct? That seems invalid, and the separate streams should be configured to write to different files.
ghost
commented
5 years ago I'm not sure I agree with the need for making test logging append. Appending to an existing log may actually be a surprise rather than a feature.
Ah, it's not just append, it's O_APPEND | O_TRUNC(with | O_WRONLY | O_CREAT) which is like first re-creating the file(so it's 0 bytes initially due to O_TRUNC) and then appending to it(which is supposedly: Opening a file in append mode (a as the first character of mode) causes all subsequent write operations to this stream to occur at end-of-file, as if preceded the call: fseek(stream, 0, SEEK_END); from man 3 fopen, or from man 3p open: O_APPEND If set, the file offset shall be set to the end of the file prior to each write., or from man 2 open: O_APPEND The file is opened in append mode. Before each write(2), the file offset is positioned at the end of the file, as if with lseek(2). The modification of the file offset and the write operation are performed as a single atomic step. - although see [1] to find how true that is with fopen at least)
automake could also do that in their test-driver script, I suggested it here
EDIT: oh I almost forgot, all writers to the same log file would have to have it opened in that mode, else it won't work. ie. both check and test-driver would have to do it, else overwriting would still occurr.
In the situation you ran into two streams were being written to the same file, correct?
Yes.
Midnight Commander is(and has been) using this in their tests(bug here), for example in
https://github.com/MidnightCommander/mc/blob/ee08fa9f56929b5ed2f7404b64c6e3654a1a1848/tests/src/filemanager/do_cd_command.c#L172
but I guess either they didn't know it's the same log file that /usr/share/automake-1.16/test-driver was logging to, or likely they know but just wanted to log to the same file so as to avoid having more than 1 log file for each test.
But it turns out there are other situations, a bit unrelated to this(although this could still hit them), where multiple streams in append mode can still interleave their output [1] especially if buffer size is less than 128 bytes.
[1] https://sourceware.org/bugzilla/show_bug.cgi?id=24621
Anyway, I'm quite happy with my workarounds. Applied locally in all of these Arch Linux packages: bash, automake, check.
I don't expect check to make any changes because of all this. But this was a really fun experience in discovering all this stuff. Thank you btw!
brarcher
commented
5 years ago Thanks for sharing your experience
EDIT: jump to reproduction steps using
check_moneyexample!Note: ignore all other comments(of mine) until that one, to save your time :)
testing latest git master local/check 0.12.0.r36.gd6c1ffe-1
or
so this part is from just a few lines before, repeated:
or,