From dab16ec126ba3567a00912f11327bdc1f5abf98d Mon Sep 17 00:00:00 2001
From: Gordon Watts <gwatts@uw.edu>
Date: Tue, 25 May 2021 22:19:57 -0700
Subject: [PATCH] Get logging correct

That took a few iterations to understand how this actually works
---
 README.md                                    | 11 +++++++++--
 src/servicex_did_finder_lib/communication.py |  7 ++++---
 src/servicex_did_finder_lib/logging.py       |  4 ++--
 3 files changed, 15 insertions(+), 7 deletions(-)

diff --git a/README.md b/README.md
index 3dd8e41..f9e3e2d 100644
--- a/README.md
+++ b/README.md
@@ -110,9 +110,12 @@ Another pattern in the above code that one might find useful - a thread-safe way
 In the end, all DID finders for ServiceX will run under Kubernetes. ServiceX comes with a built in logging mechanism. If anything is to be logged it should use the log system using the python standard `logging` module, with some extra information. For example, here is how to log a message from your callback function:
 
 ```python
+    import logger
+    __log = logger.getLogger(__name__)
     async def my_callback(did_name: str, info: Dict[str, Any]):
-        info['log'].info(f'Looking up dataset {did_name}.',
-                         extras={'requestId': info['request-id']})
+        __log.info(f'Looking up dataset {did_name}.',
+                     extra={'requestId': info['request-id']})
+
         for i in range(0, 10):
             yield {
                 'file_path': f"root://atlas-experiment.cern.ch/dataset1/file{i}.root",
@@ -123,3 +126,7 @@ In the end, all DID finders for ServiceX will run under Kubernetes. ServiceX com
 ```
 
 Note the parameter `request-id`: this marks the log messages with the request id that triggered this DID request. This will enable the system to track all log messages across all containers connected with this particular request id - making debugging a lot easier.
+
+The `start_did_finder` will configure the python root logger properly to dump messages with a request ID in them.
+
+*NOTE*: Once `start_did_finder` is called, whenever you log a message you _must_ pass the extra argument. If not, a formatting exception will occur during logging and the message will be swallowed.
diff --git a/src/servicex_did_finder_lib/communication.py b/src/servicex_did_finder_lib/communication.py
index adf559e..743b426 100644
--- a/src/servicex_did_finder_lib/communication.py
+++ b/src/servicex_did_finder_lib/communication.py
@@ -11,7 +11,7 @@
 from make_it_sync import make_sync
 
 from servicex_did_finder_lib.did_summary import DIDSummary
-from servicex_did_finder_lib.logging import initialize_logging
+from servicex_did_finder_lib.logging import initialize_root_logger
 from .servicex_adaptor import ServiceXAdapter
 
 # The type for the callback method to handle DID's, supplied by the user.
@@ -22,6 +22,7 @@
 # is also changed in the ServiceX_App
 QUEUE_NAME_POSTFIX = '_did_requests'
 
+# Easy to use local logger
 __logging = logging.getLogger(__name__)
 __logging.addHandler(logging.NullHandler())
 
@@ -82,7 +83,6 @@ def rabbit_mq_callback(user_callback: UserDIDHandler, channel, method, propertie
 
         info = {
             'request-id': request_id,
-            'log': initialize_logging()
         }
 
         # Process the request and resolve the DID
@@ -185,7 +185,8 @@ def start_did_finder(did_finder_name: str,
         default_command_line_args(parser)
         parsed_args = parser.parse_args()
 
-    # Parse the arguments, and get the callback going
+    # Initialize the root logger
+    initialize_root_logger(did_finder_name)
 
     # Start up rabbit mq and also callbacks
     init_rabbit_mq(callback,
diff --git a/src/servicex_did_finder_lib/logging.py b/src/servicex_did_finder_lib/logging.py
index c01ee92..dfb4c57 100644
--- a/src/servicex_did_finder_lib/logging.py
+++ b/src/servicex_did_finder_lib/logging.py
@@ -25,7 +25,7 @@ def format(self, record: logging.LogRecord) -> str:
             return super().format(record)
 
 
-def initialize_logging():
+def initialize_root_logger(did_scheme: str):
     """
     Get a logger and initialize it so that it outputs the correct format
     :param request: Request id to insert into log messages
@@ -35,7 +35,7 @@ def initialize_logging():
     log = logging.getLogger()
     instance = os.environ.get('INSTANCE_NAME', 'Unknown')
     formatter = DIDFormatter('%(levelname)s ' +
-                             f"{instance} rucio_did_finder " +
+                             f"{instance} {did_scheme}_did_finder " +
                              '%(requestId)s %(message)s')
     handler = logging.StreamHandler()
     handler.setFormatter(formatter)