Seelog concept

Simplified concept

The simplified diagram bellow shows principal parts of Seelog.

A brief description of each block

• Seelog.Trace/Debug/Info/Warn/Error/Critical are the actual funcs used to perform logging and the starting point. The parameters of these funcs are the same as fmt.Sprintf params (Log format and arguments list). Log performance depends on the length of message and parameters in the same way as fmt.Sprintf performance depends.
• Fast check is a fast 'if' instruction that check whether this log level is disabled. Log level is disabled if it is not used in any constraints (both general constraints and exceptions).
• Logger represents logging strategy in terms of application load and logger priority. Logger types (sync logger/async loop logger/async timer logger) differ in their behaviors.

  • Synchronous:) Logging is performed in the same goroutine where Trace/Debug/.../Critical func are called. It is a blocking behavior, chosen to log into file we would be forced to wait until the Trace/Debug/.../Critical func returns (until the file IO is finished).

  • Asynchronous: Trace/Debug/.../Critical creates a struct with message, arguments, log level, and then puts it into a queue (a channel actually). The application is not blocked and func returns immediately. Then the queue is processed in another goroutine according to the async logger type:

    Async loop: processes the queue in a 'for loop'. So the goroutine tries to process messages as fast as possible.

    Async timer: processes messages with some minimal time interval between them. The bigger the interval, the less appload generated by the logger subsystem.

• Dispatcher is a subsystem which dispatches the message according to the dispatcher configuration. For example, if you want to log to a file, to console, and to network, dispatcher will send the message to these three outputs.
• Format is a formatting subsystem which provides messages formatting functionality. This is actually the most dangerous place in context of performance. For example, if you choose format like “%Date/%Time [%Level] %Msg”, it will significantly hit the performance, because %Date or %Time both uses the standard Go package ‘time’ and the standard ‘Format’ function for every log message. For example, during one of our early proof-of-concept performance tests of one of our Seelog releases pprof tool showed us that ‘time.Format’ took about 40% of all the time our tests took. So, when high performance is needed, we recommend to use fast “%Ns” format verb, which maps current time to nanoseconds without any conversions or string formatting operations.
• Writers are the final byte-receivers of the formatted log messages which transfer them to hard drive, netword, e-mail, etc. Here is another dangerous place in terms of performance. For example, writing to console would significantly lag your app, while writing to file would be less dangerous. Buffered writers would be even more faster.

Example

Here is an example which is composed to show how the log messages travel through the pipeline. We are going to create a config, explain the goals of this config, and then try to log with different log levels in different functions and see what happens.

Config

NOTE: Syntax of some elements and their attributes (like 'smtp' element) is subject to changing in later versions. Stay tuned.

<seelog minlevel="info">
    <exceptions>
        <exception filepattern="perfcriticalfile.go" minlevel="critical"/>
    </exceptions>
    <outputs format="common">
        <file path="file.log"/>
        <filter levels="critical">
            <file path="critical.log" formatid="critical"/>
            <smtp formatid="criticalemail" senderaddress="noreply-notification-service@none.org" sendername="Automatic notification service" hostname="mail.none.org" hostport="587" username="nns" password="123">
                <recipient address="john-smith@none.com"/>
                <recipient address="hans-meier@none.com"/>
            </smtp>
        </filter>
    </outputs>
    <formats>
        <format id="common" format="[%LEV] %Msg"/>
        <format id="critical" format="%Time %Date %RelFile %Func %Msg"/>
        <format id="criticalemail" format="Critical error on our server!\n    %Time %Date %RelFile %Func %Msg \nSent by Seelog"/>
    </formats>
</seelog>

Config description

