实战:第四章:java后端日志埋点实现

前段时间架构让我弄日志埋点,因为其他工作不断延期,而且到现在也没给明确的需求,这里自己手写一套简单的日志埋点:

第一步:引入依赖

    <!--aop-->
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-aop</artifactId>
    </dependency>
     
    <!--log4j-->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.3</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>1.7.25</version>
    </dependency>

第二步:因为公司有自己的日志配置,这里我简单配置一条凑合用就行,在application.properties配置:

    #日志文件路径 默认生成文件名:spring.log 为了简单便于学习这里我使用默认的
    logging.path=F:/Log4j

第三步:自定义注解:

    package com.javaliao.portal.annotations;
     
    import org.springframework.web.bind.annotation.ResponseBody;
    import java.lang.annotation.*;
     
    /**
     *  app controller 统一包装注解类
     */
    @Target({ElementType.PARAMETER, ElementType.METHOD})//作用在参数和方法上
    @Retention(RetentionPolicy.RUNTIME)//运行时注解
    @Documented//表明这个注解应该被 javadoc工具记录
    @ResponseBody//响应时转JSON格式
    public @interface AppController {
     
        /**
         * 业务描述
         * @return
         */
        String description() default "";
        
        /**
         * 是否打日志 默认打
         */
        boolean isLog() default true;
    }

