Logging #478

arcavaliere · 2019-10-15T13:51:33Z

I'd like to define a custom logger for the logging the progress of models (ModelLogger). It's based on Logging.SimpleLogger and currently attempts to format @info calls as:
[dd/mm/yyyy HH:MM:SS] module source_file:line_number: message.

Once that is in place I'd like to define some custom LogStates and have ModelLogger handle those as well. Chiefly @diagnostic.

I wired up one of the examples to use ModelLogger rather than printf.

ali-ramadhan · 2019-10-15T14:41:09Z

Hey @arcavaliere thanks for working on this! Just added "[WIP]" to the title as that's our convention for PRs that are still a work in progress.

About your error, you did define min_enabled_level but I think you need to import methods from Logging to extend them.

I think something like this would work:

import Logging: min_enabled_level
min_enabled_level(logger::ModelLogger) = logger.min_level

or

import Logging
Logging.min_enabled_level(logger::ModelLogger) = logger.min_level

and the same goes for shouldlog and handle_message.

Might also be good to include("logging.jl") in src/Oceananigans.jl so it gets exported and available to users after using Oceananigans.

PS: Looks like your second account made the commits haha. We can fix this later.

arcavaliere · 2019-10-15T15:02:52Z

Thanks for that! I was able to get examples/ocean_wind_mixing_and_convection to use ModelLogger successfully. I'll look into defining custom LogState next.

codecov · 2019-10-15T18:54:27Z

Codecov Report

Merging #478 into master will decrease coverage by 0.89%.
The diff coverage is 0%.

@@            Coverage Diff            @@
##           master     #478     +/-   ##
=========================================
- Coverage   67.72%   66.83%   -0.9%     
=========================================
  Files          69       70      +1     
  Lines        1952     1978     +26     
=========================================
  Hits         1322     1322             
- Misses        630      656     +26

Impacted Files	Coverage Δ
src/Oceananigans.jl	`75% <ø> (ø)`	⬆️
src/logger.jl	`0% <0%> (ø)`

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 a511fdd...e31988c. Read the comment docs.

c42f

This looks like a promising start.

Can I suggest that we work together on improving both Base, MicroLogging and the ModelLogger you have here so that we get something really solid?

I'm willing to put in some design work, what I've been missing is a solid use case to drive the improvements which are needed in Base.

For LogState — that's a purely internal implementation detail of Base.CoreLogging and you cannot change it by design. However perhaps you refer to defining custom LogLevels? For that, if you can read JuliaLang/julia#33418 and contribute your use cases I'd be delighted.

c42f · 2019-10-16T00:07:25Z

src/logger.jl

+import Logging, Dates
+export ModelLogger, shouldlog, min_enabled_level, catch_exceptions, handle_message
+
+struct ModelLogger <: Logging.AbstractLogger


Yes, this is the correct way to do this :-)

c42f · 2019-10-16T00:09:33Z

examples/ocean_wind_mixing_and_convection.jl

+    # @printf("i: %04d, t: %s, Δt: %s, wmax = %.1e ms⁻¹, wall time: %s\n", 
+    #         model.clock.iteration, prettytime(model.clock.time), prettytime(wizard.Δt), 
+    #         wmax(model), prettytime(walltime))           
+    @info string("i: %04d, t: %s, Δt: %s, wmax = %.1e ms⁻¹, wall time: %s\n", 
            model.clock.iteration, prettytime(model.clock.time), prettytime(wizard.Δt), 
            wmax(model), prettytime(walltime))           


To keep the existing format you want @sprintf here, not string. string concatenates the various values:

julia> string("%04d", 10) "%04d10" julia> using Printf julia> @sprintf("%04d", 10) "0010"

That explains the literal %s's that were getting printed!

BTW, @info allows you to attach arbitrary keywords which can preserve a lot of semantic information for later analysis rather than trying to cram all that information into a string and then parse it again later.

For example:

@info "Ocean wind mixing iteration" clock=model.clock Δt=wizard.Δt wmax=wmax(model) walltime progress=model.clock.time/end_time

MicroLogging master can print progress bars when the progress keyword is attached.

c42f · 2019-10-16T00:10:27Z

src/logger.jl

+    module_name = something(_module, "nothing")
+    file_name = something(filepath, "nothing")
+    line_number = something(line, "nothing")
+    msg_timestamp = Dates.format(Dates.now(), "[dd/mm/yyyy HH:MM:SS]")


This is how the system is meant to be used :-)

As you have found out, you can get timestamps for every message in your application by customizing the logging backend rather than messing with the @info statements themselves.

examples/ocean_wind_mixing_and_convection.jl

arcavaliere · 2019-10-16T01:36:56Z

