CRASH: `Fatal error: failed to create trace file ` ... `window.0000` ...., with `window.0001` directory

[palmer-dabbelt]

Describe the bug
From time to time I have a DynamoRIO crash with an error message along the lines of

Fatal error: failed to create trace file /root/palmerdabbelt/runs/django-mini-drmemtrace_interval-1.OflDffjb/drmemtrace.uwsgi.1937455.5528.dir/raw/window.0000/drmemtrace.uwsgi.1937455.0618.raw.lz4

The resulting trace directory has a window.0001 file instead, so that error message itself seems somewhat sane. I think it's a race -- init_offline_dir() has an unprotected load of the trace window ID:

    if (has_tracing_windows())
        open_new_window_dir(tracing_window.load(std::memory_order_acquire));

and if the trace window has moved

The issue goes away if I just stick a second mkdir in there

diff --git a/clients/drcachesim/tracer/output.cpp b/clients/drcachesim/tracer/output.cpp
index 63a8b9353..c4e40ff00 100644
--- a/clients/drcachesim/tracer/output.cpp
+++ b/clients/drcachesim/tracer/output.cpp
@@ -398,6 +398,11 @@ open_new_thread_file(void *drcontext, ptr_int_t window_num)
             dr_snprintf(windir, BUFFER_SIZE_ELEMENTS(windir), "%s%s" WINDOW_SUBDIR_FORMAT,
                         logsubdir, DIRSEP, window_num);
             NULL_TERMINATE_BUFFER(windir);
+
+           if (!file_ops_func.create_dir(windir))
+                FATAL("Fiailed to create window subdir %s\n", windir);
+           NOTIFY(2, "Created new window dir %s\n", windir);
+
             dir = windir;
         } else if (data->file != INVALID_FILE)
             return false;

but I think that warrants a little refactoring to remove the duplicate calls (and code from open_new_window_dir()). I'll post a patch, unless someone has a better idea of what's going on.

To Reproduce
(Happy to write more, but I think I'm going to fix it myself.)

1. I'm using DCPerf's Django-mini workload.
2. Running with -trace_for_insns 1000 makes this happen almost always.

It's fine without any client, and I haven't tried a debug build.

Expected behavior
I get traces ;)

Screenshots or Pasted Text

Fatal error: failed to create trace file /root/palmerdabbelt/runs/django-mini-drmemtrace_interval-1.OflDffjb/drmemtrace.uwsgi.1937455.5528.dir/raw/window.0000/drmemtrace.uwsgi.1937455.0618.raw.lz4

Versions
I'm running github's main branch from this morning, on an aarch64 machine (CentOS Stream 9-ish).

[abhinav92003]

Thanks for filing the issue.

I see that open_new_thread_file expects some types of failures and retries (e.g., if the path returned by drx_open_unique_appid_file already exists1). But, just to confirm, your claim is that the failures you observed were because the window.0000 sub-directory doesn't exist, right?

init_offline_dir() has an unprotected load of the trace window ID:

But init_offline_dir is invoked in drmemtrace_client_main and fork_init, and in both of those cases there shouldn't be other threads updating the tracing_window in parallel.

The issue goes away if I just stick a second mkdir in there

If it's the first window dir that's missing (window.0000), can you find out why the open_new_window_dir call in init_offline_dir2 didn't create it? I see there are certain error conditions where init_offline_dir may return early.

I'm using DCPerf's Django-mini workload.
Running with -trace_for_insns 1000 makes this happen almost always.

Did you observe the issue to happen with only the above workload, or any workload with -trace_for_instrs 1000?

I see that we don't have any test3 that uses only -trace_for_instrs (without other options like -trace_after_instrs etc, which I suspect may have been hiding this issue). Maybe try adding a new test to show the failure?

[palmer-dabbelt]

Thanks for filing the issue.

I see that open_new_thread_file expects some types of failures and retries (e.g., if the path returned by drx_open_unique_appid_file already exists1). But, just to confirm, your claim is that the failures you observed were because the window.0000 sub-directory doesn't exist, right?

init_offline_dir() has an unprotected load of the trace window ID:
But init_offline_dir is invoked in drmemtrace_client_main and fork_init, and in both of those cases there shouldn't be other threads updating the tracing_window in parallel.

OK, I'll try to figure out what's going on then.

The issue goes away if I just stick a second mkdir in there

If it's the first window dir that's missing (window.0000), can you find out why the open_new_window_dir call in init_offline_dir2 didn't create it? I see there are certain error conditions where init_offline_dir may return early.

I'm using DCPerf's Django-mini workload.
Running with -trace_for_insns 1000 makes this happen almost always.

Did you observe the issue to happen with only the above workload, or any workload with -trace_for_instrs 1000?

I haven't seen it on other workloads, but I haven't really run that many yet.

I see that we don't have any test3 that uses only -trace_for_instrs (without other options like -trace_after_instrs etc, which I suspect may have been hiding this issue). Maybe try adding a new test to show the failure?

OK, I'll give it a shot. Right now my workload is still hanging after this, so I'm going to try and figure out if maybe there's another problem that's really the root cause here and I've just mis-analyzed this one.

Might take a bit, I'm super new to DynamoRIO...