Page tree
Skip to end of metadata
Go to start of metadata

Magnolia CMS provided you with default audit logging service where some major actions such as login, logout, activate and deactivate are logged to default appender. Follow the same principle with some additional integrations, I would like to introduce an approach on how to implement some extra logging information with minimal impact on existing code base.

Overview

An example use case is that we would like to log some information after execution of info.magnolia.importexport.command.JcrImportCommand where current implementation didn't provide any logging out of the box. We just don't want to alter existing code to include few lines of code, rebuild the whole bundle and redeploy them that takes us too much time and efforts. By utilizing AOP - Load time weaving, we just have to implement our Before or After advice for some information in this case. Moreover you can also alter some instance object values or parameters during runtime (on the fly). Therefore this is an easy way to achieve our goal with an affordable effort.

Implementation

Add AspectJ libraries to your Maven project

<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjrt</artifactId>
  <version>1.9.1</version>
</dependency>

<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjweaver</artifactId>
  <version>1.9.1</version>
</dependency>

Implement your weaver config

Put your aop.xml under src/main/resource folder in development mode or right under WEB-INF/classes in production mode, notice our include tags which define where we would like to put our point cuts.

<aspectj>
  <aspects>
    <aspect name="info.magnolia.audit.AuditLogger" />
    <weaver options="-showWeaveInfo">
      <include within="info.magnolia.importexport.command.JcrImportCommand" />
      <include within="info.magnolia.ui.framework.action.*" />
      <include within="info.magnolia.commands.impl.*" />
      <include within="info.magnolia.audit.*"/>
    </weaver>
  </aspects>
</aspectj>


Implement your Aspect

In this example, I'm using info.magnolia.audit.AuditLogger as our aspect file AuditLogger.java, just notice the advice below:

@Aspect
public class AuditLogger {
    
    private static final Logger log = LoggerFactory.getLogger(AuditLogger.class);
    
    @Before("execution(* info.magnolia.importexport.command.JcrImportCommand.execute(..)) ")
    public void beforeImportLogger(JoinPoint point) throws RepositoryException {
        JcrImportCommand runner = (JcrImportCommand) point.getThis();
        Context context = (Context) point.getArgs()[0];
        final Node node = context.getJCRSession(runner.getRepository()).getNode(runner.getPath());
        log.info("Importing file {} to node path {}.", runner.getFileName(), node.getPath());
        log.info("Before function {}.{}({}) called by user {}.", 
                point.getTarget().getClass().getName(), 
                MethodSignature.class.cast(point.getSignature()).getMethod().getName(), 
                Arrays.toString(point.getArgs()),
                getUser());
    }
    
    @After("execution(* info.magnolia.importexport.command.JcrImportCommand.execute(..)) ")
    public void afterImportLogger(JoinPoint point) {
        log.info("After function {}.{}({}) called by user {}.", 
                point.getTarget().getClass().getName(), 
                MethodSignature.class.cast(point.getSignature()).getMethod().getName(), 
                Arrays.toString(point.getArgs()),
                getUser());
    }

    ...

}


Enabling Load-Time Weaving

AspectJ load-time weaving can be enabled using AspectJ agent that can get involved in the class loading process and weave any types before they are defined in the VM. We specify the javaagent option to the JVM -javaagent:pathto/aspectjweaver.jar or using Maven plugin to configure the javaagent:

<plugin>
    <groupId>org.apache.maven.plugins</groupId>
    <artifactId>maven-surefire-plugin</artifactId>
    <version>2.10</version>
    <configuration>
        <argLine>
            -javaagent:"${settings.localRepository}"/org/aspectj/
            aspectjweaver/${aspectj.version}/
            aspectjweaver-${aspectj.version}.jar
        </argLine>
        <useSystemClassLoader>true</useSystemClassLoader>
        <forkMode>always</forkMode>
    </configuration>
</plugin>

Verify your setup

Few lines of log should be printed out in your default log when we import a page under our 'travel' demo site:

2018-06-12 11:10:10,447 INFO  info.magnolia.audit.AuditLogger                   : Importing file website.mypage.xml to node path /travel.
2018-06-12 11:10:10,447 INFO  info.magnolia.audit.AuditLogger                   : Before function info.magnolia.importexport.command.JcrImportCommand.execute([info.magnolia.context.SimpleContext@cfd5f7a]) called by user superuser.
2018-06-12 11:10:10,498 INFO  info.magnolia.audit.AuditLogger                   : After function info.magnolia.importexport.command.JcrImportCommand.execute([info.magnolia.context.SimpleContext@cfd5f7a]) called by user superuser.


Log4j2 config

Configure log4j2.xml to direct audit log info to magnolia-audit.log just by adding your aspect class to the log such as this case:

    <Logger name="info.magnolia.audit.AuditLogger" level="DEBUG" additivity="true">
        <AppenderRef ref="log-audit"/>
    </Logger>

Recommended update for magnolia-audit.log appender to have a nicer output - please change your existing PatternLayout using provided patter here for better log info "%-5p %c %d{dd.MM.yyyy HH:mm:ss} -- %m%n"

    <RollingFile name="sync-log-audit"
                 fileName="${magnolia.logs.dir}/magnolia-audit.log"
                 filePattern="${magnolia.logs.dir}/magnolia-audit-%i.log"
                 append="true">
      <PatternLayout pattern="%-5p %c %d{dd.MM.yyyy HH:mm:ss} -- %m%n"/>
      <ThresholdFilter level="DEBUG"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="1MB"/>
      </Policies>
      <DefaultRolloverStrategy max="5"/>
    </RollingFile>
    <Async name="log-audit">
      <AppenderRef ref="sync-log-audit"/>
    </Async>

Performance warning

Load time weaving will intercept your instance at JVM level. This instrumentation will produce some overhead and has its performance trade-offs. So please just use it to trace your issue then turn it off later. Also this approach has a limitation that you have to restart your running instance to get it work.


  • No labels