Fifo exception warning in test output

[Seeker04]

We get the following warning in the unit test output:

Warning: [Thread 4] Thread running "fifo:process_fifo("/tmp/test-fifo")" died on exception: open/3: source_sink `"/tmp/test-fifo"' does not exist (No such file or directory)

It does not fail the test, but looks a little ugly.

Steps to reproduce:

• Run make test

[Seeker04]

I created this issue a little too hastily without paying enough attention to the actual error output I see.

This is what I see in the Docker build output:

error(syntax_error(end_of_file),file(/tmp/test-terms,1,4,3))

The exception itself is intentional, because this test makes it read an invalid syntax. In this case plwm is supposed to write to user_error (stderr) which usually goes to the logfile. So the user is informed of the erroneous term they pushed to the fifo.

What's queer is that on my Void linux install, user_output (stdout) and user_error (stderr) are both suppressed by default in PlUnit.

But in the ubuntu:latest Docker image, it outputs everything from unit tests (can be verified by adding a writeln/1 call to a test).

I believe, it simply comes from the difference in the swipl versions:

SWI-Prolog version 9.0.4 for x86_64-linux # Docker Ubuntu
SWI-Prolog version 9.2.9 for x86_64-linux # Void

Note: :- set_test_options([output(never)]). (documented here) doesn't work in these versions.

---

With all this said, the above output I see is not what you reported.

Could you please recheck this and attach the full make test output?

[xelxebar]

$ make test 2>test.log
tests/run_unit_tests.sh
tests/unit_tests/animation.plt
tests/unit_tests/fifo.plt
tests/unit_tests/layout.plt
tests/unit_tests/menu.plt
tests/unit_tests/utils.plt
$ cat test.log
[16/16] animation_tests:interpolate_geom - (stepcnt < 0) ..................................................... passed (0.000 sec)
% All 16 tests passed in 0.046 seconds (0.021 cpu)
[2/5] fifo_tests:setup_fifo + (already exists) ............................................................... passed (0.004 sec)
Warning: [Thread 4] Thread running "fifo:process_fifo("/tmp/test-fifo")" died on exception: open/3: source_sink `"/tmp/test-fifo"' does not exist (そのようなファイルやディレクトリはありません)
[4] current_output closed; set to user_output
[5/5] fifo_tests:read_terms - ................................................................................ passed (0.000 sec)
% All 5 tests passed in 0.148 seconds (0.032 cpu)
[11/11] layout_tests:stack_ys - .............................................................................. passed (0.000 sec)
% All 11 tests passed in 0.019 seconds (0.019 cpu)
[43/43] menu_tests:list_cmds ................................................................................. passed (0.224 sec)
% All 43 tests passed in 0.788 seconds (0.067 cpu)
[49/49] utils_tests:str_withoutlastch - (empty input) ........................................................ passed (0.000 sec)
% All 49 tests passed in 0.254 seconds (0.044 cpu)

[Seeker04]

From the looks of it, the open(FifoPath, read, Fifo) line causes it for you here.

Can you please check a few things?

• /tmp directory exists and the user running make test has write permission there.
• A test-fifo file does not already exist on that path (or if it does, there's write permission for it).
• Try setting a path that's under you user's home directory by adjusting this line in fifo.plt:

optcnf_then(fifo_path(FifoPath), Then) :- FifoPath = "/tmp/test-fifo", Then.

• Verify that the file is created in the first place by adding a sleep(10) before the delete_file(FifoPath) line in the first fifo.plt test. This gives you enough time to see if /tmp/test-fifo really exists. (Though it has to, otherwise that test should fail...)
• From the output, it's not evident exactly which test causes this. There are 5 in fifo.plt. Try commenting them out too see which throws this.
• Create and delete it manually to see if it works in your environment:

mkfifo /tmp/test-fifo
ls -l /tmp/test-fifo
rm /tmp/test-fifo
ls -l /tmp/test-fifo

• Check you swipl version with swipl --version

[xelxebar]

I think it might be a race condition somewhere. The error is happening only about 80% with the below process.

It's setup_fifo + (already exists) that's triggering the warning. I've disabled other tests and confirmed the issue in $HOME just to demonstrate it's not a permissions or missing path issue. Note that without setup_fifo unrelated errors result, so I keep it enabled:

$ grep '^%\? *test' tests/unit_tests/fifo.plt
test("setup_fifo +", [
test("setup_fifo + (already exists)", [
% test("process_fifo", [
% test("read_terms +", [
% test("read_terms -", [
$ swipl -g run_tests -t halt tests/unit_tests/fifo.plt 2>test.err
$ cat test.err
[2/2] fifo_tests:setup_fifo + (already exists) ............................................................... passed (0.004 sec)
Warning: [Thread 4] Thread running "fifo:process_fifo("/home/x/test.fifo")" died on exception: open/3: source_sink `"/home/x/test.fifo"' does not exist (そのようなファイルやディレクトリはありません)
[4] current_output closed; set to user_output
% All 2 tests passed in 0.029 seconds (0.021 cpu)

Also note that I only see the warning when redirecting stderr like this. In a second terminal, we use inotifywait to directly watch for filesystem changes as the test runs. No need for sleep/1:

$ inotifywait -m /home/x -e create -e delete
Setting up watches.
Watches established.
./ CREATE test.fifo
./ DELETE test.fifo
./ CREATE test.fifo
./ DELETE test.fifo
./ CREATE test.fifo
./ DELETE test.fifo

So we are creating and deleting three times. Running just setup_fifo by itself only creates and deletes once, so it's setup_fifo + (already exists) that's creating and deleting twice. Since creation + deletion happen back-to-back very quickly, this also suggests a potential race condition.

[Seeker04]

Yeah, that unrelated error is because the tests check the number of threads running. So the 2nd test goes with the presumption that the 1st has already spawned one. Unit tests should be independent and isolated, but there's no way to delete detached threads (as far as I know), so it's a must here.

Anyway, I think I see where the problem lies now. It's indeed a race condition:

1. setup_fifo/0 creates the fifo
2. setup_fifo/0 starts the process_fifo/1 thread
3. Rest of the testcase runs, including the cleanup part with delete_file(FifoPath)
4. 2nd thread tries open(FifoPath, read, Fifo)

This is a possible sequence of execution. It can happen if the 2nd thread is slow enough, i.e. it only executes its first term after the main thread had already finished with the rest of the test.

Could you please try and see what happens if you add sleep(0.1), lines before the first two delete_file(FifoPath) lines in fifo.plt?
I.e. at these tests: setup_fifo + and setup_fifo + (already exists).

[xelxebar]

Okay, I think I got this pinned down. Yes, throwing in a sleep/1 does hack around the error, but there's maybe a better way: #101.