はじめに
Javaで開発をしているときにメソッドの入出力のログを出力したいと思うことがあるかと思います。ここではSpring BootのAOPライブラリを使用したログ出力について記述したいと思います
環境について
この記事に出てくるサンプルプログラムは下記の環境で作成しました
| 名前 | バージョン |
|---|---|
| Java | Amazon Corretto version 17.0.9 |
| Spring Boot | 3.2.0 |
| Gradle | 8.5 |
ログ出力機能追加前のソースコードについて
ログ出力前のソースコードは下記のとおりです。
build.gradle
plugins {
id 'java'
id 'org.springframework.boot' version '3.2.0'
id 'io.spring.dependency-management' version '1.1.4'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
java {
sourceCompatibility = '17'
}
repositories {
mavenCentral()
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-thymeleaf'
implementation 'org.springframework.boot:spring-boot-starter-web'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
}
tasks.named('test') {
useJUnitPlatform()
}
com.example.loggingdemo.LoggingDemoApplication.java
package com.example.loggingdemo;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class LoggingDemoApplication {
public static void main(String[] args) {
SpringApplication.run(LoggingDemoApplication.class, args);
}
}
com.example.loggingdemo.controller.LoggingDemoController.java
package com.example.loggingdemo.controller;
import com.example.loggingdemo.service.Greeting;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.GetMapping;
@Controller
public class LoggingDemoController {
private final Greeting greeting;
@Autowired
public LoggingDemoController(Greeting greeting) {
this.greeting = greeting;
}
@GetMapping("/greeting")
public String greetingForm(Model model) {
String text = greeting.getGreeting("テスト","太郎");
model.addAttribute("greeting", text);
return "greeting";
}
}
com.example.loggingdemo.service.Greeting.java
package com.example.loggingdemo.service;
import org.springframework.stereotype.Service;
@Service
public class Greeting {
public Greeting() {
}
public String getGreeting(String firstName,String lastName) {
return privateBuildGreeting(firstName,lastName);
}
private String privateBuildGreeting(String firstName, String lastName) {
return "Hello " + firstName + ":" + lastName;
}
}
greeting.html
<!DOCTYPE HTML>
<html xmlns:th="https://www.thymeleaf.org">
<head>
<title>Logging Demo</title>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" />
</head>
<body>
<h1>Logging Demo</h1>
<p th:text="'greeting: ' + ${greeting}" />
</body>
</html>
実際にブラウザでアクセスすると下記のような表示になります
ログ出力の方法について
さて、現在の状態ではメソッド入出力のログは出力されません。
出力するためには下記のファイルの修正、追加を行います
- build.gradleに「implementation 'org.springframework.boot:spring-boot-starter-aop'」を追加
- AOPLogging用のクラスを追加
build.gradleは下記のようになります。
build.gradle
plugins {
id 'java'
id 'org.springframework.boot' version '3.2.0'
id 'io.spring.dependency-management' version '1.1.4'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
java {
sourceCompatibility = '17'
}
repositories {
mavenCentral()
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-thymeleaf'
implementation 'org.springframework.boot:spring-boot-starter-web'
// 下記の行を追加してAOPを有効にする
implementation 'org.springframework.boot:spring-boot-starter-aop'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
}
tasks.named('test') {
useJUnitPlatform()
}
Logging用のクラスは、検索するといろいろと出てくるとは思いますが、例えば下記のようになります
com.example.loggingdemo.aop.LoggingAdvice.java
package com.example.loggingdemo.aop;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import java.util.ArrayList;
@Aspect
@Component
public class LoggingAdvice {
private final Logger logger;
public LoggingAdvice() {
this.logger = LoggerFactory.getLogger(getClass());
}
//com.example.loggingdemoパッケージ配下の全てのクラスのメソッドがログ出力の対象となる
@Before("execution(* com.example.loggingdemo..*.*(..))")
public void logBefore(JoinPoint jp) {
startLog(jp);
}
@AfterReturning(value = "execution(* com.example.loggingdemo..*.*(..))", returning = "retval")
public void logAfter(JoinPoint jp, Object retval) {
endLog(jp, retval);
}
private void startLog(JoinPoint jp) {
String mess = "[START]" + getClassName(jp) + "." + getSignature(jp) + ":args=[" + getArgs(jp) + "]";
logger.info(mess);
}
private void endLog(JoinPoint jp, Object retval) {
String mess = "[END]" + getClassName(jp) + "." + getSignature(jp) + ":retval=[" + getRetVal(retval) + "]";
logger.info(mess);
}
private String getClassName(JoinPoint jp) {
return jp.getTarget().getClass().toString();
}
private String getSignature(JoinPoint jp) {
return jp.getSignature().getName();
}
private String getArgs(JoinPoint jp) {
if (jp.getArgs() == null) {
return "args is null";
}
Object[] args = jp.getArgs();
ArrayList<String> list = new ArrayList();
int i = 0;
for (Object arg : args) {
i++;
if (arg != null) {
list.add("arg" + i + "=" + arg);
} else {
list.add("arg" + i + "=null");
}
}
return String.join(" ", list);
}
private String getRetVal(Object retval) {
if (retval == null) {
return "retval is null";
} else {
return retval.toString();
}
}
}
ソースコードのコメントにも書いてありますが、この例では、 com.example.loggingdemoパッケージ配下の全てのクラスのメソッドがログ出力の対象になります。
この状態でビルドし、ブラウザで再度アクセスすると下記のようなログが出力されます
output.log
2023-12-14T23:28:28.669+09:00 INFO 27527 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [START]class com.example.loggingdemo.controller.LoggingDemoController.greetingForm:args=[arg1={}]
2023-12-14T23:28:28.669+09:00 INFO 27527 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [START]class com.example.loggingdemo.service.Greeting.getGreeting:args=[arg1=テスト arg2=太郎]
2023-12-14T23:28:28.671+09:00 INFO 27527 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [END]class com.example.loggingdemo.service.Greeting.getGreeting:retval=[Hello テスト:太郎]
2023-12-14T23:28:28.672+09:00 INFO 27527 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [END]class com.example.loggingdemo.controller.LoggingDemoController.greetingForm:retval=[greeting]
これでひとまずメソッドの入出力のログが取れるようになったのですが、今のままではpublicメソッドが出力されるだけで、privateメソッドが出力されるようになっていません.privateメソッドの入出力をログに出力するためには、コンパイル時にアスペクトの織り込みをする(compile-time weaving)必要があります。
Spring Bootでcompile-time weavingを行うには、build.gradleを修正し、下記のプラグインを追加します
id "io.freefair.aspectj.post-compile-weaving" version '8.4'
build.gradle全体では最終的に下記の通りになります
build.gradle
plugins {
id 'java'
id 'org.springframework.boot' version '3.2.0'
id 'io.spring.dependency-management' version '1.1.4'
// compile-time weaving を有効にする
id "io.freefair.aspectj.post-compile-weaving" version '8.4'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
java {
sourceCompatibility = '17'
}
repositories {
mavenCentral()
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-thymeleaf'
implementation 'org.springframework.boot:spring-boot-starter-web'
// 下記の行を追加してAOPを有効にする
implementation 'org.springframework.boot:spring-boot-starter-aop'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
}
tasks.named('test') {
useJUnitPlatform()
}
上記プラグインを追加した場合、LoggingAdviceクラス自身がポイントカットの対象になっていると、Spring Bootが正常に起動しなくなるため、LogginAdviceクラスのexecution ポイントカット指定子を修正して、対象にならないようにします。
LogginAdviceクラスは下記のようになります。（対象部分だけ抜粋）
com.example.loggingdemo.aop.LoggingAdvice.java
// この例では、serviceパッケージ配下のみログ出力の対象とする
@Before("execution(* com.example.loggingdemo.service..*.*(..))")
public void logBefore(JoinPoint jp) {
startLog(jp);
}
// この例では、serviceパッケージ配下のみログ出力の対象とする
@AfterReturning(value = "execution(* com.example.loggingdemo.service..*.*(..))", returning = "retval")
public void logAfter(JoinPoint jp, Object retval) {
endLog(jp, retval);
}
この状態で、ビルドし直して再度プログラムを起動してブラウザでアクセスすると下記のようなログが出力されます
2023-12-14T23:32:42.774+09:00 INFO 27592 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [START]class com.example.loggingdemo.service.Greeting.getGreeting:args=[arg1=テスト arg2=太郎]
// privateメソッドのログが出力されている
2023-12-14T23:32:42.775+09:00 INFO 27592 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [START]class com.example.loggingdemo.service.Greeting.privateBuildGreeting:args=[arg1=テスト arg2=太郎]
2023-12-14T23:32:42.776+09:00 INFO 27592 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [END]class com.example.loggingdemo.service.Greeting.privateBuildGreeting:retval=[Hello テスト:太郎]
2023-12-14T23:32:42.776+09:00 INFO 27592 --- [nio-8080-exec-1] c.example.loggingdemo.aop.LoggingAdvice : [END]class com.example.loggingdemo.service.Greeting.getGreeting:retval=[Hello テスト:太郎]
今回のプログラムの全体のディレクトリ構成は下記の通りになります
参考にしたサイト