Design Log Monitor System Prototype — 1. Spring MVC

by leelight · Published December 2, 2018 · Updated December 4, 2018

1. Background

In this article, a log monitor system is designed for one classic monolithic Spring MVC project, which contains three module layers: Controller, Service, and Repository.

2. Requirement

All system exceptions should be recorded.
Pretty log format. Compatible for further scaled and distributed micro service
Easy to trace the bug must have: when, where, who, what, How long
Performance measurement for rest request in the Controller layer
Performance measurement for Business Service layer
Report problem when database SQL query in the Repository layer takes longer time

When: the time the bug occurs
Where: in which application, which layer, which package, which Class, which line
Who: account which calls the request, if the request is not anonymous. Or IP address
What: what happened? the full stack message or short message
How long: the execution time for each layer

3. About Log

3-1. 1. Log Level:

The log4j has defined the common log level as :

TRACE — The TRACE Level designates finer-grained informational events than the DEBUG
DEBUG — The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
INFO — The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
WARN — The WARN level designates potentially harmful situations.
ERROR — The ERROR level designates error events that might still allow the application to continue running.
FATAL — The FATAL level designates very severe error events that will presumably lead the application to abort.

This definition is just simple and in practice, which kind of log should be recorded, your team should discuss for it. Here is one discussion in StackOverflow.

The log level in a project should be clear and followed by every developer.
Log standard is must have. Besides developers, the testing engineers and DevOps engineers can also locate the bug easily
About log level:
FATAL — System level error which should be handled by administrator immediately. When such error occurs, means your service is not available. This level should be used cautiously because this is the most serious log level. It does not make sense if such log level occurs often. As usually, a fatal log should be recorded only once in life circle of a process, which will be terminated without retrieving. If child service of one service has beyond retrieved exception, this exception could be also recorded as a fatal log.
ERROR — This level should be handled immediately but has lower priority than fatal level. This level has affected the user’s operation. From this point, error and fatal error has the same affection on users. Fatal means service is down, and error means cannot provide normal service and keep printing error log. But any error related to users’ incorrect operations, such as wrong parameters, should not be recorded as error level.
WARN — This level means the system could have problem probably, or not, such as network problem. For those which not yet recognized as errors but will turn to errors if no one has handled, could be recorded as warn level. For example, one SQL query execution time has longer than a threshold, or the storage of one service has almost reached the limit. Such kind of log does not require to be handled immediately although, but still require checking and handling in a schedule. Warn level logs should not be recorded too often.
INFO — This level records normal working status, such as service initialization or one request has been processed successfully. Through info logs, the developer can easily locate fatal, error and warn errors. Too many Info logs are inappropriate. Normally, info level logs should less than 10% of trace level logs.
DEBUG or TRACE — This level should record each step of process exactly, for example, which operation, what parameters. The developer can diagnose and locate the bug with debug messages.

Rule 1: The Team including DevOps should define the log level standard and the corresponding process.

3-2. 2. Log Maintenance

DEBUG or TRACE level log is important to locate the bug so that the log format should be optimized.

The team should optimize the log format and standard, and follow it. The team should review the logs periodically.
Every team member should abide by the rules
Developer try to work as DevOps, locate bug from logs
If DevOps find a problem in logs, should report to developers
If takes a long time to locate the bug, that means the log is not perfect enough and should be improved.
Thinking about error prediction via logs. For example, OOM error, slow sql query or resource limitation error.

Rule 2: The team should review and optimize the logs periodically.

3-3. 3. Log Category

3-3-1. Diagnosed Log

Request input and output
Request and response for external service
Resource operation: open file
service exception: database not available
Background schedule process
Service start, loading and stop

3-3-2. Statistic Log

User visit statistic
Page visit statistic
Charging or payment log

3-3-3. Audit Log

Administration operation

Rule 3: Clarify the purpose of different log and classify them.

3-4. 4. Redundant Log vs Useless Log

some example here….. TODO

Rule 4: DO NOT record useless log to avoid log flood

3-5. 5. Log record integrity

For example, a user is editing his blog. It could have the following steps:

Controller request&response
Blog Service operation
Blog Repository database update

Errors could occur in every step. What is recommended to record including:

The initialization parameters when the system starting or initializing
Record all exceptions during the system running
Record all warnings during the system running
Record value changing before and after database persistence
Record the communication among modules
Record the important state changing
The schedule job working status

What is not recommended to record:

Function calling
file content. If it is required, take a piece of it
“benign” error. Sometimes there is an error, but there is right process can handle it. For example, find duplicated data before insert data.

Rule 5: Log should be exact and have integrity, bugs can be located only depends on logs

3-6. 6. Test Log

Unit test, API test… TODO

3-7. 7. APM and Distributed Tracing

What is APM? What is distributed tracing?

A Monolithic application could have many modules or external services. Transforming monolithic application into a microservices-based one is hard to trace the bug. If you have 100 servers and you get the error in one request, image that.

We need a global unique RequestID, which will go through all child service and in each communication. If we collect all logs and we can find one completion tracing records with such RequestID.

3-8. 7. Dynamic Log Recording

DEBUG level log record too many details and could cause flood logs in distributed service. We need a switch to turn on or shut down the debug level during runtime.

Add such switch in configuration, property file or yml
add a switch as a query string parameter in request url, such as “DEBUG=ON”.

The administrator could config the debug level for some modules or some requests at any time.

3-9. 8. Log Isolation and Size Control

In some case, the error log could be recorded into separated files.

The log size should under control. The huge log file is not convenience for monitor or bug tracking. Log slicing by day or hour, it depends on the number of logs. The only principle is that the developer can locate the bug as soon as possible.

To avoid occupying the hard disk by log file, the log files need to be cleaned under schedule. For example, clear logs too months ago after receiving the hard disk limit warning.

4. Practice

4-1. 1. Log format

You can define yours own team log format.

Name	Remark
requestID	uuid
timestamp	log record time
level	log level
message	log message
app	application name
module	module name
operation label	custom annotation label or request uri
accountId	account id
accountType	account type
status	response status code
elapsed	the number of milliseconds elapsed for the execution of logging event
error	full error message
thread id
Class name
package.class	Used to output the category of the logging event
line number	Used to output the line number from where the logging request was issued

This is the log pattern layout example in log4j.xml:

[app] [%-5p] [%d{yyyy-MM-dd HH:mm:ss,SSS}] [-%-4r] [%t] [%X{MDC.RequestID}] [%X{MDC.AccountId}:%X{MDC.AccountType}] [%X{MDC.Elapsed}] [%c{1}:%L] - %m%n

1	[app] [%-5p] [%d{yyyy-MM-dd HH:mm:ss,SSS}] [-%-4r] [%t] [%X{MDC.RequestID}] [%X{MDC.AccountId}:%X{MDC.AccountType}] [%X{MDC.Elapsed}] [%c{1}:%L] - %m%n

4-2. 2. Generate RequestID

You can use UUID as RequestID as will. I am using snowflake ID in my project.

Add a filter to add RequestID in the header and transmit it in the request.

/*
 * Copyright (c) 2016-2018 Mobabel.net
 *
 * All rights reserved.
 */
package net.mobabel.nova.service.monitoring;

import static net.mobabel.nova.service.monitoring.Constants.MDC_CLIENT_IP_KEY;
import static net.mobabel.nova.service.monitoring.Constants.MDC_UUID_REQUEST_ID_KEY;
import static net.mobabel.nova.service.monitoring.Constants.REQUEST_ID_HEADER;
import static net.mobabel.nova.core.util.Inet4Address.getRemortIP;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import net.mobabel.nova.core.util.UuidUtil;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

@Component
public class LogMDCFilter extends OncePerRequestFilter
{

   @Override
   protected void doFilterInternal( final HttpServletRequest request, final HttpServletResponse response, final FilterChain chain )
      throws java.io.IOException, ServletException
   {
      try
      {
         final String token = extractToken( request );
         final String clientIP = getRemortIP( request );
         MDC.put( MDC_UUID_REQUEST_ID_KEY, token );
         MDC.put( MDC_CLIENT_IP_KEY, clientIP );
         if (!StringUtils.isEmpty( REQUEST_ID_HEADER ))
         {
            response.addHeader( REQUEST_ID_HEADER, token );
         }
         chain.doFilter( request, response );
      }
      finally
      {
         MDC.remove( MDC_UUID_REQUEST_ID_KEY );
         MDC.remove( MDC_CLIENT_IP_KEY );
      }
   }