I was just looking at that issue! I have a similar desire to define some custom logging macros tied to LogLevel (And yeah I did mean LogLevel). I'd love to help out! I'll post the use case over there.

c42f · 2019-10-22T01:08:22Z

src/logger.jl

+# -------------------------------------------------------------------------------------
+# Custom LogStates
+const Diagnostic = Logging.LogLevel(-500)  # Sits between Debug and Info
+const Setup = Logging.LogLevel(500)


Custom LogLevels not LogStates!

It's interesting that you've put these at different importance levels; that would certainly be consistent with them being regarded as custom log levels 👍

Whoops! I'll clean that up.

This looks perfect. I think we will have to think a bit about exactly what custom log levels we need. I think both Setup (for logging the model setup + construction of key model types?) and Diagnostic are excellent. We may also want something like Simulation: Diagnostic would print the results of diagnostics calculations; Simulation would print more general information about the progress of a simulation even when no diagnostics are being calculated.

On the spectrum from Debug to Info we could have something like

Debug < Diagnostic < Simulation < Setup < Info

This of course doesn't have to be included in the PR here, but something to think about for the future.

I'm happy to add those additional levels and structure the levels in that order so we can have a baseline.

glwagner · 2019-10-23T13:18:21Z

Hi all, sorry for being late to the game, just wanted to provide some hopefully-useful input here:

Can I suggest that we work together on improving both Base, MicroLogging and the ModelLogger you have here so that we get something really solid?

@c42f this suggestion could be directed more broadly to all Oceananigans.jl developers --- if @arcavaliere wants to submit a more concentrated PR to Oceananigans.jl then I think myself and @ali-ramadhan would be happy to continue work along the lines you suggest. And of course if @arcavaliere is interested in this (which seems like fairly long term work?) that's awesome!

This PR looks really great!

glwagner · 2019-10-23T13:28:17Z

Does it make sense to encapsulate the code added by this PR into a submodule of Oceananigans? The log level Diagnostic, for example, is dangerously similar to the abstract type AbstractDiagnostic. We will almost certainly have a Simulation concrete type in the future, but we'll also want a log level for simulations. Perhaps @ali-ramadhan has some thoughts about this.

Ref #456.

c42f · 2019-10-24T03:58:39Z

@glwagner thanks. Indeed I think it's worthwhile pursuing good logging for all climate-machine simulations (XRef #71 (comment), CliMA/ClimateMachine.jl#134)

ali-ramadhan · 2019-10-28T13:44:05Z

Hmmm, I don't know if many log levels will be that helpful. I guess for debug messages we'll want to have the file name and line number, but for user-facing info messages maybe we should remove the file name and line number and instead a custom log level like DIAGNOSTIC or MODEL_SETUP will be useful.

I think one place that logging can hugely improve user experience is in setting up large models, especially on the GPU, where you could be waiting for several minutes while all of Julia, CUDA, and Oceananigans compiles, model is being set up, memory is allocated, etc.

We know it takes time but most users will think that something is wrong if Julia is silent for 5 minutes. In this context info messages can be useful and reassure the user that Oceananigans is working properly.

It's well known that progress indicators improve user experience, e.g.: https://www.nngroup.com/articles/progress-indicators/

c42f · 2019-10-29T00:55:40Z

Hmmm, I don't know if many log levels will be that helpful.

I'm not entirely sure either. It's worth considering whether the standard Info and Debug levels might be enough for some of your uses, but there's also nothing wrong with trying out some custom levels and removing them if they don't end up making sense.

For general logging I've often wondered whether it would be helpful to have a Notice level with severity between Info and Warn to allow informational messages to be stratified into two groups, though we would need clear guidelines for how to use it. Likewise, to have a Debug2 or VerboseDebug level for "really verbose" debugging messages (possibly compiled out by default, though that would need a minor tweak in Base to make it possible).

but for user-facing info messages maybe we should remove the file name and line number and instead a custom log level like DIAGNOSTIC or MODEL_SETUP will be useful.

This is basically what the standard Info level printing does in Logging.ConsoleLogger - it just ignores the line and file info captured by the fontend to simplify the pretty printing of the message. Btw, the pretty printing of log events can be separate from the storage format if desired. For example we could serialize log records to a binary file (including all file,line information etc) but have a tool to pretty print them with extra filtering, replay the messages from a simulation in faster than real time etc.

ali-ramadhan · 2019-11-03T17:03:38Z

