聊聊日志打印与日志审计

柏炎

发布于 2022-08-23 14:22:18

2.3K0

发布于 2022-08-23 14:22:18

文章被收录于专栏：深入浅出java后端深入浅出java后端

一.前言

hello,everyone.

日志对于我们日常排查bug，记录用户执行记录，审计等都是至关重要的。本文将给大家介绍一下博主开发的，在日常工作中会用到的日志切面与日志审计组件。

二.日志切面

springboot中默认提供的日志打印功能无法打印函数的入参与出参信息。现在如果有个bug在生产环境可以复现，测试环境怎么也复现不了，本地代码又无法连接生产环境进行调试。生产环境一般一般情况下指挥打印info级别的日志。这个时候就头疼了，无法定位解决问题。

因此线上环境能有一个功能帮我们打印函数的详细的入参或者出参这个功能是很重要的。当然这个功能默认情况下还是不要开启，毕竟大多数线上环境的调用链封装比较深，出参与入参信息打印会比较多，对于日志的存储会是一个比较大的问题。这里可以选择在在xml中配置日志每天保存一份归档，保存至多7天或者30天【根据业务场景自己配置】。

2.1.源码及说明

/**
 * 详细日志切面
 *
 * 【默认情况下建议不要开启，开发测试定位问题的时候可以打开，打开就变成了硬盘的事儿都不叫事儿，爆炸打印】
 * @author baiyan
 * @date 2021/07/07
 */
@Aspect
@Component
@Order(10)
@Slf4j(topic = "DetailAppender")
@Lazy
@ConditionalOnProperty(value = "baiyan.detail.log.enable", havingValue = "true")
public class LogDetailAspect implements CommandLineRunner{
        
        //是否启动表示
    private static boolean started = false;

        //日志打印忽略
    private static final String[] ignoreUrl = {};

        //出参忽略打印类型
    private static final Class<?>[] excludeReturnClass;
    
    //不进行日志打印的类
    private static final Class<?>[] excludeClass;
        
        //序列化工具类，我习惯使用gson，大家可以自由选择自己熟悉的序列化工具
    private static final Gson gson = new GsonBuilder().setExclusionStrategies(new LogExclusionStrategy()).create();

        //初始化不进行日志打印的类，根据业务场景自由配置
    static {
        excludeReturnClass = new Class[]{ServletRequest.class, ServletResponse.class, InputStreamSource.class, File.class};
        excludeClass = new Class[]{HandlerInterceptor.class,Filter.class,InputStream.class};
    }

    @Override
    public void run(String... args) throws Exception {
        started = true;
    }

        //web层日志打印
    @Around("execution(* com.baiayn..*.*(..)) &amp;&amp; @within(org.springframework.web.bind.annotation.RequestMapping)")
    public Object aroundController(ProceedingJoinPoint pjp) throws Throwable {
        return doAround(pjp, true, true);
    }

        //service层日志打印
    @Around("(execution(* com.baiyan..*.*(..)) &amp;&amp; @within(org.springframework.stereotype.Service) || @within(org.springframework.stereotype.Component))")
    public Object aroundService(ProceedingJoinPoint pjp) throws Throwable {
        return doAround(pjp, true, false);
    }

        //mapper层日志打印
    @Around("execution(* com.baiyan.service.mapper.*.*(..))")
    public Object aroundMapper(ProceedingJoinPoint pjp) throws Throwable {
        return doAround(pjp, false, false);
    }

    private static final String NULL_STR = "null";
    private static final String IN_LOG_FORMAT = "in: {}#{} - [{}]";
    private static final String OUT_LOG_FORMAT = "out: {}#{} - [{}] - {}ms";

