CIFuzz seems to fail sporadically

[evverx]

It appears CIFuzz fails to delete temporary corpora from time to time with:

2021-03-13T15:34:55.2974771Z 2021-03-13 15:34:55,296 - root - INFO - RUN_FUZZERS_MODE is: ci
2021-03-13T15:34:55.2978883Z 2021-03-13 15:34:55,297 - root - INFO - Using OSS-Fuzz as ClusterFuzz deployment.
2021-03-13T15:34:55.2982426Z 2021-03-13 15:34:55,297 - root - INFO - Using address sanitizer.
2021-03-13T15:34:55.3078727Z 2021-03-13 15:34:55,307 - root - INFO - Fuzz targets: ['/github/workspace/out/fuzz-network-parser']
2021-03-13T15:34:55.3079961Z 2021-03-13 15:34:55,307 - root - INFO - Fuzzer fuzz-network-parser, started.
2021-03-13T15:34:57.2870798Z 2021-03-13 15:34:57,286 - root - INFO - Running command: docker run --rm --privileged --volumes-from 8f4401845a0e -e OUT=/github/workspace/out -e FUZZING_ENGINE=libfuzzer -e SANITIZER=address -e CIFUZZ=True -e RUN_FUZZER_MODE=interactive gcr.io/oss-fuzz-base/base-runner bash -c run_fuzzer fuzz-network-parser -seed=1337 -len_control=0 -max_total_time=600 /github/workspace/out/cifuzz-corpus/fuzz-network-parser
2021-03-13T15:45:07.2951342Z 2021-03-13 15:45:07,291 - root - ERROR - Fuzzer fuzz-network-parser timed out, ending fuzzing.
2021-03-13T15:45:07.2955102Z 2021-03-13 15:45:07,292 - root - INFO - Deleting corpus, seed corpus and fuzz target of fuzz-network-parser to save disk.
2021-03-13T15:45:07.7340109Z Traceback (most recent call last):
2021-03-13T15:45:07.7341634Z   File "/opt/oss-fuzz/infra/cifuzz/run_fuzzers_entrypoint.py", line 97, in <module>
2021-03-13T15:45:07.7342241Z     sys.exit(main())
2021-03-13T15:45:07.7343023Z   File "/opt/oss-fuzz/infra/cifuzz/run_fuzzers_entrypoint.py", line 83, in main
2021-03-13T15:45:07.7343691Z     result = run_fuzzers.run_fuzzers(config)
2021-03-13T15:45:07.7344929Z   File "/opt/oss-fuzz/infra/cifuzz/run_fuzzers.py", line 208, in run_fuzzers
2021-03-13T15:45:07.7345646Z     if not fuzz_target_runner.run_fuzz_targets():
2021-03-13T15:45:07.7346674Z   File "/opt/oss-fuzz/infra/cifuzz/run_fuzzers.py", line 136, in run_fuzz_targets
2021-03-13T15:45:07.7347848Z     result = self.run_fuzz_target(target)
2021-03-13T15:45:07.7348836Z   File "/opt/oss-fuzz/infra/cifuzz/run_fuzzers.py", line 95, in run_fuzz_target
2021-03-13T15:45:07.7349483Z     fuzz_target_obj.free_disk_if_needed()
2021-03-13T15:45:07.7350301Z   File "/opt/oss-fuzz/infra/cifuzz/fuzz_target.py", line 159, in free_disk_if_needed
2021-03-13T15:45:07.7350998Z     shutil.rmtree(self.latest_corpus_path)
2021-03-13T15:45:07.7351603Z   File "/usr/lib/python3.5/shutil.py", line 478, in rmtree
2021-03-13T15:45:07.7352188Z     onerror(os.rmdir, path, sys.exc_info())
2021-03-13T15:45:07.7352755Z   File "/usr/lib/python3.5/shutil.py", line 476, in rmtree
2021-03-13T15:45:07.7353237Z     os.rmdir(path)
2021-03-13T15:45:07.7354174Z OSError: [Errno 39] Directory not empty: '/github/workspace/out/cifuzz-corpus/fuzz-network-parser'

The full logs can be found at https://github.com/systemd/systemd/actions/runs/649329522 and https://github.com/systemd/systemd/actions/runs/647504148

[jonathanmetzman]

Ouch. Thanks for reporting this. I wish I knew why exactly this is happening.
My best guess is that fuzzing isn't completely done when the process times out (maybe something to do with docker and child processes) so fuzzing continues to write to the directory as rmtree is called.
I was able to get the exception by running an infinite loop that created a file in a directory, running that loop and then trying to run rmtree in another process. So this does seem plausible to me.

[jonathanmetzman]

Ouch. Thanks for reporting this. I wish I knew why exactly this is happening.
My best guess is that fuzzing isn't completely done when the process times out (maybe something to do with docker and child processes) so fuzzing continues to write to the directory as rmtree is called.
I was able to get the exception by running an infinite loop that created a file in a directory, running that loop and then trying to run rmtree in another process. So this does seem plausible to me.

Apparently we aren't even killing the process after the timeout (passing timeout to communicate as we do here does not do this see python docs).
Even if we did kill the parent process, that wouldn't be enough since the actual fuzzer gets run in child process. We need to end all the children as well.
Note that the fuzzing process won't hang around forever, since it was passed a timeout. It's just that relying on this timeout can be racy.
#5391 should work around this issue, but there are still more underlying ones to fix.

[jonathanmetzman]

@evverx You aren't still seeing this issue right?

[oliverchang]

Ouch. Thanks for reporting this. I wish I knew why exactly this is happening.
My best guess is that fuzzing isn't completely done when the process times out (maybe something to do with docker and child processes) so fuzzing continues to write to the directory as rmtree is called.
I was able to get the exception by running an infinite loop that created a file in a directory, running that loop and then trying to run rmtree in another process. So this does seem plausible to me.

Apparently we aren't even killing the process after the timeout (passing timeout to communicate as we do here does not do this see python docs).
Even if we did kill the parent process, that wouldn't be enough since the actual fuzzer gets run in child process. We need to end all the children as well.
Note that the fuzzing process won't hang around forever, since it was passed a timeout. It's just that relying on this timeout can be racy.
#5391 should work around this issue, but there are still more underlying ones to fix.

The parent process is docker right? if we kill that I believe it should bring down all the child processes since it has its own process namespace.

[evverx]

@evverx You aren't still seeing this issue right?

@jonathanmetzman looks like it's gone. Thanks!

[jonathanmetzman]

Ouch. Thanks for reporting this. I wish I knew why exactly this is happening.
My best guess is that fuzzing isn't completely done when the process times out (maybe something to do with docker and child processes) so fuzzing continues to write to the directory as rmtree is called.
I was able to get the exception by running an infinite loop that created a file in a directory, running that loop and then trying to run rmtree in another process. So this does seem plausible to me.

Apparently we aren't even killing the process after the timeout (passing timeout to communicate as we do here does not do this see python docs).
Even if we did kill the parent process, that wouldn't be enough since the actual fuzzer gets run in child process. We need to end all the children as well.
Note that the fuzzing process won't hang around forever, since it was passed a timeout. It's just that relying on this timeout can be racy.
#5391 should work around this issue, but there are still more underlying ones to fix.

The parent process is docker right? if we kill that I believe it should bring down all the child processes since it has its own process namespace.

Thanks for mentioning this. I'm going to test this. If it's true (and it would be kind of crazy if it weren't) it will make my life a lot easier.