Intermittent container settings error with Azure pool

[pditommaso]

I'm getting an intermittent error when running Nextflow tests with Azure

https://github.com/nextflow-io/nextflow/runs/4586840414?check_suite_focus=true

It reports a problem with the container settings, however, I don't see anything wrong

A bit more suspicious the second error read timeout, tho not clear which component is performing that connection. Maybe just a temporary hiccup.

[pditommaso]

@manuelesimi have you ever seen this? ☝️

[manuelesimi]

I'll take the request on .command.run back. This an AZ batch job and the container properties are passed to the Batch API.

Is there any way to inspect the containerOptions for this task?

[manuelesimi]

I dug a bit into the stacktrace of the CI and noticed you are running the rnaseq-nf pipeline. So, there are no custom container options. I tried the same batch configuration (but with a different pipeline) and it worked well. Odd.

One point that could help to shed some light. The error appears for the second task submitted, not the first:

[86/69804e] Submitted process > RNASEQ:INDEX (ggal_1_48850000_49020000)
[82/48acf6] Submitted process > RNASEQ:FASTQC (FASTQC on ggal_gut)
Error executing process > 'RNASEQ:FASTQC (FASTQC on ggal_gut)'

Caused by:
  At least one value of specified task container settings is invalid

Since you mentioned you're getting this error occasionally, is it always FASTQC that generates the error? If so, and INDEX works, then there must be something in FASTQC that bothers AZ Batch.
Just speculating...

[pditommaso]

Starting to think that's could the rate limit for the Quay registry

nextflow/validation/azure.config

Line 8 in 7491610

container = 'quay.io/nextflow/rnaseq-nf:latest'

[manuelesimi]

As far as I know, quai did not introduce a rate limit (docker hub did). But I see that rnseq-nf builds from miniconda3 on docker hub, so the limit would apply. One solution often suggested is to republish the base image to the quai registry and avoid docker hub pulls.

However, if the limit was the reason, you should get this error randomly, even when you run AWS tests. My understanding is that you're getting this error only on Azure tests. So it must be something specific to this executor.

[pditommaso]

Tho I agree it should not be a problem with rate limits, still quay have some

only rate limits in the most severe circumstances to maintain service levels (e.g. tens of requests per second from the same IP address).

https://access.redhat.com/articles/5531191

Don't think Docker hub should be involved since the image is on Quay.

I'm trying a new build with 21.10.x branch to see if it happens also with that or it's only a problem with current master

[pditommaso]

The last build it's all green. I conclude that was some kind of temporary issue on Azure side https://github.com/nextflow-io/nextflow/actions/runs/1608780159

[manuelesimi]

Wonderful, case closed :)

[pditommaso]

Umm, not got a timeout error. Still think it's an Azure issue, better to keep an eye open if there's any regression on Azure Batch execution on 21.12.0-edge release

+ echo 'Azure batch tests'
+ bash azure.sh
+ /home/runner/work/nextflow/nextflow/nextflow -C ./azure.config run nextflow-io/rnaseq-nf -with-report -with-trace -with-tower
N E X T F L O W  ~  version 21.12.0-edge
Launching `nextflow-io/rnaseq-nf` [elated_knuth] - revision: 3976659137 [master]
 R N A S E Q - N F   P I P E L I N E
 ===================================
 transcriptome: /home/runner/.nextflow/assets/nextflow-io/rnaseq-nf/data/ggal/ggal_1_48850000_49020000.Ggal71.500bpflank.fa
 reads        : /home/runner/.nextflow/assets/nextflow-io/rnaseq-nf/data/ggal/ggal_gut_{1,2}.fq
 outdir       : results
 
Uploading local `bin` scripts folder to az://my-data/work/tmp/62/346b4585a18781049336197e0f122b/bin
Monitor the execution with Nextflow Tower using this url https://tower.nf/user/pditommaso/watch/1GYgQ6qKRGiwi6
[20/4b8d6b] Submitted process > RNASEQ:INDEX (ggal_1_48850000_49020000)
[27/5c7a30] Submitted process > RNASEQ:FASTQC (FASTQC on ggal_gut)
Error executing process > 'RNASEQ:FASTQC (FASTQC on ggal_gut)'