        /**
     * 环绕通知
     * @param pjp
     * @param logOut 是否打印日志
     * @param logException 是否抛出异常
     * @return
     * @throws Throwable
     */
    private Object doAround(ProceedingJoinPoint pjp, boolean logOut, boolean logException) throws Throwable {
        /** 不需要打印日志 */
        if (!started || isIgnore()) {
            return pjp.proceed();
        }

        MethodSignature signature = (MethodSignature) pjp.getSignature();
        Class<?> declaringClass = signature.getMethod().getDeclaringClass();
        if (inExcludeClass(declaringClass)) {
            return pjp.proceed();
        }

        long start = System.currentTimeMillis();
        String className = declaringClass.getSimpleName();
        String method = signature.getMethod().getName();
        String in = logInParams(pjp.getArgs());
        log.info(IN_LOG_FORMAT, className, method, in);
        Object result = null;
        Throwable error = null;
        try {
            result = pjp.proceed();
            return result;
        } catch (Throwable t) {
            error = logException ? t : null;
            throw t;
        } finally {
            String out;
            if (!logOut) {
                out = "";
            } else if (error != null) {
                out = Throwables.getStackTraceAsString(error);
            } else {
                out = processResult(result);
            }
            log.info(OUT_LOG_FORMAT, className, method, out, System.currentTimeMillis() - start);
        }
    }

    private boolean inExcludeClass(Class<?> clazz) {
        return Arrays.stream(excludeClass)
                .anyMatch(c -> c.isAssignableFrom(clazz));

    }

    private String logInParams(Object[] args) {
        if (args == null || args.length == 0) {
            return NULL_STR;
        }
        return Stream.of(args)
                .filter(this::filterClass)
                .map(s -> {
                        //此处可以自行定义不同入参类型返回的日志结果输出
                    if (s == null) {
                        return NULL_STR;
                    }
                    return tryLog(s);
                }).collect(Collectors.joining(", "));
    }

    private String processResult(Object result) {
        String out = "";
        //自定义出参结果打印，可以只打印参数中某个属性
        if (result == null) {
            out = NULL_STR;
        } else if (filterClass(result)) {
            out = tryLog(result);
        }
        return out;
    }

    private String tryLog(Object obj) {
        try {
            return gson.toJson(obj);
        } catch (Exception e) {
            log.error("日志打印失败", e);
            return "";
        }
    }

    private boolean isIgnore() {
        String url = "";
        return Arrays.asList(ignoreUrl).contains(url);
    }

    @SuppressWarnings("unchecked")
    private boolean filterClass(Object obj) {
        if (obj == null) {
            return true;
        }
        return Arrays.stream(excludeReturnClass).noneMatch(e -> e.isAssignableFrom(obj.getClass()));
    }

    private static class LogExclusionStrategy implements ExclusionStrategy {

        @Override
        public boolean shouldSkipField(FieldAttributes fieldAttributes) {
            String fieldName = fieldAttributes.getName();
            return isFieldInSuperclass(fieldAttributes.getDeclaringClass(), fieldName);
        }

        @Override
        public boolean shouldSkipClass(Class<?> aClass) {
            return Arrays.asList(excludeReturnClass).contains(aClass);
        }

        private boolean isFieldInSuperclass(Class<?> clazz, String fieldName) {
            Class<?> superclass = clazz.getSuperclass();
            Field field;
            while (superclass != null) {
                field = getField(superclass, fieldName);
                if (field != null) {
                    return true;
                }
                superclass = superclass.getSuperclass();
            }
            return false;
        }

        private Field getField(Class<?> clazz, String fieldName) {
            try {
                return clazz.getDeclaredField(fieldName);
            } catch (NoSuchFieldException e) {
                return null;
            }
        }
    }
}

2.2.修改logback-spring.xml

增加配置

<!--    模块自己定义的日志打印-->
<include resource="baiyan-detail-logback.xml" />

与logback-spring.xml新建同级文件baiyan-detail-logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <appender name="DETAIL_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/detail.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/history-detail/detail.%d{yyyy-MM-dd}.gz</fileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>
        <encoder charset="UTF-8">
            <pattern>${PATTERN}</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
        </filter>
    </appender>

    <appender name="ASYNC_DETAIL_FILE" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <appender-ref ref="DETAIL_FILE" />
    </appender>

    <logger name="DetailAppender" additivity="false" level="INFO">
        <appender-ref ref="ASYNC_DETAIL_FILE" />
    </logger>

</included>

2.3.配置

默认情况日志切面不被加载，配置文件中配置baiyan.detail.log.enable=true开启配置

三.日志审计starter开发

