How to log to file with a customized log format?

New to Julia
1

I’m currently trying to build a logging demonstration using the JuliaLogging components (standard library + a few seemingly very standard packages).

I may be wrong, however I think there are 3 parts to logging. This isn’t specific to Julia, this is more general and applies to any language, really.

  1. Log data capturing (sources)
  2. Log string (or otherwise - might be a binary string) formatting
  3. Log sinks

Sources/data capture are some statements in code which specify the inputs. It could be as simple as a log message string, or it might include metadata, such as a module name, line number, or other data.

Formatters are things which take data from a source and structure it into some human or machine readable string.

Log sinks are devices which can accept string formatted logs and write or store them somewhere. Files, the console, or databases could be examples of this.

This is, in an approximate sense, how most logging frameworks are structured.

Julia’s logging tools might be structured like this, or it might be a bit different. I don’t have a solid understanding of how everything fits together yet. Please do let me know if my mental model is wrong.

What is relatively easy to understand are the sources. (Because these are fixes for any application.)

We have the macros

  • @error
  • @warn
  • @info
  • @debug

These macros expect a string to follow and then optionally, metadata. Some additional metadata is automatically provided, such as the module name, function name and line number.

These macros are all provided by the Logging package.

There are 11 other packages mentioned on JuliaLogging. This is where things get complicated. If I understand correctly, all of these things are supposed to interop together.

In regards to formatting, there is the LoggingFormats package. However, this appears to contain a predefined set of formats, which includes a tool for formatting logs in JSON format. The more general purpose FormatLogger is actually in LoggingExtras.

In this package, we also find the FileLogger, which is a sink.

Ok, so let’s accept that sources, formatting intermediaries and sinks are not separated into seperate packages but mixed together. Fine.

It seems I have all the pieces.

I want to be able to

@info "just a test!"

and have this write to a file, formatted using FormatLogger.

I’m somewhat lost as to how to take these “individual pieces” and put them together to achieve this.

Here’s some snippets of code where I’ve been testing out a few things.

using Logging
using LoggingExtras

function (@main)(args)
    println("hello world")
  1. Just the standard stdout/stderr default log sink and format.
    @info "hello world - info"
    @warn "hello world - warning"

It will give you