Caused by:
  timeout

[manuelesimi]

I'll switch to use version 21.12.0-edge too and let you know if any problem arises. However, I'm working on a different region, I might not experience the same issues if the problem is on the Azure side.

[pditommaso]

Nice, note 21.12.0-edge was skipped, the latest is 21.12.1-edge

[pditommaso]

No way, this still continues to happen. can't see anything wrong in the log

Dec-23 11:59:14.222 [main] DEBUG nextflow.executor.Executor - [warm up] executor > azurebatch
Dec-23 11:59:14.228 [main] DEBUG n.processor.TaskPollingMonitor - Creating task monitor for executor 'azurebatch' > capacity: 1000; pollInterval: 10s; dumpInterval: 5m 
Dec-23 11:59:14.280 [main] DEBUG nextflow.util.CustomThreadPool - Creating default thread pool > poolSize: 3; maxThreads: 1000
Dec-23 11:59:15.737 [Task submitter] DEBUG n.c.azure.batch.AzBatchTaskHandler - [AZURE BATCH] Submitting task reads_pair - work-dir=az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca
Dec-23 11:59:16.168 [Task submitter] DEBUG n.cloud.azure.batch.AzBatchService - [AZURE BATCH] Checking VM pool id=nextflow-ci; size=AzVmType(name:Standard_D4_v3, maxDataDiskCount:8, memory:16 GB, numberOfCores:4, osDiskSize:1023 GB, resourceDiskSize:100 GB)
Dec-23 11:59:16.173 [Task submitter] DEBUG n.cloud.azure.batch.AzBatchService - [AZURE BATCH] Executor options=endpoint=null; account-name=nfbatchtest; account-key=s5NOh...
Dec-23 11:59:18.344 [Task submitter] DEBUG n.cloud.azure.batch.AzBatchService - Task output path: .exitcode -> az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca
Dec-23 11:59:18.345 [Task submitter] DEBUG n.cloud.azure.batch.AzBatchService - Task output path: .command.log -> az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca
Dec-23 11:59:18.538 [Task submitter] DEBUG n.c.azure.batch.AzBatchTaskHandler - [AZURE BATCH] Submitted task reads_pair with taskId=nextflow.cloud.azure.batch.AzTaskKey(job-19feefda14381a92528d-reads_pair, nf-09bc36cc4f6ea426fc8b82a39ce76dca)
Dec-23 11:59:18.540 [Task submitter] INFO  nextflow.Session - [09/bc36cc] Submitted process > reads_pair
Dec-23 11:59:24.438 [Task monitor] DEBUG n.c.azure.batch.AzBatchTaskHandler - [AZURE BATCH] Task status reads_pair taskId=nextflow.cloud.azure.batch.AzTaskKey(job-19feefda14381a92528d-reads_pair, nf-09bc36cc4f6ea426fc8b82a39ce76dca); running=true
Dec-23 12:01:24.564 [Task monitor] DEBUG n.c.azure.batch.AzBatchTaskHandler - [AZURE BATCH] Cannot read exitstatus for task: `reads_pair` | az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca/.exitcode
Dec-23 12:01:24.768 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 1; name: reads_pair; status: COMPLETED; exit: -; error: nextflow.exception.ProcessUnrecoverableException: At least one value of specified task container settings is invalid; workDir: az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca]
Dec-23 12:01:24.933 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump output of process 'null' -- Cause: java.nio.file.NoSuchFileException: az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca/.command.out
Dec-23 12:01:25.081 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'null' -- Cause: java.nio.file.NoSuchFileException: az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca/.command.err
Dec-23 12:01:25.229 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'null' -- Cause: java.nio.file.NoSuchFileException: az://my-data/work/09/bc36cc4f6ea426fc8b82a39ce76dca/.command.log

[manuelesimi]

Any trouble on your azure subscription? How many files do you have on the my-data blob storage? Could you wipe it out or use another blob for testing?

[pditommaso]

ummmm, let me try

[pditommaso]

Other users are reporting the same error using 21.10.6, therefore it's not a problem caused by the latest edge