• We have a production server, so we want only a few info messages, errors, warnings, critical error messages. We wrote these so that it doesn't hit performance. That's why we set ''.
• We want all of these to be written using a high-performance format "%Ns [%LEV] %Msg", which doesn't use the time.Format or any other operations that would hit performance.
• For critical errors (Probably server dies with these messages or something becomes totally broken) we want a separate file and a separate format that gives full detail of what happened and where it happened. These messages rarely occur, so we can use an inefficient, but more readable format "%Time %Date %RelFile %Func %Msg" with more info in it.
• We also want these messages to be sent to our administrator's e-mail.
• We have a performance bottleneck file 'perfcriticalfile' and we want an exception for this file: we want only critical errors to be logged from it.

Case 1

Description: seelog.Debug("test") is called in method 'someFunc' in file 'someFile.go'.

Result: no output is produced

Explanation:

1. Called Seelog with log level = "Debug" and message = "test"
2. Seelog analyzer found that 'Debug' level is not used anywhere, so it is disabled and seelog.Debug(..) does nothing and returns immediately

Case 2

Description: seelog.Info("test") is called in method 'someFunc' in file 'someFile.go'.

Result: After some time in other goroutine the following happens:

• "[INF] test" is written to file.log

Explanation:

1. Called Seelog with log level = "Info" and message = "test"
2. Seelog analyzer found that 'Info' level is used somewhere, so message is allowed to be processed by Logger
3. Default logger type is used (because nothing is specified in config). This is an asynchronous loop logger. It means that we put the log message to a channel and other goroutine receives messages from this channel and processes them in a loop.
4. (In other goroutine) Constraints checker states that it is allowed to use "Info" log level in function "someFunc" in file "someFile.go", so the message proceeds to the dispatcher.
5. Dispatcher dispatches the message to two outputs: a file and a filter.
   1. File output uses an associated format "common" ([%LEV] %Msg) to format message and write to the file "file.log"
   2. Filter output only allows messages with level="critical", so this message is skipped by this filter

Case 3

Description: seelog.Info("test") is called in any function in file 'perfcriticalfile.go'.

Result: no output is produced

Explanation:

1. Called Seelog with log level = "Info" and message = "test"
2. Seelog analyzer found that 'Info' level is used somewhere, so message is allowed to be processed by Logger
3. Default logger type is used (because nothing is specified in config). This is an asynchronous loop logger. It means that we put the log message to a channel and other goroutine receives messages from this channel and processes them in a loop.
4. (In other goroutine) Constraints checker states that only "Critical" messages are allowed in file "perfcriticalfile.go", so this message is not sent to the Dispatcher.

Case 4

Description: seelog.Critical("panic!") is called in function "someFunc" in file "someFile.go".

Result: After some time in other goroutine the following happens:

• "[CRT] panic!" is written to file.log
• "2011-12-12 15:04:05 ./someFile.go someFunc panic!" is written to critical.log
• "Critical error on our server!\n 2011-12-12 15:04:05 ./someFile.go someFunc panic! \nSent by Seelog" is sent to e-mail "admin@cin.io"

Explanation:

1. Called Seelog with log level = "Critical" and message = "panic!"
2. Seelog analyzer found that 'Critical' level is used somewhere, so message is allowed to be processed by Logger
3. Default logger type is used (because nothing is specified in config). This is an asynchronous loop logger. It means that we put the log message to a channel and other goroutine receives messages from this channel and processes them in a loop.
4. (In other goroutine) Constraints checker states that it is allowed to use "Info" log level in function "someFunc" in file "someFile.go", so the message proceeds to the dispatcher.
5. Dispatcher dispatches the message to two outputs: a file and a filter.
   1. File output uses an associated format "common" ([%LEV] %Msg) to format message and write to the file "file.log"
   2. Filter allows messages with level="critical", so this message is allowed to filter sub-elements
      1. File output uses an associated format "critical" (%Time %Date %RelFile %Func %Msg) to format message and write to the file "critical.log"
      2. Smtp output uses an associated format "criticalemail" (Critical error on our server!\n %Time %Date %RelFile %Func %Msg \nSent by Seelog) to format message and send to e-mail "admin@cin.io"