   private String extractToken( final HttpServletRequest request )
   {
      final String token;
      if (!StringUtils.isEmpty( REQUEST_ID_HEADER ) && !StringUtils.isEmpty( request.getHeader( REQUEST_ID_HEADER ) ))
      {
         token = request.getHeader( REQUEST_ID_HEADER );
      }
      else
      {
         token = UuidUtil.getId() + "";
      }
      return token;
   }

   @Override
   protected boolean isAsyncDispatch( final HttpServletRequest request )
   {
      return false;
   }

   @Override
   protected boolean shouldNotFilterErrorDispatch()
   {
      return false;
   }
}

package net.mobabel.nova.service.monitoring;

import static net.mobabel.nova.service.monitoring.Constants.MDC_CLIENT_IP_KEY;

import static net.mobabel.nova.service.monitoring.Constants.MDC_UUID_REQUEST_ID_KEY;

import static net.mobabel.nova.service.monitoring.Constants.REQUEST_ID_HEADER;

import static net.mobabel.nova.core.util.Inet4Address.getRemortIP;

import javax.servlet.FilterChain;

import javax.servlet.ServletException;

import javax.servlet.http.HttpServletRequest;

import javax.servlet.http.HttpServletResponse;

import net.mobabel.nova.core.util.UuidUtil;

import org.apache.commons.lang3.StringUtils;

import org.slf4j.MDC;

import org.springframework.stereotype.Component;

import org.springframework.web.filter.OncePerRequestFilter;

@Component

public class LogMDCFilter extends OncePerRequestFilter

{

@Override

protected void doFilterInternal( final HttpServletRequest request, final HttpServletResponse response, final FilterChain chain )

throws java.io.IOException, ServletException

{

try

{

final String token = extractToken( request );

final String clientIP = getRemortIP( request );

MDC.put( MDC_UUID_REQUEST_ID_KEY, token );

MDC.put( MDC_CLIENT_IP_KEY, clientIP );

if (!StringUtils.isEmpty( REQUEST_ID_HEADER ))

{

response.addHeader( REQUEST_ID_HEADER, token );

}

chain.doFilter( request, response );

}

finally

{

MDC.remove( MDC_UUID_REQUEST_ID_KEY );

MDC.remove( MDC_CLIENT_IP_KEY );

}

private String extractToken( final HttpServletRequest request )

{

final String token;

if (!StringUtils.isEmpty( REQUEST_ID_HEADER ) && !StringUtils.isEmpty( request.getHeader( REQUEST_ID_HEADER ) ))

{

token = request.getHeader( REQUEST_ID_HEADER );

}

else

{

token = UuidUtil.getId() + "";

}

return token;

}

@Override

protected boolean isAsyncDispatch( final HttpServletRequest request )

{

return false;

}

@Override

protected boolean shouldNotFilterErrorDispatch()

{

return false;

}

in web.xml

<filter>
		<filter-name>logMDCFilter</filter-name>
		<filter-class>net.mobabel.nova.service.monitoring.LogMDCFilter</filter-class>
	</filter>
	<filter-mapping>
		<filter-name>logMDCFilter</filter-name>
		<url-pattern>/*</url-pattern>
	</filter-mapping>

<filter-name>logMDCFilter</filter-name>

<filter-class>net.mobabel.nova.service.monitoring.LogMDCFilter</filter-class>

</filter>

<filter-mapping>

<filter-name>logMDCFilter</filter-name>

<url-pattern>/*</url-pattern>

</filter-mapping>

In log4j.xml pattern layout:

[%X{MDC.RequestID}]

1	[%X{MDC.RequestID}]

3. MDC

what is MDC: Mapped Diagnostic Context ?

4-3. 3. AOP or Interceptor Implementation

In your config property file define some value for AOP.

monitor.operation_logging.log_requests=true
monitor.operation_logging.included_packages.controller=net.mobabel.nova.manager.controller
monitor.operation_logging.included_packages.service=net.mobabel.nova.service.domain
monitor.operation_logging.included_packages.repository=net.mobabel.nova.repository

monitor.operation_logging.log_requests=true

monitor.operation_logging.included_packages.controller=net.mobabel.nova.manager.controller

monitor.operation_logging.included_packages.service=net.mobabel.nova.service.domain

monitor.operation_logging.included_packages.repository=net.mobabel.nova.repository

4-3-1. 3.1 AOP for Repository

Show me the code.

/*
 * Copyright (c) 2016-2018 Mobabel.net
 *
 * All rights reserved.
 */
package net.mobabel.nova.service.monitoring.aspect;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_ID;
import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_TYPE;
import static net.mobabel.nova.service.monitoring.Constants.MDC_EXECUTION_LASTED;
import static net.mobabel.nova.service.monitoring.Constants.MDC_OPERATION_LABEL;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodFullName;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodName;

import java.lang.reflect.Method;
import java.lang.reflect.Parameter;
import java.util.List;
import javax.servlet.http.HttpServletRequest;

import net.mobabel.nova.core.util.Logger;
import net.mobabel.nova.model.authc.BasicAccount;
import net.mobabel.nova.service.monitoring.MonitorUtils;
import net.mobabel.nova.service.monitoring.NotLogOperation;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

@Aspect
@Component
public class RepositoryAspect
{
   protected Logger logger = Logger.getLogger( this.getClass() );

   @Value( "${monitor.operation_logging.log_requests:false}" )
   private boolean opsLogRequestsEnable;
   @Value( "#{'${monitor.operation_logging.included_packages.repository}'.split(',')}" )
   private List<String> opsIncludedPackages;

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )
   public void logPointCut()
   {
   }

   @Pointcut(
        "execution(public * net.mobabel.nova.repository..*.add*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.save*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.edit*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.update*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.delete*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.remove*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.list*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.get*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.find*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.search*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.is*(..))"
      + " || execution(public * net.mobabel.nova.repository..*.has*(..))"
   )
   public void domainPointCut()
   {
   }

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )
   public void notLogPointCut()
   {
   }

   @Before( "logPointCut()" )
   public void doBefore( JoinPoint joinPoint )
   {
   }

   @Around( "("
            + "domainPointCut()"
            + "|| logPointCut()"
            + ")"
            + "&& !notLogPointCut()" )
   public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable
   {
      MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();
      Method method = methodSignature.getMethod();
      final String packageName = method.getDeclaringClass().getPackage().getName();
      Throwable errorProduced = null;
      Object result = null;
      if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))
      {
         try
         {
            long start = System.currentTimeMillis();

            result = joinPoint.proceed();

            long end = System.currentTimeMillis();
            long time = end - start;
            MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );
         }
         catch (Throwable t)
         {
            errorProduced = t;
            throw t;
         }
         finally
         {
            if (opsLogRequestsEnable)
            {
               String methodName;
               try
               {
                  if (errorProduced != null)
                  {
                     methodName =  extractMethodFullName(joinPoint) ;
                     logger.error( "[repository][{}]|[{}]", methodName, errorProduced.getClass().getSimpleName() );
                  }
                  else
                  {
                     methodName =  extractMethodName(joinPoint) ;
                     logger.info( "[repository][{}]|[]", methodName );
                  }
               }
               finally
               {
               }
            }
            MDC.remove( MDC_EXECUTION_LASTED );
         }
      }
      else

      {
         result = joinPoint.proceed();
      }
      return result;
   }

   @AfterReturning( returning = "object", pointcut = "logPointCut()" )
   public void doAfterReturning( Object object )
   {
   }

   @After( "logPointCut()" )
   public void doAfter( JoinPoint joinPoint )
   {
   }

   @AfterThrowing( pointcut = "logPointCut()", throwing = "e" )
   public void doAfterThrowing( JoinPoint joinPoint, Throwable e )
   {
   }


}

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

package net.mobabel.nova.service.monitoring.aspect;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_ID;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_TYPE;

import static net.mobabel.nova.service.monitoring.Constants.MDC_EXECUTION_LASTED;