开发政企或者金融相关的TOB的系统功能中常常有一个模块是日志审计，用于记录外部请求当前系统请求的日志。市面上常见的日志审计分析大数据量时就是ELK，数据量较少的情况下就是基于自定义方法注解与切面形式记录。

从DDD分层角度来看，任何可能作为外部输入的请求被视为用户交互层，因此controller层，rpc层，mq层均认为是用户交互层。拦截到输入的参数并进行解析，存储到kafka中。logstash拉取kafka上的日志信息存储至es中。到这一步日志数据链路已经打通了。那对于日志数据如何进行解析有两种方式，一种是利用kibana上面默认提供的一些报表功能，另外一种就是需要集成在当前应用系统内的报表数据展示，做二次业务应用开发。

本文将针对最复杂的拦截web请求封装成kafka消息作为示例介绍一下思路，并说一下博主在开发过程中遇到的坑。

3.1.定义拦截器解析请求

/**
 * 请求数据埋点拦截器
 * @author baiyan
 * @date 2021/07/07
 */
@Component
@Slf4j
public class OperatorInterceptor extends HandlerInterceptorAdapter {
    @Autowired
    OperatorLogMessageSender operatorLogMessageSender;

    @Value("${spring.application.name}")
    private String applicationName;

    /**
     * 操作日志中需要过滤的请求方式，枚举项为：GET,POST,PUT,DELETE  过滤多个中间使用英文逗号间隔，单词均需要大写
     */
    @Value("${operator.log.filter:}")
    private String operatorLogFilter;

    /**
     * 日志拦截处理，由于HttpServletRequest接口无法被序列化，且为线程不安全。
     * 如果将解析动作与发消息动作都放置在线程池中，可能会出现，拦截器还没有解析完成，
     * 业务处理已经将HttpServletRequest内部的Map数据清空，无法获取到值、
     * 因此这里解析参数的动作必须要做同步，发消息做线程池异步处理，
     * 防止RabbitMQ挂掉的时候影响到实际的业务逻辑处理
     *
     * @param httpServletRequest
     * @param httpServletResponse
     * @param handler
     * @return
     */
    @Override
    public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object handler) {

        if(!this.checkFilterRequest(httpServletRequest)){

            RequestWrapper requestWrapper = new RequestWrapper(httpServletRequest);
            OperatorLogDTO operatorLogDTO = new OperatorLogDTO();
            this.setBaseInfo(requestWrapper,operatorLogDTO,handler);
            operatorLogDTO.setBodyParams(requestWrapper.getBody());

            OperatorLogThreadPool.getBlockThreadPool().addTask(
                    ()-> operatorLogMessageSender.sendAddMessage(operatorLogDTO)
            );
        }
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object handler, ModelAndView modelAndView) throws Exception {
    }

    @Override
    public void afterCompletion(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object handler, Exception e) throws Exception {
    }

    /**
     * 设置基础信息
     * @param httpServletRequest
     * @param operatorLogDTO
     * @param handler
     */
    private void setBaseInfo(HttpServletRequest httpServletRequest , OperatorLogDTO operatorLogDTO , Object handler) {
        //设置token用于获取用户数据
        operatorLogDTO.setToken(AuthorizationUtil.getToken(httpServletRequest));
        //设置url 与 参数
        try {
            operatorLogDTO.setUrl(URLDecoder.decode(httpServletRequest.getRequestURL().toString(),"UTF-8"));
            if(StringUtils.isNotBlank(httpServletRequest.getQueryString())){
                operatorLogDTO.setUrlParams(URLDecoder.decode(httpServletRequest.getQueryString(),"UTF-8"));
            }
        } catch (UnsupportedEncodingException unSupport) {
            log.error("url格式错误：{}",unSupport.getMessage());
        } catch (Exception ex){
            log.error("日志拦截url解析出现错误：{}",ex.getMessage());
        }
        operatorLogDTO.setRequestHeaders(getHeadNames(httpServletRequest));
        operatorLogDTO.setRequestMethod(httpServletRequest.getMethod());
        operatorLogDTO.setApplicationName(this.applicationName);
        // 根据swagger上的请求描述增加事件
        if (handler instanceof HandlerMethod) {
            operatorLogDTO.setEvent(this.getMethodDesc(handler));
        }
        operatorLogDTO.setIp(HttpRequestUtil.getIpAddr(httpServletRequest));

    }

    /**
     * 获取请求头信息
     * @param httpServletRequest
     * @return
     */
    private String getHeadNames(HttpServletRequest httpServletRequest){
        Enumeration headNames = httpServletRequest.getHeaderNames();
        Map map = new HashMap(16);
        while (headNames.hasMoreElements()){
            String name = headNames.nextElement().toString();
            String header = httpServletRequest.getHeader(name);
            map.put(name,header);
        }
        return map.toString();
    }

    /**
     * 获取请求方法的描述
     * @param handler
     * @return
     */
    private String getMethodDesc(Object handler){
        HandlerMethod handlerMethod = (HandlerMethod) handler;
        Method method = handlerMethod.getMethod();
        ApiOperation apiOperation = AuthorizationUtil.findAnnotation(method, ApiOperation.class);
        return apiOperation !=null ? apiOperation.value() : null;
    }

    /**
     * 校验请求方式是否过滤，此处直接使用url是否相等，可以使用spring的表达式配置，去支持/**这种批量过滤
     * @param httpServletRequest
     * @return true为需要过滤，false为不需过滤
     */
    private Boolean checkFilterRequest(HttpServletRequest httpServletRequest){
        String method = httpServletRequest.getMethod();
        if(StringUtils.isBlank(method) || StringUtils.isBlank(this.operatorLogFilter)){
            return false;
        }
        return Stream.of(this.operatorLogFilter.split(",")).anyMatch(e->
                Objects.equals(method.toUpperCase(),e.toUpperCase())
        );
    }

}

