Spring AOP(MethodInterceptor)

aop.groovy

@Grab('spring-aop')
@Grab('aspectjrt')
@Grab('aspectjtools')
@Grab('aspectjweaver')


import groovy.util.logging.Slf4j

import java.lang.annotation.Retention
import java.lang.annotation.Target
import java.lang.annotation.RetentionPolicy
import java.lang.annotation.ElementType

import java.time.Instant
import java.time.format.DateTimeFormatter

import org.aopalliance.intercept.MethodInterceptor
import org.aopalliance.intercept.MethodInvocation

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

import org.springframework.aop.Advisor
import org.springframework.aop.aspectj.AspectJExpressionPointcut
import org.springframework.aop.support.DefaultPointcutAdvisor

@RestController
@RequestMapping('/app')
@Slf4j
class WebCon {

  final MyService service

  WebCon(MyService service) { this.service = service }

  @GetMapping(produces = 'application/json')
  ResponseEntity<Map<String,String>> get(@RequestParam(value = 'name', defaultValue = 'foo-bar') String name) {
    log.info('get - name: {}', name)
    return ResponseEntity.ok(name: name, now: service.now())
  }
}

@Component
class MyService {

  @Log String now() {
    DateTimeFormatter.ISO_INSTANT.format(Instant.now())
  }
}

@Component
@Slf4j
class Logging implements MethodInterceptor {
  @Override Object invoke(MethodInvocation invocation) {
    def attr = RequestContextHolder.currentRequestAttributes()
    log.info('attr: {}, {}', attr.class, attr.sessionId)
    def serv = attr as ServletRequestAttributes

    def en = serv.request.headerNames
    def map = [:]
    while(en.hasMoreElements()) {
      def k = en.nextElement()
      map[k] = serv.request.getHeader(k)
    }

    log.info('header - {}', map)
    def result = invocation.proceed()
    log.info('{} - {}', invocation.method.name, result)
    return result
  }
}

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@interface Log {}

@Configuration
class LogConfig {

  final Logging logging

  LogConfig(Logging logging) { this.logging = logging }

  @Bean Advisor logAdvisor() {
    def pointcut = new AspectJExpressionPointcut()
    pointcut.expression = '@annotation(Log)'
    return new DefaultPointcutAdvisor(pointcut, logging)
  }
}

running log

$ spring run aop.groovy
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.codehaus.groovy.reflection.CachedClass (jar:file:/Users/shinya.mochida/.sdkman/candidates/springboot/2.3.5.RELEASE/lib/spring-boot-cli-2.3.5.RELEASE.jar!/BOOT-INF/lib/groovy-2.5.13.jar!/) to method java.lang.Object.finalize()
WARNING: Please consider reporting this to the maintainers of org.codehaus.groovy.reflection.CachedClass
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.5.RELEASE)

2020-11-24 13:51:32.282  INFO 11009 --- [       runner-0] o.s.boot.SpringApplication               : Starting application on anatato-Java-imasugu-download.local with PID 11009 (started by someone in /path/to/groovy-scripts)
2020-11-24 13:51:32.291  INFO 11009 --- [       runner-0] o.s.boot.SpringApplication               : No active profile set, falling back to default profiles: default
2020-11-24 13:51:33.270  INFO 11009 --- [       runner-0] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-11-24 13:51:33.280  INFO 11009 --- [       runner-0] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-11-24 13:51:33.281  INFO 11009 --- [       runner-0] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.39]
2020-11-24 13:51:33.311  INFO 11009 --- [       runner-0] org.apache.catalina.loader.WebappLoader  : Unknown class loader [org.springframework.boot.cli.compiler.ExtendedGroovyClassLoader$DefaultScopeParentClassLoader@22a71081] of class [class org.springframework.boot.cli.compiler.ExtendedGroovyClassLoader$DefaultScopeParentClassLoader]
2020-11-24 13:51:33.343  INFO 11009 --- [       runner-0] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-11-24 13:51:33.343  INFO 11009 --- [       runner-0] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 988 ms
2020-11-24 13:51:33.557  INFO 11009 --- [       runner-0] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-11-24 13:51:33.839  INFO 11009 --- [       runner-0] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-11-24 13:51:33.848  INFO 11009 --- [       runner-0] o.s.boot.SpringApplication               : Started application in 1.955 seconds (JVM running for 3.685)
2020-11-24 13:51:40.848  INFO 11009 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-11-24 13:51:40.848  INFO 11009 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-11-24 13:51:40.855  INFO 11009 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 7 ms
2020-11-24 13:51:40.889  INFO 11009 --- [nio-8080-exec-1] WebCon                                   : get - name: ishida
2020-11-24 13:51:40.931  INFO 11009 --- [nio-8080-exec-1] Logging                                  : attr: class org.springframework.web.context.request.ServletRequestAttributes, 7513C14279D4F261BBD68B15C6F615A3
2020-11-24 13:51:40.947  INFO 11009 --- [nio-8080-exec-1] Logging                                  : header - {host=localhost:8080, user-agent=curl/7.64.1, x-foo-bar=aiiin, accept=application/json}
2020-11-24 13:51:40.968  INFO 11009 --- [nio-8080-exec-1] Logging                                  : now - 2020-11-24T04:51:40.960762Z
^C2020-11-24 13:51:59.997  INFO 11009 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'