[ Info: hello world - info
┌ Warning: hello world - warning
└ @ Main ~/work/tmp/JuliaLogging/main.jl:9
  1. I managed to get logging to a file to work. For some reason, I needed a SimpleLogger?
    io_stream = open("example-log-stream.txt", "a")
    logger = SimpleLogger(io_stream, Debug)
    with_logger(logger) do
        @info "SimpleLogger info log"
        @warn "SimpleLogger warning log"
    end

This is the output

┌ Info: SimpleLogger info log
└ @ Main /home/user/work/tmp/JuliaLogging/main.jl:14
┌ Warning: SimpleLogger warning log
└ @ Main /home/user/work/tmp/JuliaLogging/main.jl:15

so I would guess that a SimpleLogger is a type of FormatLogger?

They both inherit from AbstractLogger, so this doesn’t seem to check out exactly.

Maybe a SimpleLogger is an alternative to a FormatLogger and defines a fixed format for logging?

  1. I also managed to get FileLogger working. But this seems to be using the SimpleLogger format, despite none of the code specifying this.
    file_logger = FileLogger(io_stream)
    with_logger(file_logger) do
        @info "info to file_logger stream"
    end

Here’s the output

┌ Info: info to file_logger stream
└ @ Main /home/user/work/tmp/JuliaLogging/main.jl:31

which is suspiciously similar to the above.

The code ends with a final end for the end of function (@main)

end

The specific question I have is how do I plumb a FileLogger up to a FormatLogger?

To rephrase it slightly - how do I log to a file using a user-defined format?

More generally, I am somewhat lost when it comes to this (quite extensive) logging ecosystem. If anyone has any wisdom which can help me to understand it that would also be much appreciated.

1 Like
2

Here is an example that I used for some simulations:

using Logging
using LoggingExtras

function add_datetime_logger(logger)
    return TransformerLogger(logger) do log
        merge(log, (; message = "[$(Dates.now())]-#$(Threads.threadid()): $(log.message)"))
    end
end

function logger_for_params(params, minlevel = Logging.Info)
    logfile = datadir("logs", savename(params, "txt"))
    return MinLevelLogger(
        add_datetime_logger(
            TeeLogger(
                MinLevelLogger(ConsoleLogger(stdout), Logging.Warn),
                FileLogger(logfile))),
        minlevel)
end

This writes the log both to the console and to a file and prepends the current time and thread ID to the message. Also filters below the given minlevel (so excludes all “weaker” messages) .

I think this example might be sufficient for you to understand how to use these packages. If you need a more detailed explanation please ask :slight_smile:

1 Like
3

Hard to tell from this but I think what your code suggests is something like this is possible:

logger = 
MinLevelLogger(
    TransformerLogger(
        TeeLogger(
            MinLevelLogger(
                ConsoleLogger(stdout), Logging.Warn),
            FileLogger("log-file.log"),
        )
    ),
    Logging.Info,
)

I suspected this might be the kind of thing which should be possible. Almost like a declaration of a chain of processing modules which process log events.

So I’m wondering. Can something like this be done?

f = (io, logdata)->println(io, "$(logdata._module)->{ [$(logdata.level)]~$(logdata.message)}")
logger = FileLogger(FormatLogger(f, io_stream, true))

This won’t compile. It’s not easy to figure out what the right syntax is from the docs.

4

If you state something like this, then it is always very helpful if you post the error :slight_smile:

Using the help-mode in Julia’s REPL (accessible via ?) I found that likely you are using FormatLogger wrong. I think it should be: FormatLogger(f, io_stream; append=true)

help?> FormatLogger
search: FormatLogger FileLogger AbstractLogger ConsoleLogger TransformerLogger TeeLogger NullLogger current_logger

  FormatLogger(f::Function, io::IO=stderr; always_flush=true)

  Logger sink that formats the message and finally writes to io. The formatting function should be of the form
  f(io::IOContext, log_args::NamedTuple) where log_args has the following fields: (level, message, _module, group, id,
  file, line, kwargs). See LoggingExtras.handle_message_args for more information on what field is.

  Examples
  ≡≡≡≡≡≡≡≡

  julia> using Logging, LoggingExtras

  julia> logger = FormatLogger() do io, args
             println(io, args._module, " | ", "[", args.level, "] ", args.message)
         end;

  julia> with_logger(logger) do
             @info "This is an informational message."
             @warn "This is a warning, should take a look."
         end
  Main | [Info] This is an informational message.
  Main | [Warn] This is a warning, should take a look.

  ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────

  FormatLogger(f::Function, path::AbstractString; append=false, always_flush=true)

  Logger sink that formats the message and writes it to the file at path. This is similar to FileLogger except that it
  allows specifying the printing format.

  To append to the file (rather than truncating the file first), use append=true. If always_flush=true the stream is
  flushed after every handled log message.
5

I don’t understand how to use it correctly.

Allow me to give a single example.

If a FormatLogger takes an io_stream as an argument, that would suggest it is incompatiable with a FileLogger.

Why? Because it needs to take some lower level IO object than a FileLogger.

Maybe that’s the wrong constructor to use? I looked at the others and couldn’t see any other forms of the constructor which would be relevant.

6

As it says here in the docstring I posted

A FormatLogger is a sink. A FileLogger is also a sink. So naturally you cannot combine them. A format logger formats the message and then writes them to the provided iostream (which can be an opened file). A FileLogger is more specialized and just writes everything it gets to a file directly. If you want to transform a message and then pass them on to different loggers downstream, you’ll need to use a
TransformerLogger like in the example code I posted.

1 Like
7

Ok right, I was afraid it might be this way. Never mind, thank you for your help.

Does this mean I have the wrong mental model? Do we just have sources and sinks with no formatting intermediaries?

(Still things like Tee are an intermediary)

8

Why are you afraid?

No there are intermediaries that transform the log messages. Like the TransformerLogger in my example. Let me quote the Readme from LoggingExtras.jl

Loggers break down into four types:

Sinks: Sinks are the endpoint of a log message journey. They write it to file or display it on the console or set off a red flashing light in the laboratory. A Sink should never decide what to accept, only what to do with it.
Filters: Filters wrap around other loggers and decide whether or not to pass on a message. When that decision occurs, they can be further broken down (See ActiveFilteredLogger vs EarlyFilteredLogger).
Transformers: Transformers modify the content of log messages before passing them on, including metadata, such as severity level. Unlike Filters, they can’t block a log message, but they could drop its level down to say Debug so that usually no one would see it.
Tee: There is only one possible TeeLogger, and it is central to log routing. It acts as a hub that receives one log message and then sends copies to all its child loggers. Like in the diagram above, it can be composed with Filters to control what goes where.

Personally I think this is a very flexible system which should be able to express virtually anything. I suggest you read the Readme of the Github Repo that I linked and then ask more questions/give feedback about parts you find incomprehensible :slight_smile: then we can help you understand and improve the docs :slight_smile:

9

You can’t really have an intermediate formatting logger[1] since how to format the message is very tightly coupled to what the sink is. Formatting the message would mean very different things if the sink is the terminal, a database, an HTTP request, etc.

  1. You can of course do things as manipulating the log message and such as a type of formatting but not decide what will happen with the various metadata fields. ↩︎

10

Yea, you can say that. SimpleLogger could have been implemented as a FormatLogger with a predefined formatting function.

See LoggingExtras.jl/src/Sinks/filelogger.jl at 414e0c8136ab51ffb44183cbe7cab59c66d89490 · JuliaLogging/LoggingExtras.jl · GitHub – FileLogger is just a convenience layer around SimpleLogger for automatically opening/flushing/closing the IO stream.

You don’t, but the FormatLogger can be used exactly like the FileLogger since it also has the capability to open/flush/close the stream, see LoggingExtras.jl/src/Sinks/formatlogger.jl at 414e0c8136ab51ffb44183cbe7cab59c66d89490 · JuliaLogging/LoggingExtras.jl · GitHub

I see you have already found https://julialogging.github.io/ which was my attempt at documenting these things from a couple of years ago. You may also find @oxinabox 's video presentation from JuliaCon last year useful.

1 Like