Double printed config

[brunovollmer]

Hey everybody,

I have the problem that each log message is printed out twice. Once with the module name and once with HYDRA (see example output):

[2021-06-08 08:14:54,738][HYDRA] config initialized
[2021-06-08 08:14:54,738][soundmap.util.config][INFO] - config initialized
[2021-06-08 08:14:54,794][HYDRA] starting process image_acquisition_task with pid: 8954
[2021-06-08 08:14:54,794][soundmap.process.process_manager][INFO] - starting process image_acquisition_task with pid: 8954

This feels more like a wrong configuration on my side than a bug. My config looks like this:

defaults:
  - data: data
  - task: task
  - util: util

simulation: false
visualization: true
benchmark: true

hydra:
  output_subdir: null
  job_logging: null
  run:
    dir: .

The goal behind my config is to disable the output dir for the moment and only print the logs to the console. Later on I want to take advantage of the extra output dir and the file logging.

Any suggestions how to resolve this problem?

[omry]

1. Are you attempting to configure the logging directly in your application?
2. Can you produce a minimal runable example reproducing this?

[brunovollmer]

1. No I'm not touching the logger library except for getting the logger object.

2. See below

import hydra
import logging
from omegaconf import DictConfig

logger = logging.getLogger(__name__)


@hydra.main(config_path="conf", config_name="config")
def main(cfg: DictConfig):
    for i in range(10):
        logger.info(i)


if __name__ == "__main__":
    main()

Output:

[2021-06-09 10:16:41,492][HYDRA] 0
[2021-06-09 10:16:41,492][main][INFO] - 0
[2021-06-09 10:16:41,492][HYDRA] 1
[2021-06-09 10:16:41,492][main][INFO] - 1
[2021-06-09 10:16:41,493][HYDRA] 2
[2021-06-09 10:16:41,493][main][INFO] - 2
[2021-06-09 10:16:41,493][HYDRA] 3
[2021-06-09 10:16:41,493][main][INFO] - 3
[2021-06-09 10:16:41,493][HYDRA] 4
[2021-06-09 10:16:41,493][main][INFO] - 4
[2021-06-09 10:16:41,493][HYDRA] 5
[2021-06-09 10:16:41,493][main][INFO] - 5
[2021-06-09 10:16:41,493][HYDRA] 6
[2021-06-09 10:16:41,493][main][INFO] - 6
[2021-06-09 10:16:41,493][HYDRA] 7
[2021-06-09 10:16:41,493][main][INFO] - 7
[2021-06-09 10:16:41,493][HYDRA] 8
[2021-06-09 10:16:41,493][main][INFO] - 8
[2021-06-09 10:16:41,493][HYDRA] 9
[2021-06-09 10:16:41,493][main][INFO] - 9

[omry]

What if you remove job_logging: null from your config?

[brunovollmer]

Then it works as intended but it also creates a log file which I don't want.

[jieru-hu]

I think the issue is you passed in a null value to hydra.job_logging which is supposed to be a config group (not just a config value), and this is causing some weirdness.

if you want to disable job_logging or hydra_logging (so no log file will be created), pls override the corresponding hydra config group

hydra:
  run:
    dir: .

defaults:
  - override /hydra/job_logging: none

$ python my_app.py 
[2021-06-09 10:03:48,299][HYDRA] HELLO

[omry]

#1661 is preventing the assignment of null to hydra.hydra_logging and hydra.job_logging. This is not something that was ever supported.

As Jieru suggested, you can override override /hydra/job_logging and hydra/hydra_logging.

These are your options (you can also create your own, see how to customize the logging):

python my_app.py --hydra-help | grep "^hydra/.*logging"
hydra/hydra_logging: default, disabled, hydra_debug, none
hydra/job_logging: default, disabled, none, stdout

Specifically, job_logging comes with a built in config for outputing to stdout but hydra_logging does not.