import static net.mobabel.nova.service.monitoring.Constants.MDC_OPERATION_LABEL;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodFullName;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodName;

import java.lang.reflect.Method;

import java.lang.reflect.Parameter;

import java.util.List;

import javax.servlet.http.HttpServletRequest;

import net.mobabel.nova.core.util.Logger;

import net.mobabel.nova.model.authc.BasicAccount;

import net.mobabel.nova.service.monitoring.MonitorUtils;

import net.mobabel.nova.service.monitoring.NotLogOperation;

import org.aspectj.lang.JoinPoint;

import org.aspectj.lang.ProceedingJoinPoint;

import org.aspectj.lang.annotation.After;

import org.aspectj.lang.annotation.AfterReturning;

import org.aspectj.lang.annotation.AfterThrowing;

import org.aspectj.lang.annotation.Around;

import org.aspectj.lang.annotation.Aspect;

import org.aspectj.lang.annotation.Before;

import org.aspectj.lang.annotation.Pointcut;

import org.aspectj.lang.reflect.MethodSignature;

import org.slf4j.MDC;

import org.springframework.beans.factory.annotation.Value;

import org.springframework.stereotype.Component;

import org.springframework.web.context.request.RequestContextHolder;

import org.springframework.web.context.request.ServletRequestAttributes;

@Aspect

@Component

public class RepositoryAspect

{

protected Logger logger = Logger.getLogger( this.getClass() );

@Value( "${monitor.operation_logging.log_requests:false}" )

private boolean opsLogRequestsEnable;

@Value( "#{'${monitor.operation_logging.included_packages.repository}'.split(',')}" )

private List<String> opsIncludedPackages;

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )

public void logPointCut()

{

}

@Pointcut(

"execution(public * net.mobabel.nova.repository..*.add*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.save*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.edit*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.update*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.delete*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.remove*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.list*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.get*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.find*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.search*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.is*(..))"

+ " || execution(public * net.mobabel.nova.repository..*.has*(..))"

)

public void domainPointCut()

{

}

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )

public void notLogPointCut()

{

}

@Before( "logPointCut()" )

public void doBefore( JoinPoint joinPoint )

{

}

@Around( "("

+ "domainPointCut()"

+ "|| logPointCut()"

+ ")"

+ "&& !notLogPointCut()" )

public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable

{

MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();

Method method = methodSignature.getMethod();

final String packageName = method.getDeclaringClass().getPackage().getName();

Throwable errorProduced = null;

Object result = null;

if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))

{

try

{

long start = System.currentTimeMillis();

result = joinPoint.proceed();

long end = System.currentTimeMillis();

long time = end - start;

MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );

}

catch (Throwable t)

{

errorProduced = t;

throw t;

}

finally

{

if (opsLogRequestsEnable)

{

String methodName;

try

{

if (errorProduced != null)

{

methodName = extractMethodFullName(joinPoint) ;

logger.error( "[repository][{}]|[{}]", methodName, errorProduced.getClass().getSimpleName() );

}

else

{

methodName = extractMethodName(joinPoint) ;

logger.info( "[repository][{}]|[]", methodName );

}

finally

{

}

MDC.remove( MDC_EXECUTION_LASTED );

}

else

{

result = joinPoint.proceed();

}

return result;

}

@AfterReturning( returning = "object", pointcut = "logPointCut()" )

public void doAfterReturning( Object object )

{

}

@After( "logPointCut()" )

public void doAfter( JoinPoint joinPoint )

{

}

@AfterThrowing( pointcut = "logPointCut()", throwing = "e" )

public void doAfterThrowing( JoinPoint joinPoint, Throwable e )

{

}

4-3-2. 3.2 AOP for Service

Show me the code.

/*
 * Copyright (c) 2016-2018 Mobabel.net
 *
 * All rights reserved.
 */
package net.mobabel.nova.service.monitoring.aspect;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_ID;
import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_TYPE;
import static net.mobabel.nova.service.monitoring.Constants.MDC_EXECUTION_LASTED;
import static net.mobabel.nova.service.monitoring.Constants.MDC_OPERATION_LABEL;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodFullName;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodName;

import java.lang.reflect.Method;
import java.util.List;
import javax.servlet.http.HttpServletRequest;

import net.mobabel.nova.core.util.Logger;
import net.mobabel.nova.model.authc.BasicAccount;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

@Aspect
@Component
public class ServiceAspect
{
   protected Logger logger = Logger.getLogger( this.getClass() );

   @Value( "${monitor.operation_logging.log_requests:false}" )
   private boolean opsLogRequestsEnable;
   @Value( "#{'${monitor.operation_logging.included_packages.service}'.split(',')}" )
   private List<String> opsIncludedPackages;

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )
   public void logPointCut()
   {
   }

   @Pointcut(
      "execution(public * net.mobabel.nova.service.domain..*.add*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.save*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.edit*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.update*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.delete*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.remove*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.list*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.get*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.find*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.search*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.is*(..))"
      + " || execution(public * net.mobabel.nova.service.domain..*.has*(..))"
   )
   public void domainPointCut()
   {
   }

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )
   public void notLogPointCut()
   {
   }

   @Before( "logPointCut()" )
   public void doBefore( JoinPoint joinPoint )
   {
   }

   @Around( "("
            + "domainPointCut()"
            + "|| logPointCut()"
            + ")"
            + "&& !notLogPointCut()" )
   public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable
   {
      MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();
      Method method = methodSignature.getMethod();
      final String packageName = method.getDeclaringClass().getPackage().getName();
      Throwable errorProduced = null;
      Object result = null;
      if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))
      {
         BasicAccount basicAccount = extractBasicAccount();
         final String operationName = extractOperationName();
         try
         {
            if (basicAccount != null)
            {
               MDC.put( MDC_ACCOUNT_ID, Long.toString( basicAccount.getId() ) );
               MDC.put( MDC_ACCOUNT_TYPE, Integer.toString( basicAccount.getAccountType() ) );
            }
            long start = System.currentTimeMillis();

            result = joinPoint.proceed();

            long end = System.currentTimeMillis();
            long time = end - start;
            MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );
         }
         catch (Throwable t)
         {
            errorProduced = t;
            throw t;
         }
         finally
         {
            if (opsLogRequestsEnable)
            {
               String methodName;
               try
               {
                  MDC.put( MDC_OPERATION_LABEL, operationName );
                  if (errorProduced != null)
                  {
                     methodName = extractMethodFullName( joinPoint );
                     logger.error( "[service][{}][{}]|[{}]", operationName, methodName, errorProduced.getClass().getSimpleName() );
                  }
                  else
                  {
                     methodName = extractMethodName( joinPoint );
                     logger.info( "[service][{}][{}]|[]", operationName, methodName );
                  }
               }
               finally
               {
                  MDC.remove( MDC_OPERATION_LABEL );
               }
            }
            MDC.remove( MDC_ACCOUNT_ID );
            MDC.remove( MDC_ACCOUNT_TYPE );
            MDC.remove( MDC_EXECUTION_LASTED );
         }
      }
      else

      {
         result = joinPoint.proceed();
      }
      return result;
   }

   @AfterReturning( returning = "object", pointcut = "logPointCut()" )
   public void doAfterReturning( Object object )
   {
   }

   @After( "logPointCut()" )
   public void doAfter( JoinPoint joinPoint )
   {
   }

   @AfterThrowing( pointcut = "logPointCut()", throwing = "e" )
   public void doAfterThrowing( JoinPoint joinPoint, Throwable e )
   {
   }

   private String extractOperationName()
   {
      try
      {
         ServletRequestAttributes servletRequestAttributes = ( (ServletRequestAttributes) RequestContextHolder.getRequestAttributes() );
         if (servletRequestAttributes != null)
         {
            HttpServletRequest request = servletRequestAttributes.getRequest();
            return request.getRequestURI();
         }
      }
      catch (Exception ignore)
      {
      }
      return "";
   }

}

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

package net.mobabel.nova.service.monitoring.aspect;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_ID;

import static net.mobabel.nova.service.monitoring.Constants.MDC_ACCOUNT_TYPE;

import static net.mobabel.nova.service.monitoring.Constants.MDC_EXECUTION_LASTED;

