LoginSignup
3
2

More than 1 year has passed since last update.

@kazokmr(kazo)

Spring AOP で Log4J2をで出力しているログのテストコードを書く

Last updated at Posted at 2021-07-16

Spring AOP (@Aspect)でログ出力を行なっている場合のテストコードを書いてみた。
ポイントになるのは次の2つ

  1. AOPで定義している処理をテストで実行させる
  2. 出力されるログの内容を取得して検証する

この記事では、ログ出力 + ログファサードを Log4J2 とした場合のテストコードとなっている。
ログ出力を logback にしている場合は、AppenderモックをはじめログデータをlogbackのAPIを使うことである程度、サンプルコードが参考にできるかもしれないが未確認です。

サンプルコード

今回のテストコードも、もっといい書き方はありそうだが、まずはやりたいことは実現できているので、気づきがあれば後で修正する。

プロダクションコード

AOPの処理を定義したAdviceクラスは下記の通り。ロギングはControllerクラスを呼び出した時に出力されるがControllerクラスのコードは省略する。

LoggingAdvice.kt

import com.custome.application.service.security.CustomeUserDetails
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.Logger
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.springframework.security.core.context.SecurityContextHolder
import org.springframework.stereotype.Component
import org.springframework.web.context.request.RequestContextHolder
import org.springframework.web.context.request.ServletRequestAttributes

private val logger: Logger = LogManager.getLogger(LoggingAdvice::class.java)

@Aspect
@Component
class LoggingAdvice {

    @Before("execution(* com.custome.presentation.controller..*.*(..))")
    fun beforeLog(joinPoint: JoinPoint) {
        val account = SecurityContextHolder.getContext().authentication.principal as CustomeUserDetails
        logger.info("Start: ${joinPoint.signature} accountId=${account.id}")
        logger.info("Class: ${joinPoint.target.javaClass}")
        logger.info(
            "Session: ${(RequestContextHolder.getRequestAttributes() as ServletRequestAttributes).request.session.id}"
        )
    }

    @After("execution(* com.custome.presentation.controller..*.*(..))")
    fun afterLog(joinPoint: JoinPoint) {
        val account = SecurityContextHolder.getContext().authentication.principal as CustomeUserDetails
        logger.info("End: ${joinPoint.signature} accountId=${account.id}")
    }

    @Around("execution(* com.custome.presentation.controller..*.*(..))")
    fun aroundLog(joinPoint: ProceedingJoinPoint): Any? {
        val account = SecurityContextHolder.getContext().authentication.principal as CustomeUserDetails
        logger.info("Start Proceed: ${joinPoint.signature} accountId=${account.id}")

        val result = joinPoint.proceed()

        logger.info("End Proceed: ${joinPoint.signature} accountId=${account.id}")

        return result
    }

    @AfterReturning("execution(* com.custome.presentation.controller..*.*(..))", returning = "returnValue")
    fun afterReturningLog(joinPoint: JoinPoint, returnValue: Any?) {
        logger.info("End: ${joinPoint.signature} returnValue=$returnValue")
    }

    @AfterThrowing(
        "execution(* com.custome.application..*.*(..)) || " +
                "execution(* com.custome.presentation.controller..*.*(..))",
        throwing = "e"
    )
    fun afterThrowingLog(joinPoint: JoinPoint, e: Exception) {
        logger.error("Exception: ${e.javaClass} signature=${joinPoint.signature} message=${e.message}")
    }
}

テストコード

ログに出力している情報が多いため、変数も多くなっている。詳細は後述する。

LoggingAdviceTest.kt

import com.nhaarman.mockitokotlin2.any
import com.nhaarman.mockitokotlin2.mock
import com.nhaarman.mockitokotlin2.reset
import com.nhaarman.mockitokotlin2.times
import com.nhaarman.mockitokotlin2.verify
import com.nhaarman.mockitokotlin2.whenever
import org.apache.logging.log4j.Level
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.core.Appender
import org.apache.logging.log4j.core.LogEvent
import org.apache.logging.log4j.core.LoggerContext
import org.assertj.core.api.Assertions.assertThat
import org.assertj.core.api.SoftAssertions
import org.junit.jupiter.api.AfterEach
import org.junit.jupiter.api.BeforeEach
import org.junit.jupiter.api.DisplayName
import org.junit.jupiter.api.Test
import org.junit.jupiter.api.assertThrows
import org.mockito.ArgumentCaptor
import org.mockito.Captor
import org.springframework.aop.aspectj.annotation.AspectJProxyFactory
import org.springframework.boot.test.autoconfigure.web.servlet.WebMvcTest
import org.springframework.boot.test.mock.mockito.MockBean
import org.springframework.http.HttpStatus.BAD_REQUEST
import org.springframework.mock.web.MockHttpServletRequest
import org.springframework.mock.web.MockHttpSession
import org.springframework.security.core.context.SecurityContextHolder
import org.springframework.web.context.request.RequestContextHolder
import org.springframework.web.context.request.ServletRequestAttributes
import org.springframework.web.server.ResponseStatusException
import java.time.LocalDate
import java.time.format.DateTimeFormatter

