949 separate logging for callbacks by d-perl · Pull Request #958 · DiamondLightSource/hyperion

d-perl · 2023-11-03T11:30:57Z

Fixes #949

Link to dodal PR (if required): #228

To test:

Confirm tests pass

DominicOram

When I run pytest -m "not s03" -s I get multiple copies of logs printed. Have we got multiple handlers added? e.g.

[2023-11-09 15:19:37,488] bluesky.RE.state run_engine INFO: Change state on <bluesky.run_engine.RunEngine object at 0x7fac701ccb80> from 'idle' -> 'running'
[2023-11-09 15:19:37,488] bluesky.RE.state run_engine INFO: Change state on <bluesky.run_engine.RunEngine object at 0x7fac701ccb80> from 'idle' -> 'running'
[2023-11-09 15:19:37,488] bluesky.RE.state run_engine INFO: Change state on <bluesky.run_engine.RunEngine object at 0x7fac701ccb80> from 'idle' -> 'running'
[2023-11-09 15:19:37,488] bluesky.RE.state run_engine INFO: Change state on 
...

Must: If we merge this the setup of ISYB_LOGGER and NEXUS_LOGGER never gets called in prod so we won't get any logs from them. I know this is probably fixed in subsequent PRs when we move it to a separate process but I think it's good practice for main to not be broken between PRs
It feels like either:
- NEXUS_LOGGER/ISPYB_LOGGER are sufficiently separate that they should live in with the nexus/ispyb callback code
- We should have a helper list/dict in log.py that contains all LOGGERs for setup/teardown of tests

DominicOram · 2023-11-09T15:25:15Z

+    if "hyperion.log" in sys.modules:
+        hyperion_log = sys.modules["hyperion.log"]
+        [h.close() for h in hyperion_log.LOGGER.handlers]
+        [hyperion_log.LOGGER.removeHandler(h) for h in hyperion_log.LOGGER.handlers]
+    if "dodal.log" in sys.modules:
+        dodal_log = sys.modules["dodal.log"]
+        [h.close() for h in dodal_log.LOGGER.handlers]
+        [dodal_log.LOGGER.removeHandler(h) for h in dodal_log.LOGGER.handlers]


Should: Pull this into a shared function

DominicOram · 2023-11-09T15:31:00Z

+                "hyperion_ispyb_callback.txt",
+                ISPYB_LOGGER,
+                "DEBUG",
+                True,  # TODO set dev mode for tests and remove this


Must: Is this todo addressed in a different PR? Feels like we shouldn't be doing this here...

DominicOram · 2023-11-09T15:33:28Z

+    log.LOGGER.handlers.clear()
+    log.ISPYB_LOGGER.handlers.clear()
+    log.NEXUS_LOGGER.handlers.clear()
+    dodal_logger.handlers.clear()


Nit: I would put these in a list and clear them all with list comprehension, you can do the same below after the with too

DominicOram · 2023-11-09T15:48:10Z

+def set_up_callback_logging_handlers(
+    filename,
+    logger=LOGGER,
+    logging_level: str = "INFO",
+    dev_mode: bool = False,
+):
+    stream_handler = logging.StreamHandler()
+    _add_handler(logger, stream_handler, logging_level)
+    graylog_handler = set_up_graylog_handler(logging_level, dev_mode, logger)
+    file_handler = set_up_file_handler(
+        logging_level, dev_mode, _get_logging_file_path(filename), logger
+    )
+    logger.addFilter(dc_group_id_filter)
+    return [stream_handler, graylog_handler, file_handler]


Should: What am I missing here that means we can't use dodal's set_up_logging_handlers?

d-perl · 2023-11-09T17:08:47Z

Good point - do you think we should separate the repositories at some stage? If so I'll move the loggers to be with the modules.

I did set up the ISPYB logger in the ispyb callback class, but this made me reconsider - yes, better to set them up in main, and then move them to the new main for the callbacks

codecov · 2023-11-09T19:05:50Z

Codecov Report

Merging #958 (4d867bb) into main (92b23da) will decrease coverage by 0.07%.
Report is 10 commits behind head on main.
The diff coverage is 86.27%.

@@            Coverage Diff             @@
##             main     #958      +/-   ##
==========================================
- Coverage   93.32%   93.26%   -0.07%     
==========================================
  Files          54       54              
  Lines        2591     2597       +6     
==========================================
+ Hits         2418     2422       +4     
- Misses        173      175       +2

Files	Coverage Δ
...l_interaction/callbacks/rotation/ispyb_callback.py	`91.66% <100.00%> (ø)`
...l_interaction/callbacks/rotation/nexus_callback.py	`100.00% <100.00%> (ø)`
..._interaction/callbacks/rotation/zocalo_callback.py	`100.00% <100.00%> (ø)`
...nteraction/callbacks/xray_centre/ispyb_callback.py	`95.83% <100.00%> (+0.37%)`	⬆️
...nteraction/callbacks/xray_centre/nexus_callback.py	`100.00% <100.00%> (ø)`
...teraction/callbacks/xray_centre/zocalo_callback.py	`98.46% <100.00%> (ø)`
...erion/external_interaction/ispyb/store_in_ispyb.py	`97.28% <100.00%> (ø)`
src/hyperion/log.py	`100.00% <100.00%> (ø)`
...ernal_interaction/callbacks/ispyb_callback_base.py	`92.45% <66.66%> (ø)`
src/hyperion/__main__.py	`86.33% <20.00%> (-0.96%)`	⬇️