import static net.mobabel.nova.service.monitoring.Constants.MDC_OPERATION_LABEL;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodFullName;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractMethodName;

import java.lang.reflect.Method;

import java.util.List;

import javax.servlet.http.HttpServletRequest;

import net.mobabel.nova.core.util.Logger;

import net.mobabel.nova.model.authc.BasicAccount;

import org.aspectj.lang.JoinPoint;

import org.aspectj.lang.ProceedingJoinPoint;

import org.aspectj.lang.annotation.After;

import org.aspectj.lang.annotation.AfterReturning;

import org.aspectj.lang.annotation.AfterThrowing;

import org.aspectj.lang.annotation.Around;

import org.aspectj.lang.annotation.Aspect;

import org.aspectj.lang.annotation.Before;

import org.aspectj.lang.annotation.Pointcut;

import org.aspectj.lang.reflect.MethodSignature;

import org.slf4j.MDC;

import org.springframework.beans.factory.annotation.Value;

import org.springframework.stereotype.Component;

import org.springframework.web.context.request.RequestContextHolder;

import org.springframework.web.context.request.ServletRequestAttributes;

@Aspect

@Component

public class ServiceAspect

{

protected Logger logger = Logger.getLogger( this.getClass() );

@Value( "${monitor.operation_logging.log_requests:false}" )

private boolean opsLogRequestsEnable;

@Value( "#{'${monitor.operation_logging.included_packages.service}'.split(',')}" )

private List<String> opsIncludedPackages;

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )

public void logPointCut()

{

}

@Pointcut(

"execution(public * net.mobabel.nova.service.domain..*.add*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.save*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.edit*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.update*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.delete*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.remove*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.list*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.get*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.find*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.search*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.is*(..))"

+ " || execution(public * net.mobabel.nova.service.domain..*.has*(..))"

)

public void domainPointCut()

{

}

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )

public void notLogPointCut()

{

}

@Before( "logPointCut()" )

public void doBefore( JoinPoint joinPoint )

{

}

@Around( "("

+ "domainPointCut()"

+ "|| logPointCut()"

+ ")"

+ "&& !notLogPointCut()" )

public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable

{

MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();

Method method = methodSignature.getMethod();

final String packageName = method.getDeclaringClass().getPackage().getName();

Throwable errorProduced = null;

Object result = null;

if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))

{

BasicAccount basicAccount = extractBasicAccount();

final String operationName = extractOperationName();

try

{

if (basicAccount != null)

{

MDC.put( MDC_ACCOUNT_ID, Long.toString( basicAccount.getId() ) );

MDC.put( MDC_ACCOUNT_TYPE, Integer.toString( basicAccount.getAccountType() ) );

}

long start = System.currentTimeMillis();

result = joinPoint.proceed();

long end = System.currentTimeMillis();

long time = end - start;

MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );

}

catch (Throwable t)

{

errorProduced = t;

throw t;

}

finally

{

if (opsLogRequestsEnable)

{

String methodName;

try

{

MDC.put( MDC_OPERATION_LABEL, operationName );

if (errorProduced != null)

{

methodName = extractMethodFullName( joinPoint );

logger.error( "[service][{}][{}]|[{}]", operationName, methodName, errorProduced.getClass().getSimpleName() );

}

else

{

methodName = extractMethodName( joinPoint );

logger.info( "[service][{}][{}]|[]", operationName, methodName );

}

finally

{

MDC.remove( MDC_OPERATION_LABEL );

}

MDC.remove( MDC_ACCOUNT_ID );

MDC.remove( MDC_ACCOUNT_TYPE );

MDC.remove( MDC_EXECUTION_LASTED );

}

else

{

result = joinPoint.proceed();

}

return result;

}

@AfterReturning( returning = "object", pointcut = "logPointCut()" )

public void doAfterReturning( Object object )

{

}

@After( "logPointCut()" )

public void doAfter( JoinPoint joinPoint )

{

}

@AfterThrowing( pointcut = "logPointCut()", throwing = "e" )

public void doAfterThrowing( JoinPoint joinPoint, Throwable e )

{

}

private String extractOperationName()

{

try

{

ServletRequestAttributes servletRequestAttributes = ( (ServletRequestAttributes) RequestContextHolder.getRequestAttributes() );

if (servletRequestAttributes != null)

{

HttpServletRequest request = servletRequestAttributes.getRequest();

return request.getRequestURI();

}

catch (Exception ignore)

{

}

return "";

}

4-3-3. 3.3 AOP for Controller

ControllerAspect

/*
 * Copyright (c) 2016-2018 Mobabel.net
 *
 * All rights reserved.
 */
package net.mobabel.nova.service.monitoring.aspect;

import net.mobabel.nova.core.basic.Re;
import net.mobabel.nova.core.util.Logger;
import net.mobabel.nova.model.authc.BasicAccount;
import net.mobabel.nova.service.monitoring.MonitorUtils;
import net.mobabel.nova.service.monitoring.NotLogOperation;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.http.ResponseEntity;
import org.springframework.stereotype.Component;

import java.lang.reflect.Method;
import java.lang.reflect.Parameter;
import java.util.List;

import static net.mobabel.nova.service.monitoring.Constants.*;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractOperationName;


@Aspect
@Component
public class ControllerAspect
{
   protected Logger logger = Logger.getLogger( this.getClass() );

   @Value( "${monitor.operation_logging.log_requests:false}" )
   private boolean opsLogRequestsEnable;
   @Value( "#{'${monitor.operation_logging.included_packages.controller}'.split(',')}" )
   private List<String> opsIncludedPackages;

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )
   public void logPointCut()
   {
   }

   @Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )
   public void notLogPointCut()
   {
   }

   @Before( "logPointCut()" )
   public void doBefore( JoinPoint joinPoint )
   {
   }

   @Around( "("
            + "@annotation(org.springframework.web.bind.annotation.RequestMapping)"
            + "|| @annotation(org.springframework.web.bind.annotation.GetMapping)"
            + "|| @annotation(org.springframework.web.bind.annotation.PostMapping)"
            + "|| @annotation(org.springframework.web.bind.annotation.PutMapping)"
            + "|| @annotation(org.springframework.web.bind.annotation.DeleteMapping)"
            + "|| @annotation(org.springframework.web.bind.annotation.PatchMapping)"
            + "|| logPointCut()"
            + ")"
            + "&& !notLogPointCut()" )
   public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable
   {
      MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();
      Method method = methodSignature.getMethod();
      final String packageName = method.getDeclaringClass().getPackage().getName();
      Throwable errorProduced = null;
      Object result = null;
      if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))
      {
         Object[] args = joinPoint.getArgs();
         final String operationName = extractOperationName( method );
         BasicAccount basicAccount = extractBasicAccount( args );
         try
         {
            if (basicAccount != null)
            {
               MDC.put( MDC_ACCOUNT_ID, Long.toString( basicAccount.getId() ) );
               MDC.put( MDC_ACCOUNT_TYPE, Integer.toString( basicAccount.getAccountType() ) );
            }
            long start = System.currentTimeMillis();
            if (opsLogRequestsEnable)
            {
               logger.info( "[controller][{}][]|[]", operationName );
            }

            result = joinPoint.proceed();

            long end = System.currentTimeMillis();
            long time = end - start;
            MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );
         }
         catch (Throwable t)
         {
            errorProduced = t;
            throw t;
         }
         finally
         {
            if (opsLogRequestsEnable)
            {
               if (operationName != null)
               {
                  try
                  {
                     MDC.put( MDC_OPERATION_LABEL, operationName );
                     StringBuilder sbArgs = extractArguments( method, args );
                     if (errorProduced != null)
                     {
                        logger.error( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), errorProduced.getClass().getSimpleName() );
                     }
                     else if (result != null && result instanceof ResponseEntity)
                     {
                        logger.info( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), ( (ResponseEntity<?>) result ).getStatusCodeValue() );
                     }
                     else if (result != null && result instanceof Re)
                     {
                        logger.info( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), ( (Re) result ).getCode() );
                     }
                     else
                     {
                        logger.info( "[controller][{}][{}]|[]", operationName, sbArgs.toString() );
                     }
                  }
                  finally
                  {
                     MDC.remove( MDC_OPERATION_LABEL );
                  }
               }
            }
            MDC.remove( MDC_ACCOUNT_ID );
            MDC.remove( MDC_ACCOUNT_TYPE );
            MDC.remove( MDC_EXECUTION_LASTED );
         }
      }
      else

      {
         result = joinPoint.proceed();
      }
      return result;
   }

   @AfterReturning( returning = "object", pointcut = "logPointCut()" )
   public void doAfterReturning( Object object )
   {
   }

   @After( "logPointCut()" )
   public void doAfter( JoinPoint joinPoint )
   {
   }

   @AfterThrowing( pointcut = "logPointCut()", throwing = "e" )
   public void doAfterThrowing( JoinPoint joinPoint, Throwable e )
   {
   }

   private StringBuilder extractArguments( Method method, Object[] args )
   {
      StringBuilder sb = new StringBuilder();
      try
      {
         Parameter[] parameters = method.getParameters();
         boolean added = false;
         if (parameters != null && parameters.length > 0)
         {
            sb.append( ": " );
            for (int i = 0; i < parameters.length; i++)
            {
               Parameter parameter = parameters[i];
               if (parameter.getAnnotation( NotLogOperation.class ) == null && args[i] != null)
               {
                  if (parameter.getType().isPrimitive() || parameter.getType().isEnum()
                      || CharSequence.class.isAssignableFrom( parameter.getType() ))
                  {
                     if (added)
                     {
                        sb.append( ";" );
                     }
                     sb.append( parameter.getName() );
                     sb.append( "=" );
                     sb.append( args[i].toString() );
                     added = true;
                  }
                  else if (parameter.getType().isArray()
                           && ( parameter.getType().getComponentType().isPrimitive() || parameter.getType().getComponentType().isEnum()
                                || CharSequence.class.isAssignableFrom( parameter.getType().getComponentType() ) ))
                  {

                     if (added)
                     {
                        sb.append( ";" );
                     }
                     sb.append( parameter.getName() );
                     sb.append( "=" );
                     sb.append( MonitorUtils.join( ",", (Object[]) args[i] ) );
                     added = true;
                  }
               }
            }
         }
      }
      catch (Exception e)
      {
         logger.error( "Error extracting arguments from method", e );
      }
      return sb;
   }

}

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