说明：

定义拦截器拦截请求，先进行判断当前url是否需要进行过滤。不进行过滤的情况进行解析HttpServletRequest获取请求的参数信息，根据请求头的身份验证信息获取用户信息，如果身份验证失败，也可进行记录，防止恶意攻击，频繁攻击的可以直接封禁ip请求。解析完成将消息发送到kafka。

此处有两个坑点：

坑点1：

HttpServletRequest中获取delete，put，post请求中body中的参数时，由于是根据流获取的，一旦解析获取一次将会把流清空，因此这里需要重新定义一个RequestWrapper进行流的复制，防止实际的业务请求无法获取到正确的参数。

代码见3.2

坑点2：

HttpServletRequest在tomcat中是重复利用的，切不可复制。这个我在最开始开发的时候想用线程池去解析参数，异步解析，不阻碍实际的业务请求。但是后面出现了日志拦截这里无法获取到日志拦截数据，或者日志拦截数据拦截到的参数不是当前请求的情况，切在debug的情况下还是正常的。出现这个情况的原因是HttpServletRequest重复利用，业务请求执行比解析动作要快，解析还没结束，业务请求已经返回将HttpServletRequest置空了，导致解析失败；下一个请求又进来了，导致请求获取到的参数不一致。因此这里在解析参数这一步需要做同步处理，发送kafka消息可以放到线程池中去做。

我是用的线程池，可以参考我的另一篇博客，强烈推荐：我用这个线程池捕获了后端妹子的芳心

3.2.自定义RequestWrapper

/**
 * 获取@RequestBody注解标注的请求体中参数
 * @author baiyan
 * @date 2021/07/07
 */
@Slf4j
public class RequestWrapper extends HttpServletRequestWrapper {
    private final String body;

    /**
     * 此处设计原因为 request.getInputStream()这个方法在spring中一旦被调用，则将会清空内部数据
     * 如果不进行数据复制的动作，将会导致后续业务处理无法获取到post请求中body里面的数据
     * @param request
     */
    public RequestWrapper(HttpServletRequest request) {
        super(request);
        StringBuilder stringBuilder = new StringBuilder();
        BufferedReader bufferedReader = null;
        InputStream inputStream = null;
        try {
            inputStream = request.getInputStream();
            if (inputStream != null) {
                bufferedReader = new BufferedReader(new InputStreamReader(inputStream));
                char[] charBuffer = new char[1024];
                int bytesRead = -1;
                while ((bytesRead = bufferedReader.read(charBuffer)) > 0) {
                    stringBuilder.append(charBuffer, 0, bytesRead);
                }
            }
        } catch (Exception ex) {
            log.error("获取接口请求体异常：{}",ex.getMessage());
        } finally {
            IOUtils.closeQuietly(inputStream);
            IOUtils.closeQuietly(bufferedReader);
        }
        body = stringBuilder.toString();
    }

