TraceLoggingInterceptor implements HandlerInterceptor { @Override public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) { if (!(handler instanceof HandlerMethod)) { return; } long startTime = 0; if (request.getAttribute(START_ATTR) != null) { startTime = ((Long) request.getAttribute(START_ATTR)).longValue(); } long handlingTime = System.nanoTime() - startTime; request.removeAttribute(START_ATTR); request.setAttribute(HANDLING_ATTR, handlingTime); String formattedHandlingTime = String.format("%1$,3d", handlingTime); boolean isWarnHandling = handlingTime > warnHandlingNanos; if (!isEnabledLogLevel(isWarnHandling)) { return; } HandlerMethod handlerMethod = (HandlerMethod) handler; Method m = handlerMethod.getMethod(); Object view = null; Map<String, Object> model = null; if (modelAndView != null) { view = modelAndView.getView(); model = modelAndView.getModel(); if (view == null) { view = modelAndView.getViewName(); } } logger.trace("[END CONTROLLER ] {}.{}({})-> view={}, model={}", new Object[] { m.getDeclaringClass().getSimpleName(), m .getName(), buildMethodParams(handlerMethod), view, model }); String handlingTimeMessage = "[HANDLING TIME ] {}.{}({})-> {} ns"; if (isWarnHandling) { logger.warn(handlingTimeMessage + " > {}", new Object[] { m .getDeclaringClass().getSimpleName(), m.getName(), buildMethodParams(handlerMethod), formattedHandlingTime, warnHandlingNanos }); } else { logger.trace(handlingTimeMessage, new Object[] { m .getDeclaringClass().getSimpleName(), m.getName(), buildMethodParams(handlerMethod), formattedHandlingTime }); } }  @Override boolean preHandle(HttpServletRequest request,
            HttpServletResponse response, Object handler); @Override void postHandle(HttpServletRequest request,
            HttpServletResponse response, Object handler,
            ModelAndView modelAndView); void setWarnHandlingNanos(long warnHandlingNanos);  }
@Test public void testPostHandle_NormalLogOutput() throws Exception { HandlerMethod paramHandler = new HandlerMethod(controller, TraceLoggingInterceptorController.class .getMethod("createForm")); long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } String logMessage1 = jdbcTemplate.queryForObject( "SELECT FORMATTED_MESSAGE FROM LOGGING_EVENT WHERE EVENT_ID=:id", Collections.singletonMap("id", 1), String.class); String logMessage2 = jdbcTemplate.queryForObject( "SELECT FORMATTED_MESSAGE FROM LOGGING_EVENT WHERE EVENT_ID=:id", Collections.singletonMap("id", 2), String.class); assertThat(logMessage1, is( "[END CONTROLLER ] TraceLoggingInterceptorController.createForm()-> view=null, model={}")); assertThat(logMessage2.startsWith( "[HANDLING TIME ] TraceLoggingInterceptorController.createForm()->"), is(true)); }
@Ignore @Test public void testPostHandle_NormalLogOutput_ViewNotNull() { long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); HandlerMethod paramHandler = new HandlerMethod(controller, method[3]); View view = mock(View.class); when(model.getView()).thenReturn(view); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } String expectedLogStr = "TraceLoggingInterceptorController.second(SampleForm,Model)->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.TRACE), 2); }
@Ignore @Test public void testPostHandle_NormalLogOutput_ModelNull() { long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); HandlerMethod paramHandler = new HandlerMethod(controller, method[0]); try { interceptor.postHandle(request, response, paramHandler, null); } catch (Exception e) { fail("illegal case"); } String expectedLogStr = "TraceLoggingInterceptorController.createForm()->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.TRACE), 2); }
@Ignore @Test public void testPostHandle_NotStarted() { HandlerMethod paramHandler = new HandlerMethod(controller, method[0]); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } String expectedLogStr = "TraceLoggingInterceptorController.createForm()->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.TRACE), 1); }
@Test public void testPostHandle_NotHandler() { Object paramHandler = new Object(); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } final String expectedLogStr = "TraceLoggingInterceptorController.createForm()->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.TRACE), 0); }
@Ignore @Test public void testPostHandle_NotHandler_Normal() { long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); Object paramHandler = new Object(); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } String expectedLogStr = "[HANDLING TIME ]->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.TRACE), 1); }
@Test public void testPostHandleNullStartAttr() throws Exception { HandlerMethod paramHandler = new HandlerMethod(controller, TraceLoggingInterceptorController.class .getMethod("createForm")); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", null); try { interceptor.postHandle(request, response, paramHandler, null); } catch (Exception e) { fail("illegal case"); } String expectedLogStr = "[HANDLING TIME ] TraceLoggingInterceptorController.createForm()->"; verifyLogging(expectedLogStr, ImmutableList.of(Level.WARN), 1); }
@Test public void testIsEnabledLogLevelIsWarnEnabledFalse() throws Exception { LogLevelChangeUtil.setLogLevel(LogLevelChangeUtil.LogLevel.INFO); HandlerMethod paramHandler = new HandlerMethod(controller, TraceLoggingInterceptorController.class .getMethod("createForm")); long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } assertThat(logger.isDebugEnabled(), is(false)); LogLevelChangeUtil.resetLogLevel(); }
@Test public void testIsEnabledLogLevelIsTraceEnabledFalse() throws Exception { LogLevelChangeUtil.setLogLevel(LogLevelChangeUtil.LogLevel.INFO); HandlerMethod paramHandler = new HandlerMethod(controller, TraceLoggingInterceptorController.class .getMethod("createForm")); long startTime = System.nanoTime(); request.setAttribute(TraceLoggingInterceptor.class.getName() + ".startTime", startTime); try { interceptor.postHandle(request, response, paramHandler, model); } catch (Exception e) { fail("illegal case"); } assertThat(logger.isDebugEnabled(), is(false)); LogLevelChangeUtil.resetLogLevel(); }