package net.mobabel.nova.service.monitoring.aspect;

import net.mobabel.nova.core.basic.Re;

import net.mobabel.nova.core.util.Logger;

import net.mobabel.nova.model.authc.BasicAccount;

import net.mobabel.nova.service.monitoring.MonitorUtils;

import net.mobabel.nova.service.monitoring.NotLogOperation;

import org.aspectj.lang.JoinPoint;

import org.aspectj.lang.ProceedingJoinPoint;

import org.aspectj.lang.annotation.*;

import org.aspectj.lang.reflect.MethodSignature;

import org.slf4j.MDC;

import org.springframework.beans.factory.annotation.Value;

import org.springframework.http.ResponseEntity;

import org.springframework.stereotype.Component;

import java.lang.reflect.Method;

import java.lang.reflect.Parameter;

import java.util.List;

import static net.mobabel.nova.service.monitoring.Constants.*;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractOperationName;

@Aspect

@Component

public class ControllerAspect

{

protected Logger logger = Logger.getLogger( this.getClass() );

@Value( "${monitor.operation_logging.log_requests:false}" )

private boolean opsLogRequestsEnable;

@Value( "#{'${monitor.operation_logging.included_packages.controller}'.split(',')}" )

private List<String> opsIncludedPackages;

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.LogOperation)" )

public void logPointCut()

{

}

@Pointcut( "@annotation(net.mobabel.nova.service.monitoring.NotLogOperation)" )

public void notLogPointCut()

{

}

@Before( "logPointCut()" )

public void doBefore( JoinPoint joinPoint )

{

}

@Around( "("

+ "@annotation(org.springframework.web.bind.annotation.RequestMapping)"

+ "|| @annotation(org.springframework.web.bind.annotation.GetMapping)"

+ "|| @annotation(org.springframework.web.bind.annotation.PostMapping)"

+ "|| @annotation(org.springframework.web.bind.annotation.PutMapping)"

+ "|| @annotation(org.springframework.web.bind.annotation.DeleteMapping)"

+ "|| @annotation(org.springframework.web.bind.annotation.PatchMapping)"

+ "|| logPointCut()"

+ ")"

+ "&& !notLogPointCut()" )

public Object doAround( ProceedingJoinPoint joinPoint ) throws Throwable

{

MethodSignature methodSignature = (MethodSignature) joinPoint.getStaticPart().getSignature();

Method method = methodSignature.getMethod();

final String packageName = method.getDeclaringClass().getPackage().getName();

Throwable errorProduced = null;

Object result = null;

if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch( packageName::startsWith ))