    @Override
    public ServletInputStream getInputStream() {
        final ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(body.getBytes());
        ServletInputStream servletInputStream = new ServletInputStream() {
            @Override
            public boolean isFinished() {
                return false;
            }
            @Override
            public boolean isReady() {
                return false;
            }
            @Override
            public void setReadListener(ReadListener readListener) {
            }
            @Override
            public int read(){
                return byteArrayInputStream.read();
            }
        };
        return servletInputStream;

    }

    @Override
    public BufferedReader getReader() {
        return new BufferedReader(new InputStreamReader(this.getInputStream()));
    }

    public String getBody() {
        return this.body;
    }

}

拦截器拦截复制RequestWrapper

/**
 * 过滤器传递request
 * @author baiyan
 * @date 2021/07/07
 */
@Component
@WebFilter(urlPatterns = "/*",filterName = "operatorFilter")
public class OperatorFilter implements Filter {

    @Override
    public void init(FilterConfig filterConfig) {

    }

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        ServletRequest requestWrapper = null;
        if(servletRequest instanceof HttpServletRequest) {
            requestWrapper = new RequestWrapper((HttpServletRequest) servletRequest);
        }
        if(requestWrapper == null) {
            filterChain.doFilter(servletRequest, servletResponse);
        } else {
            filterChain.doFilter(requestWrapper, servletResponse);
        }
    }

    @Override
    public void destroy() {

    }
}

3.3.配置

3.3.1.webmvc配置

/**
 * 操作日志webMvcConfig
 
 * @author baiyan
 * @date 2021/07/07
 */
@Configuration
public class OperatorLogWebMvcConfig implements WebMvcConfigurer {

    @Autowired
    private OperatorInterceptor operatorInterceptor;

    @Autowired
    private UrlProperties urlProperties;

    /**
     * 添加拦截器
     */
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        InterceptorRegistration interceptorRegistration = registry.addInterceptor(operatorInterceptor);
        if(!Objects.isNull(urlProperties.getUrlArray())){
            interceptorRegistration.excludePathPatterns(urlProperties.getUrlArray());
        }
    }
}

3.3.2.过滤的url配置

/**
 * 用户日志白名单记录，多个url使用逗号间隔
 * @author baiyan
 * @date 2021/07/07
 */
@Data
@Configuration
@ConfigurationProperties("operator.log")
@RefreshScope
public class UrlProperties {

    private String filterUrl;

    public String[] getUrlArray(){
        return StringUtils.isBlank(this.filterUrl) ? null : filterUrl.split(",");
    }

}

3.3.3.自动配置

配置resources/META-INF/spring.factories

org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
  com.baiyan.operatorlog.interceptor.OperatorFilter,\
  com.baiyan.operatorlog.interceptor.OperatorInterceptor,\
  com.baiyan.operatorlog.configuration.UrlProperties,\
  com.baiyan.operatorlog.configuration.OperatorLogWebMvcConfig

3.4.kafka消息实体

/**
 * @author baiyan
 * @date 2021/07/07
 */
@Data
@Builder
@NoArgsConstructor
@AllArgsConstructor
public class OperatorLogDTO {

    /** 用户id */
    private Long userId;

    /** 用户名 */
    private String userName;

    /** 真实姓名 */
    private String realName;

    /** 请求链接 */
    private String url;

    /** 手机号 */
    private String mobilePhone;

    /** 请求所在应用名称 */
    private String applicationName;

    /** 请求头 */
    private String requestHeaders;

    /** 请求方式 */
    private String requestMethod;

    /** 链接请求参数 */
    private String urlParams;

    /** 请求体参数 */
    private String bodyParams;

    /** 时间 */
    private String event;

    /** ip */
    private String ip;

    /** token */
    private String token;

}