// Controllerクラスに対するログ出力なのでWebMvcTestとMockUserを付ける
@WebMvcTest(controllers = [CustomeController::class])
@WithCustomMockUser
internal class LoggingAdviceTest {

    // Controllerテストに必要なMockBean
    @MockBean
    private lateinit var authenticationService: AuthenticationService

    @MockBean
    private lateinit var customeService: CustomeService

    // AOP(ログ出力)対象クラス
    private lateinit var proxy: CustomeController
    // Session情報を取得するためのMockリクエスト
    private lateinit var request: MockHttpServletRequest

    // 検査用のログ出力先となるAppender
    private lateinit var mockAppender: Appender
    // 出力したログを保持する
    @Captor
    private lateinit var logMessageCaptor: ArgumentCaptor<LogEvent>

    @BeforeEach
    internal fun setUp() {

        // Controllerクラスの実行をAspectJProxyFactoryでフィルタリングして、追加したAdviceクラスを実行させる
        val bookController = CustomeController(customeService)
        val factory = AspectJProxyFactory(bookController)
        factory.addAspect(LoggingAdvice())
        proxy = factory.getProxy()

        // Log出力でセッション情報を出力するためのMock
        val session = MockHttpSession()
        request = MockHttpServletRequest().apply { setSession(session) }
        RequestContextHolder.setRequestAttributes(ServletRequestAttributes(request))

        // AOPで出力するログを検査するためのAppenderモックを設定
        mockAppender = mock()
        reset(mockAppender)
        whenever(mockAppender.name).thenReturn("MockAppender")
        whenever(mockAppender.isStarted).thenReturn(true)
        whenever(mockAppender.isStopped).thenReturn(false)

        // AppenderモックをLog出力設定に追加
        val ctx = LoggerContext.getContext(false)
        ctx.configuration.addAppender(mockAppender)
        ctx.configuration.getLoggerConfig(LogManager.ROOT_LOGGER_NAME).apply {
            level = Level.INFO
            addAppender(mockAppender, Level.INFO, null)
        }
        ctx.updateLoggers()
    }

    @AfterEach
    internal fun tearDown() {
        // Appenderモックを除去する
        val ctx = LoggerContext.getContext(false)
        ctx.configuration.loggers.values.forEach { it.removeAppender(mockAppender.name) }
        ctx.configuration.rootLogger.removeAppender(mockAppender.name)
    }

    @Test
    @DisplayName("戻り値があるメソッドのログが出力されること")
    fun `logging when there is return value then logging`() {

        // Given
        val book = Book(9999, "title", "author", LocalDate.now())
        whenever(customeService.getDetail(any() as Long)).thenReturn(CustomeEntity(book, null))

        val userDetails = SecurityContextHolder.getContext().authentication.principal as CustomeUserDetails
        val method = proxy.javaClass.declaredMethods.first { it.name == "getDetail" }

        // When
        proxy.getDetail(book.id)

        // Then
        verify(mockAppender, times(7)).append(logMessageCaptor.capture())

        // 出力されるログのメッセージを順番に文字列で取得しておく
        val logMessages = logMessageCaptor.allValues.map { it.message.formattedMessage }
        SoftAssertions().apply {
            assertThat(logMessages[0])
                .startsWith("Start Proceed:")
                .contains(method.returnType.simpleName)
                .contains(method.name)
                .endsWith("accountId=${userDetails.id}")
            assertThat(logMessages[1])
                .startsWith("Start:")
                .contains(method.returnType.simpleName)
                .contains(method.name)
                .endsWith("accountId=${userDetails.id}")
            assertThat(logMessages[2])
                .startsWith("Class: class ${CustomeController::class.java.canonicalName}")
            assertThat(logMessages[3])
                .isEqualTo("Session: ${request.session?.id}")
            assertThat(logMessages[4])
                .startsWith("End:")
                .contains(method.returnType.simpleName)
                .contains(method.name)
                .endsWith(
                    """
                        returnValue=${method.returnType.simpleName}(
                        id=${book.id}, 
                        title=${book.title}, 
                        author=${book.author}, 
                        releaseDate=${book.releaseDate.format(DateTimeFormatter.ISO_DATE)}, 
                        rentalInfo=null
                        )
                    """.trimIndent().replace("\n", "")
                )
            assertThat(logMessages[5])
                .startsWith("End:")
                .contains(method.returnType.simpleName)
                .contains(method.name)
                .endsWith("accountId=${userDetails.id}")
            assertThat(logMessages[6])
                .startsWith("End Proceed:")
                .contains(method.returnType.simpleName)
                .contains(method.name)
                .endsWith("accountId=${userDetails.id}")
        }.assertAll()
    }

