trouble setting dask distributed worker to log level debug

[lastephey]

What happened:

Dear Dask devs,

I am unable to set the only the dask distributed worker log level to 'DEBUG' when manually starting a cluster. I have seen there have been several issues and PRs on this subject, but I apologize-- it's still not totally clear to me what the state is or what the correct syntax is.

#2937
#2419
#2952
#4642

What you expected to happen:

I was trying to follow the advice in the dask distributed docs. I copy/pasted the logging yaml example into the configuration conversion utility to try to generate the right environment variables. The example formatting generated was

export DASK_LOGGING__DISTRIBUTED="debug"
export DASK_LOGGING__DISTRIBUTED.CLIENT="debug"
export DASK_LOGGING__DISTRIBUTED.WORKER="debug"

I saw though in this comment that the dot in the key should translate to a double underscore in the environment variable, so I have changed that in my test below.

Minimal Complete Verifiable Example:

My ultimate goal is to set the workers and maybe client to log level debug, but here I'll demonstrate with the scheduler since it shows the same behavior.

Based on the output of the config generator, I first tried:

DASK_LOGGING__DISTRIBUTED__SCHEDULER=debug \
python -m distributed.cli.dask_scheduler \
    --protocol ucx \
    --interface hsn0 \
    --scheduler-file $scheduler_file &

although this syntax is apparently invalid. It gives the error:

TypeError: Level not an integer or a valid string: {'scheduler': 'debug'}

Based on this comment I also tried:

DASK_LOGGING__DISTRIBUTED=debug \
python -m distributed.cli.dask_scheduler \
    --protocol ucx \
    --interface hsn0 \
    --scheduler-file $scheduler_file &

which does work today, even if it didn't 2 years ago (which is confusing). This turns on logging for everything which is good, but of course it's really verbose. I was hoping I could turn it on only for particular parts of Dask distributed.

tl;dr I only stumbled onto a partially working solution. I would really appreciate it if you could clarify what should/shouldn't work, and perhaps document it somewhere like the logging page.

Anything else we need to know?:

Environment:

• Dask version:

dask                      2022.3.0           pyhd8ed1ab_1    conda-forge
dask-core                 2022.3.0           pyhd8ed1ab_0    conda-forge
dask-cuda                 22.06.00a220401         py38_13    rapidsai-nightly
dask-cudf                 22.04.00a220401 cuda_11_py38_ga02b7c2b44_301    rapidsai-nightly

• Python version: 3.8.5

• Operating System: Running inside a custom container implementation shifter, ubuntu 20.04

• Install method (conda, pip, source): conda

Cluster Dump State:

Thank you all very much for your work on Dask,
Laurie

[mrocklin]

Hi @lastephey !

Good to see you again. Try this maybe?

DASK_LOGGING__DISTRIBUTED=debug python -m distributed.cli.dask_scheduler

[lastephey]

Hi @mrocklin,

Thank you, same to you!

Your suggestion does work, but it seems to turn all other Dask logging to DEBUG also.

Starting the scheduler like

DASK_LOGGING__DISTRIBUTED=debug python -m distributed.cli.dask_scheduler

and then some workers like

python -m dask_cuda.cli.dask_cuda_worker

results in a lot of output, where it appears all parts of Dask distributed are now set to DEBUG logging. Here's a small snippet:

2022-04-14 05:28:28,833 - distributed.core - DEBUG - Calling into handler heartbeat_worker
2022-04-14 05:28:28,833 - distributed.worker - DEBUG - Heartbeat: ucx://10.250.0.42:53529
2022-04-14 05:28:28,834 - distributed.core - DEBUG - Message from 'ucx://10.250.0.42:8786': {'op': 'heartbeat_worker', 'address': 'ucx://10.250.0.42:53529', 'now': 1649914108.833852, 'metrics': {'executing': 0, 'in_memory': 0, 'ready': 0, 'in_flight': 0, 'bandwidth': {'total': 100000000, 'workers': {}, 'types': {}}, 'spilled_nbytes': {'memory': 0, 'disk': 0}, 'cpu': 0.0, 'memory': 466034688, 'time': 1649914108.8323712, 'read_bytes': 33459.160358374196, 'write_bytes': 21298.015515550625, 'read_bytes_disk': 0.0, 'write_bytes_disk': 0.0, 'num_fds': 90, 'gpu_utilization': 0, 'gpu_memory_used': 34465120256, 'gpu': {'utilization': 0, 'memory-used': 34465120256}}, 'executing': {}, 'reply': True}

Is there a way I can change the DEBUG setting in a more targeted manner, i.e. only for dask worker?

Thank you very much,
Laurie

[quasiben]

Configuring individual loggers might not be possible from the command line. The . in the name is surely going to cause some problems. This could be done with the dask configuration YAML file however:

distributed:
  version: 2
  logging:
    distributed: info
    distributed.client: warning
    distributed.scheduler: debug

[lastephey]

Thanks @quasiben, changing the logging settings via the config file does what I need.

Thank you both very much for your help. I'll go ahead and close this.

[dbalabka]

@quasiben, I've implemented the possibility of configuring these loggers via environment variables in the following PR:
dask/dask#10992