Tutorial - Logging

What you’ll learn

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

Prerequisites

  1. Follow the Granitic installation instructions
  2. Read the before you start tutorial
  3. Either have completed tutorial 2 or open a terminal and run
cd $GOPATH/src/github.com/graniticio
git clone https://github.com/graniticio/granitic-examples.git
cd $GOPATH/src/github.com/graniticio/granitic-examples/tutorial
./prepare-tutorial.sh 3

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 them 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 dispatch 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 member variable that is exactly:

    Log logging.Logger

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

package endpoint

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

type ArtistLogic struct {
  EnvLabel string
  Log      logging.Logger
}

func (al *ArtistLogic) Process(ctx context.Context, req *ws.WsRequest, res *ws.WsResponse) {

  a := new(ArtistDetail)
  a.Name = "Hello, World from " + al.EnvLabel

  res.Body = a

  l := al.Log
  l.LogInfof("Environment is set to '%s'", al.EnvLabel)
  l.LogTracef("Request served")

}

type ArtistDetail struct {
  Name string
}

and run

cd $GOPATH/src/granitic-tutorial/recordstore
grnc-bind
go build
./recordstore -c resource/config,resource/env/production.json

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

09/Aug/2017:14:50:24 Z INFO [artistLogic] Environment is set to 'PROD'

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 (artistLogic)
  • The message itself

Unit tests

You may find the function logging.CreateAnonymousLogger useful when writing unit tests for code that relies on having access to a 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

$GRANITIC_HOME/resource/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

resource/config/config.json
and edit it so it looks like:

{
    "Facilities": {
            "HttpServer": true,
            "JsonWs": true
    },
    
    "ApplicationLogger":{
            "GlobalLogLevel": "ERROR"
    },
    
    "environment": {
            "label": "UNSET"
    }
}

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 so use the FrameworkLogger which has its own GlobalLogLevel

File logging

By default Granitic only logs messages to the console. Look at

$GRANITIC_HOME/resource/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.json file so that the ApplicationLogger section looks like:

"ApplicationLogger": {
    "GlobalLogLevel": "ERROR",
    "ComponentLogLevels": {
        "artistLogic": "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:

09/Aug/2017:21:05:55 Z INFO  [artistLogic] Environment is set to 'PROD'
09/Aug/2017:21:05:55 Z TRACE [artistLogic] Request served

Try setting the artistLogic log level to FATAL to see what happens.

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

resource/config/config.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:

10/Aug/2017:06:55:28 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.

Open a terminal and run:

grnc-ctl help

To get a list of the high level actions you can perform with this tool and then:

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 artistLogic FATAL

to raise the logging threshold for the artistLogic 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 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

Further reading

Next

The next tutorial covers the capture of data from web-service calls