Flux-core: Wreck job archival causes a race condition

[SteVwonder]

I am currently experiencing what I believe to be a race condition with the job archival.

The simulator inserts information into the kvs about jobs after they have completed. In a non-deterministic manner, some of the jobs never have this information inserted into their KVS directories. I assumed that this was do to a race condition with the job archival and the put, so I ending up writing my own archive job function that moves a directory, commits, and then tries to put into the new directory (followed by a commit). It pretty consistently fails (the fail is silent, as the information never makes it into the directory). If I add a sleep of 1 second after the 1st commit, it succeeds more often. If I lump the move and the put into a single commit, it fails just as frequently.

Any thoughts? I am not sure if this expected behavior or not. I can try making a small reproducer if it would help.

[SteVwonder]

Here is a snippet of what the failing archival looks like:

static int archive_job (ssrvctx_t *ctx, flux_lwj_t *job)
{
    char *from = NULL;
    char *to = NULL;
    char *complete_key = NULL;
    double sim_time = ctx->sctx.sim_state->sim_time;
    int rc = -1;

    flux_log (ctx->h, LOG_DEBUG, "%s: archiving job %"PRId64"", __FUNCTION__, job->lwj_id);

    if (asprintf (&to, "lwj.%"PRId64"", job->lwj_id) < 0
        || asprintf (&from, "lwj-active.%"PRId64"", job->lwj_id) < 0) {
        flux_log_error (ctx->h, "archive_lwj: asprintf");
        goto out;
    }
    if ((rc = kvs_move (ctx->h, from, to)) < 0) {
        flux_log_error (ctx->h, "kvs_move (%s, %s)", from, to);
        goto out;
    }

    if (kvs_commit (ctx->h) < 0)
        flux_log_error (ctx->h, "kvs_commit");

    //sleep(1);
    asprintf(&complete_key, "lwj.%"PRId64".complete_time", job->lwj_id);
    if (kvs_put_double (ctx->h, complete_key, sim_time) < 0) {
        flux_log_error (ctx->h, "%s: kvs_put", __FUNCTION__);
        goto out;
    }
    if (kvs_commit(ctx->h) < 0) {
        flux_log_error (ctx->h, "%s: kvs_commit", __FUNCTION__);
        goto out;
    }

out:
    free (to);
    free (from);
    free (complete_key);
    return (rc);
}

[SteVwonder]

A dropcache in place of the sleep also seems to improve things. I will work on a reproducer to see if it occurs outside of the simulator.

[grondo]

The function above runs in the simulator? I assume this is for simulated run of a job, and thus wrexecd is not also a writer to lwj.<id>?

The reproducer might help us understand what is going on globally, if it isn't too difficult to create.

[garlick]

Is this code racing with the similar code in wrexecd?

It ought to work - we've tested this pretty hard.

[SteVwonder]

I was leveraging the wrexecd job archival, but while trying to diagnose the problem, my first instinct was to comment out the wrexecd code, copy it over to code in the simulator, and try and get the move and put as close together as possible (so that I could try different orderings of the calls, etc). I certainly could have introduced bugs in that process. So I am working on a reproducer now. I hope that it will reveal a mistake on my part _fingers crossed_.

[grondo]

This doesn't solve the issue with the standalone code above, but I'm noticing that there is no event or other way for a third party to key off job archive completion. If you need this functionality for the simulator we may have to generate an event in wrexecd once archive is complete. We could also move the generation of the "wreck.complete" event to after the archive is finished.

[SteVwonder]

@grondo: Moving the state change to "complete" until after the archival worked perfectly!

I am still working on a reproducer because I am totally confused as to what is going on, and I'm hoping it will clarify some things.

[SteVwonder]

@grondo & @garlick, clarifying question:

In the case of job archival, I would assume that any kvsdir objects that used to point to "lwj.X" would no longer be valid after the archival (since the symlink was deleted and the active directory was moved). Is this the case?

(I don't think this issue is the cause, but just out of curiosity).

[garlick]

Right, once the directory moves, you'd need to get a new kvsdir.

To clarify, the archival consists of moving lwj-active.X to lwj.X.

[grondo]

Moving the state change to "complete" until after the archival worked perfectly!

Cool! If you want, go ahead and open a PR!

[SteVwonder]

I created a test involving 2 processes.

• Process 1 creates lwj-active directories and lwj symlinks, populates the directory with random data, performs the archive, and then fill the directory with known test data ("completed time")
• Process 2 continually checks the kvs for the existence of the "known" key ("complete_time") and verifies that the values are correct once the key exists

This is similar to how the simulator/initial_program operate. The main difference being that the initial_program is running a reactor and checks/waits for the keys after the jobs' states change to "completed". The test runs just fine (no errors). So I'm not quite sure what is happening in the simulator. Maybe the reactor loop is important? Maybe I should try leveraging wreck instead of manually creating/archiving lwj directories?

I will investigate further (and submit a PR) next week, but for now I will stick with the wreck modification (I have deadline this Friday). Thanks for the help @grondo and @garlick!

[SteVwonder]

After spending the whole day trying to create a reproducer, I cannot replicate the issue with a more minimal set of code. I'm in a bit of a catch 22: I don't understand what is causing the issue so I am struggling to create a reproducer and without a reproducer I am struggling to understand what is going. My current hunch is that it is somehow related to https://github.com/flux-framework/capacitor/issues/5, but at this point, I am ok with just moving on and submitting a PR with the changes to wreck if you both are ok with the proposed modification to wreck: send the complete event after archival.

[grondo]

@SteVwonder great thanks for doing that!

[garlick]

I am ok with just moving on and submitting a PR with the changes to wreck if you both are ok with the proposed modification to wreck: send the complete event after archival.

@SteVwonder did this change ever happen? Looking at wrexecd.c, it would seem that archive_lwj() is the last thing before exiting (no event is sent after that).

[SteVwonder]

@garlick: it did not. Thanks for the reminder. I'll submit a PR by the end of the week.