First8 is gespecialiseerd in het pragmatisch ontwikkelen van bedrijfskritische Java toepassingen waarbij integratie van systemen, hoge eisen aan beveiliging en veel transacties een belangrijke rol spelen. Op deze pagina vindt je onze blogs. Op www.first8.nl vind je ons nieuws, de agenda, vacatures en meer.

Why Grails logs package names in different ways

I just realized something that had me puzzled for some time.

For some reason, Grails logging for a specific component or class stopped or started ‘working’ at some point in time. I never got around to looking into it much, though the idea of not knowing why this happened was uncomfortable.

TLDR: Not all loggers are created equal

grails-logo-sm

Grails’ implicit logger

This is actually (for Grails 2) an instance of a log4j logger with an Apache commons-logging api. You won’t really notice any of the API details because of the awesome GStrings that Groovy provides that allow for very flexible messages.

Grails promotes using its conventions and one of them is actually to use the default (no) package for standard artifacts (controllers, services, etc).

To clarify which artifacts are actually logging, the framework prefixes the logs with something that can be traced back to the specific source folder for the type of artifact.

So whenever the implicit Grails ‘log‘ instance is used, the package of that logger is prefixed with the ‘classpath type‘, say “grails.app.controllers.” for example for a controller.

 

Groovy’s AST logger

However, when you put the @Slf4j annotation on that same controller, the logger still named “log” is replaced by a compiled version that is not in any way Grails aware. It is just a standard logger, using standard package naming, with actually an Slf4j api. The AST annotation makes sure that the groovy compiler will add the required logger at compile time (to the Abstract-Syntax-Tree).

The package is then not prefixed in to the logs. This tiny code change, the addition of a seemingly harmless annotation, can lead to needing to change configuration (ie: changing packages in the log4j closure in the Config.groovy).

So in short, when using the AST logger, the log4j config setting TRACE grails.app.controllers.com.crv.MyController becomes TRACE com.crv.MyController

 

Not all loggers are created equal

There are multiple ways in which logger can be created. They will have subtle differences and at some point you may need to care about this.

Did you know:

  • when using GStrings, switching between commons logging and slf4j is hardly noticable?
  • that for the AST, the name of the log instance can be customized using the annotation value?
  • you may run in to trouble calling a log instance inside a closure (hint: ‘delegate first’)?
  • if you have more than one commons-logging (jcl) implementation on your classpath, thing can get tricky?
  • Grails 3 actually uses logback by default?