Update cli.py to support custom loggers (#1906)

* Update cli.py to support custom loggers

Allows a config.py file (via rq worker --config) to support things like this for logfmt logging:

DICT_CONFIG = {
        "version": 1,
        "formatters": {"logfmt": {
            "()": "logfmter.Logfmter",
            "keys": ["level","when","pid"],
            "mapping": {"level":"levelname","when":"asctime","pid":"process"},
            "datefmt": "%Y-%m-%dT%H:%M:%S%z"
            }},
        "handlers": {"console": {"class": "logging.StreamHandler","formatter": "logfmt" }},
        "loggers": {
            "root": {"handlers":["console"], "level": "INFO"},
            "rq":   {"handlers":["console"], "level": "INFO", "propagate": False},
            }
        }

* added simple test and documentation for DICT_CONFIG

* further attempt to get testing right for dictConfig

* move import to correct location

* fix

* remove meaningless options.get() usage

* linting checks and added missing test config file

docs/docs/workers.md

@@ -276,6 +276,33 @@ SENTRY_DSN = 'sync+http://public:secret@example.com/1'
 
 # If you want custom worker name
 # NAME = 'worker-1024'
+
+# If you want to use a dictConfig <https://docs.python.org/3/library/logging.config.html#logging-config-dictschema>
+# for more complex/consistent logging requirements.
+DICT_CONFIG = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'standard': {
+            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
+        },
+    },
+    'handlers': {
+        'default': {
+            'level': 'INFO',
+            'formatter': 'standard',
+            'class': 'logging.StreamHandler',
+            'stream': 'ext://sys.stderr',  # Default is stderr
+        },
+    },
+    'loggers': {
+        'root': {  # root logger
+            'handlers': ['default'],
+            'level': 'INFO',
+            'propagate': False
+        },
+    }
+}
 ```
 
 The example above shows all the options that are currently supported.

rq/cli/cli.py

@@ -2,6 +2,8 @@
 RQ command line tool
 """
 
+import logging
+import logging.config
 import os
 import sys
 import warnings
@@ -229,6 +231,10 @@ def worker(
     sentry_debug = sentry_debug or settings.get('SENTRY_DEBUG')
     sentry_dsn = sentry_dsn or settings.get('SENTRY_DSN')
     name = name or settings.get('NAME')
+    dict_config = settings.get('DICT_CONFIG')
+
+    if dict_config:
+        logging.config.dictConfig(dict_config)
 
     if pid:
         with open(os.path.expanduser(pid), "w") as fp:
@@ -303,7 +309,7 @@ def worker(
             dequeue_strategy=dequeue_strategy,
         )
     except ConnectionError as e:
-        print(e)
+        logging.error(e)
         sys.exit(1)
 
 

tests/config_files/dummy_logging.py

@@ -0,0 +1,19 @@
+# example config taken from <https://stackoverflow.com/a/7507842/784804>
+DICT_CONFIG = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'standard': {'format': 'MY_LOG_FMT: %(asctime)s [%(levelname)s] %(name)s: %(message)s'},
+    },
+    'handlers': {
+        'default': {
+            'level': 'DEBUG',
+            'formatter': 'standard',
+            'class': 'logging.StreamHandler',
+            'stream': 'ext://sys.stdout',  # Default is stderr
+        },
+    },
+    'loggers': {
+        'root': {'handlers': ['default'], 'level': 'DEBUG', 'propagate': False},  # root logger
+    },
+}

tests/test_cli.py

@@ -67,6 +67,11 @@ class TestRQCli(CLITestCase):
         self.assertIn('REDIS_HOST', settings)
         self.assertEqual(settings['REDIS_HOST'], 'testhost.example.com')
 
+    def test_config_file_logging(self):
+        runner = CliRunner()
+        result = runner.invoke(main, ['worker', '-u', self.redis_url, '-b', '-c', 'tests.config_files.dummy_logging'])
+        self.assert_normal_execution(result)
+
     def test_config_file_option(self):
         """"""
         cli_config = CliConfig(config='tests.config_files.dummy')