📣 Codecov offers a browser extension for seamless coverage viewing on GitHub. Try it in Chrome or Firefox today!

DominicOram

Great, thanks for cleaning up the types as you went too. Nits in code, take them or leave them

DominicOram · 2023-11-13T14:51:42Z

+    hyperion.log.set_up_logging_handlers(
+        logging_level=logging_level, dev_mode=bool(dev_mode)
+    )
+    hyperion.log.set_up_logging_handlers(
+        logging_level=logging_level,
+        dev_mode=dev_mode,
+        filename="hyperion_ispyb_callback.txt",
+        logger=hyperion.log.ISPYB_LOGGER,
+    )
+    hyperion.log.set_up_logging_handlers(
+        logging_level=logging_level,
+        dev_mode=dev_mode,
+        filename="hyperion_nexus_callback.txt",
+        logger=hyperion.log.NEXUS_LOGGER,
+    )


Nit: I would do this with dictionary comprehension, but likely going to change soon when moved to separate processes anyway so big deal

DominicOram · 2023-11-13T14:52:43Z

+    for logger in loggers:
+        for handler in logger.handlers:
+            handler.close()
+    [logger.handlers.clear() for logger in loggers]


Nit: You're running the for loop anyway, just move this into there and remove the list comprehension

DominicOram · 2023-11-13T14:54:29Z

+        if LOGGER.handlers == []:
+            if dodal_logger.handlers == []:
+                print(f"Initialising Hyperion logger for tests at {log_level}")
+                set_up_logging_handlers(LOGGER, log_level, True)
+        if ISPYB_LOGGER.handlers == []:
+            print(f"Initialising ISPyB logger for tests at {log_level}")
+            set_up_logging_handlers(
+                logging_level=log_level,
+                dev_mode=True,
+                filename="hyperion_ispyb_callback.txt",
+                logger=ISPYB_LOGGER,
+            )
+        if NEXUS_LOGGER.handlers == []:
+            print(f"Initialising nexus logger for tests at {log_level}")
+            set_up_logging_handlers(
+                logging_level=log_level,
+                dev_mode=True,
+                filename="hyperion_nexus_callback.txt",
+                logger=NEXUS_LOGGER,
+            )


Nit: I would do this with dictionary comprehension

DominicOram · 2023-11-13T16:00:04Z

    If the HYPERION_LOG_DIR environment variable exists then logs will be put in here.
-
-    If no envrionment variable is found it will default it to the tmp/dev directory.
+    If no envrionment variable is found it will default it to the ./tmp/dev directory.


Nit: Spelling on environment

DominicOram · 2023-11-13T16:00:48Z

-    else:
-        logging_path = Path("./tmp/dev/")
-
+    logging_path = Path(environ.get("HYPERION_LOG_DIR") or "./tmp/dev/")


This is beautiful, thanks!

DominicOram · 2023-11-13T16:11:26Z

+    assert nexus_filehandler.baseFilename != hyperion_filehandler.baseFilename  # type: ignore
+    assert ispyb_filehandler.baseFilename != hyperion_filehandler.baseFilename  # type: ignore
+    assert ispyb_filehandler.baseFilename != nexus_filehandler.baseFilename  # type: ignore


Nit: I would maybe do an explicit cast to FileHandler but not that big a deal

DominicOram

Great, thank you!

DominicOram · 2023-11-13T16:22:08Z

Good point - do you think we should separate the repositories at some stage? If so I'll move the loggers to be with the modules.

I think we should stay open to needing to but no need to now

d-perl added 11 commits November 1, 2023 15:33

breakdown loggers only for logging tests

11d4ef6

add separate ISPyB logger

b0e18a6

add nexus logger

7ff3f54

update dodal ref

9fab828

add test for different filenames

b955da4

add mark

6bc868d

update dodal req

d3dedf3

Merge branch 'main' into 949_separate_logging_for_callbacks

3a7250c

delete flaky test (939)

a79d974

fix logging test setup

eeee644

fix test setup, add commandline logging option

ade4ada

DominicOram suggested changes Nov 9, 2023

View reviewed changes

d-perl added 2 commits November 9, 2023 18:59

tidy up and fix in response to review

b602f8a

update dodal req

cb3e209

d-perl added 2 commits November 10, 2023 15:28

ispyb logger should warn rather than info

e890320

remove optional dev mode type

4d867bb

DominicOram approved these changes Nov 13, 2023

View reviewed changes

d-perl added 2 commits November 13, 2023 16:23

tidy up

a973a0c

Merge branch 'main' into 949_separate_logging_for_callbacks

d11097f

d-perl merged commit 6b0b5df into main Nov 14, 2023

d-perl deleted the 949_separate_logging_for_callbacks branch November 14, 2023 13:38

Uh oh!

Conversation

d-perl commented Nov 3, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

To test:

Uh oh!

DominicOram left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

d-perl commented Nov 9, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codecov Bot commented Nov 9, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

DominicOram left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

DominicOram left a comment

Choose a reason for hiding this comment

Uh oh!

DominicOram commented Nov 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

d-perl commented Nov 3, 2023 •

edited

Loading

d-perl commented Nov 9, 2023 •

edited

Loading

codecov Bot commented Nov 9, 2023 •

edited

Loading

DominicOram commented Nov 13, 2023 •

edited

Loading