第四步:拦截用户请求

    package com.javaliao.portal.aspect;
     
    import com.alibaba.fastjson.JSON;
    import com.javaliao.portal.annotations.AppController;
    import com.javaliao.portal.common.CommonResult;
    import com.javaliao.portal.model.TbLogVisit;
    import com.javaliao.portal.service.ActionService;
    import com.javaliao.portal.util.CollectionHelp;
    import com.javaliao.portal.util.TimeUtils;
    import org.aspectj.lang.JoinPoint;
    import org.aspectj.lang.ProceedingJoinPoint;
    import org.aspectj.lang.annotation.*;
    import org.aspectj.lang.reflect.MethodSignature;
    import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;
    import org.springframework.stereotype.Component;
    import org.springframework.web.context.request.RequestContextHolder;
    import org.springframework.web.context.request.ServletRequestAttributes;
    import javax.annotation.Resource;
    import javax.servlet.http.HttpServletRequest;
    import javax.servlet.http.HttpSession;
    import java.lang.reflect.Method;
    import java.net.InetAddress;
    import java.util.*;
    import java.util.concurrent.atomic.AtomicLong;
     
    @Component
    @Aspect
    @SuppressWarnings("all") //@SuppressWarnings("all")抑制所有警告.@SuppressWarnings注解主要用在取消一些编译器产生的警告对代码左侧行列的遮挡,有时候这会挡住我们断点调试时打的断点
    public class AppControllerAspect {
     
        //注入Service用于把日志保存数据库,实际项目入库采用队列做异步
        @Resource
        private ActionService actionService;
        //日志工厂获取日志对象
        static Logger logger = LoggerFactory.getLogger(AppControllerAspect.class);
     
        /**
         * ThreadLocal多线程环境下,创建多个副本,各自执行,互不干扰
         */
     
        //startTime存放开始时间
        ThreadLocal<Map<String, Long >> startTime = new ThreadLocal<>();
        //count存放方法被调用的次数O 使用volatile利用它的三大特性:保证可见性(遵守JMM的可见性),不保证原子性,禁止指令重排
        volatile ThreadLocal<Map<String, Long>> count = new ThreadLocal<>();
        //timeConsuming存放方法总耗时
        ThreadLocal<Map<String, Long >> timeConsuming = new ThreadLocal<>();
        //fromType存放渠道
        ThreadLocal<Map<String, String >> fromType = new ThreadLocal<>();
        //tbLogVisit日志访问对象
        ThreadLocal<TbLogVisit> tbLogVisit = new ThreadLocal<>();
     
        //Controller层切点
        @Pointcut("@annotation(com.javaliao.portal.annotations.AppController)")
        public void controllerAspectse() {
        }
     
        //前置通知  用于拦截Controller层记录用户的操作
        @Before("controllerAspectse()")
        public void before(JoinPoint pjp) {
            //初始化
            TbLogVisit tbLogVisit = this.tbLogVisit.get();
            tbLogVisit = new TbLogVisit();
            Map<String, Long> countMap = this.count.get();
            countMap = new HashMap<>();
            this.count.set(countMap);
            Map<String, Long> timeConsumingMap = this.timeConsuming.get();
            timeConsumingMap = new HashMap<>();
            this.timeConsuming.set(timeConsumingMap);
            Map<String, String> fromTypeMap = this.fromType.get();
            fromTypeMap = new HashMap<>();
            this.fromType.set(fromTypeMap);
            Map<String, Long> map = new HashMap<>();
            map.put("startTime",System.currentTimeMillis());
            this.startTime.set(map);
            logger.info("==============前置通知开始:记录用户的操作==============");
            String currentTime = TimeUtils.getCurrentTime("YYYY-MM-dd HH:mm:ss");
            logger.info("请求开始时间:" + currentTime);
            tbLogVisit.setVisitStartTime(new Date());
            String resultString = "";
            // 是否打日志 默认打
            boolean isLog = true;
            try {
                MethodSignature signature = (MethodSignature) pjp.getSignature();
                AppController appController = signature.getMethod().getAnnotation(AppController.class);
                //是否开启日志打印
                isLog = appController.isLog();
                if(isLog){
                    //开始打印日志
                    HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();
                    HttpSession session = request.getSession();
                    String api = pjp.getTarget().getClass().getName() + "." + pjp.getSignature().getName();
                    logger.info("请求API:" + api);
                    tbLogVisit.setVisitApi(api);
     
                    String methodDescription = getControllerMethodDescription(pjp);
                    logger.info("方法描述:" + methodDescription);
                    tbLogVisit.setVisitDescription(methodDescription);
     
                    String ipAddress = InetAddress.getLocalHost().toString().substring(InetAddress.getLocalHost().toString().lastIndexOf("/") + 1);
                    logger.info("请求ip:"+ ipAddress);
                    tbLogVisit.setVisitIpAddress(ipAddress);
     
                    String hostName = InetAddress.getLocalHost().getHostName();
                    logger.info("机器名:" + hostName);
                    tbLogVisit.setVisitHostName(hostName);
     
                    Enumeration<?> enu = request.getParameterNames();
                    String params = "{";
                    while (enu.hasMoreElements()) {
                        String paraName = (String) enu.nextElement();
                        params += "\"" + paraName + "\":\"" + request.getParameter(paraName) + "\",";
                    }
                    String methodParams = params + "}";
                    String substring = methodParams.substring(0, methodParams.length() - 2);
                    substring = substring + "}";
                    logger.info("方法参数:" + substring);
                    tbLogVisit.setVisitParams(substring);
     
                    StringBuffer url = request.getRequestURL();
                    logger.info("URL:" + url);
                    tbLogVisit.setVisitUrl(String.valueOf(url));
                }
            } catch (Exception e) {
                StackTraceElement stackTraceElement2 = e.getStackTrace()[2];
                String reason = "异常:【"+
                        "类名:"+stackTraceElement2.getClassName()+";"+
                        "文件:"+stackTraceElement2.getFileName()+";"+"行:"+
                        stackTraceElement2.getLineNumber()+";"+"方法:"
                        +stackTraceElement2.getMethodName() + "】";
                //记录本地异常日志
                logger.error("==============前置通知异常:记录访问异常信息==============");
                String message = e.getMessage() + "|" + reason;
                logger.error("异常信息:",message);
                tbLogVisit.setVisitThrowingErro(message);
                tbLogVisit.setVisitResult("请求发生异常,异常信息:" + message);
            }finally {
                this.tbLogVisit.set(tbLogVisit);
            }
        }
     
        @Around("controllerAspectse()")
        public Object around(ProceedingJoinPoint pjp)throws Throwable {
            String result = JSON.toJSONString(pjp.proceed());
            logger.info("请求结果:" + result);
            TbLogVisit tbLogVisit = this.tbLogVisit.get();
            tbLogVisit.setVisitResult(result);
            this.tbLogVisit.set(tbLogVisit);
            return CommonResult.success("");
        }
     
     
        /**
         * 对Controller下面的方法执行后进行切入,统计方法执行的次数和耗时情况
         *  注意,这里的执行方法统计的数据不止包含Controller下面的方法,也包括环绕切入的所有方法的统计信息
         * @param jp
         */
     
        @AfterReturning("controllerAspectse()")
        public void afterMehhod(JoinPoint jp) {
            logger.info("==============方法执行完成==============");
            TbLogVisit tbLogVisit = this.tbLogVisit.get();
            try {
                //获取方法名
                String methodName = jp.getSignature().getName();
                //开始统计数量与耗时
                if(count.get().get(methodName) == null){
                    //第一次赋值为0
                    count.get().put(methodName,0L);
                }
                //使用原子整型进行增值
                AtomicLong atomicInteger = new AtomicLong(count.get().get(methodName));
                //加一 这里暂时不解决ABA问题,仅保证原子性 解决了volatile不保证原子性的问题 getAndIncrement()先返回再加1,incrementAndGet()先加1再返回
                long increment = atomicInteger.incrementAndGet();
                //然后增加新值
                count.get().replace(methodName,increment);
                Long end = System.currentTimeMillis();
                Long total =  end - startTime.get().get("startTime");
                logger.info("执行总耗时为:" +total);
                if(timeConsuming.get().containsKey(methodName)){
                    timeConsuming.get().replace(methodName, total);
                }else {
                    timeConsuming.get().put(methodName, (total));
                }
                tbLogVisit = this.tbLogVisit.get();
                tbLogVisit.setVisitTimeConsuming(String.valueOf(total));
                String endTime = TimeUtils.getCurrentTime("YYYY-MM-dd HH:mm:ss");
                logger.info("请求结束时间:" + endTime);
                tbLogVisit.setVisitEndTime(new Date());
                /**
                 * 从原来的map中将最后的连接点方法给移除了,替换成最终的,避免连接点方法多次进行叠加计算,
                 * 由于原来的map受ThreadLocal的保护,这里不支持remove,因此,需要单开一个map进行数据交接
                 */
                //重新new一个map
                Map<String, Long> map = new HashMap<>();
                for(Map.Entry<String, Long> entry:timeConsuming.get().entrySet()){
                    if(entry.getKey().equals(methodName)){
                        map.put(methodName, total);
                    }else{
                        map.put(entry.getKey(), entry.getValue());
                    }
                }
                for (Map.Entry<String, Long> entry :count.get().entrySet()) {
                    for(Map.Entry<String, Long> entry2 :map.entrySet()){
                        if(entry.getKey().equals(entry2.getKey())){
                            Long num = entry.getValue();
                            logger.info("调用次数:" + num);
                            tbLogVisit.setVisitNum(num);
                        }
                    }
                }
                //这里的渠道暂时写死
                Map<String, String> stringMap = fromType.get();
                Map<String, String> fromMap ;
                if(CollectionHelp.isMapNotEmpty(stringMap)){
                    fromMap = stringMap;
                }else {
                    fromMap = new HashMap<>();
                    fromMap.put(methodName,"个人开发电商平台");
                }
                String channel = fromMap.get(methodName);
                logger.info("渠道:" + channel);
                tbLogVisit.setVisitChannel(channel);
            } catch (Exception e) {
                StackTraceElement stackTraceElement2 = e.getStackTrace()[2];
                String reason = "异常:【"+
                        "类名:"+stackTraceElement2.getClassName()+";"+
                        "文件:"+stackTraceElement2.getFileName()+";"+"行:"+
                        stackTraceElement2.getLineNumber()+";"+"方法:"
                        +stackTraceElement2.getMethodName() + "】";
                //记录本地异常日志
                logger.error("==============通知异常:记录访问异常信息==============");
                String message = e.getMessage() + "|" + reason;
                logger.error("异常信息:",message);
                tbLogVisit.setVisitThrowingErro(message);
                tbLogVisit.setVisitResult("请求发生异常!!!");
            } finally {
                this.tbLogVisit.set(tbLogVisit);
                //添加日志信息入库
                actionService.insertLogVisit(this.tbLogVisit.get());
            }
        }
     
     
     
        /**
         * 获取注解中对方法的描述信息 用于Controller层注解
         */
        public static String getControllerMethodDescription(JoinPoint joinPoint) throws Exception {
            String targetName = joinPoint.getTarget().getClass().getName();
            String methodName = joinPoint.getSignature().getName();//目标方法名
            Object[] arguments = joinPoint.getArgs();
            Class targetClass = Class.forName(targetName);
            Method[] methods = targetClass.getMethods();
            String description = "";
            for (Method method:methods) {
                if (method.getName().equals(methodName)){
                    Class[] clazzs = method.getParameterTypes();
                    if (clazzs.length==arguments.length){
                        description = method.getAnnotation(AppController.class).description();
                        break;
                    }
                }
            }
            return description;
        }
     
    }

