Tutorial - Logging

What you’ll learn

How Granitic handles logging from your code.
How to adjust which messages are logged.
How to change logging behaviour at runtime.

Prerequisites

Follow the Granitic installation instructions
Read the before you start tutorial
Either have completed tutorial 2 or clone the tutorial repo and navigate to json/003/recordstore in your terminal.

Logging

Logging in Granitic gives developers fine-grained control over which components output logging information. There are two main concepts for you to become familiar with:

Loggers - the components that format log messages and choose whether or not to write them to a console or file, based on the severity assigned to the message.
Severity - the importance of a message to be logged.

Severities are (in ascending order of importance) TRACE, DEBUG, INFO, WARN, ERROR, FATAL. See the GoDoc for more detail

Your code will log messages through a Granitic component called a Logger. Granitic has two built-in Loggers the ApplicationLogger and the FrameworkLogger.

As the names suggest, the FrameworkLogger is used by internal Granitic components and the ApplicationLogger is for your application’s code.

As the majority of components that you build will need access to the ApplicationLogger, Granitic has a built-in ComponentDecorator that automatically injects a reference to the ApplicationLogger into any of your components with a struct field that is exactly:

    Log logging.Logger

To see this in action, modify the file artist/get.go so it looks like:

package artist

import (
	"context"
	"fmt"
	"github.com/graniticio/granitic/v2/logging"
	"github.com/graniticio/granitic/v2/ws"
)

type GetLogic struct {
	EnvLabel string
	Log      logging.Logger
}

func (gl *GetLogic) Process(ctx context.Context, req *ws.Request, res *ws.Response) {

	an := fmt.Sprintf("Hello, %s!", gl.EnvLabel)

	res.Body = Info{
		Name: an,
	}

	log := gl.Log

	log.LogInfof("Environment is set to '%s'", gl.EnvLabel)
	log.LogTracef("Request served")
}

type Info struct {
	Name string
}

Open your terminal and run:

grnc-bind && go build && ./recordstore

Keep the terminal window visible and visit http://localhost:8080/artist and you’ll see a line appear in your terminal similar to:

07/Aug/2023:18:37:16 Z INFO  [artistHandlerLogic] Environment is set to 'TEST'

This line shows:

The timestamp of when the message was logged
The severity of the message (INFO)
The name of the component issuing the message (artistHandlerLogic)
The message itself

Unit tests

You may find the type logging.ConsoleErrorLogger useful when writing unit tests for code that needs a logging.Logger

Global log level

You may have noticed that the INFO level message is shown but the TRACE message is not. This is because the global log level for the ApplicationLogger is also set to INFO in the facility configuration file

facility/config/logging.json

which looks something like:

{
  "LogWriting": {
    "EnableConsoleLogging": true,
    "EnableFileLogging": false,
    "File": {
      "LogPath": "./granitic.log",
      "BufferSize": 50
    },
    "Format": {
      "UtcTimes":     true,
      "Unset": "-"
    }
  },

  "FrameworkLogger":{
    "GlobalLogLevel": "INFO"
  },
  "ApplicationLogger":{
    "GlobalLogLevel": "INFO"
  }
}

The global log level means that only messages with a severity equal to or greater than the global log level with be logged.

You can override the global log level for you own application. Open config/base.json and set the contents to:

{
  "Facilities": {
    "HTTPServer": true,
    "JSONWs": true
  },

  "ApplicationLogger":{
    "GlobalLogLevel": "ERROR"
  },

  "environment": {
    "label": "DEV"
  }
}

If you stop and restart your recordstore application and refresh or re-visit http://localhost:8080/artist, you’ll see that the INFO message is no longer displayed.

Notice that you are still seeing other INFO messages from components whose names start grnc. These components are built-in Granitic components and use the FrameworkLogger component which has its own GlobalLogLevel

File logging

By default Granitic only logs messages to the console. Look at the file facility/config/logging.json to see how you can enable logging to a file.

Component specific log levels

Sometimes you want to allow a single component to log messages that are below the global log level (to aid debugging) or to squelch a component that is too noisy. This can be achieved by setting a log level for a specific component. Modify your config/base.json file so that the ApplicationLogger section looks like:

"ApplicationLogger": {
    "GlobalLogLevel": "ERROR",
    "ComponentLogLevels": {
        "artistHandlerLogic": "TRACE"
    }
}

If you stop and restart your recordstore application and refresh or re-visit http://localhost:8080/artist, you’ll see an additional message displayed:

07/Aug/2023:18:43:03 Z INFO  [artistHandlerLogic] Environment is set to 'UNSET'
07/Aug/2023:18:43:03 Z TRACE [artistHandlerLogic] Request served

Runtime control of logging

When investigating problems with production code it can be very helpful to enable lower-priority messages without having to restart or re-deploy an application. Granitic supports this through the RuntimeCtl facility.

Stop your instance of recordstore and change

config/base.json

so that the Facilities section looks like:

"Facilities": {
    "HTTPServer": true,
    "JSONWs": true,
    "RuntimeCtl": true
}

Restart recordstore and you will see a new line in the startup logs:

07/Aug/2023:18:44:05 Z INFO  [grncCtlServer] Listening on 9099

You can now use the grnc-ctrl command line tool to issue commands to recordstore while it is running.

To get a list of the high level actions you can perform with this tool, open a new terminal and run:

grnc-ctl help

and for more detailled help about the commands relating to log-level management:

grnc-ctl help global-level
grnc-ctl help log-level

for more information on the commands related to logging.

Try running:

grnc-ctl log-level artistHandlerLogic FATAL

to raise the logging threshold for the artistHandlerLogic component to FATAL

Any changes you make with the grnc-ctl tool are non-permanent and will be reset the next time you start your application.

Recap

Granitic can automatically inject a Logger into your application code.
You can log at different levels of severity.
You can set the global severity level at which messages will be logged in configuration.
You can override this global level for individual components.
You can change both the global and component-specific levels at runtime using grnc-ctl