Why does crew::crew_worker(... show up in logs only *sometimes*?

[Aariq]

My institution's HPC is updating it's OS and I'm migrating pipelines I'm actively working on and occasionally running into issues (like #50). While troubleshooting, I noticed that on the old cluster (running CentOS) I get worker logs that end with:

/var/spool/slurm/d/job3209062/slurm_script: line 11: 30256 Terminated              Rscript -e 'crew::crew_worker(settings = list(url = "<redacted>", asyncdial = FALSE, autoexit = 15L, cleanup = 1L, output = TRUE, maxtasks = Inf, idletime = 2e+06, walltime = Inf, timerstart = 0L, tls = c("-----BEGIN CERTIFICATE-----<redacted>\n-----END CERTIFICATE-----\n", ""), rs = c(10407L, -93166921L, -1085057140L, -927254755L, 1993644858L, -1889779853L, -1148541416L)), launcher = "hpc_large", worker = 1L, instance = "fdcb9bfce8ed797c7ba97d0a", options_metrics = crew::crew_options_metrics(path = NULL, seconds_interval = 5))'

While on the new cluster (running Rocky Linux) I get logs that just end in Terminated. Why is that? Everything else is the same (R version, package versions) except which BLAS and LAPACK is used.

I'm not sure if it is important to see all the information printed there, but seems like some of it (e.g. the url) could be useful for debugging.

[wlandau]

Hard to say, but there are times when crew may terminate a worker before it has a chance to dial into the main process. If a worker takes more than seconds_launch to dial in, then crew's policy is to cancel the current worker instance and retry with a new one. Whenever that happens, it is possible that both worker instances will both launch and fight over the websocket, so crew.cluster terminates the old one with qdel/scancel to prevent it from meddling. It's possible that the logs you are seeing are stale worker instances that start on the cluster but then get cancelled before crew_worker() starts.

[wlandau]

Or, maybe some workers are in the queue when the pipeline finishes, then crew cancels them with scancel before they start. Can a log get created for a job that gets cancelled while it is still in the queue?

[Aariq]

Sorry, I don't mean to belabour this—I just want to make sure I'm understanding correctly. All of the worker logs end in just Terminated, without all the Rscript -e bits. Would that still be expected for a successful run? The log of the main process doesn't indicate any issues and no targets were skipped. I'll try making these tests take a little longer and see if that gives the workers a chance to "dial in"

[wlandau]

Would that still be expected for a successful run?

The lack of Rscript -e 'crew::crew_worker()' does not indicate a problem with the pipeline or the results. It just indicates that the worker never dialed in and so all the targets were completed on different workers. In other words, the logs without Rscript -e 'crew::crew_worker()' were from SLURM jobs that turned out to be irrelevant to the pipeline. These superfluous jobs may have come about because they were submitted shortly before the pipeline ended, or crew's auto-scaling had trouble predicting the demand for workers for the near-term future. Either way, if we believe the logs, these jobs did not interact with the pipeline at all, and there were enough other workers to run everything that needed to run.

[Aariq]

Interesting.. but in this case there were no logs that had the Rscript -e 'crew::crew_worker()' lines. The logs from all the workers were missing these lines.

[wlandau]

Hmmm that one's a mystery. If you know those targets actually ran on SLURM nodes (verifiable by returning the hostname with the result) then it may be an issue with how logging works on the cluster.