第五步:业务层发消息:

    package com.javaliao.portal.service.impl;
     
    import com.javaliao.portal.mapper.TbLogVisitMapper;
    import com.javaliao.portal.model.TbLogVisit;
    import com.javaliao.portal.service.ActionService;
    import com.javaliao.portal.util.ActiveMQUtil;
    import net.sf.json.JSONObject;
    import org.apache.activemq.command.ActiveMQMapMessage;
    import org.springframework.beans.factory.annotation.Autowired;
    import org.springframework.stereotype.Service;
    import javax.jms.*;
     
    @Service
    public class ActionServiceImpl implements ActionService {
     
        @Autowired
        TbLogVisitMapper tbLogVisitMapper;
     
        @Autowired
        ActiveMQUtil activeMQUtil;
     
        @Override
        public void insertLogVisit(TbLogVisit tbLogVisit) {
            try {
                // 连接消息服务器
                Connection connection = activeMQUtil.getConnection();
                connection.start();
                //第一个值表示是否使用事务,如果选择true,第二个值相当于选择0
                Session session = connection.createSession(true, Session.SESSION_TRANSACTED);
                // 发送消息
                Queue testqueue = session.createQueue("LOG_VISIT_QUEUE");
                MessageProducer producer = session.createProducer(testqueue);
                MapMessage mapMessage=new ActiveMQMapMessage();
                String toString = JSONObject.fromObject(tbLogVisit).toString();
                mapMessage.setString("tbLogVisit",toString);
                producer.setDeliveryMode(DeliveryMode.PERSISTENT);
                producer.send(mapMessage);
                session.commit();// 事务型消息,必须提交后才生效
                connection.close();
            } catch (JMSException e) {
                e.printStackTrace();
            }
        }
     
    }