{

Object[] args = joinPoint.getArgs();

final String operationName = extractOperationName( method );

BasicAccount basicAccount = extractBasicAccount( args );

try

{

if (basicAccount != null)

{

MDC.put( MDC_ACCOUNT_ID, Long.toString( basicAccount.getId() ) );

MDC.put( MDC_ACCOUNT_TYPE, Integer.toString( basicAccount.getAccountType() ) );

}

long start = System.currentTimeMillis();

if (opsLogRequestsEnable)

{

logger.info( "[controller][{}][]|[]", operationName );

}

result = joinPoint.proceed();

long end = System.currentTimeMillis();

long time = end - start;

MDC.put( MDC_EXECUTION_LASTED, Long.toString( time ) );

}

catch (Throwable t)

{

errorProduced = t;

throw t;

}

finally

{

if (opsLogRequestsEnable)

{

if (operationName != null)

{

try

{

MDC.put( MDC_OPERATION_LABEL, operationName );

StringBuilder sbArgs = extractArguments( method, args );

if (errorProduced != null)

{

logger.error( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), errorProduced.getClass().getSimpleName() );

}

else if (result != null && result instanceof ResponseEntity)

{

logger.info( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), ( (ResponseEntity<?>) result ).getStatusCodeValue() );

}

else if (result != null && result instanceof Re)

{

logger.info( "[controller][{}][{}]|[{}]", operationName, sbArgs.toString(), ( (Re) result ).getCode() );

}

else

{

logger.info( "[controller][{}][{}]|[]", operationName, sbArgs.toString() );

}

finally

{

MDC.remove( MDC_OPERATION_LABEL );

}

MDC.remove( MDC_ACCOUNT_ID );

MDC.remove( MDC_ACCOUNT_TYPE );

MDC.remove( MDC_EXECUTION_LASTED );

}

else

{

result = joinPoint.proceed();

}

return result;

}

@AfterReturning( returning = "object", pointcut = "logPointCut()" )

public void doAfterReturning( Object object )

{

}

@After( "logPointCut()" )

public void doAfter( JoinPoint joinPoint )

{

}

@AfterThrowing( pointcut = "logPointCut()", throwing = "e" )

public void doAfterThrowing( JoinPoint joinPoint, Throwable e )

{

}

private StringBuilder extractArguments( Method method, Object[] args )

{

StringBuilder sb = new StringBuilder();

try

{

Parameter[] parameters = method.getParameters();

boolean added = false;

if (parameters != null && parameters.length > 0)

{

sb.append( ": " );

for (int i = 0; i < parameters.length; i++)

{

Parameter parameter = parameters[i];

if (parameter.getAnnotation( NotLogOperation.class ) == null && args[i] != null)

{

if (parameter.getType().isPrimitive() || parameter.getType().isEnum()

|| CharSequence.class.isAssignableFrom( parameter.getType() ))

{

if (added)

{

sb.append( ";" );

}

sb.append( parameter.getName() );

sb.append( "=" );

sb.append( args[i].toString() );

added = true;

}

else if (parameter.getType().isArray()

&& ( parameter.getType().getComponentType().isPrimitive() || parameter.getType().getComponentType().isEnum()

|| CharSequence.class.isAssignableFrom( parameter.getType().getComponentType() ) ))

{

if (added)

{

sb.append( ";" );

}

sb.append( parameter.getName() );

sb.append( "=" );

sb.append( MonitorUtils.join( ",", (Object[]) args[i] ) );

added = true;

}

catch (Exception e)

{

logger.error( "Error extracting arguments from method", e );

}

return sb;

}

4-3-4. 3.4 AOP Controller Problem

But I have this problem: AOP cannot advise on annotated controllers

3.4.1 Previous config:

application-context.xml

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">
    <context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />
</context:component-scan>

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">

<context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />

</context:component-scan>

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

spring-mvc-servlet.xml

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />
<mvc:annotation-driven/>
<mvc:default-servlet-handler/>

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />

<mvc:annotation-driven/>

<mvc:default-servlet-handler/>

web.xml

<web-app xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns="http://java.sun.com/xml/ns/javaee"
	xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd"
	version="2.5">
	<context-param>
		<param-name>contextConfigLocation</param-name>
		<param-value>
			classpath:spring/application-context.xml
		</param-value>
	</context-param>

<servlet>
		<servlet-name>dispatcher</servlet-name>
		<servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>
		<init-param>
			<param-name>contextConfigLocation</param-name>
			<param-value>classpath:spring/spring-mvc-servlet.xml</param-value>
		</init-param>
		<load-on-startup>1</load-on-startup>
	</servlet>
	<servlet-mapping>
		<servlet-name>dispatcher</servlet-name>
		<url-pattern>/</url-pattern>
	</servlet-mapping>

<web-app xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

xmlns="http://java.sun.com/xml/ns/javaee"

xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd"

version="2.5">

<context-param>

<param-name>contextConfigLocation</param-name>

<param-value>

classpath:spring/application-context.xml

</param-value>

</context-param>

<servlet-name>dispatcher</servlet-name>

<servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>

<init-param>

<param-name>contextConfigLocation</param-name>

<param-value>classpath:spring/spring-mvc-servlet.xml</param-value>

</init-param>

<load-on-startup>1</load-on-startup>

</servlet>

<servlet-mapping>

<servlet-name>dispatcher</servlet-name>

<url-pattern>/</url-pattern>

</servlet-mapping>

4-3-4-1. 3.4.2 Try 1

Ref: spring-aop-is-not-working-in-with-mvc-structure

The aspects and the beans to be applied needs to be in the same ApplicationContext but ApplicationContext is not aware of WebApplicationContext.

application-context.xml

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">
    <context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />
</context:component-scan>

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">

<context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />

</context:component-scan>

spring-mvc-servlet.xml

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

<mvc:annotation-driven/>
<mvc:default-servlet-handler/>

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

<mvc:annotation-driven/>

<mvc:default-servlet-handler/>

This solution works, now ControllerAscpect can intercept controller. But there is a problem, all controllers and methods which protected by Shiro, return 404 not found error!

4-3-4-2. 3.4.3 Try 2

Ref: Spring AOP Advice on Annotated Controllers

web.xml

		<servlet-name>dispatcher</servlet-name>
		<servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>
		<init-param>
			<param-name>contextConfigLocation</param-name>
			<param-value>classpath:spring/application-context.xml,classpath:spring/spring-mvc-servlet.xml</param-value>
		</init-param>

<servlet-name>dispatcher</servlet-name>

<servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>

<init-param>

<param-name>contextConfigLocation</param-name>

<param-value>classpath:spring/application-context.xml,classpath:spring/spring-mvc-servlet.xml</param-value>

</init-param>

This solution works, now ControllerAscpect can intercept controller. But same problem 404 not found as Try 1.

Then I tried to remove the Shiro AOP for annotation from spring-mvc-servlet.xml:

<bean id="lifecycleBeanPostProcessor" class="org.apache.shiro.spring.LifecycleBeanPostProcessor" />
    <bean class="org.springframework.aop.framework.autoproxy.DefaultAdvisorAutoProxyCreator" depends-on="lifecycleBeanPostProcessor" />
    <bean class="org.apache.shiro.spring.security.interceptor.AuthorizationAttributeSourceAdvisor">
        <property name="securityManager" ref="securityManager" />
    </bean>

</bean>

Now the Shiro protected controllers work again. BUT all the Shiro annotations stop working!!!!

I have not found an AOP solution for my controllers. TODO

4-3-4-3. 3.4.4 Try Interceptor

Other developers mentioned that Interceptor is more suitable for controller:

For MVC controllers the preferred method of accomplishing what you are trying to do is to use interceptors. General rule is use interceptors when you want to intercept certain web requests. Use Aspects when you want to intercept methods on normal spring beans. Since the question is related to intercepting Controllers (which are mapped to web requests)….

/*
 * Copyright (c) 2016-2018 Mobabel.net
 *
 * All rights reserved.
 */
package net.mobabel.nova.service.monitoring.interceptor;

import net.mobabel.nova.core.util.Logger;
import net.mobabel.nova.model.authc.BasicAccount;
import net.mobabel.nova.service.monitoring.LogOperation;
import org.slf4j.MDC;
import org.springframework.core.NamedThreadLocal;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.*;
import org.springframework.web.method.HandlerMethod;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.lang.reflect.Method;
import java.util.List;

import static net.mobabel.nova.service.monitoring.Constants.*;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;
import static net.mobabel.nova.service.monitoring.MonitorUtils.extractOperationName;

public class ControllerLogInterceptor implements HandlerInterceptor {
    protected Logger logger = Logger.getLogger(this.getClass());

    private boolean opsLogRequestsEnable;
    private List<String> opsIncludedPackages;

    private static final ThreadLocal<Long> startTimeThreadLocal = new NamedThreadLocal<Long>("ThreadLocal StartTime");
    private static final ThreadLocal<String> operationNameThreadLocal = new NamedThreadLocal<String>("ThreadLocal operationName");

    public ControllerLogInterceptor() {
    }

    public ControllerLogInterceptor(boolean opsLogRequestsEnable, List<String> opsIncludedPackages) {
        this.opsLogRequestsEnable = opsLogRequestsEnable;
        this.opsIncludedPackages = opsIncludedPackages;
    }

    public void setOpsLogRequestsEnable(final boolean opsLogRequestsEnable) {
        this.opsLogRequestsEnable = opsLogRequestsEnable;
    }

    public void setOpsIncludedPackages(final List<String> opsIncludedPackages) {
        this.opsIncludedPackages = opsIncludedPackages;
    }

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
                             Object handler) throws Exception {
        try {
            long beginTime = System.currentTimeMillis();
            startTimeThreadLocal.set(0L);

            if (handler instanceof HandlerMethod) {
                HandlerMethod handlerMethod = (HandlerMethod) handler;
                Method method = handlerMethod.getMethod();
                final String packageName = method.getDeclaringClass().getPackage().getName();//TODO

                boolean isController = method.getDeclaringClass().isAnnotationPresent(Controller.class);
                boolean isRequestMapping =
                        method.getDeclaringClass().isAnnotationPresent(RequestMapping.class) || method.isAnnotationPresent(RequestMapping.class);
                boolean isGetMapping = method.getDeclaringClass().isAnnotationPresent(GetMapping.class) || method.isAnnotationPresent(GetMapping.class);
                boolean isPostMapping = method.getDeclaringClass().isAnnotationPresent(PostMapping.class) || method.isAnnotationPresent(PostMapping.class);
                boolean isPutMapping = method.getDeclaringClass().isAnnotationPresent(PutMapping.class) || method.isAnnotationPresent(PutMapping.class);
                boolean isDeleteMapping =
                        method.getDeclaringClass().isAnnotationPresent(DeleteMapping.class) || method.isAnnotationPresent(DeleteMapping.class);
                boolean isPatchMapping =
                        method.getDeclaringClass().isAnnotationPresent(PatchMapping.class) || method.isAnnotationPresent(PatchMapping.class);
                boolean isLogOperation =
                        method.getDeclaringClass().isAnnotationPresent(LogOperation.class) || method.isAnnotationPresent(LogOperation.class);

                if (isController &&
                        (isRequestMapping
                                || isGetMapping
                                || isPostMapping
                                || isPutMapping
                                || isDeleteMapping
                                || isPatchMapping
                                || isLogOperation
                        )
                        ) {
                    if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch(packageName::startsWith)) {
                        final String operationName = extractOperationName(method);
                        BasicAccount basicAccount = extractBasicAccount();
                        if (basicAccount != null) {
                            MDC.put(MDC_ACCOUNT_ID, Long.toString(basicAccount.getId()));
                            MDC.put(MDC_ACCOUNT_TYPE, Integer.toString(basicAccount.getAccountType()));
                        }
                        MDC.put(MDC_OPERATION_LABEL, operationName);
                        operationNameThreadLocal.set(operationName);

                      /*MethodParameter[] methodParameters = handlerMethod.getMethodParameters();
                      for (MethodParameter methodParameter : methodParameters)
                      {
                         if (methodParameter.getParameterType().isInstance( BasicAccount.class ))
                         {
                            System.out.println( "========================" + methodParameter.getParameter() );
                         }
                      }*/

                        startTimeThreadLocal.set(beginTime);
                        if (opsLogRequestsEnable) {
                            logger.info("[controller][{}][]|[]", operationName);
                        }
                    }
                }
            }

        } finally {
            MDC.remove(MDC_ACCOUNT_ID);
            MDC.remove(MDC_ACCOUNT_TYPE);
            MDC.remove(MDC_OPERATION_LABEL);
        }
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
                           ModelAndView modelAndView) throws Exception {

    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
                                Object handler, Exception errorProduced) throws Exception {
        long beginTime = startTimeThreadLocal.get();
        try {
            if (beginTime != 0L && handler instanceof HandlerMethod) {
                final String operationName = operationNameThreadLocal.get();
                MDC.put(MDC_OPERATION_LABEL, operationName);

                long endTime = System.currentTimeMillis();
                long time = endTime - beginTime;
                MDC.put(MDC_EXECUTION_LASTED, Long.toString(time));

                if (opsLogRequestsEnable) {
                    if (errorProduced != null) {
                        logger.error("[controller][{}][{}]|[{}]", operationName, "", errorProduced.getClass().getSimpleName());
                    } else {
                        logger.info("[controller][{}][{}]|[]", operationName, "");
                    }
                }
            }
        } finally {
            MDC.remove(MDC_EXECUTION_LASTED);
            MDC.remove(MDC_OPERATION_LABEL);
        }

    }

}

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

package net.mobabel.nova.service.monitoring.interceptor;

import net.mobabel.nova.core.util.Logger;

import net.mobabel.nova.model.authc.BasicAccount;

import net.mobabel.nova.service.monitoring.LogOperation;

import org.slf4j.MDC;

import org.springframework.core.NamedThreadLocal;

import org.springframework.stereotype.Controller;

import org.springframework.web.bind.annotation.*;

import org.springframework.web.method.HandlerMethod;

import org.springframework.web.servlet.HandlerInterceptor;

import org.springframework.web.servlet.ModelAndView;

import javax.servlet.http.HttpServletRequest;

import javax.servlet.http.HttpServletResponse;

import java.lang.reflect.Method;

import java.util.List;

import static net.mobabel.nova.service.monitoring.Constants.*;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractBasicAccount;

import static net.mobabel.nova.service.monitoring.MonitorUtils.extractOperationName;

public class ControllerLogInterceptor implements HandlerInterceptor {

protected Logger logger = Logger.getLogger(this.getClass());

private boolean opsLogRequestsEnable;

private List<String> opsIncludedPackages;

private static final ThreadLocal<Long> startTimeThreadLocal = new NamedThreadLocal<Long>("ThreadLocal StartTime");

private static final ThreadLocal<String> operationNameThreadLocal = new NamedThreadLocal<String>("ThreadLocal operationName");

public ControllerLogInterceptor() {

}

public ControllerLogInterceptor(boolean opsLogRequestsEnable, List<String> opsIncludedPackages) {

this.opsLogRequestsEnable = opsLogRequestsEnable;

this.opsIncludedPackages = opsIncludedPackages;

}

public void setOpsLogRequestsEnable(final boolean opsLogRequestsEnable) {

this.opsLogRequestsEnable = opsLogRequestsEnable;

}

public void setOpsIncludedPackages(final List<String> opsIncludedPackages) {

this.opsIncludedPackages = opsIncludedPackages;

}

@Override

public boolean preHandle(HttpServletRequest request, HttpServletResponse response,

Object handler) throws Exception {

try {

long beginTime = System.currentTimeMillis();

startTimeThreadLocal.set(0L);

if (handler instanceof HandlerMethod) {

HandlerMethod handlerMethod = (HandlerMethod) handler;

Method method = handlerMethod.getMethod();

final String packageName = method.getDeclaringClass().getPackage().getName();//TODO

boolean isController = method.getDeclaringClass().isAnnotationPresent(Controller.class);

boolean isRequestMapping =

method.getDeclaringClass().isAnnotationPresent(RequestMapping.class) || method.isAnnotationPresent(RequestMapping.class);

boolean isGetMapping = method.getDeclaringClass().isAnnotationPresent(GetMapping.class) || method.isAnnotationPresent(GetMapping.class);

boolean isPostMapping = method.getDeclaringClass().isAnnotationPresent(PostMapping.class) || method.isAnnotationPresent(PostMapping.class);

boolean isPutMapping = method.getDeclaringClass().isAnnotationPresent(PutMapping.class) || method.isAnnotationPresent(PutMapping.class);

boolean isDeleteMapping =

method.getDeclaringClass().isAnnotationPresent(DeleteMapping.class) || method.isAnnotationPresent(DeleteMapping.class);

boolean isPatchMapping =

method.getDeclaringClass().isAnnotationPresent(PatchMapping.class) || method.isAnnotationPresent(PatchMapping.class);

boolean isLogOperation =

method.getDeclaringClass().isAnnotationPresent(LogOperation.class) || method.isAnnotationPresent(LogOperation.class);

if (isController &&

(isRequestMapping

|| isGetMapping

|| isPostMapping

|| isPutMapping

|| isDeleteMapping

|| isPatchMapping

|| isLogOperation

)

) {

if (opsIncludedPackages == null || opsIncludedPackages.stream().anyMatch(packageName::startsWith)) {

final String operationName = extractOperationName(method);

BasicAccount basicAccount = extractBasicAccount();

if (basicAccount != null) {

MDC.put(MDC_ACCOUNT_ID, Long.toString(basicAccount.getId()));

MDC.put(MDC_ACCOUNT_TYPE, Integer.toString(basicAccount.getAccountType()));

}

MDC.put(MDC_OPERATION_LABEL, operationName);

operationNameThreadLocal.set(operationName);

/*MethodParameter[] methodParameters = handlerMethod.getMethodParameters();

for (MethodParameter methodParameter : methodParameters)

{

if (methodParameter.getParameterType().isInstance( BasicAccount.class ))

{

System.out.println( "========================" + methodParameter.getParameter() );

}

}*/

startTimeThreadLocal.set(beginTime);

if (opsLogRequestsEnable) {

logger.info("[controller][{}][]|[]", operationName);

}

} finally {

MDC.remove(MDC_ACCOUNT_ID);

MDC.remove(MDC_ACCOUNT_TYPE);

MDC.remove(MDC_OPERATION_LABEL);

}

return true;

}

@Override

public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,

ModelAndView modelAndView) throws Exception {

}

@Override

public void afterCompletion(HttpServletRequest request, HttpServletResponse response,

Object handler, Exception errorProduced) throws Exception {

long beginTime = startTimeThreadLocal.get();

try {

if (beginTime != 0L && handler instanceof HandlerMethod) {

final String operationName = operationNameThreadLocal.get();

MDC.put(MDC_OPERATION_LABEL, operationName);

long endTime = System.currentTimeMillis();

long time = endTime - beginTime;

MDC.put(MDC_EXECUTION_LASTED, Long.toString(time));

if (opsLogRequestsEnable) {

if (errorProduced != null) {

logger.error("[controller][{}][{}]|[{}]", operationName, "", errorProduced.getClass().getSimpleName());

} else {

logger.info("[controller][{}][{}]|[]", operationName, "");

}

} finally {

MDC.remove(MDC_EXECUTION_LASTED);

MDC.remove(MDC_OPERATION_LABEL);

}

application-context.xml

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">
    <context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />
</context:component-scan>

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

<context:component-scan base-package="net.mobabel.nova.**" use-default-filters="true">

<context:exclude-filter type="annotation" expression="org.springframework.stereotype.Controller" />

</context:component-scan>

<aop:aspectj-autoproxy expose-proxy="true" proxy-target-class="true" />

spring-mvc-servlet.xml

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />
<mvc:annotation-driven/>
<mvc:default-servlet-handler/>


    <bean id="propertyConfigurer" class="org.springframework.beans.factory.config.PropertyPlaceholderConfigurer">
        <!-- works for XML-->
        <property name="locations">
            <list>
                <value>classpath:system_config.properties</value>
            </list>
        </property>
    </bean>

    <!-- request interceptor -->
    <bean id="controllerLogInterceptor" class="net.mobabel.nova.service.monitoring.interceptor.ControllerLogInterceptor" >
        <property name="opsLogRequestsEnable" value="${monitor.operation_logging.log_requests:false}"/>
        <property name="opsIncludedPackages" value="#{'${monitor.operation_logging.included_packages.repository}'.split(',')}"/>
    </bean>

    <mvc:interceptors>
        <mvc:interceptor>
            <mvc:mapping path="/**/**" />
            <ref bean="controllerLogInterceptor" />
        </mvc:interceptor>
    </mvc:interceptors>

<context:component-scan base-package="net.mobabel.nova.web.shop.controller.**" />

<mvc:annotation-driven/>

<mvc:default-servlet-handler/>

<list>

<value>classpath:system_config.properties</value>

</list>

</property>

</bean>

</bean>

<mvc:interceptors>

<mvc:interceptor>

<mvc:mapping path="/**/**" />

</mvc:interceptor>

</mvc:interceptors>

This solution works. And ControllerInterceptor works with ServiceAspect and RepositoryAspect now.

5. Test

In the test, a blog edit request was executed, and all related logs were collected here:

[mgr] [INFO ] [2018-12-03 14:22:47,634] [-79463] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [ControllerLogInterceptor:55] - [controller][/blog/post/edit][]|[]
[mgr] [DEBUG] [2018-12-03 14:22:47,835] [-79664] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [edit:159] - ==>  Preparing: update blog_posts set parent_id = ?, title = ?, summary = ?, content = ? where id = ? 
[mgr] [DEBUG] [2018-12-03 14:22:47,838] [-79667] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [edit:159] - <==    Updates: 1
[mgr] [INFO ] [2018-12-03 14:22:47,839] [-79668] [http-apr-8080-exec-1] [259708060346486784] [1:0] [86] [RepositoryAspect:55] - [repository][edit()]|[]
[mgr] [DEBUG] [2018-12-03 14:22:47,839] [-79668] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [PreparedStatementPool:160] - {conn-10001, pstmt-20004} exit cache
[mgr] [DEBUG] [2018-12-03 14:22:47,840] [-79669] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [PreparedStatementPool:129] - {conn-10001, pstmt-20025} enter cache
[mgr] [INFO ] [2018-12-03 14:22:47,842] [-79671] [http-apr-8080-exec-1] [259708060346486784] [1:0] [194] [ServiceAspect:55] - [service][/blog/post/edit.do][edit()]|[]
[mgr] [INFO ] [2018-12-03 14:22:47,844] [-79673] [http-apr-8080-exec-1] [259708060346486784] [:] [210] [ControllerLogInterceptor:55] - [controller][/blog/post/edit][]|[]

[mgr] [INFO ] [2018-12-03 14:22:47,634] [-79463] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [ControllerLogInterceptor:55] - [controller][/blog/post/edit][]|[]

[mgr] [DEBUG] [2018-12-03 14:22:47,835] [-79664] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [edit:159] - ==> Preparing: update blog_posts set parent_id = ?, title = ?, summary = ?, content = ? where id = ?

[mgr] [DEBUG] [2018-12-03 14:22:47,838] [-79667] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [edit:159] - <== Updates: 1

[mgr] [INFO ] [2018-12-03 14:22:47,839] [-79668] [http-apr-8080-exec-1] [259708060346486784] [1:0] [86] [RepositoryAspect:55] - [repository][edit()]|[]

[mgr] [DEBUG] [2018-12-03 14:22:47,839] [-79668] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [PreparedStatementPool:160] - {conn-10001, pstmt-20004} exit cache

[mgr] [DEBUG] [2018-12-03 14:22:47,840] [-79669] [http-apr-8080-exec-1] [259708060346486784] [1:0] [] [PreparedStatementPool:129] - {conn-10001, pstmt-20025} enter cache

[mgr] [INFO ] [2018-12-03 14:22:47,842] [-79671] [http-apr-8080-exec-1] [259708060346486784] [1:0] [194] [ServiceAspect:55] - [service][/blog/post/edit.do][edit()]|[]

[mgr] [INFO ] [2018-12-03 14:22:47,844] [-79673] [http-apr-8080-exec-1] [259708060346486784] [:] [210] [ControllerLogInterceptor:55] - [controller][/blog/post/edit][]|[]

Take one line and map the content to the log format table:

[mgr] [INFO ] [2018-12-03 14:22:47,842] [-79671] [http-apr-8080-exec-1] [259708060346486784] [1:0] [194] [ServiceAspect:55] - [service][/blog/post/edit.do][edit()]|[]

1	[mgr] [INFO ] [2018-12-03 14:22:47,842] [-79671] [http-apr-8080-exec-1] [259708060346486784] [1:0] [194] [ServiceAspect:55] - [service][/blog/post/edit.do][edit()]\|[]

Name	Content
requestID	259708060346486784
timestamp	2018-12-03 14:22:47,842
level	INFO
message	[service][/blog/post/edit.do][edit()]\|[]
app	mgr
module	service
operation label	/blog/post/edit.do
accountId	1:0
accountType	1:0
status
elapsed	194
error	— available in error
thread id	79671
Class name	ServiceAspect
package.class	— available in error
line number	— available in error

6. ELK

TODO

7. Reference:

最佳日志实践

最佳日志实践（v2.0）

[elk]基于elk的业务日志格式设计

Spring 使用笔记之(二) – AOP和Interceptor(拦截器)

Spring Boot: Setting a unique ID per request

自己写分布式链路追踪框架1–TraceId/SpanId/ParentSpanId生成及传递

在SpringBoot项目中添加logback的MDC

[总结]日志格式

NOST-73

Tags: Log Monitor

Cookie	Duration	Description
cookielawinfo-checkbox-analytics	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Analytics".
cookielawinfo-checkbox-functional	11 months	The cookie is set by GDPR cookie consent to record the user consent for the cookies in the category "Functional".
cookielawinfo-checkbox-necessary	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookies is used to store the user consent for the cookies in the category "Necessary".
cookielawinfo-checkbox-others	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Other.
cookielawinfo-checkbox-performance	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Performance".
viewed_cookie_policy	11 months	The cookie is set by the GDPR Cookie Consent plugin and is used to store whether or not user has consented to the use of cookies. It does not store any personal data.

Design Log Monitor System Prototype — 1. Spring MVC

You may also like...

Leave a Reply Cancel reply

Meta

Categories

Design Log Monitor System Prototype — 1. Spring MVC

1. Background

2. Requirement

3. About Log

3-1. 1. Log Level:

3-2. 2. Log Maintenance

3-3. 3. Log Category

3-3-1. Diagnosed Log

3-3-2. Statistic Log

3-3-3. Audit Log

3-4. 4. Redundant Log vs Useless Log

3-5. 5. Log record integrity

3-6. 6. Test Log

3-7. 7. APM and Distributed Tracing

3-8. 7. Dynamic Log Recording

3-9. 8. Log Isolation and Size Control

4. Practice

4-1. 1. Log format

4-2. 2. Generate RequestID

4-3. 3. AOP or Interceptor Implementation

4-3-1. 3.1 AOP for Repository

4-3-2. 3.2 AOP for Service

4-3-3. 3.3 AOP for Controller

4-3-4. 3.4 AOP Controller Problem

4-3-4-1. 3.4.2 Try 1

4-3-4-2. 3.4.3 Try 2

4-3-4-3. 3.4.4 Try Interceptor

5. Test

6. ELK

7. Reference:

Related posts:

You may also like...

[转]有赞百亿级日志系统是怎么设计出来的?

[汇总]日志开发经验

Disable Logback log files in containers

Leave a Reply Cancel reply

Meta

Categories