    @Test
    @DisplayName("例外が投げられたらログレベルErrorのログを出力する")
    fun afterThrowingLog() {

        // Given
        val bookId: Long = 824
        val reason = "存在しない書籍: $bookId"
        whenever(customeService.getDetail(any() as Long)).thenThrow(IllegalArgumentException(reason))

        // When
        assertThrows<ResponseStatusException> {
            proxy.getDetail(bookId)
        }

        // Then
        verify(mockAppender, times(6)).append(logMessageCaptor.capture())
        assertThat(logMessageCaptor.allValues.count { it.level == Level.ERROR }).isEqualTo(1)

        val errorLog = logMessageCaptor.allValues.first { it.level == Level.ERROR }
        assertThat(errorLog.message.formattedMessage)
            .startsWith("Exception: ")
            .endsWith("message=${BAD_REQUEST.value()} ${BAD_REQUEST.name} \"$reason\"")
    }
}

ポイント

テストコードの上から、ポイントとなる部分をメモしておく

Controllerクラスを実行するための準備

今回のAOP処理（ロギング）は、Controllerクラスが処理を行うと呼び出されるため、テストではControllerクラスを実行する必要がある。
このためControllerクラス自身のテストを行うような準備やMockBeanが必要だった。

// Controllerクラスに対するログ出力なのでWebMvcTestとMockUserを付ける
@WebMvcTest(controllers = [BookController::class])
@WithCustomMockUser
internal class LoggingAdviceTest {

    // Controllerテストに必要なMockBean
    @MockBean
    private lateinit var authenticationService: AuthenticationService