第六步:接收消息执行添加业务:

    package com.javaliao.portal.listener;
     
    import com.javaliao.portal.log4j.BaseLogger;
    import com.javaliao.portal.model.TbLogVisit;
    import com.javaliao.portal.service.ActionService;
    import net.sf.json.JSONObject;
    import org.springframework.beans.factory.annotation.Autowired;
    import org.springframework.jms.annotation.JmsListener;
    import org.springframework.stereotype.Component;
    import javax.jms.JMSException;
    import javax.jms.MapMessage;
     
    @Component
    public class LogVisitListener {
     
        @Autowired
        ActionService actionService;
     
        @JmsListener(containerFactory = "jmsQueueListener" ,destination = "LOG_VISIT_QUEUE")
        public void consumeLogResult(MapMessage mapMessage){
            try {
                String object = mapMessage.getString("tbLogVisit");
                JSONObject jsonObject = new JSONObject().fromObject(object);
                TbLogVisit logVisit = (TbLogVisit) JSONObject.toBean(jsonObject, TbLogVisit.class);
                int count = actionService.insertLog(logVisit);
                if(count < 1){
                    BaseLogger.info("日志更新失败");
                }
            } catch (JMSException e) {
                e.printStackTrace();
            }
        }
     
    }

执行业务:

    package com.javaliao.portal.service.impl;
     
    import com.javaliao.portal.mapper.TbLogVisitMapper;
    import com.javaliao.portal.model.TbLogVisit;
    import com.javaliao.portal.model.TbLogVisitExample;
    import com.javaliao.portal.service.ActionService;
    import com.javaliao.portal.util.ActiveMQUtil;
    import com.javaliao.portal.util.CollectionHelp;
    import com.javaliao.portal.util.NumberUtils;
    import net.sf.json.JSONObject;
    import org.apache.activemq.command.ActiveMQMapMessage;
    import org.apache.commons.lang3.StringUtils;
    import org.springframework.beans.factory.annotation.Autowired;
    import org.springframework.stereotype.Service;
    import javax.jms.*;
    import java.util.Date;
    import java.util.List;
     
    @Service
    public class ActionServiceImpl implements ActionService {
     
        @Autowired
        TbLogVisitMapper tbLogVisitMapper;
     
        //这里去掉了之前发消息的代码
        /**
         * 添加日志信息入库
         * @param tbLogVisit
         * @return
         */
        @Override
        public int insertLog(TbLogVisit tbLogVisit) {
            tbLogVisit.setUpdateTime(new Date());
            int count = 0;
            //如果有异常直接添加
            if(StringUtils.isNoneEmpty(tbLogVisit.getVisitThrowingErro())){
                tbLogVisit.setCreateTime(new Date());
                count = tbLogVisitMapper.insert(tbLogVisit);
            }else {
                String visitIpAddress = tbLogVisit.getVisitIpAddress();
                String visitApi = tbLogVisit.getVisitApi();
                TbLogVisitExample tbLogVisitExample = new TbLogVisitExample();
                TbLogVisitExample.Criteria criteria = tbLogVisitExample.createCriteria();
                criteria.andVisitIpAddressEqualTo(visitIpAddress);
                criteria.andVisitApiEqualTo(visitApi);
                List<TbLogVisit> tbLogVisits = tbLogVisitMapper.selectByExample(tbLogVisitExample);
                if(CollectionHelp.isNotEmpty(tbLogVisits)){
                    Long nums = 0L;
                    Double sums = 0D;
                    for (TbLogVisit logVisit : tbLogVisits) {
                        //统计调用次数
                        Long visitNum = logVisit.getVisitNum();
                        nums = tbLogVisit.getVisitNum() + visitNum;
                        //统计耗时
                        Double visitTimeConsumingData = NumberUtils.Double(logVisit.getVisitTimeConsuming());
                        Double visitTimeConsumingParam = NumberUtils.Double(tbLogVisit.getVisitTimeConsuming());
                        Double sum = visitTimeConsumingData + visitTimeConsumingParam;
                        sums = sums + sum;
                    }
                    Double numDouble = NumberUtils.Double(String.valueOf(nums));
                    //统计平均耗时
                    Double avg = sums / numDouble;
                    tbLogVisit.setVisitTimeConsuming(avg.toString());
                    tbLogVisit.setVisitNum(nums);
                    count = tbLogVisitMapper.updateByExample(tbLogVisit,tbLogVisitExample);
                }else {
                    tbLogVisit.setCreateTime(new Date());
                    count = tbLogVisitMapper.insert(tbLogVisit);
                }
            }
     
            return count;
        }
    }

一开始没有设计好,后面强迫改动,导致访客的开始时间和结束时间都是最近一次的,不过我把每次请求的耗时改为平均耗时,勉强达到效果(不过有些请求异常的耗时时间长的就比较影响耗时统计了,唉不说了,最开始没有设计好,也算勉强了),效率也不算太差,不会太影响性能,