Skip to content

Instantly share code, notes, and snippets.

@c42f
Created April 27, 2020 23:26
Show Gist options
  • Save c42f/a0d223dff468b0b4e8c1d3d1389e47df to your computer and use it in GitHub Desktop.
Save c42f/a0d223dff468b0b4e8c1d3d1389e47df to your computer and use it in GitHub Desktop.
Julia #logging slack channel history
Manually copied out of slack on 2020-04-28
logging
@rofinn created this channel on May 15th, 2018. This is the very beginning of the logging channel.
Rory Finnegan 6:07 AM
joined #logging along with 2 others.
Kevin Bonham:microbiome: 6:56 AM
Thanks for making the channel @rofinn. The main thing I’ve been trying to
do is set up logging to the console or to the file. Eg, if I’ve got a
script that takes a --logfile foo.log, I’d like to be able to write to
that file. With MicroLogging it seems I need to use the syntax:
logstream = open("foo.log", "w")
with_logger(SimpleLogger(logstream)) do
@info "My message"
end
But that seems overly verbose. I’d like to just be able to set the logger
to have the file as the output.
Rory Finnegan 7:04 AM
In Memento.jl, that would just be push!(logger, DefaultHandler("foo.log").
From then on messages to logger will write to foo.log. You can also attach
filters to handlers to determine which records are written to the file.
(edited)
Kevin Bonham:microbiome: 7:08 AM
Neat - can you have a single logger that has multiple outputs as well (eg
writes to both console + a file?). What I’d really love is:
logger = # make logger
if not args["quiet"]
# set logger to log to console
end
if !isnull(args["logfile"])
# set logger to write to file
end
@info "A message"
And have that work for all combinations of arguments (edited)
Rory Finnegan 7:12 AM
# Not sure where this would be run, but if you just want to use the "root" logger then you could do.
# Default is to log only warnings to console
logger = Memento.config("warn")
# If not quiet then change to info messages
args["quiet"] || setlevel!(logger, "info")
isnull(args["logfile"]) || push!(logger, DefaultHandler(args["logfile"]))
info(logger, "A message") # If both check have succeeded then "A message" will be written to both the console and a file.
(edited)
Kevin Bonham:microbiome: 7:16 AM
Interesting. I’ll give it a shot, thanks!
Rory Finnegan 3:38 AM
Folks might be interested in this prototype for replacing the base logger
with Memento. https://github.com/invenia/Memento.jl/pull/75
GitHubGitHub
Replacing base logging by rofinn · Pull Request #75 · invenia/Memento.jl
Initial attempt to get stdlib logging working. Example) julia> using Memento; getlogger(@__MODULE__); Memento.config!("info"; recursive=true); Memento.setglobal!() Logging.ConsoleLogge...
Kevin Bonham:microbiome: 7:02 AM
Very nice
Lyndon White:ox: 11:46 AM
joined #logging along with 2 others.
Eric Davies:invenia: 8:37 AM
@quinnj Look what you made me do: https://github.com/JuliaLang/julia/issues/28400
GitHubGitHub
log_record_id runtime increases quadratically with duplicate logs · Issue #28400 · JuliaLang/julia
I've copied the code in question from logging.jl here: _log_record_ids = Set{Symbol}() # Generate a unique, stable, short, human readable identifier for a logging # statement. The idea here is ...
Jacob Quinn 8:37 AM
joined #logging.
Jacob Quinn 8:39 AM
Yay; we definitely need more performance scrutiny on the logging system. It can be such a pitfall right now.
Sergey Tsarev 4:19 AM
joined #logging along with
.
Lyndon White:ox: 9:39 PM
Debugging errors in a custom console logger is hard,
because the console logger is used to display errors.
9:39
including extracting the line number...
9:41
Also Revise.jl doesn't work with it. I think.
Lyndon White:ox: 11:16 PM
@fredrikekre, @c42f
Something changed with how log message ids are generated and I can't workout what.
I know that before July 8, (idk if I was on master or a nightly, though, so not useful)
log messages via @info for loops would be given the same id.
And now they are not
Fredrik Ekre 11:16 PM
was added to #logging by , along with
.
Lyndon White:ox: 11:17 PM
https://github.com/oxinabox/OhMyLog.jl
was working to detect that they were the same message source then, and now it is not. (edited)
11:20
I feel like they **should** have the same id,
since id is used for message_limits/ maxlog.
Which I assume is tested.
So maybe I am doing something wrong
11:22
Alt: no I think it is broken.
11:22
I will raise a bug report
Lyndon White:ox: 11:30 PM
https://github.com/JuliaLang/julia/issues/29227
GitHubGitHub
`maxlog` is broken, log ids are always unique, thus breaking `maxlog` · Issue #29227 · JuliaLang/julia
The following comes from julia 0.7 (release) or 1.0 julia> for ii in 1:10 @info("this", maxlog=5) end [ Info: this [ Info: this [ Info: this [ Info: this [ Info: this [ Info: this [ In...
Lyndon White:ox: 11:46 PM
Ah it is known :juliaheartpulse:
Lyndon White:ox: 12:26 AM
https://github.com/oxinabox/OhMyLog.jl
Enhanced logging for the REPL.
Now with progress-bars
Demo: https://asciinema.org/a/00hoDMBZqtNxwHxKThDg5j9cC?t=9 (edited)
miguel raz guzmán 3:39 AM
joined #logging along with 2 others.
Lyndon White:ox: 5:53 PM
New day, new logging related package
https://github.com/oxinabox/LoggingExtras.jl (edited)
GitHubGitHub
oxinabox/LoggingExtras.jl
Additional Loggers for Julia (Demux, File, and Filtered) - oxinabox/LoggingExtras.jl
Lyndon White:ox: 12:48 PM
2.0 request: use a struct to hold all the arguments to handle_message (edited)
12:49
7+, the kwarg is too much.
12:51
And logrecord.module, logrecord.message etc reads fine
cossio 1:02 AM
joined #logging.
cossio 1:03 AM
Hi
1:03
anyone here?
Lyndon White:ox: 1:06 AM
:ocean:
Kevin Bonham:microbiome: 5:55 AM
:cricket::cricket::cricket::cricket: (edited)
cossio 7:04 AM
How can I implement a custom logger that stores logged objects?
7:05
I want to take advantage of the logging severity levels, so that I can
disable the (probably expensive) storage if I am logging only @info, say.
But I can have access to the stored objects at @debug level.
Lyndon White:ox: 10:05 AM
Take a look at LoggingExtras.jl for examples to start from.
Emily 1:44 AM
joined #logging.
cossio 8:03 AM
How do you flush the logger?
4 replies
Last reply 2 years agoView thread
Simon Byrne:juliaspinner: 6:59 AM
joined #logging.
Simon Byrne:juliaspinner: 7:00 AM
How about having a task_logger function which sets the task-local logger?
Chris Foster 9:43 AM
Yep, we need something like that; it should have probably preceded the with_logger interface TBH.
9:43
I do have a branch with something like that sitting around.
9:44
But I felt a deep unease about the design and never made a PR :wink:
9:45
the branch in question attempted to unify global_logger and your proposed task_logger into a more general config system (edited)
9:50
For now, we could just go with a simple task_logger(task=current_task(), logger) and at least provide that low level interface. (edited)
Chris Foster 8:15 PM
I've been thinking a lot about how to flesh out the set of AbstractLogger types to make stdlib/Logging usable rather than a hollow shell...The main challenge is composability: how to make multiple modules cooperate in piping the logs to the outer application, without an intermediate module having the power to filter logs out completely. Ie, consider an application which has the call chains
A calls B calls C
A calls D calls C (edited)
8:18
B may know that the logs from C don't matter much, so it may wish to filter them out. But in the context of D the logs from C may be quite important. And the outer application A should be able to override these decisions in some way if it really needs to know what's happening inside C.
Chris Foster 8:24 PM
I just had an idea which might actually solve this problem and also allow for early filtering to continue working.
What if we allowed log filters inside B and D to perform arithmetic on the log level of messages before passing them on to the parent logger installed by A?
8:26
This way B and D can affect the messages seen up the stack by A, but A always has ultimate control, in that it can always increase the verbosity until it starts to see the desired messages.
8:28
The log level < comparison currently defines the global ordering of increasing verbosity which is not perfect, as the level also has some categorical aspects. But we could try to encourage "log level as verbosity, group as category".
Lyndon White:ox: 8:47 PM
:thinking_face: (edited)
Kevin Bonham:microbiome: 2:29 AM
@c42f to put it in concrete terms, you're saying A might want something like @debug from D calling C but not B calling C? Or that A might want certain types of messages, but what's defined as @info in B calling C and D calling C are different? Or something else?
1 reply
1 year agoView thread
Lyndon White:ox: 5:05 AM
I feel like rather than looking at this as a problem where you just have the option of what to pass to the parent "filtering" you say.
It is worth considering it as routing.
5:08
Where based on rules you can send a log message from and source (as in source location/content eg module) to any sink (console, json file, plaintext file, Amaxon Cloudwatch, ) etc (edited)
5:12
(This can be done right now I. LoggingExtras.jl but that does not do early filtering with shouldlog, because it can filter on content.
I have been meaning to add a EarlyFilter logger that does that)
5:14
What I don't get is what want out of modules A which uses B which uses C cooperating.
5:17
To my mind configuration of the loggers is basically only done at a global level.
And thus if both A and B are configuring loggers then A should overwrite B's settings.
(The local level withlogger is exception, but I think it isn't something to be used under normal circumstances.)
5:22
If one wants to write rules like _all logs from modules imported by A should be muted then that can be accomplished with a recursive call to names(A) filtering for Modules,
Which can then be used to build an EarlyFilter to drop them
Kevin Bonham:microbiome: 6:11 AM
To my mind configuration of the loggers is basically only done at a global level.
I'm pretty sure I agree with this... though I am definitely sure I don't know all the implications.
Chris Foster 9:52 AM
configuration of the loggers is basically only done at a global level
That's what I thought originally (and what we have right now in 1.0), but it is non-composable. (edited)
9:53
Currently, I'm starting to think that certain carefully chosen kinds of log filtering can offer composability.
9:54
Example: Suppose an entry point of module B wants to add some module level context to every non-filtered log message. (edited)
Chris Foster 10:00 AM
Example 2: (see above) The author of D knows that calling C in a certian context will generate an irrelevant warning and wishes to downgrade it to a lower verbosity level (which can still be turned on by A)
3 replies
Last reply 1 year agoView thread
Chris Foster 10:13 AM
@oxinabox My feeling is that a network of filters/mappers combined with a set of sinks is the right way to go.
What I'm suggesting is that it's consistent to configure certain types of filters as part of the call stack
filterlogs(MyFilter()) do
some_work()
end
for example. (edited)
4 replies
Last reply 1 year agoView thread
Chris Foster 10:56 AM
I'm also wondering about whether there's a consistent way to resolve @fredrikekre’s complaint from here:
https://github.com/JuliaLang/julia/pull/28229#issuecomment-448176106
Lyndon White:ox: 7:03 PM
I hear what you are saying, but I am not sure they really occur in the wild. (i've not yet read the issue there), but i follow your earlier two examples. (edited)
Chris Foster 7:39 PM
Not sure what you mean — why then do you even have DowngradingLogger if not to attach it with with_logger() somewhere?
Of course, you can downgrade all messages globally, but I don't think that's particularly useful.
Lyndon White:ox: 7:42 PM
You've convinced me that with_logger is useful.
7:43
and that your example 2 is real and could occur
7:45
but your example 1 is the one that
A.) can't be done with the existing system trivially,
B.) I'm not sure is that common in the wild
7:48
What I've been thinking about as far as logging is that one would have small loggers, that achieve compositionality via taking another logger in the stack as an argument normally via currentlogger (edited)
Chris Foster 7:50 PM
perfect, that's exactly the conclusion I came to
Lyndon White:ox: 7:50 PM
Right ok, then what are you proposing to add that we can't do now?
7:50
(I'll be back in 30 got to get to work)
Chris Foster 7:51 PM
sure, np
Chris Foster 7:51 PM
Not yet sure Example 1 is something that can't occur.
7 replies
Last reply 1 year agoView thread
Chris Foster 7:54 PM
I have a strong feeling that existing logging libraries (that I'm aware of) haven't "taken composition seriously" :wink: (edited)
2 replies
Last reply 1 year agoView thread
Chris Foster 8:08 PM
Our big design break with python/log4j etc is to start building a hierarchy in the call stack rather than in a connected network of logging objects (which I think is usually defined statically in the code producing rather than consuming the logs, and usually aligned to the module hierarchy in python).
I'd claim what we've got in julia is a more functional "dynamically scoped" approach to logging; as a mental model you can almost imagine that each function returns a bunch of log messages which may be intercepted / filtered / mapped using with_logger. But with_logger is not quite the right abstraction, for the reasons we've been discussing further up. (edited)
Chris Foster 8:13 PM
@oxinabox I'll need to read LoggingExtras again (I did have a quick look when it was brand new), but I think we're coming to similar conclusions with the filters which is good. For my efforts in this direction, see the WIP at
https://github.com/c42f/MicroLogging.jl/commit/222d94548a09430abb8f6b9f206112e38b84337d
8:18
There you can also see what I did with filterlogs, and my attempts to remove the filtering we currently have in stdlib ConsoleLogger and make it into a pure sink.
Lyndon White:ox: 8:34 PM
I definitely am feeling the call of dynamic scoping is the right kind of scope for loggers.
Lyndon White:ox: 8:48 PM
Is the way we can imitate it with with_logger enough for general use?
All the common scenarios?I am wondering if maybe when people want to do a rarer more arbitrary dynmic scope based rule.
Say “Drop the loglevel of functions from module X, when called from module Y`
we can just say use Cassette,
which can definitely do this.
Or perhaps we can build a cassette based logging package.
(Problem is the need to decorate the entry point of the code with @overdub)
Chris Foster 9:17 PM
Cassette seems like it's the ultimate in flexibility and I think it could be the right thing for really powerful dynamic tracing. I feel like it might be overkill for everyday logging though?
5 replies
Last reply 1 year agoView thread
Chris Foster 9:24 PM
replied to a thread:
Not yet sure Example 1 is something that can't occur.
Well I think the dynamic scoping thing has worked out ok so far. At least for log testing it seems particularly nicer than the alternatives I've seen elsewhere.This part is definitely a switch in thinking vs the model I've seen in python / log4j / various other stuff. There must be another serious framework out there using it but I haven't found it yet.
9:25
Oops, that was meant to go to the thread. Oh well.
Chris Foster 9:29 PM
I am wondering if maybe when people want to do a rarer more arbitrary dynmic scope based rule.
Say “Drop the loglevel of functions from module X, when called from module Y`
This can be done by using a backtrace in shouldlog, but it would be awfully expensive
2 replies
Last reply 1 year agoView thread
Lyndon White:ox: 9:55 PM
What are your thoughts on loggers being mutable?
All the stdlib Loggers and the the loggers i have define in LoggingExtras
are immutable.
So if you want to change say min_level you need to redefine them.
In contrast, I believe all Memento loggers are mutable.
Chris Foster 9:59 PM
Yeah, the immutable ones are kind of annoying, but mutable loggers don't work well with early filtering.
Lyndon White:ox: 9:59 PM
right
Chris Foster 9:59 PM
(ie, with min_enabled_level)
Lyndon White:ox: 10:00 PM
Is min_enabled_level required?
Can’t that filtering be done just as early, on shouldlog ?
Chris Foster 10:00 PM
shouldlog hits dynamic dispatch. I was trying to get something which didn't
10:00
hence the cached min level
10:01
I feel like that part of the design could be refined though. Not sure it's quite right.
Lyndon White:ox: 10:02 PM
hmm, probably should have some similar(logger; settings...) which constructs a logger that is the same but with different settings
Chris Foster 10:02 PM
I had / have configure_logging in MicroLogging which does something like this.
10:03
But it felt a bit off, so I didn't put it in the stdlib yet
Lyndon White:ox: 10:03 PM
configure_logging to me sounds mutating, even without the !,
10:04
similar does not, since used to it for Linear Algebra (edited)
Chris Foster 10:05 PM
Yeah, well it mutates the log state, without mutating the logger itself.
10:06
Ie, constructs a new one in a similar-like manner based on the current one. Then replaces the current one with that.
10:06
But as I said, I think it wasn't quite right.
10:06
Kind of right, but not really :slightly_smiling_face:
Lyndon White:ox: 10:07 PM
Probably want to make the similar-like method public,
so that it can be used to manipulate and build loggers without immediately setting them to the global.
Since if you are composing a bunch of small loggers,
you want to do things like that.
Chris Foster 10:09 PM
Well for composition, I quite liked how my filters were turning out using the compose operator ∘ and filterlogs:
10:09
filterlogs(LogLevelFilter(MicroLogging.Info, Foo=>MicroLogging.Debug) ∘
CatchLogErrors(false)) do
@info "In main here"
@info 1÷0
Foo.foo()
end
10:09
But that's not the full story
Chris Foster 10:10 PM
ie, how do we configure sinks? How do we write config in a file and have it loaded in a sensible way by any logger?
4 replies
Last reply 1 year agoView thread
Chris Foster 10:11 PM
This was really the sticking point for configure_logging. I'd have liked to have keywords there which are meaningful between different loggers. But that just didn't seem to be working out.
4 replies
Last reply 1 year agoView thread
Lyndon White:ox: 10:37 PM
replied to a thread:
ie, how do we configure sinks? How do we write config in a file and have it loaded in a sensible way by any logger?
Making sinks AbstractLoggers, that are composed with to determine final use of handle_message (and nothing else about filtering/shouldlog etc)
I think is a important idea.
Chris Foster 10:38 PM
There's also mappers (example 1 above) which can modify messages, eg, to add context.
4 replies
Last reply 1 year agoView thread
Chris Foster 10:43 PM
replied to a thread:
There's also mappers (example 1 above) which can modify messages, eg, to add context.
So I was thinking that LogFilters may just combine the jobs of mapping and filtering into one abstraction. The important thing being that they compose properly up the call stack.
10:44
For some definition of "properly" which I haven't entirely figured out :slightly_smiling_face:
Chris Foster 10:45 PM
These can also route messages off to the side in a manner similar to unix tee
29 replies
Last reply 1 year agoView thread
Lyndon White:ox: 10:45 PM
I think it would be easier to make them two things,
and then make each of those compose properly.
and stick to a rule of change handlemessage or shouldlog/minenabled_level, and delegate the other.
never both
1 reply
1 year agoView thread
Lyndon White:ox: 11:02 PM
replied to a thread:
These can also route messages off to the side in a manner similar to unix tee
The general taxonomy as I see itis Sink: Accept Everything, Custom Handle Message,
Mapper: Delegate Acceptance. Custom Handle Message the delegates the results
Filter: Custom Acceptance, Delegate Handle Meessage
exceptions exist, e.g. tee, but should be primarily doing one as purpose and the other only as an optimisation,
Chris Foster 11:13 PM
Sounds about right.
I think filters aren't actually AbstractLogger subtypes because you want to be able to construct them without knowing what the parent will be.
7 replies
Last reply 1 year agoView thread
Chris Foster 11:15 PM
(that's ok though, shouldn't be a big deal) (edited)
Lyndon White:ox: 11:27 PM
Anyway, good talk. I should get on with other things.
LoggingExtras should go away and similar functionality added to the StdLib.I do not think we’ve resolved example 1 still.
But other than that I think we are basically thinking a like
Chris Foster 11:29 PM
Yep, MicroLogging should go away, I'm just using it as a playground as well.
I want to split the stdlib out of JuliaLang/julia and into JuliaLang/Logging, just haven't got to it yet. (edited)
1 reply
1 year agoView thread
Kevin Bonham:microbiome: 12:56 AM
What's the recommended way to format a log? For example, I'd like to have each item in an array on a separate line, but I don't want to do
for x in myarray
@info x
end
Since they'd all be in separate messages. I tried something like
julia> let msg = join("$x\n" for x in [1,2,3])
@info msg
end
┌ Info: 1
│ 2
└ 3
but I'm not a fan of the fact that 1 is in a different column than 2 and 3.
1:00
Hm... this gives me close to what I want:
julia> @info "test" [1,2,3]
┌ Info: test
│ [1, 2, 3] =
│ 3-element Array{Int64,1}:
│ 1
│ 2
└ 3
but this doesn't:
julia> @info [1,2,3]
[ Info: [1, 2, 3]
(edited)
1:02
And as my actual list is far longer, the former doesn't work because I need every element and longer lists get elided
julia> @info "test" rand(100)
┌ Info: test
│ rand(100) =
│ 100-element Array{Float64,1}:
│ 0.12603043559640903
│ 0.8763504180212371
│ 0.9634891782083297
│ 0.6362426903054084
│ 0.9584565965795007
│ 0.7198660738023954
│ 0.2672179180563017
│ 0.02759293234849114
│ 0.8962656544693237
│ 0.5654534736251811
│ 0.6637579054973675
│ ⋮
│ 0.9528410098300009
│ 0.6474033492666753
│ 0.21262228883614154
│ 0.32608863691406853
│ 0.5239364210370638
│ 0.340321423923164
│ 0.6478369340091554
│ 0.3536753581857808
│ 0.6366292903675879
└ 0.18894835999013293
Chris Foster 8:34 AM
@kescobo the right thing to do here is to configure the logger, rather than messing with the way you make the messages:
8:34
using Logging
global_logger(ConsoleLogger(stderr, show_limited=false))
@info "Something" x=rand(100)
8:35
In particular, setting the show_limited=false when constructing the logger
Kevin Bonham:microbiome: 8:44 AM
@c42f That makes sense. I suppose my question is also for the more general case where there's not necessarily a nice show defined.
julia> v = rand(100);
julia> @info "The first element it $(v[1])\nThe second element is $(v[2])"
┌ Info: The first element it 0.9719049634522652
└ The second element is 0.6835565578906526
8:45
Anyway, not a huge deal, I remember trying to figure out the number of character offsets with doing logging in python too. Maybe some formatting options would be a nice thing to go into a package or something
Chris Foster 8:45 AM
I was thinking the longer term goal is to format all log message strings assuming markdown (edited)
8:46
So that would give a way to produce nice human readable messages.
8:47
If you're sending data along for the ride (like in the example x=rand(100) above, keep in mind that it's not turned into a string until the logger sees it and formats it for you.
8:47
So you can define your own logger which can do whatever it likes to format that data
8:49
It can call repr or string or show or your_custom_show to make text. It can dump the data to disk and display it in a GUI. Whatever :slightly_smiling_face: (edited)
Kevin Bonham:microbiome: 8:50 AM
I was thinking the longer term goal is to format all log message strings assuming markdown
that would give a way to produce nice human readable messages.
That would be great! (edited)
Lyndon White:ox: 1:59 AM
Another type of filter logger one might want to compose in is a throttling logger that would prevent the same message (according to ID) being shown more than once per x seconds.
2:02
Relating to that, some of the smarter things the ConsoleLogger does, like configurable message_limits could be moved to there own small composable loggers (in this case a Filter).
And the ConsoleLogger could eventually become just the composition of a pile of these on top of a fairly basic stream logger skin. (probably not worth going too far, e.g. color and formatting not much gain in moving those into MapLoggerers. they basically are part of the sink)
Nathan Tran 2:36 AM
joined #logging.
Chris Foster 8:34 AM
@oxinabox yes that's what I was thinking. By the way, I've been thinking that the API required for map/filter of log events is very transducer-like.
Lyndon White:ox: 8:36 AM
I should really take a look at transducers.
Chris Foster 8:44 AM
I think the details are not quite the same because log events have to be dealt with one at a time (so more iterator-like). But there are some strikingly similar features.
Yeesian Ng 1:42 AM
joined #logging along with
.
Lyndon White:ox: 4:10 AM
All my philosophical ( :philosoraptor:) issues about how I was handling compositional loggers (:log:) and sinks (:kitchen_sink:) are going to be dealt with in
https://github.com/oxinabox/LoggingExtras.jl/pull/9
Lyndon White:ox: 9:41 PM
I might just go implement TransformingLogger
I'm not exactly having fun with this, but I do get satisfaction from knowing the full set of composable logging features for your your logger plumbing exists.
And noone should ever write anything that isn't a pure sink again. (edited)
1 reply
1 year agoView thread
Lyndon White:ox: 9:42 PM
i.e. you should only overload, handle_message
Lyndon White:ox: 10:04 PM
Hmm I think there might in theory there could be a EarlyFilterTransform composabler logger,
which tranforms the inputs to shouldlog before passing them to its child’s shouldlog in order to decide if it should log them. (edited)
3 replies
Last reply 1 year agoView thread
Chris Foster 5:43 PM
I started looking through this. Bear with me, it's a fair bit to digest. But ping me if I havn't done it in a couple of days.
Chris Foster 3:51 PM
Looks pretty good, I added some comments to the github issue.
Radovan Kavicky:flag-sk: 8:33 PM
joined #logging.
Kevin Bonham:microbiome: 2:21 AM
@oxinabox Seems like the API for logging changed recently? I have a script that used to work and is now throwing a bunch of errors in the logging stuff. Is there a concise list of changes somewhere? If not - any chance you can let me know how this call might have changed?
function setup_logs!(loglevel, logpath; dryrun=false)
glog = SimpleLogger(stderr, loglevel)
if logpath === nothing || dryrun
global_logger(glog)
else
logpath = abspath(expanduser(logpath))
global_logger(DemuxLogger(
FileLogger(logpath, loglevel),
glog, include_current_global=false))
end
end
Where loglevel is something like Logging.Info and logpath is a String?I had to remove min_level as a keyword from FileLogger(), and now I'm getting
ERROR: LoadError: MethodError: Cannot `convert` an object of type String to an object of type SimpleLogger
Closest candidates are:
convert(::Type{S}, !Matched::T<:(Union{CategoricalString{R}, CategoricalValue{T,R} where T} where R)) where {S, T<:(Union{CategoricalString{R}, CategoricalValue{T,R} where T} where R)} at /Users/ksb/.julia/packages/CategoricalArrays/ucKV2/src/value.jl:91
convert(::Type{T}, !Matched::T) where T at essentials.jl:154
SimpleLogger(::Any, !Matched::Any, !Matched::Any) at logging.jl:511
Stacktrace:
[1] FileLogger(::String, ::LogLevel) at /Users/ksb/.julia/packages/LoggingExtras/qQgFq/src/filelogger.jl:2
[2] #setup_logs!#3(::Bool, ::Function, ::LogLevel, ::String) at /Users/ksb/repos/lab_repos/echo_analysis/bin/metascrub.jl:60
[3] (::getfield(Main, Symbol("#kw##setup_logs!")))(::NamedTuple{(:dryrun,),Tuple{Bool}}, ::typeof(setup_logs!), ::LogLevel, ::String) at ./none:0
[4] main(::Dict{String,Any}) at /Users/ksb/repos/lab_repos/echo_analysis/bin/metascrub.jl:231
[5] top-level scope at /Users/ksb/repos/lab_repos/echo_analysis/bin/metascrub.jl:314
[6] include at ./boot.jl:326 [inlined]
[7] include_relative(::Module, ::String) at ./loading.jl:1038
[8] include(::Module, ::String) at ./sysimg.jl:29
[9] exec_options(::Base.JLOptions) at ./client.jl:267
[10] _start() at ./client.jl:436
in expression starting at /Users/ksb/repos/lab_repos/echo_analysis/bin/metascrub.jl:313
Lyndon White:ox: 2:25 AM
See the release notes
https://github.com/oxinabox/LoggingExtras.jl/releases/tag/v0.3.0
2:27
FileLogger no longer takes a loglevel argument.
2:28
rather than:
FileLogger(logpath, loglevel),
do
MinLevelLogger(FileLogger(logpath), loglevel)
(edited)
Kevin Bonham:microbiome: 2:35 AM
:thumbsup:
2:35
Thanks
Kevin Bonham:microbiome: 1:44 AM
@oxinabox is there a way with LoggingExtras to log only every X times through a loop? Eg
for x in 1:1000
@info x some_option 50 # only logs 1:50:1000
end
?
Lyndon White:ox: 2:00 AM
Yes,
2:02
it is very similar to the example in https://github.com/oxinabox/LoggingExtras.jl#earlyfilteredlogger
but instead of doing timing just make a counter that loops around.
Kevin Bonham:microbiome: 2:23 AM
Neat - I'll give it a shot, thanks :slightly_smiling_face: (edited)
2:23
I guess if I'm looping through something that's not a number, I'd want to do enumerate or something to use for the logger yeah?
Lyndon White:ox: 3:01 AM
I would just use the msg,id
and count how often that id occurred.
3:02
id’s are basically unique (but repeatable) per use of @info (etc) (edited)
Chris Foster 3:04 PM
Yep, ids are meant to be unique to the source code location - I guess you could say it's a lexical (not dynamic) id. (edited)
3:05
Kinda obvious, but another way to do this is to simply put the log message inside an if statement...
3:06
It depends on whether you want the logger to be able to override the step 50 afterward, or if you're content for it to always be fixed in the source code. (edited)
Kevin Bonham:microbiome: 7:53 PM
Oh, very cool. I haven't played with ids at all, I guess now is a good time to learn.
Chris Foster 4:14 PM
@kescobo I'd be interested to hear about your experience with it when you've played with it a bit.
There's still an uneasy balance between the duties of the log event generator (the @info statement and surrounding code) vs the logger.
Especially for presentation/formatting, but also for efficient filtering.
Kevin Bonham:microbiome: 10:52 PM
Good to know. Unfortunately, I realized I can't use logging at all the way I intended because of how it interacts with Weave.jl (when weaving a document, the log statements get spit to stdout instead of into the results block of the resulting html file). I think there's a way to make change this behavior on the logger end, but I decided to find a different solution :confused:
10:52
Will definitely be coming back to it though
Chris Foster 11:29 PM
Yeah it's very easy, you can just direct the logger to some other stream than stdout. Or anywhere else really (it doesn't need to go to an IO per se)
Lyndon White:ox: 11:44 PM
the fiddly part is probably getting hold of the IOBuffer weave is using.
though maybe that is just a redirected stdout so reisntantiating the logger before logging might do it.
Chris Foster 11:47 PM
Oh I got it backward. I though you wanted to exclude the results from weave.
11:48
Yeah if you want to include them it depends on how weave harvests info; might need customization in weave itself depending on how configurable it is.
Kevin Bonham:microbiome: 2:53 AM
OK, good to know. I really wish that I had the time to explore all of these different avenues to get stuff done right, but right now I'm trying to get a paper out :confused:
Jesse Bettencourt:butterbot: 3:40 AM
was added to #logging by
.
Lyndon White:ox: 3:41 AM
We should really have a some logger sinks that do things like writing to Feather,
BSON, JSON, XML and CSV files. (edited)
Lyndon White:ox: 3:42 AM
Maybe making a logger that can use Tables.jl API can do most of this?
8 replies
Last reply 10 months agoView thread
Lyndon White:ox: 3:43 AM
i don’t know that Tables defines a clear trival way to serialize things to disk.
3:43
@quinnj do any of your JSON packages act as Tables ?
in a way that they can accept having rows appended to them.
Jacob Quinn 3:43 AM
was added to #logging by
.
Jesse Bettencourt:butterbot: 4:03 AM
Yes please! I want to be able to easily read my logs back into arrays!
Jacob Quinn 4:58 AM
Yeah, we should do a JSONTables package or something for this
Chris Foster 2:11 PM
That would be cool. JSON is a fairly good format for log streams.
Chris Foster 2:17 PM
I've been wondering whether a useful next step for Logging would be to agree on a LogRecord type. Basically a minimal change to neaten up some APIs. Also to disentangle log level severity (an ordinal concept) from class (a categorical concept). (So you can have a high priority Info message, and a low priority Warning message.)
Nicolas Thiessen 1:04 AM
joined #logging.
Jesse Bettencourt:butterbot: 1:14 PM
I thought my model was slow because each iteration was taking longer than I’d like, but I switched from appending to an array to using TensorBoardLogger and it’s so much faster.
1 reply
9 months agoView thread
Jesse Bettencourt:butterbot: 1:16 PM
@oxinabox I saw you asking some questions about BSON did that have to do with the julia-importable logger or something else? I don’t remember where I saw this.
1 reply
9 months agoView thread
Jesse Bettencourt:butterbot: 1:18 PM
(since tensorboard tells me the relative times, for 200 iterations appending the loss to a list in callback it took 2min 40s, the same model with tensorboard logging took 40s to reach the same iteration)
Nathanael Wong 10:56 AM
A question on Logging - I've noticed that on the cluster I'm using, the logging output is only printed into the stdout file after the job finishes running/fails/force stops. Is there a way to print the logging output into the stdout file at the same time at the job run? I have a suspicion that this is causing memory failure for my jobs, though I'd be very surprised because if it's plain text it shouldn't require that much memory, right?
1 reply
6 months agoView thread
Chris Foster 3:14 PM
Handling of stdout / stderr on clusters which use older versions of PBS/Torque schedulers has always been a real pain in my experience (may be the case for other schedulers too). The scheduler keeps the logs on the compute node in a hidden directory and only copies it over to the login node when the job completes. (edited)
3:16
It can be worked around by manually logging to a file in a specific location (eg, an NFS mount of your home directory) if you want to see logs appear in real time from compute nodes. Maybe there's a better way...
Lyndon White:ox: 8:39 PM
@c42f @tkf shall we start a package: TabularLoggers.jl ?
Takafumi Arakaki 8:39 PM
was added to #logging by
.
Lyndon White:ox: 8:40 PM
@pkofod might be interested as Optim.jl currently does this, but without using the logging system.
Patrick Mogensen:house_with_garden: 8:40 PM
was added to #logging by
.
Lyndon White:ox: 8:40 PM
@PhilipVinc might be interested as it a natural compliment to TensorBoardLogger.jl
8:45
My proposal is that it should print any of the logging kwargs (the custom ones) as columns in a table.
And that it should track what it printed last,
and if this log message has more fields, then it should reprint the header with the new name.
And if it has less then it should fill the missing fields with --
8:46
I expect that it would primarily be used either in a given scope via withlogger (TabularLogger(…)) do
or with a group marker and a LoggingExtras filter.
Patrick Mogensen:house_with_garden: 1:19 AM
You've got me curious! :eyes:
Filippo Vicentini 2:21 AM
That’s interesting and I’d like to be kept in the loop, but I’ll have very limited bandwidth until next year..
Chris Foster 10:25 AM
@oxinabox Sure, how about we consolidate the interactive console logger sinks into a package, ConsoleLoggers or some such?
I don't think we need an entirely new package just for the tabular work, but it would be good to have a coherent place to consolidate console tools for progress logging (rip them out of micrologging and elsewhere) + tabular display + "replay logging"
10:25
replay / refiltering of saved log streams
10:25
basically interactive tooling for understanding log event streams
10:26
TerminalLoggers could be another name?
Chris Foster 10:59 AM
Actually the logging backends in MicroLogging have largely been focused on solving the Terminal UI side of logging. So we could just extend that package (or rename it, or rip out the useful parts and put them in TerminalLoggers ?)
Lyndon White:ox: 5:06 PM
Sure
Takafumi Arakaki 11:36 PM
Creating TerminalLogging for feature-rich all-in-one entry point sounds great :+1:. Another nice to-have feature is small "sticky" plotting, something like sparklines ▁▂▃▅▂▇ (https://github.com/holman/spark) or maybe UnicodePlots.I guess it would help us find out a practical strategy for making loggers composable.
Lyndon White:ox: 12:04 AM
So I guess the main reason not to do this in LoggingExtras (or MicroLogging if that does plain on keeping composable stuff)
is to avoid big dependencies.
12:05
But maybe that isn’t even a big deal anymore.
12:05
I am thinking things like saving logs as CSV or Fixed width formats,
or as JSONTables
Takafumi Arakaki 12:22 PM
I think a reason might be that TerminalLogger can approach the problem in a completely "feature-driven" manner, rather than trying to figure out the minimal building blocks from the get-go. Also, I'm afraid TerminalLogger might need to take a somewhat monolithic approach (at least for a first few rounds) since StickyMessages is inherently not composable, IIUC; i.e., there can be only one StickyMessages instance per TTY (@c42f is it correct?). So, I think a TerminalLogger need to track "model" and "view" separately to aggregate logging events and consistently update the sticky messages.
Chris Foster 12:58 PM
Indeed, StickyMessages is not a logger utility - it's a TTY UI utility.
1:01
So it really belongs in Terminals.jl or TerminalUI.jl or something... or in Base REPL utilities. It's just a big job to get it into Base because I'd need to hack libuv as well to fix the windows problems. A bit of a longer term project.
Takafumi Arakaki 2:36 PM
Is ccall'ing printf out of question? Or it just does not work? Or, considering Julia already forked libuv (IIUC), maybe it's more straightforward to apply the existing patch?
Chris Foster 5:01 PM
IIRC the problem was that libuv's abstraction of a terminal interprets terminal escape codes itself on windows. Presumably under the assumption that the windows console is broken which is partly true.
Unfortunately it does so incorrectly for the scroll region commands as those already work correctly for non-julia programs. At least that's what I inferred last time I looked; could be wrong & needs testing, etc :-)
5:02
But yes, patching our version of libuv would seem to be the way to fix this in the medium term.
Takafumi Arakaki 4:51 PM
I see, Windows terminal seems to cause many issues in Julia...
Chris Foster 5:15 PM
Regarding directly calling printf (or fputs/fwrite) as a workaround, it's an interesting thought and we would bypass libuv that way. I'm a bit hesitant about whether it would work sensibly at all, I guess that depends on how much buffering there is in the various layers.
Chris Foster 4:46 PM
I made TerminalLoggers: https://github.com/c42f/TerminalLoggers.jl
4:46
I think anything related to terminal UI for logging is in scope.
Takafumi Arakaki 1:06 PM
I thought maintaining patches of `libuv` has some costs and you'd want to minimize it if possible. But it depends on how simple/robust the `printf`-hack is.
Chris Foster 3:35 PM
For sure. Patches should go upstream if possible. It's just a matter of putting in the time.
Lyndon White:ox: 4:38 AM
Maybe I should submit a juliacon talk about LoggingExtras
Filippo Vicentini 7:42 PM
@c42f I have not really been following what's happening to the logging framework but I just thought about one thing: we are often using some keywords in log message to pass metadata/context/information to specific backends in addition to the message itself. (We do it in TensorBoard, but it seems to me you are also doing it in Progresslogging/TerminalLogging).But if you don't use the correct logging backends, those keyword arguments, that are usually hidden in the native terminal. show up.Would it be interesting to agree on a standard format for those metadata fields of a log message and never display them? For example, all fields starting with an underscore won't be displayed, or something like that?
Lyndon White:ox: 8:55 PM
a bit late for underscore.
ConsoleLogger in the stdlibs has a magic argument maxlog
8:56
I guess just because ConsoleLogger doesn;t follow, is no reason for everyone else to also.
Chris Foster 9:01 PM
I don't think it's too late to solve some of these problems.
9:02
This is the very reason that Logging doesn't have many features (turns out it has too many?!)
Lyndon White:ox: 9:05 PM
Sorting out ENV["JULIA_DEBUG"] to only apply to the ConsoleLogger would be good.
6 replies
Last reply 1 month agoView thread
Lyndon White:ox: 9:05 PM
the ConsoleLogger has way too many features.
9:05
Solution to that would be to replace it with the composition of like 4 LoggingExtras.jl loggers, which would mean moving that into the LoggingStdLib
9:08
Once the ENV["JULIA_DEBUG"] is put in the ConsoleLogger, rather than messing with the whole logging mechanism.
we can have a compositional logger that replicates its behavour (but in a non-“break everything” way) that can then be used with any logger
Filippo Vicentini 9:11 PM
The underscore is just an example.
Lyndon White:ox: 9:11 PM
yeah
9:11
I think its a good idea though
9:12
maybe _magic_ to be less likely to collide with a variable name someone wants to use (edited)
9:12
can always have maglog as a legacy version of _maxlog_ and have it not get non-printed
Filippo Vicentini 9:13 PM
I agree with you.
But, to be fair, I dislike those magic naming things, and would like this to be only a stopgap. Would it be possible to build into Base.Logging some sort of built-in support for message metadata?
9:14
So that you're more explicit what fields you pass in a message are metadata/context and what are not
9:14
or am i too crazy?
Filippo Vicentini 9:21 PM
Also because messages are passed around as a list of Pair{Symbol,Any}, right? So to check that a field starts with _magic_ I would need to convert to string, and do some string checks, that seems a lot of work for nothing...
Chris Foster 9:32 PM
I believe string(::Symbol) can be made almost free (though it isn't right now)
Chris Foster 9:37 PM
So FWIW, I think there's a definite problem with the flat namespace
9:38
Originally I'd considered actual syntax to separate namespaces
9:39
like @info "msg" k=val [metadata_key=val, metadata_key2=val]
9:39
Or some such thing.
9:39
... some syntax for the frontend which would allow us to have two namespaces
9:40
Actually we could probably still do something like that. For example taking curly braces because they're not a valid syntax by themselves.
9:41
@info "msg" i=10 {group=blah, id=blahblah, maxlog=2} (edited)
9:42
My thought is that the backends are a lot easier, because making changes there is less disruptive.
9:43
eg, we could introduce a LogRecord type with a namespace for metadata and one for data
Filippo Vicentini 9:45 PM
In my opinion that would be a good idea
9:48
But we can still experiment with a magical _magic_ in the meantime. A LogRecord would have to wait for Julia 2.0 or that could end up in a point release?
Chris Foster 9:49 PM
It's not in Base so it can be added in a point release, in principle.
Chris Foster 9:49 PM
The big problem is that stdlib versioning is still strictly tied to Base
5 replies
Last reply 28 days agoView thread
Chris Foster 9:51 PM
This somewhat stagnates all stdlibs because if we release a breaking change users won't have recourse to using an older version of the stdlib.
9:52
But do note that LogRecord could be added in a package.
9:54
Basically the first logger in the pipeline would create the LogRecord inside handle_message and pass it down the log routing chain.
This would make it not really interoperable with other loggers out there, but it could certainly consume messages from packages which is the main point.
9:56
For the short term, declaring metadata to be any keys which start with an underscore seems reasonable to me.
9:57
Then you can experiment as much as you please with data structures for routing/filtering in the backend. It can all be in a package.
Chris Foster 11:32 AM
Another thought: we don't actually need special syntax for metadata; we could simply use a meta keyword and pass a named tuple in there.
11:33
Sometimes I forget that when Logging was designed there were no `NamedTuple`s.
So the interface is more keyword argument heavy than might be ideal.
Filippo Vicentini 7:47 PM
So one could do @info "mymsg" a=1 b=2 meta=(option_1=1, option_2=2) , and logging backends could special-case meta to never print it unless some option is specified
7:47
it seems the easiest way to implement it at the moment, indeed.
Lyndon White:ox: 11:25 PM
and we would leave maxlog as a leftover legacy thing? and make meta=(maxlog=1.) act like maxlog=1 does? (edited)
Filippo Vicentini 12:27 AM
I'd say yes
12:27
though it's a vit verbose
Chris Foster 7:33 AM
Yes that's what we'd probably have to do. Indeed it's a bit ugly...
Lyndon White:ox: 7:49 AM
I don't think it's ugly
Chris Foster 4:57 PM
Well, I think it's better than having everything in one namespace.
Patrick Mogensen:house_with_garden: 6:43 PM
I'd like to try to use Logging.jl in Optim. I could just log to the global logger, but what's the best way of enabling the users to choose the logger? Should they just create a function that calls Optim and wrap it in a with_logger or?
6:44
I guess they could input their logger, but I'd honestly rather not have with_logger all over the code
Patrick Mogensen:house_with_garden: 6:51 PM
Oh, you can log to a logger
6:51
@info logger string
6:54
Didn't get that from the docs, or maybe I'm just blind :slightly_smiling_face:
Lyndon White:ox: 7:07 PM
I didn’t know you could do that either, and I have written a logging library…
Patrick Mogensen:house_with_garden: 7:18 PM
Seems to work?
julia> using Loggingjulia> @info NullLogger "aweb"
┌ Info: Base.CoreLogging.NullLogger
└ aweb = "aweb"julia> @info ConsoleLogger "aweb"
┌ Info: ConsoleLogger
└ aweb = "aweb"
4 replies
Last reply 12 days agoView thread
Patrick Mogensen:house_with_garden: 7:18 PM
Right?
7:19
I got it from a commented out line of code in a github gist for some trust region code :man-shrugging:
Patrick Mogensen:house_with_garden: 7:23 PM
replied to a thread:
Seems to work?…
okay okay... shoot..
7:24
So what I should do is then have users
with_logger(logger) do
optimize(whatever)
end
?
7:25
Or maybe that's not even what I want, because I only want my info to go to their logger.
7:25
okay, I guess I'll have to use with_logger in my code..
Fredrik Ekre 7:26 PM
But then users can't suppress it. (edited)
Patrick Mogensen:house_with_garden: 7:26 PM
why not?
Fredrik Ekre 7:28 PM
Because you override it, e.g. if I have in my code
my = MyLogger()
with_logger(my) do
optimize(...)
end
and inside optimize you have
optim_logger = OptimLogger()
with_logger(optim_logger) do
# ...
end
then you override my logger with your internal with_logger.
Patrick Mogensen:house_with_garden: 7:29 PM
think more like this
optimize(...; logger=mylogger)
7:30
and then inside optimize
with_logger(logger) do
whatevs
end
Fredrik Ekre 7:30 PM
Why do that at all then?
Patrick Mogensen:house_with_garden: 7:31 PM
Because I only want to log specific information I don't want warnings from random lines
Fredrik Ekre 7:31 PM
Then don't @warn?
Patrick Mogensen:house_with_garden: 7:31 PM
I don't warn (edited)
7:32
I don't want any logging events from any other code in that particular log
7:32
just the trace
7:34
Say if some code inside the objective function decides to @info. I don't want that in there, that can just go to the global logger
Fredrik Ekre 7:34 PM
They will mix anyway in the users terminal, no?
Patrick Mogensen:house_with_garden: 7:35 PM
not if the logger is a file for example
7:35
I mean if the logger you provide writes to a file
Fredrik Ekre 7:37 PM
Okay, yea I guess that will work.
Fredrik Ekre 7:43 PM
Or you can just log and the user can use a logger that filters properly
Patrick Mogensen:house_with_garden: 7:43 PM
You're overestimating the programming skills of a lot of Optim users
7:44
I'm not talking about the Julia regulars, but more the crowd that would normally be using Matlab. If they could, they would prefer to chose the file in a GUI :slightly_smiling_face:
Patrick Mogensen:house_with_garden: 9:45 PM
I'm not going to do that, but probably many users would want a save_to="path" keyword. Allowing them to input a logger f or the trace is the next best thing, and something I actually think is ok
Chris Foster 9:46 PM
Hmm, I think this is all going in the wrong (or at least, a confusing) direction.
9:47
At least, I'm a bit confused by what you want to do!
9:47
If you want to write a single message to a file (and nothing else) a logger might be the wrong choice.
9:49
But if you want to produce some structured, informational messages which can be displayed more richly in the user's chosen UI, a logger is a promising approach
Patrick Mogensen:house_with_garden: 9:50 PM
Hm, I want to log progress basically
9:51
so it's going to print for how many iterations it needs and print out different measures of progress
Chris Foster 9:51 PM
Oh right cool. Definitely good for a logger then.
9:51
Though our pretty printing infrastructure is still somewhat a WIP
9:52
Did you install that and try emitting progress records with ProgressLogging.jl?
9:53
I think that's where we are heading
Patrick Mogensen:house_with_garden: 9:53 PM
Nope i didnt know that package, let me try
Chris Foster 9:53 PM
Then for REPL UI, you want to try TerminalLoggers.jl
9:53
That will give a taste for what's possible
9:55
I think ProgressLogging also works automatically with Juno's UI (though I may be mistaken?)
9:55
Other UI pieces haven't been done though. We need one for Jupyter and vscode presumably
9:56
Jupyter discussion at https://github.com/c42f/TerminalLoggers.jl/issues/25
9:58
The nice thing about all (at least in principle) is that it separates the UI components from the code emitting the progress events.
9:59
Each end-user UI should eventually come with some nice filters which recognize structured log messages of various types and do their best to display it in a friendly way.
10:00
Oh btw, beware that TerminalLoggers.jl doesn't work with progress pretty printing on windows due to libuv woes. I need to make a workaround for that
Filippo Vicentini 10:04 PM
@c42f is the idea to eventually merge terminalloggers.jl in base?
Chris Foster 10:28 PM
Yes for sure.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment