Introduction

J’ai récemment eu le besoin d’écrire des messages de logs avec plusieurs niveaux. Venant du monde Java j’étais habitué à l’utilisation de Log4j. J’avais bien entendu parlé de loggers pour le langage Go mais à vrai dire, c’est plus amusant d’écrire un logger soi-même. J’ai alors consulté cette page signé Jean-Michel Doudoux (une référence francophone sur Java), dans le but de faire un bonne conception pour mon logger.

Voici les fonctionnalités à mettre en place:

  • Avoir plusieurs niveaux de logs
  • Pouvoir activé ou désactivé un niveau
  • Avoir une instance de logger par fichier
  • Récupéré le path du fichier qui appele le logger ainsi que le numéro de la ligne (la base)
  • Pouvoir logger dans la console (stdout) ou dans un buffer ou un fichier

Pour se faire nous allons suivre le plan suivant:

Implémentation des niveaux

Le niveau d’un log est un élément à ne pas prendre à la légère. Après avoir discuté avec certains Gophers, j’ai pu comprendre que beaucoup ont abandonné l’idée de mettre des break-points un peu partout pour déboguer.

En effet, en Go il est très facile de programmer les choses de façon asynchrone or, interompre l’exécution d’un programme faisant appel à des processus lancés de manière asynchrone n’est vraiment pertinent.

Selon ces mêmes Gophers, il vaut mieux logger un maximum de choses en utilisant de bons niveaux. Sachant qu’un niveau peut être activé ou désactivé à volonté, on peut très bien filtrer le contenu produit par le programme et ainsi déployer son application de façon à ce que cette dernière génère des logs pertinent pour de la prod ou du dev en local.

Le premier réflexe pour créer les niveaux de logs, c’est de créer une énumération.

package log

type levelEnum int

const (
	trace levelEnum = iota
	debug
	info
	warn
	err
	fatal
)

C’est sympa mais pas suffisant. Nous avons besoin d’activer ou désactiver un niveau. Autrement dit il nous faut un état pour chaque niveau. Or qui dit état, dit classe, donc une structure en Go. La solution est donc d’encapsuler chaque énumération par une structure.

// Level struct which represent a log level
type Level struct {
	value  levelEnum
	Enable bool
	name   string
}

func newLevel(value levelEnum, state bool, name string) *Level {
	level := new(Level)
	level.value = value
	level.Enable = state
	level.name = name
	return level
}

var (
	// TRACE log level
	TRACE = newLevel(trace, true, "TRACE")
	// DEBUG log level
	DEBUG = newLevel(debug, true, "DEBUG")
	// INFO log level
	INFO = newLevel(info, true, "INFO")
	// WARN log level
	WARN = newLevel(warn, true, "WARN")
	// ERROR log level
	ERROR = newLevel(err, true, "ERROR")
	// FATAL log level
	FATAL = newLevel(fatal, true, "FATAL")
)

J’ai créé une fonction pour créer un pointer de structure Level plus facilement. Ici j’ai fait le choix de créer des instances de Level globales et surtout publiques ! En effet je veux que les niveaux soient communs à tous les loggers et accessibles partout.

Si je désactive le niveau DEBUG, je veux que toutes les instances de logger n’écrivent plus de log de type DEBUG.

Ensuite, il nous faut une structure pour représenter le logger.

Implémentation de la structure Logger

// Logger struct which represent logger
type Logger struct {
	level  *Level
	file   string
	line   int
	mux    sync.Mutex
	Buffer io.Writer
}

On va revenir dessus ensemble si vous voulez bien. (et même si vous ne voulez pas d’ailleurs) On a un attribut level, effectivement notre logger a un niveau de log défini par défault si ce dernier n’est pas précisé à l’appel de la fonction chargé d’écrire un message de log.

Il y a un attribut file de type string qui contient le chemin absolu vers le fichier qui a appelé le logger. Rappelons que nous volons qu’une instance de logger par fichier ! L’attribut mux sera utilisé pour définir un sémaphore pour s’assurer que plusieurs loggers ne puissent pas écrire de messages en même temps.

L’attribut Buffer permettra de définir un buffer par défaut. C’est à dire, où le logger doit écrire ses messages. Cela peut être une variable de type bytes.Buffer, un fichier via os.File, ou la console via os.Stdout ect. Bref tout ce qui implémente l’interface io.Writer.

// Contains unique instance of each logger
var loggers = map[string]*Logger{}

// Instance get logger instance, create one if not exist for file
func Instance() *Logger {
	_, file, _, ok := runtime.Caller(1)

	if ok == false {
		panic("Unable to get result from runtime.Caller")
	}

	log, isPresent := loggers[file]

	if isPresent {
		return log
	}

	created := new(Logger)
	created.file = file
	loggers[file] = created

	return created
}

Le logger se comporte un peut comme un Singleton dont l’instance est rattachée au nom du fichier appelant.

Je fais appelle à runtime.Caller pour récupérer quelques informations de la pile d’exécution afin de retrouver le chemin absolu vers le fichier qui appelle le logger. Si l’appel à runtime.Caller a échoué je déclanche une panic.

Oui le logger peut planter et j’ai pas voulu implémenter un defer panic recover. Dans ce cas de figure je ne veux pas que le programme poursuive son exécution.

Ce qui suit est un getter et un setter fluent, classique même si considéré un peu comme un anti-pattern en Go.

// SetLevel of logger
func (l *Logger) SetLevel(level *Level) *Logger {
	l.level = level
	return l
}

// GetLevel get logger lovel
func (l *Logger) GetLevel() *Level {
	return l.level
}

Écriture des logs

Voici ci-dessous notre fonction qui a pour but d’écrire un message de log. J’ai souhaité formatter le message un peu à la manière de log4j.

Note à moi-même: Prévoir dans une évolution du logger la possibilité de renseigner un format différent pour les messages.

// Used by other functions
func (l *Logger) log(writer io.Writer, level *Level, format string, a ...interface{}) {
	if level.Enable == false {
		return
	}

	l.updateDataStacked(3)
	toPrint := fmt.Sprintf("%s [%s] (%s:%d) %s\n", time.Now().UTC().String(), level.name, l.file, l.line, fmt.Sprintf(format, a...))
	defer l.mux.Unlock()
	l.mux.Lock()
	fmt.Fprintf(writer, toPrint)
}

Et à présent, notre super fonction Log (accessible depuis d’autres packages), celle-ci va écrire un message de log selon le niveau défini dans le logger. D’abord on vérifie que le niveau désiré est activé (si non, on quitte la fonction) puis on met à jour les infos provenant de la pile d’exécution avant de construire le message à écrire dans un buffer.

Si le buffer par défault n’est pas paramétré, on défini un buffer par défaut à l’aide de la méthode defaultBuffer. Attention, le switch doit se faire sur la valeur de type levelEnum de chaque instance de Level. Rappelons que le levelEnum est un type alias de int.

func (l *Logger) defaultBuffer(buffer io.Writer) io.Writer {
	if l.Buffer == nil {
		return buffer
	}
	return l.Buffer
}

// Log method to make logs
func (l *Logger) Log(format string, a ...interface{}) {
	switch l.level.value {
	case trace:
		l.log(l.defaultBuffer(os.Stdout), TRACE, format, a...)
		break
	case debug:
		l.log(l.defaultBuffer(os.Stdout), DEBUG, format, a...)
		break
	case info:
		l.log(l.defaultBuffer(os.Stdout), INFO, format, a...)
		break
	case warn:
		l.log(l.defaultBuffer(os.Stdout), WARN, format, a...)
		break
	case err:
		l.log(l.defaultBuffer(os.Stderr), ERROR, format, a...)
		break
	case fatal:
		l.log(l.defaultBuffer(os.Stderr), FATAL, format, a...)
		break
	default:
		l.log(l.defaultBuffer(os.Stdout), TRACE, format, a...)
	}
}

Cela dit c’est pas toujours pratique, on veut pouvoir écrire des logs avec différents niveaux mais avec une même instance de logger. J’ai défini quelques fonctions simples à utiliser qui ne nécessitent pas de passer le niveau désiré en paramètre.

Exemple pour Trace et Debug.

// Trace explicit TRACE log call
func (l *Logger) Trace(format string, a ...interface{}) {
	l.log(l.defaultBuffer(os.Stdout), TRACE, format, a...)
}

// Debug explicit DEBUG log call
func (l *Logger) Debug(format string, a ...interface{}) {
	l.log(l.defaultBuffer(os.Stdout), DEBUG, format, a...)
}

Cependant, il est souvent bon de pouvoir écrire dans différent buffers. C’est pourquoi j’ai défini Flog qui prends en paramètre un objet implémentant l’interface io.Writer et un niveau de log.

// Flog like Log function but you have to provide your own io.Writer
func (l *Logger) Flog(writer io.Writer, level *Level, format string, a ...interface{}) {
	l.log(writer, level, format, a...)
}

Tests unitaires

Tester un message n’est pas si évident. En effet pour tester le logger nous devons tester plusieurs paramètres.

  • Le nom du fichier qui appelle le logger.
  • Le numéro de la ligne où le logger est appelé.
  • Le niveau du message.
  • Et quelques comportement concernant le logger et les niveaux.
func TestNewLevel(t *testing.T) {
	level := newLevel(trace, true, "TRACE")

	if level.value == trace && level.Enable {
		t.Logf("OK")
	} else {
		t.Errorf("%v", level)
	}
}

func TestLevelEnum(t *testing.T) {
	condition := trace == 0 && debug == 1 && info == 2 && warn == 3 && err == 4 && fatal == 5

	if condition {
		t.Log("OK")
	} else {
		t.Errorf("wrong levelEnum, trace %d, debug %d, info %d, warn %d, err %d, fatal %d", trace, debug, info, warn, err, fatal)
	}
}

Ici on test l’initialisation d’un Level ainsi que l’énumération levelEnum.

func testLoggerInstanceDeeper(t *testing.T, logger *Logger) {
	filepath := logger.file

	if filepath == "" {
		t.Errorf("No filepath found on logger %v", logger)
	}

	splitted := strings.Split(filepath, "/")

	if len(splitted) == 0 {
		t.Errorf("Invalid filepath %s", filepath)
	}

	filename := splitted[len(splitted)-1]

	if filename != "logger_test.go" {
		t.Errorf("Invalid filename %s", filename)
	}

	if logger.line != 0 {
		t.Errorf("Invalid line %d", logger.line)
	}

	if logger.level != nil {
		t.Errorf("Invalid level %v", logger.level)
	}
}

func TestInstance(t *testing.T) {
	logger := Instance()

	testLoggerInstanceDeeper(t, logger)

	logger2 := Instance()

	if reflect.DeepEqual(logger, logger2) {
		t.Logf("OK")
	} else {
		t.Errorf("logger and logger2 not equal\nlogger: %v\nlogger2: %v", logger, logger2)
	}
}

On s’assure que le logger est bien initialisé et on vérifie que la méthode statique Instance retourne bien la même instance de logger.

func testLog(t *testing.T, level *Level) {
	loggers := Instance().SetLevel(level)
	var buffer bytes.Buffer
	loggers.Buffer = &buffer

	loggers.Log("test %d", 42)

	output := buffer.String()
	condition := strings.Contains(output, fmt.Sprintf(" [%s] ", level.name)) && strings.Contains(output, "logger_test.go:89") && strings.Contains(output, "test 42")

	if condition {
		t.Logf("OK")
	} else {
		t.Errorf("Invalid log, output: %s", output)
	}
}

type logCallback func(format string, a ...interface{})

func testLogUsingCallback(t *testing.T, level *Level, log logCallback, line int) {
	loggers := Instance()
	var buffer bytes.Buffer
	loggers.Buffer = &buffer

	log("test %d", 42)

	output := buffer.String()
	condition := strings.Contains(output, fmt.Sprintf(" [%s] ", level.name)) && strings.Contains(output, "logger_test.go:") && strings.Contains(output, "test 42")

	if condition {
		t.Logf("OK")
	} else {
		t.Errorf("Invalid log, output: %s", output)
	}
}

func testLogWithDisabledLog(t *testing.T, level *Level, log logCallback) {
	loggers := Instance()
	var buffer bytes.Buffer
	loggers.Buffer = &buffer

	log("test %d", 42)

	output := buffer.String()
	condition := len(output) == 0

	if condition {
		t.Logf("OK")
	} else {
		t.Errorf("Invalid log, output: %s", output)
	}
}

func testFlog(t *testing.T, level *Level) {
	loggers := Instance().SetLevel(level)
	var buffer bytes.Buffer
	loggers.Buffer = &buffer

	loggers.Flog(&buffer, level, "test %d", 42)

	output := buffer.String()
	condition := strings.Contains(output, fmt.Sprintf(" [%s] ", level.name)) && strings.Contains(output, "logger_test.go:142") && strings.Contains(output, "test 42")

	if condition {
		t.Logf("OK")
	} else {
		t.Errorf("Invalid log, output: %s", output)
	}
}

func TestLog(t *testing.T) {
	loggers := Instance()

	testLog(t, TRACE)
	testLog(t, DEBUG)
	testLog(t, INFO)
	testLog(t, WARN)
	testLog(t, ERROR)
	testLog(t, FATAL)

	testLogUsingCallback(t, TRACE, loggers.Trace, 130)
	testLogUsingCallback(t, DEBUG, loggers.Debug, 131)
	testLogUsingCallback(t, INFO, loggers.Info, 132)
	testLogUsingCallback(t, WARN, loggers.Warn, 133)
	testLogUsingCallback(t, ERROR, loggers.Error, 134)
	testLogUsingCallback(t, FATAL, loggers.Fatal, 135)

	testFlog(t, TRACE)
	testFlog(t, DEBUG)
	testFlog(t, INFO)
	testFlog(t, WARN)
	testFlog(t, ERROR)
	testFlog(t, FATAL)
}

func TestAllLevelDisable(t *testing.T) {
	loggers := Instance()

	TRACE.Enable = false
	DEBUG.Enable = false
	INFO.Enable = false
	WARN.Enable = false
	ERROR.Enable = false
	FATAL.Enable = false

	testLogWithDisabledLog(t, TRACE, loggers.Trace)
	testLogWithDisabledLog(t, DEBUG, loggers.Debug)
	testLogWithDisabledLog(t, INFO, loggers.Info)
	testLogWithDisabledLog(t, WARN, loggers.Warn)
	testLogWithDisabledLog(t, ERROR, loggers.Error)
	testLogWithDisabledLog(t, FATAL, loggers.Fatal)
}

Là c’est un gros pavé. Je teste l’écriture d’un message de log, quels que soient le niveau (activé ou non) ou le buffer utilisé.

Conclusion

Implémenter un logger en Go n’est pas très compliqué et s’avère être un exercice assez amusant. Voici les sources du logger. Merci d’avoir lu ce torchon et à bientôt je l’espère ! :)

https://gitlab.com/protocod/log