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

[WIP] Flexible and convenient logging #30

Merged
merged 8 commits into from
Sep 17, 2017
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
122 changes: 106 additions & 16 deletions Logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -47,14 +47,15 @@ rather than `println()`. We should have:
stack trace, etc.) should be automatically gathered without a syntax burden.
* Freedom in formatting the log message - simple string interpolation,
`@sprintf` and `fmt()`, etc should all be fine.
* Zero logger setup for simple uses.
* No mention of log dispatch should be necessary at the message creation site.
* Easy filtering of log messages.
* Clear guidelines about the meaning and appropriate use of standard log levels
for consistency between packages, along with guiding the appropriate use of
logging vs stdout.
* To encourage the use of logging over ad hoc console output, the default
console log handler should emphasize the *log message*, and metadata should be
communicated in a non-intrusive way.
* The default console log handler should integrate somehow with the display
system to show log records in a way which is highly readable. Ideally logging
should be a tool for package authors just as much as it is a tool for
understanding production systems.


The API should be **flexible enough** for advanced users:
Expand Down Expand Up @@ -94,8 +95,82 @@ comes in three flavours:

## Proposed design

A rough work in progress implementation is available at
https://github.com/c42f/MicroLogging.jl
A prototype implementation is available at https://github.com/c42f/MicroLogging.jl
### Quickstart Example

#### Frontend
```julia
# using Base.Log

# Logging macros
@debug "A message for debugging (filtered out by default)"
@info "Information about normal program operation"
@warn "A potentially problem was detected"
@error "Something definitely went wrong, but we recovered enough to continue"
@logmsg Log.Info "Explicitly defined info log level"

# Free form message formatting
x = 10.50
@info "$x"
@info @sprintf("%.3f", x)
@info begin
A = ones(4,4)
"sum(A) = $(sum(A))"
end

# Progress reporting
for i=1:10
@info "Some algorithm" progress=i/10
end

# User defined key value pairs
foo_val = 10.0
@info "test" foo=foo_val bar=42
```


### What is a log record?

Logging statements are used to understand algorithm flow - the order and timing
in which logging events happen - and the program state at each event. Each
logging event is preserved in a **log record**. The information in a record
needs to be gathered efficiently, but should be rich enough to give insight into
program execution.

A log record includes information explicitly given at the call site, and any
relevant metadata which can be harvested from the lexical and dynamic
environment. Most logging libraries allow for two key pieces of information
to be supplied explicitly:

* The **log message** - a user-defined string containing key pieces of program
state, chosen by the developer.
* The **log level** - a category for the message, usually ordered from verbose
to severe. The log level is generally used as an initial filter to remove
verbose messages.

Some logging libraries (for example
[glib](https://developer.gnome.org/glib/stable/glib-Message-Logging.html)
structured logging) allow users to supply extra log record information in the
form of key value pairs. Others like
[log4j2](https://logging.apache.org/log4j/2.x/manual/messages.html) require extra information to be
explicitly wrapped in a log record type. In julia, supporting key value pairs
in logging statements gives a good mixture of usability and flexibility:
Information can be communicated to the logging backend as simple keyword
function arguments, and the keywords provide syntactic hints for early filtering
in the logging macro frontend.

In addition to the explicitly provided information, some useful metadata can be
automatically extracted and stored with each log record. Some of this is
extracted from the lexical environment or generated by the logging frontend
macro, including code location (module, file, line number) and a unique message
identifier. The rest is dynamic state which can generally on demand by the
Copy link

Choose a reason for hiding this comment

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

can be generated?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes, I generally don't know how this happened!

Copy link

Choose a reason for hiding this comment

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

still missing "be"

backend, including system time, stack trace, current task id.

### The logging frontend

### Dispatching records

### Early filtering


## Concrete use cases
Expand All @@ -113,19 +188,34 @@ both in the code and for user control.
* The depwarn system, and `--depwarn` command line flag


## Survey of other logging systems
## Inspriation

Much of the above is a reinterpretation in julia of python's standard logging
module, attempting to be even more convenient and much more efficient, while
retaining the same flexibility.
This Julep draws inspiration from many previous logging frameworks, and helpful
discussions with many people online and at JuliaCon 2017.

* A summary of how this all fits in with Logging.jl, MiniLogging.jl, Memento.jl,
LumberJack.jl, and any other logging libraries which can be found.
* glib (C) - https://developer.gnome.org/glib/stable/glib-Message-Logging.html
The Java logging framework [log4j2](https://logging.apache.org/log4j/2.x/) was a
great source of use cases, as it contains the lessons from at least twenty years
of large production systems. While containing a fairly large amount of
complexity, the design is generally very well motivated in the documentation,
giving a rich set of use cases. The julia logging libraries - Base in julia 0.6,
Logging.jl, MiniLogging.jl, LumberJack.jl, and particularly
[Memento.jl](https://github.com/invenia/Memento.jl) - provided helpful
context for the needs of the julia community.

Structured logging as available in
[glib](https://developer.gnome.org/glib/stable/glib-Message-Logging.html)
and [RFC5424](https://datatracker.ietf.org/doc/rfc5424/?include_text=1) (The
Syslog protocol) provide context for the usefulness of log records as key value
pairs.

For the most part, existing julia libraries seem to follow the design tradition
of the standard [python logging library](https://docs.python.org/3/library/logging.html),
which has a lineage further described in [PEP-282](https://www.python.org/dev/peps/pep-0282/).
The python logging system provided a starting point for this Julep, though the
design eventually diverged from the typical hierarchical setup.

TODO: Re-survey the following?
* a-cl-logger (Common lisp) - https://github.com/AccelerationNet/a-cl-logger
* Lager (Erlang) - https://github.com/erlang-lager/lager
* Some java logger *cough*? That should be enterprisey enough, right ;-)
* syslog (unix) ?

TODO - much more here.