Hey @arcavaliere sorry I think I messed up your PR :(

I was trying to get rid of a big file that invaded our git history by mistake (#509) but apparently because it rewrites git history, open pull requests become invalid so now you have a PR with 1000+ commits and 100+ merge conflicts haha.

Might be better to open a new pull request. You also need to delete the old repository and git clone a fresh copy. Don't think you can cherry-pick either...

I can help with opening a new pull request.

Again, sorry about ruining your pull request.

c42f · 2019-11-03T22:05:15Z

I don't think it's quite so drastic. It's possible to have two unrelated remotes cloned within the same git repository so you certainly should be able to fetch changes even if upstream is completely rewritten. I'd probably try squashing your logging changes into a single commit and then cherry picking that across to the newly rewritten master. (I'm not entirely sure that will work, but I think it should.)

PRs are based on branch and repo names, so once you've sorted things out locally you should be able to force push to arcavaliere:master and the conflicts here will be resolved without opening a new PR.

arcavaliere · 2019-11-06T02:24:46Z

I don't think it's quite so drastic. It's possible to have two unrelated remotes cloned within the same git repository so you certainly should be able to fetch changes even if upstream is completely rewritten. I'd probably try squashing your logging changes into a single commit and then cherry picking that across to the newly rewritten master. (I'm not entirely sure that will work, but I think it should.)

PRs are based on branch and repo names, so once you've sorted things out locally you should be able to force push to arcavaliere:master and the conflicts here will be resolved without opening a new PR.

Looks like it worked; thanks for the write up!

c42f · 2019-11-06T07:56:25Z

Looks like it worked; thanks for the write up!

You're welcome! It looks like there's still some non-logging related changes in the github diff view though?

arcavaliere · 2019-11-06T21:23:13Z

I think I may have missed something when I committed the sync of the upstream to my repo. Should I revert the commit and take those out?

c42f · 2019-11-07T01:44:01Z

It's a bit hard to tell what's gone wrong here at this point.

I'd do something like

Create a local branch with git branch logging_orig $some_hash_or_branch_name or something to keep this safe. If you've lost the original branch or hash name, don't panic (and don't delete your .git directory)! You can use git reflog to find it again.
Create and check out another local branch as a work in progress git checkout -b logging_wip logging_orig
Squash your changes with git rebase -i on logging_wip branch into a single commit.
Reset your master (this PR) to the new rewritten upstream master git checkout master; git reset --hard origin/master (presuming origin is [email protected]:climate-machine/Oceananigans.jl.git)
Cherry pick the single commit from logging_wip onto this new master with git cherry-pick logging_wip.
Force push your new master up to this pull request

(By the way, this would probably be clearer for you if you'd made the original pull request off a branch rather than your master branch. Generally that's a good idea, especially if you want to do multiple PRs)

Moves custom levels and macros to be above logger Adds level_to_string function Changes formatting of log messages

arcavaliere · 2019-11-16T04:02:40Z

Sorry for the delay on this! This time I think I've corrected the PR's state. @c42f Thank you for the assistance!

Adds documentation around log severity order Changes ModelLogger message format to move metadata to the right

ali-ramadhan

This looks great! @arcavaliere do you think it's ready to be merged? We should integrate your logger and start using it and improving it.

Sorry for letting this sit around!

I also added some minor comments about style as we follow this Julia style guide: https://github.com/jrevels/YASGuide

src/logger.jl

ali-ramadhan · 2019-12-03T22:37:10Z

src/logger.jl

+
+# -------------------------------------------------------------------------------------
+# Custom LogLevels
+_custom_log_level_docs = """


Out of curiousity, why assign the docstring to a variable?

I was mimicking what was done Base/Logging for the macros.
https://github.com/JuliaLang/julia/blob/46ce4d79337bdd257ee2e3d2f4bb1c55ff0a5030/base/logging.jl#L132

src/logger.jl

ali-ramadhan · 2019-12-03T22:39:48Z

src/logger.jl

+    file_name = something(filepath, "nothing")
+    line_number = something(line, "nothing")
+    msg_timestamp = Dates.format(Dates.now(), "[dd/mm/yyyy HH:MM:SS]")
+    formatted_message = "$message --- $msg_timestamp $level_name $file_name:$line_number"


src/logger.jl

Adds additional LogLevels and updates severity values Adds export logger to module exports Updates code style to match project guidelines

arcavaliere · 2019-12-04T15:39:41Z

Thanks for the feedback and no worries on the delay! I haven't been as active as I would have liked these past couple of months 😅
I think we can go a head and merge this in assuming I didn't break the build!

ali-ramadhan · 2019-12-04T19:29:36Z

Awesome! I'll start using it during testing first as we have a ton of println statements in there that really should be log statements.

Hope you don't mind if we ping you and request your review if we modify the ModelLogger with increasing use.

@glwagner Any objections to merging this PR?

arcavaliere · 2019-12-04T20:10:44Z

Not at all! I can look into any more infrastructural work that needs doing. I don't quite understand how the models work but I'm happy to help out where I can 😄

c42f · 2019-12-13T03:32:50Z

src/logger.jl

+    elseif level == Setup
+         "Setup"
+    elseif level == Logging.Warn 
+        "Warning"


By the way, you will have noticed how this way of using custom levels isn't really composable, and doesn't really work well with the default ConsoleLogger provided by Base.

Here's my current attempt to clean up that situation (comments welcome): JuliaLang/julia#33960

arcavaliere mentioned this pull request Oct 15, 2019

Logging. #71

Closed

ali-ramadhan added the feature 🌟 Something new and shiny label Oct 15, 2019

ali-ramadhan changed the title ~~Logging.~~ [WIP] Logging. Oct 15, 2019

c42f reviewed Oct 16, 2019

View reviewed changes

ali-ramadhan mentioned this pull request Oct 16, 2019

FINALLY reverse the k index #462

Merged

c42f reviewed Oct 22, 2019

View reviewed changes

ali-ramadhan force-pushed the master branch from 91e5626 to a3aa7a2 Compare November 3, 2019 16:49

arcavaliere force-pushed the master branch from b9d8cf7 to 3925ab7 Compare November 6, 2019 02:23

Alex Cavaliere and others added 2 commits November 15, 2019 22:52

Removes the @diagnostic export

1d8c2f8

Corrects LogStates to LogLevels

c3f1d83

Moves custom levels and macros to be above logger Adds level_to_string function Changes formatting of log messages

arcavaliere force-pushed the master branch from 453db3e to c3f1d83 Compare November 16, 2019 03:59

Removes logging macros in favor of using @logmsg

dcca887

Adds documentation around log severity order Changes ModelLogger message format to move metadata to the right

ali-ramadhan approved these changes Dec 3, 2019

View reviewed changes

Adds Logging and Dates to the Project deps

2eda4d4

Adds additional LogLevels and updates severity values Adds export logger to module exports Updates code style to match project guidelines

Merge branch 'master' into master

e31988c

ali-ramadhan changed the title ~~[WIP] Logging.~~ Logging Dec 4, 2019

ali-ramadhan merged commit f8d6dff into CliMA:master Dec 12, 2019

c42f reviewed Dec 13, 2019

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging #478

Logging #478

arcavaliere commented Oct 15, 2019

ali-ramadhan commented Oct 15, 2019

arcavaliere commented Oct 15, 2019

codecov bot commented Oct 15, 2019 •

edited

Loading

c42f left a comment •

edited

Loading

c42f Oct 16, 2019

c42f Oct 16, 2019

arcavaliere Oct 16, 2019

c42f Oct 16, 2019

c42f Oct 16, 2019

arcavaliere commented Oct 16, 2019

c42f Oct 22, 2019

arcavaliere Oct 22, 2019

glwagner Oct 23, 2019

arcavaliere Oct 25, 2019

glwagner commented Oct 23, 2019

glwagner commented Oct 23, 2019

c42f commented Oct 24, 2019

ali-ramadhan commented Oct 28, 2019

c42f commented Oct 29, 2019

ali-ramadhan commented Nov 3, 2019

c42f commented Nov 3, 2019

arcavaliere commented Nov 6, 2019

c42f commented Nov 6, 2019

arcavaliere commented Nov 6, 2019

c42f commented Nov 7, 2019

arcavaliere commented Nov 16, 2019

ali-ramadhan left a comment

ali-ramadhan Dec 3, 2019

arcavaliere Dec 4, 2019

ali-ramadhan Dec 3, 2019

arcavaliere commented Dec 4, 2019

ali-ramadhan commented Dec 4, 2019

arcavaliere commented Dec 4, 2019

c42f Dec 13, 2019

Logging #478

Logging #478

Conversation

arcavaliere commented Oct 15, 2019

ali-ramadhan commented Oct 15, 2019

arcavaliere commented Oct 15, 2019

codecov bot commented Oct 15, 2019 • edited Loading

Codecov Report

c42f left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arcavaliere commented Oct 16, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

glwagner commented Oct 23, 2019

glwagner commented Oct 23, 2019

c42f commented Oct 24, 2019

ali-ramadhan commented Oct 28, 2019

c42f commented Oct 29, 2019

ali-ramadhan commented Nov 3, 2019

c42f commented Nov 3, 2019

arcavaliere commented Nov 6, 2019

c42f commented Nov 6, 2019

arcavaliere commented Nov 6, 2019

c42f commented Nov 7, 2019

arcavaliere commented Nov 16, 2019

ali-ramadhan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arcavaliere commented Dec 4, 2019

ali-ramadhan commented Dec 4, 2019

arcavaliere commented Dec 4, 2019

Choose a reason for hiding this comment

codecov bot commented Oct 15, 2019 •

edited

Loading

c42f left a comment •

edited

Loading