    @MockBean
    private lateinit var bookService: BookService
    ......

ログ出力に必要な認証情報やセッション情報を用意する

出力するログには、ログインユーザーとして認証情報を参照したり、セッションIDを参照しているので、これらも用意しなければならなかった。

認証情報は、@WithCustomeMockUserを利用したカスタムモックユーザーを使った。またテストメソッドでこのユーザーの認証情報を取得したい場合は次のように書けば良い。

val userDetails = SecurityContextHolder.getContext().authentication.principal as CustomeUserDetails

Session情報は、MockHttpServletRequest と MockHttpSession を利用する

@WebMvcTest(controllers = [BookController::class])
@WithCustomMockUser
internal class LoggingAdviceTest {
    ......
    // Session情報を取得するためのMockリクエスト
    private lateinit var request: MockHttpServletRequest
    ......
    @BeforeEach
    internal fun setUp() {
        ......
        // Log出力でセッション情報を出力するためのMock
        val session = MockHttpSession()
        request = MockHttpServletRequest().apply { setSession(session) }
        RequestContextHolder.setRequestAttributes(ServletRequestAttributes(request))
       ......
    }

テストメソッドでセッションIDを参照する場合は、 request.session?.id で取れる。

Adviceクラスを実行させる

このままだとControllerクラスのテストを行うだけなのでログは出力されない。　
そこで ControllerクラスをAspectJProxyFactoryクラス経由で実行させることで、Conrollerクラスの処理をトリガになって、テスト対象のAdviceクラスを実行させることができるようになる。
サンプルコードの場合、次のようにテストを行うと、LogingAdviceクラスで生成したログがコンソールに出力されるようになる。

@WebMvcTest(controllers = [BookController::class])
@WithCustomMockUser
internal class LoggingAdviceTest {
    ......
    // AOP(ログ出力)対象クラス
    private lateinit var proxy: CustomeController
    ......
    @BeforeEach
    internal fun setUp() {

        // Controllerクラスの実行をAspectJProxyFactoryでフィルタリングして、追加したAdviceクラスを実行させる
        val bookController = CustomeController(customeService)
        val factory = AspectJProxyFactory(bookController)
        factory.addAspect(LoggingAdvice())
        proxy = factory.getProxy()
        ......
    }

　　　　　　　　@Test
    fun `logging when there is return value then logging`() {

        // Given
        ......

        // When
        proxy.getDetail(book.id)

        // Then
        ......
}

出力されるログをテストコードで取得し検証する

ログをコンソールに出力しただけでは、テストコードで出力内容が検証できない。
そこでログの出力先となるAppenderに、テストコード上でハンドリングできるモックを追加させて対応する。

@WebMvcTest(controllers = [BookController::class])
@WithCustomMockUser
internal class LoggingAdviceTest {
    ......
    // 検査用のログ出力先となるAppender
    private lateinit var mockAppender: Appender
    // 出力したログを保持する
    @Captor
    private lateinit var logMessageCaptor: ArgumentCaptor<LogEvent>
    ......
    @BeforeEach
    internal fun setUp() {
        ......
        // AOPで出力するログを検査するためのAppenderモックを設定
        mockAppender = mock()
        reset(mockAppender)
        whenever(mockAppender.name).thenReturn("MockAppender")
        whenever(mockAppender.isStarted).thenReturn(true)
        whenever(mockAppender.isStopped).thenReturn(false)

        // AppenderモックをLog出力設定に追加
        val ctx = LoggerContext.getContext(false)
        ctx.configuration.addAppender(mockAppender)
        ctx.configuration.getLoggerConfig(LogManager.ROOT_LOGGER_NAME).apply {
            level = Level.INFO
            addAppender(mockAppender, Level.INFO, null)
        }
        ctx.updateLoggers()

    }

　　　　　　　　@Test
    fun `logging when there is return value then logging`() {

        // Given
        ......

        // When
        proxy.getDetail(book.id)

        // Then
        verify(mockAppender, times(7)).append(logMessageCaptor.capture())

        // 出力されるログのメッセージを順番に文字列で取得しておく
        val logMessages = logMessageCaptor.allValues.map { it.message.formattedMessage }
        ......
}

MockAppenderの追加設定

setUp()メソッドでは、まずAppenderのモックオブジェクトを作成して、log4j2のロギング設定に追加している。
これを設定ファイルで説明する次のようなイメージになり、元々あったConsoleAppenderに定義した"MockAppender"を追加している。

log4j2-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout
                    pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight{%-5level}[%style{%t}{bright,blue}] %style{%C}{bright,yellow}: %m%n"/>
        </Console>
        <Mock name="MockAppender"/>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="MockAppender"/>
        </Root>
    </Loggers>
</configuration>

MockAppenderからログを取得する

前述までMockAppenderでログを出力できるようになったので、最後にこのログをテストコードで取得する。
これは　MockAppenderが出力（append）した時の引数LogEventを捕捉するオブジェクトArgumentCaptor<LogEvent>を利用することで実現する。

下記のように MockAppender(mockオブジェクト)のappend()メソッドの引数に、ArgumentCaptor<LogEvent>.capture() をセットすることでLogEventを扱うことが出来るようになる。
verify(mockAppender, times(7)).append(logMessageCaptor.capture())

今回のテストケースだとログが７行出力、つまり7回appendされるので、それらをキャプチャーした結果を順番に検証する形でログの内容をテストした。

尚、verify(mock, times()).append(logMessageCaptor.capture())を実行しないと、logMessageCaptorに結果が取得されないので、verify()で実行回数の検証が不要だったとしても実行した方が良い。　今のところ他の方法が分からなかったので。

追加したAppenderの設定は　テストごとに削除すること

ここまでのテストを複数回連続で行おうとすると、2回目以降でappendしたログがキャプチャーできずにエラーとなって失敗する。

原因は、setUp()メソッドで、毎回同じ　MockAppenderをセットしていたためだったので、tearDown()メソッドでテストの度に設定を削除すること。

    @AfterEach
    internal fun tearDown() {
        // Appenderモックを除去する
        val ctx = LoggerContext.getContext(false)
        ctx.configuration.loggers.values.forEach { it.removeAppender(mockAppender.name) }
        ctx.configuration.rootLogger.removeAppender(mockAppender.name)
    }

感想

AOPおよびロギングのユニットテストも書けた。　内容的にユニットテストと呼んでいいかは微妙だが、この”テストクラスを単独で検証”することは出来るので、いいかなとは思う。

ここ最近書いたテストコードの記事と合わせて、これでサンプルコード全体のテストカバレッジが取れるようになったので、SpringMVCの基本的なユニットテストはカバー出来たかなと思う。

3
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
3
2