https://gitter.im/nextflow-io/nextflow?at=61cde6915dc6213cd4ba2265

[manuelesimi]

I have been actively using version 21.10.4 for the past weeks on a project, and I have never experienced this issue. It might be worthy to check the differences between the two version.
It's worrisome that the behavior is not consistent nor easy to reproduce.

[pditommaso]

 git diff v21.10.4 v21.10.6 -- plugins/nf-azure/

none :/

[manuelesimi]

I'm getting back to think that I might work on a different Azure region.

[pditommaso]

I think the same it should be a problem in some Azure region

[manuelesimi]

So, I finally encountered this error too after updating to the latest code on master (but I can't imagine how this relates to the error, since the plugin version is still 0.11.2).

Looking at the error messages and the task log on Azure, I got the feeling that from time to time the docker client on the Azure node fails to pull the image from the Docker registry. This error:

UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=60)

is often associated to docker-compose (I speculate it could be used by Azure batch to run multiple containers on the same node).

Dropping my two cents here, we could consider to:

1. have a loop of attempts to pull the image
2. set DOCKER_CLIENT_TIMEOUT and/or COMPOSE_HTTP_TIMEOUT on the node as part of the pool configuration steps.

Not sure if either of them would solve.

[vsmalladi]

Ya could be a docker pull issue, but seems to be an azure issue only which is odd.

[pditommaso]

Looking if there's any pull retry, can find anything. Maybe DOCKER_CLIENT_TIMEOUT and/or COMPOSE_HTTP_TIMEOUT as suggested by Manuele can help

[manuelesimi]

I'm leaning in favor of a random issue with the quay registry (either connection or rate limit) due to some Azure-specific reasons (not under NF's control). As I mentioned, it never occurs with Docker + paid subscription.

[manuelesimi]

Looking if there's any pull retry, can find anything. Maybe DOCKER_CLIENT_TIMEOUT and/or COMPOSE_HTTP_TIMEOUT as suggested by Manuele can help

I think this would require to separate the pull and run commands, and check the return status of the pull before executing the run.

[vsmalladi]

I agree. The only thing that can be done is increase the timeout length to bypass this.

export DOCKER_CLIENT_TIMEOUT=120
export COMPOSE_HTTP_TIMEOUT=120

[manuelesimi]

I tried to fix it in this PR #2534.

[pditommaso]

Since it didn't solve the problem I've reverted the above PR. d5679dd

[manuelesimi]

Sure, it makes totally sense. Thanks.

[pditommaso]

Manuele find out that this problem is related to this Azure Batch issue Azure/Batch#4. It looks like happening when the image is too big (not in this case) but consequently it can also be cause by a slow network connection.

[pditommaso]

Interesting update Azure/Batch#4 (comment)

[pditommaso]

In both cases using batch.node.centos 8 as sku

nextflow/plugins/nf-azure/src/main/nextflow/cloud/azure/config/AzPoolOpts.groovy

Line 41 in 6930408

static public final String DEFAULT_SKU = "batch.node.centos 8"

[pabloaledo]

Hello, I would like to reopen this discussion as we are experiencing the same error when running large pipelines in Azure Batch (rnaseq full profile).

Here is what we have observed:

• The error occurs most frequently with the biocontainers/samtools container. I'm not sure if this issue is from quay.io or dockerhub.io, as we are currently pulling it from wave to add a specific layer.
• This image is only 92.7MB, which is much smaller than the ones mentioned in this thread.
• We are still encountering both the At least one value of specified task container settings is invalid and Read timed out. (read timeout=60) errors.
• We are using Standard_D4_v3 machine types.
• We have tried doubling DOCKER_CLIENT_TIMEOUT and COMPOSE_HTTP_TIMEOUT without success.
• We have also tried setting process.errorStrategy = 'retry' and process.maxRetries = -1 without success.

[pditommaso]

don't use Standard_D4_v3!

[pabloaledo]

ok, fair point. Will request quota for a better machine.

[pabloaledo]

Hey sorry, I meant Standard_D16_v3 is that we are using, but in any case it is worth trying another family. The reason I've not changed this before is that I changed the errorStrategy and that seems to solve the problem, but it appeared again today :/.