Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Enhance logging messages with rich #869

Merged
merged 9 commits into from
Aug 1, 2022
Merged

Conversation

Etesam913
Copy link
Contributor

@Etesam913 Etesam913 commented Jul 28, 2022

Summary

Many of the scripts are beautified using rich, why not add this to the logs.

Added a RichHandler object to the logging config to allow for clearer logging messages.

Updated Video:

#869 (comment)

Video

enhanced-logging.mov

Duplicated Log Messages Issue (RESOLVED) #869 (comment)

One thing that I want to fix is the duplicated log messages. You can see that each colorful log message has a uncolored version.

I believe this is because the main logger is also logging the messages, which leads to duplicated logging. One way to fix this is to set

logger.propagate = False

This does work, however, it means that the messages won't get saved in the outputs/<date>/scripts.log file. This is a pretty big issue, so I didn't apply it. Removing the duplicated messages does make the logs much easier to read though.

Any ideas on how to resolve this?

Resolves #388

Resolves #386

@facebook-github-bot facebook-github-bot added the CLA Signed This label is managed by the Facebook bot. Authors need to sign the CLA before a PR can be reviewed. label Jul 28, 2022
@Etesam913 Etesam913 changed the title Enhance logging messages with rich [WIP] Enhance logging messages with rich Jul 28, 2022
@Etesam913 Etesam913 requested review from JackUrb and pringshia July 28, 2022 16:40
Copy link
Contributor

@JackUrb JackUrb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The duplicate logging is a symptom of hydra's default logging. This should be configurable.

With a bit of digging I'd suggest

  1. Editing hydra_config.py to include a LOGGING_OVERRIDE = {'override hydra/job_logging': 'mephisto_default'} override constant.
  2. Creating a file called mephisto_default.yaml in the specific folder hydra_configs/hydra/job_logging.
  3. Include the LOGGING_OVERRIDE as the last value in a defaults list provided both to the standard TaskConfig and the version produced by build_default_task_config.

Now as far as what to do when you've gotten this far, I'm not 100% sure. Either the choice is going to be to make the hydra_log_file.yaml use the rich logger instead of the simple one (more likely), or to make it so that the hydra_log_file resembles the disabled setup to block hydra's logs to console if that doesn't work.

@@ -14,7 +14,7 @@
import subprocess
import sys
import time

from mephisto.utils.rich import console
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Mistaken import?

@Etesam913
Copy link
Contributor Author

Got it working 👍 I had to make sure that the hydra job_logging did not write results to console, but did write to file.

New Video

updated-hydra-logging.mov

@Etesam913
Copy link
Contributor Author

Etesam913 commented Jul 29, 2022

This is in mock_unit.py:
mock_unit py
Do we have to print this out given that it is already logged?

It seems a little extra.

@JackUrb
Copy link
Contributor

JackUrb commented Jul 29, 2022

This is in mock_unit.py: mock_unit py Do we have to print this out given that it is already logged?

It seems a little extra.

My concern here is if someone has logging entirely disabled, and then doesn't get to see this message

@Etesam913
Copy link
Contributor Author

Makes sense

@codecov-commenter
Copy link

codecov-commenter commented Jul 29, 2022

Codecov Report

Merging #869 (c25fddc) into main (fc28f34) will increase coverage by 0.14%.
The diff coverage is 83.33%.

@@            Coverage Diff             @@
##             main     #869      +/-   ##
==========================================
+ Coverage   64.43%   64.58%   +0.14%     
==========================================
  Files         107      108       +1     
  Lines        9291     9304      +13     
==========================================
+ Hits         5987     6009      +22     
+ Misses       3304     3295       -9     
Impacted Files Coverage Δ
mephisto/abstractions/providers/mock/mock_unit.py 87.09% <ø> (-0.41%) ⬇️
mephisto/utils/metrics.py 29.10% <ø> (-0.53%) ⬇️
...tractions/architects/channels/websocket_channel.py 76.56% <50.00%> (+8.59%) ⬆️
mephisto/operations/hydra_config.py 51.72% <66.66%> (+1.13%) ⬆️
mephisto/utils/logger_core.py 85.10% <92.30%> (+9.49%) ⬆️
mephisto/abstractions/architects/mock_architect.py 88.23% <0.00%> (-2.62%) ⬇️
mephisto/utils/rich.py 85.71% <0.00%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update fc28f34...c25fddc. Read the comment docs.

@Etesam913 Etesam913 requested a review from JackUrb July 30, 2022 23:53
@Etesam913 Etesam913 changed the title [WIP] Enhance logging messages with rich Enhance logging messages with rich Jul 30, 2022
Copy link
Contributor

@JackUrb JackUrb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for this change! One small Hydra gotcha but otherwise I'm really excited to have improved, readable logs! Thanks for taking this on :)

@@ -46,6 +46,7 @@ class TaskConfig:
mephisto: MephistoConfig = MephistoConfig()
task_dir: str = get_run_file_dir()
num_tasks: int = 5
defaults = ["_self_", LOGGING_OVERRIDE]
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You'll need to use:

defaults: List[Any] = field(default_factory=lambda: ["_self_", LOGGING_OVERRIDE])

here or Hydra will throw for base TaskConfigs.

Comment on lines +127 to +135
def assert_server_subbed_in_time(self, server, timeout: int = 5) -> None:
start_time = time.time()
while (len(server.subs) == 0) and time.time() - start_time < timeout:
time.sleep(0.3)
self.assertEqual(
len(self.architect.server.subs),
1,
"MockServer doesn't see registered channel",
)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

❤️

@Etesam913 Etesam913 merged commit ebac0c8 into main Aug 1, 2022
@pringshia
Copy link
Contributor

pringshia commented Aug 1, 2022

This is something I've been wanting for a long time. Thanks for making it happen ❤️

@pringshia
Copy link
Contributor

Side thought - The duplication of logs here could be an opportunity for clean-up?

CleanShot 2022-08-01 at 11 37 41@2x

@JackUrb
Copy link
Contributor

JackUrb commented Aug 1, 2022

Side thought - The duplication of logs here could be an opportunity for clean-up?

CleanShot 2022-08-01 at 11 37 41@2x

Etesam asked about this above. The difficulty here I suppose is that I wanted the link to always appear, even if logging is disabled. A solution would be one that forces the print only if logging isn't active, but I don't know if there's any really elegant way to do that.

@pringshia pringshia deleted the enhance-logging-messages branch August 1, 2022 19:25
@mjkanji mjkanji mentioned this pull request Nov 8, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
CLA Signed This label is managed by the Facebook bot. Authors need to sign the CLA before a PR can be reviewed.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Better CLI output Nicer looking logging
5 participants