Direct use of Log4jLogger

[jodygarnett]

Personal experiment follow up to https://github.com/geonetwork/core-geonetwork/pull/6397 looking at what it would take to use the Log4j Appenders API.

Core change:

• [x] Use BasicContext.getLogger() rather than asking BasicContext to implement Logger
• [x] LoggerWrapper implementation (formally an anonymous class in Log)
• [x] Introduce markers for the modules named in Log (example Log.JEEVES_MARKER)
• [x] Tag AppenderWrapper with appropriate marker for the functionality they wish to track
• [x] Log.createLogger() methods to support classname (or determine from stack trace)
• [x] Logger extends Log4J Logger (a lot of new efficient methods)
• [x] review LoggerWrapper.debug methods to apply marker
• [x] review LoggerWraper.info methods to apply marker
• [x] review LoggerWrapper.warn methods to apply marker
• [x] review LoggerWrapper.error methods to apply marker

Direct use of LOGGERS as a non critical follow up to improve over time:

• [ ] Remove references to Log.isDebugEnabled(module) (handy way to identify where loggers are needed)

The net effect should be using Marker to indicate geonetwork module (such as "jeeves" or "Jeeves.webapp") while having full access to the Log4J Logger API (which is much more efficient) along with the class names which can be used in the log4j2-dev.xml profile.

LOGGER Example

Although Log.createLogger() methods return org.fao.geonet.Logger it is better import org.apache.logging.log4j.Logger when possible to stick to "pure" Log4j2 API. The additional deprecated methods provided by org.fao.geonet.Logger are for things like warning(message) that can be replaced with warn(message).

import org.apache.logging.log4j.Logger;

...
private static Logger LOGGER = Log.createLogger(SchemaManager.class,Geonet.SCHEMA_MANAGER_MARKER);

Use ParameterizedMessage format

Rather than use string concatenation or formatting using ParameterizedMessage approach:

LOGGER.info(Geonet.SCHEMA_MANAGER_MARKER,
  "Loading schema {} ...",
  schemaDir.getFileName() );

Throwable

Pass in throwable as the last parameter and let configuration choose if a stack trace should be shown or not.

LOGGER.error(Geonet.SCHEMA_MANAGER_MARKER, "Cannot decode blank number from {}", baseBlank, nfe);

isDebugEabled(Marker) rarely worthwhile

Because ParameratizedMethods ares so efficient:

LOGGER.debug(Geonet.SCHEMA_MANAGER_MARKER,
  "  => Found schema {} using AUTODETECT(attributes);examination",
  schema);

It replaces the need for most occupancy of isDebugEnabled(marker):

if (LOGGER.isDebugEnabled(Geonet.SCHEMA_MANAGER_MARKER)) {
   LOGGER.debug(Geonet.SCHEMA_MANAGER_MARKER,
     "  => Found schema " + schema + " using AUTODETECT(attributes) examination");
}

However if a method call is expensive you should still use isDebugEnabled(Marker):

if (LOGGER.isDebugEnabled(Log.REQUEST_MARKER)) {
    LOGGER.debug(Log.REQUEST_MARKER, "Adding to parameters: {}", Xml.getString(elem));
}

Use markers for readability (Optional)

Since the above LOGGER was created with Log.SCHEMA_MANAGER_MARKER the following are equivalent:

LOGGER.debug("No bean defined for the schema plugin '{}'.{}",
  schemaIdentifier, e.getMessage(),
  e);

LOGGER.debug(Log.SCHEMA_MANAGER_MARKER,
  "No bean defined for the schema plugin '{}'.{}", schemaIdentifier,
  e.getMessage(),
  e);

The second option with Log.SCHEMA_MANAGER_MARKER clearly indicates intent, and does not reply on the AppenderWrapper (allowing us opportunity to drop AppenderWrapper in the future).

[jodygarnett]

@fxprunayre / @josegar74 I personally like this change but it is up to the team.

Right now I set the filters up at the top of the log4j2.xml file; but they could be broken up and applied to specific appenders, or loggers if that is cleaner. See https://logging.apache.org/log4j/2.x/manual/filters.html for details.

[juanluisrp]

I don't know if it's related to this PR, but building the projects shows these warning related to log4j-slf4j18-impl library:

[INFO] Scanning for projects...
[WARNING]
[WARNING] Some problems were encountered while building the effective model for org.geonetwork-opensource:gn-camelPeriodicProducer:jar:4.2.1-SNAPSHOT
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.apache.logging.log4j:log4j-slf4j18-impl:jar -> version (?) vs ${log4j2.version} @ org.geonetwork-opensource:gn-workers:4.2.1-SNAPSHOT, /private/tmp/core-geonetwork/workers/pom.xml, line 105, column 17
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.apache.logging.log4j:log4j-slf4j18-impl:jar -> version (?) vs ${log4j2.version} @ org.geonetwork-opensource:gn-workers:4.2.1-SNAPSHOT, /private/tmp/core-geonetwork/workers/pom.xml, line 115, column 17
[WARNING]
[WARNING] Some problems were encountered while building the effective model for org.geonetwork-opensource:gn-workers:pom:4.2.1-SNAPSHOT
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.apache.logging.log4j:log4j-slf4j18-impl:jar -> version (?) vs ${log4j2.version} @ line 105, column 17
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.apache.logging.log4j:log4j-slf4j18-impl:jar -> version (?) vs ${log4j2.version} @ line 115, column 17
[WARNING]
[WARNING] It is highly recommended to fix these problems because they threaten the stability of your build.
[WARNING]
[WARNING] For this reason, future Maven versions might no longer support building such malformed projects.
[WARNING]

[juanluisrp]

Addressing the warning showed in the previous comment in https://github.com/geonetwork/core-geonetwork/pull/6536.

[jodygarnett]

@josegar74 / @fxprunayre I thought this was approved? It is quite a bit of work and I do not wish to see it go stale.

Oh I see you identifed a few messages that can be improved. I was mostly trying to get everything calling the correct methods, and not try and get everything perfect

[jodygarnett]

rebased; this should be good to go

[jodygarnett]

@josegar74 identified TRACE methods coming out during normal production logging - which is unexpected.

@fxprunayre reported something similar which resulted in a good example web/src/main/webapp/WEB-INF/classes/log4j2.xml which needs to be tested and copied to the other profiles:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" dest="out">
  <Properties>
    <Property name="log_dir">./logs</Property>
  </Properties>

  <Filters>
    <NoMarkerFilter onMatch="ACCEPT" onMismatch="NEUTRAL"/>
    <!-- filter by geonetwork module -->
    <Filters>
      <ThresholdFilter level="INFO" onMatch="NEUTRAL" onMismatch="DENY"/>
      <MarkerFilter marker="atom" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
      <MarkerFilter marker="databasemigration" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
      <MarkerFilter marker="encryptor" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
      <MarkerFilter marker="harvester" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
    </Filters>
    <Filters>
      <ThresholdFilter level="ERROR" onMatch="NEUTRAL" onMismatch="DENY"/>
      <MarkerFilter marker="geonetwork" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
      <MarkerFilter marker="jeeves" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
    </Filters>
  </Filters>

  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%date{ISO8601} %-5level %marker [%logger] - %message%n"/>
    </Console>
    <RollingFile name="File">
      <filename>${sys:log_dir:-log_dir}/geonetwork.log</filename>
      <filePattern>${sys:log_dir:-log_dir}/geonetwork.log-%i.log</filePattern>
      <PatternLayout pattern="%date{ISO8601} %-5level [%logger] - %message%n"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="10 MB" />
      </Policies>
      <DefaultRolloverStrategy max="3" fileIndex="min"/>
    </RollingFile>
    <Routing name="Harvester">
      <Routes pattern="$${ctx:logfile}">
        <!-- value dynamically determines the name of the log file. -->
        <Route>
          <File name="harvester-${ctx:harvester}" fileName="${sys:log_dir:-log_dir}/${ctx:logfile}">
            <PatternLayout>
              <pattern>%date{ISO8601}{${ctx:timeZone}} %-5level %marker [%logger] - %message%n</pattern>
            </PatternLayout>
          </File>
        </Route>
      </Routes>
    </Routing>
  </Appenders>

  <Loggers>
    <Logger name="org.fao.geonet" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
      <AppenderRef ref="Harvester"/>
    </Logger>
    <Logger name="jeeves" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
      <AppenderRef ref="Harvester"/>
    </Logger>

    <!--  Spring logging configuration -->
    <Logger name="org.springframework" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>
    <Logger name="org.springframework.beans" level="error"/>
    <Logger name="org.springframework.security" level="error"/>
    <Logger name="org.springframework.security.ldap" level="error"/>
    <Logger name="org.springframework.aop.framework.CglibAopProxy" level="error"/>

    <Logger name="com.k_int" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>

    <!--  JZKIT logging configuration -->
    <Logger name="org.jzkit" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>
    <Logger name="org.jzkit.a2j" level="error"/>
    <Logger name="org.jzkit.search.impl.LRUCache" level="error"/>

    <Logger name="ro.isdc.wro.http" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>

    <!-- Check domain/src/main/resources/config-spring-geonetwork.xml show_sql properties. -->
    <Logger name="org.hibernate.SQL" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>
    <Logger name="org.hibernate.type" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>
    <Logger name="org.hibernate.tool.hbm2ddl" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>
    <Logger name="org.xhtmlrenderer" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>

    <Logger name="org.apache.camel" level="error" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Logger>

    <!-- Turn off logging except when explicitly declared above -->
    <Root level="off">
        <AppenderRef ref="File"/>
    </Root>
  </Loggers>
</Configuration>