Log levels

Introduction

This document represents our vision of log level gradations, log level meanings, and usage scope. This topic is debatable and there are several concepts, but as we are tuning our code in context of our vision, it is recommended not to deviate from our concepts too much.

Supported log levels

• Trace - Pervasive information about states of all elementary constructs. Use 'Trace' for deep debugging to find a problem part of a function, to check values of temporary variables
• Debug - Produces detailed report on system behavior. Diagnostically helpful messages that let you find problems during development
• Info - General information about app work. You should use 'Info' level in your code so that you could leave it 'enabled' even in production. So it is a 'production log level'
• Warn - Small errors, strange situations, failures that are automatically handled in a safe manner
• Error - Serious failure that affects application logic. Not fatal, however, doesn't force app shutdown
• Critical - Final message before app’s death
• Off - A special log level used to turn off logging

Examples of log messages

• Trace
  • "Entered parse function validation block"
  • "Validation: entered second 'if'"
  • "Dictionary 'Dict' is empty. Using default value"
• Debug
  • "Web page requested: http://somesite.com Params='...'"
  • "Response generated. Response size: 10000. Sending."
  • "New file received. Type:PNG Size:20000"
• Info
  • "Web server restarted"
  • "Hourly statistics: Requested pages: 12345 Errors: 123 ..."
  • "Service paused. Waiting for 'resume' call"
• Warn
  • "Cache corrupted for file='test.file'. Reading from back-end"
  • "Database 192.168.0.7/DB not responding. Using backup 192.168.0.8/DB"
  • "No response from statistics server. Statistics not sent"
• Error
  • "Internal error. Cannot process request #12345 Error:...."
  • "Cannot perform login: credentials DB not responding"
• Critical
  • "Critical panic received: .... Shutting down"
  • "Fatal error: ... App is shutting down to prevent data corruption or loss"

Example

Let's check a working example, which demonstrates usage of log levels in scope of our vision.

NOTE 1: This example doesn't actually make any sense in terms of calculations. Just to demonstrate difference in log level usage contexts. NOTE 2: We know that there is a 'time.Sleep(1e9)' between every input. That's why we use 'Info'. But we don't want you to use 'Info' for frequent external inputs, because 'Info' is a 'production log level' and shouldn't affect performance in production, when enabled

package main

import (
	log "github.com/cihub/sealog"
	"os"
	"time"
)

type calcStruct struct {
	x int
	y int
}

type resultStruct struct {
	result int
	error bool
}

var inputs chan calcStruct
var outputs chan resultStruct
var criticalChan chan int

func internalCalculationFunc(x, y int) (result int, err os.Error) {
	log.Debug("calculating z. x:%d y:%d", x, y)
	z := y
	
	if x == 3 {
		log.Trace("x==3")
		panic("Strange failure!")
	}
	
	if y == 1 {
		log.Trace("y==1")
		return 0, os.NewError("Error!")
	}
	
	if y == 2 {
		log.Trace("x==y")
		z = x
	} else {
		log.Trace("x!=y")
		z += x
	}
	
	log.Trace("z:%d",z)
	
	retVal := z-3
	
	log.Debug("Returning %d", retVal)
	
	return retVal, nil
}


func sendSignals(dest chan calcStruct) {
	time.Sleep(1e9)
	log.Debug("Sending 2 3")
	dest <- calcStruct{x:2, y:3}
	time.Sleep(1e9)
	log.Debug("Sending 2 1")
	dest <- calcStruct{x:2, y:1}
	time.Sleep(1e9)
	log.Debug("Sending 3 4")
	dest <- calcStruct{x:3, y:4}
	time.Sleep(1e9)
	log.Debug("Sending critical")
	criticalChan <- 1
}

func doSomethingWithResults(res chan resultStruct) {
	for {
		select {
			case <- outputs:
			//
		}
	}
}

func processInput(input calcStruct) {
	defer func() {
		if r := recover(); r != nil {
            log.Error("Unexpected error occurred: %v", r)
			outputs <- resultStruct{result:0, error:true}
        }
	}()
	log.Info("Received input signal. x:%d y:%d", input.x, input.y)	
	
	res, err := internalCalculationFunc(input.x, input.y)
				
	if err != nil {
		log.Warn("Strange error in calculations occurred: %s", err.String())
	}
			
	log.Info("Returning result: %d error: %t", res, err != nil)		
	outputs <- resultStruct{result:res, error:err != nil}	
}

func main() {
	inputs = make(chan calcStruct)
	outputs = make(chan resultStruct)
	criticalChan = make(chan int)
	log.Info("App started!")
	go doSomethingWithResults(outputs)
	log.Info("Started receiving results")
	go sendSignals(inputs)
	log.Info("Started sending signals")
		
	for {
		select {
			case input := <- inputs:
				processInput(input)
			case <- criticalChan:
				log. Critical("Someone wrote to criticalChan! Shutting down!")
				panic("Big problem! Shutting down")
		}	
	}
}