Add trace log (#4339)

* Add trace log

 * Trace alarm rule reader
 * Trace the process of running alarm rule, especailly the moving of window
 * Add toString method to relevant class for tracing

* Remove unused importsC

* Revert "Remove unused importsC"

This reverts commit 395e1678

* Update query

Co-authored-by: 吴晟 Wu Sheng <wu.sheng@foxmail.com>

oap-server/server-alarm-plugin/src/main/java/org/apache/skywalking/oap/server/core/alarm/provider/AlarmRule.java

@@ -27,6 +27,7 @@ import lombok.Builder;
 import lombok.Getter;
 import lombok.NoArgsConstructor;
 import lombok.Setter;
+import lombok.ToString;
 
 /**
  * @author wusheng
@@ -36,6 +37,7 @@ import lombok.Setter;
 @AllArgsConstructor
 @Setter(AccessLevel.PUBLIC)
 @Getter(AccessLevel.PUBLIC)
+@ToString
 public class AlarmRule {
     private String alarmRuleName;
 

oap-server/server-alarm-plugin/src/main/java/org/apache/skywalking/oap/server/core/alarm/provider/AlarmRulesWatcher.java

@@ -19,6 +19,7 @@
 package org.apache.skywalking.oap.server.core.alarm.provider;
 
 import lombok.Getter;
+import lombok.extern.slf4j.Slf4j;
 import org.apache.skywalking.oap.server.configuration.api.ConfigChangeWatcher;
 import org.apache.skywalking.oap.server.core.Const;
 import org.apache.skywalking.oap.server.core.alarm.AlarmModule;
@@ -38,6 +39,7 @@ import java.util.Map;
  * @author kezhenxu94
  * @since 6.5.0
  */
+@Slf4j
 public class AlarmRulesWatcher extends ConfigChangeWatcher {
     @Getter
     private volatile Map<String, List<RunningRule>> runningContext;
@@ -90,6 +92,7 @@ public class AlarmRulesWatcher extends ConfigChangeWatcher {
         this.rules = newRules;
         this.runningContext = newRunningContext;
         this.alarmRuleRunningRuleMap = newAlarmRuleRunningRuleMap;
+        log.info("Update alarm rules to {}", rules);
     }
 
     @Override

oap-server/server-alarm-plugin/src/main/java/org/apache/skywalking/oap/server/core/alarm/provider/Rules.java

@@ -23,6 +23,7 @@ import lombok.*;
 
 @Setter(AccessLevel.PUBLIC)
 @Getter(AccessLevel.PUBLIC)
+@ToString
 public class Rules {
     private List<AlarmRule> rules;
     private List<String> webhooks;

oap-server/server-alarm-plugin/src/main/java/org/apache/skywalking/oap/server/core/alarm/provider/RunningRule.java

@@ -18,6 +18,10 @@
 
 package org.apache.skywalking.oap.server.core.alarm.provider;
 
+import java.util.Arrays;
+import lombok.RequiredArgsConstructor;
+import lombok.ToString;
+import lombok.extern.slf4j.Slf4j;
 import org.apache.skywalking.oap.server.core.alarm.AlarmMessage;
 import org.apache.skywalking.oap.server.core.alarm.MetaInAlarm;
 import org.apache.skywalking.oap.server.core.analysis.metrics.*;
@@ -39,6 +43,7 @@ import java.util.concurrent.locks.ReentrantLock;
  *
  * @author wusheng
  */
+@Slf4j
 public class RunningRule {
     private static DateTimeFormatter TIME_BUCKET_FORMATTER = DateTimeFormat.forPattern("yyyyMMddHHmm");
 
@@ -85,17 +90,26 @@ public class RunningRule {
     public void in(MetaInAlarm meta, Metrics metrics) {
         if (!meta.getMetricsName().equals(metricsName)) {
             //Don't match rule, exit.
+            if (log.isTraceEnabled()) {
+                log.trace("Metric names are inconsistent, {}-{}", meta.getMetricsName(), metricsName);
+            }
             return;
         }
 
         if (CollectionUtils.isNotEmpty(includeNames)) {
             if (!includeNames.contains(meta.getName())) {
+                if (log.isTraceEnabled()) {
+                    log.trace("{} isn't in the including list {}", meta.getName(), includeNames);
+                }
                 return;
             }
         }
 
         if (CollectionUtils.isNotEmpty(excludeNames)) {
             if (excludeNames.contains(meta.getName())) {
+                if (log.isTraceEnabled()) {
+                    log.trace("{} is in the excluding list {}", meta.getName(), excludeNames);
+                }
                 return;
             }
         }
@@ -114,6 +128,7 @@ public class RunningRule {
                 valueType = MetricsValueType.MULTI_INTS;
                 threshold.setType(MetricsValueType.MULTI_INTS);
             } else {
+                log.warn("Unsupported value type {}", valueType);
                 return;
             }
         }
@@ -204,6 +219,9 @@ public class RunningRule {
             } finally {
                 lock.unlock();
             }
+            if (log.isTraceEnabled()) {
+                log.trace("Move window {}", transformValues(values));
+            }
         }
 
         public void add(Metrics metrics) {
@@ -226,6 +244,9 @@ public class RunningRule {
                 if (minutes >= values.size()) {
                     // too old data
                     // also should happen, but maybe if agent/probe mechanism time is not right.
+                    if (log.isTraceEnabled()) {
+                        log.trace("Timebucket is {}, endTime is {} and value size is {}", timeBucket, this.endTime, values.size());
+                    }
                     return;
                 }
 
@@ -233,6 +254,9 @@ public class RunningRule {
             } finally {
                 this.lock.unlock();
             }
+            if (log.isTraceEnabled()) {
+                log.trace("Add metric {} to window {}", metrics, transformValues(this.values));
+            }
         }
 
         public AlarmMessage checkAlarm() {
@@ -293,6 +317,9 @@ public class RunningRule {
                     case MULTI_INTS:
                         int[] ivalueArray = ((MultiIntValuesHolder) metrics).getValues();
                         Integer[] iaexpected = RunningRule.this.threshold.getIntValuesThreshold();
+                        if (log.isTraceEnabled()) {
+                            log.trace("Value array is {}, expected array is {}", ivalueArray, iaexpected);
+                        }
                         for (int i = 0; i < ivalueArray.length; i++) {
                             ivalue = ivalueArray[i];
                             Integer iNullableExpected = 0;
@@ -303,6 +330,9 @@ public class RunningRule {
                                 }
                             }
                             if (op.test(iNullableExpected, ivalue)) {
+                                if (log.isTraceEnabled()) {
+                                    log.trace("Matched, expected {}, value {}", iNullableExpected, ivalue);
+                                }
                                 matchCount++;
                                 break;
                             }
@@ -311,6 +341,9 @@ public class RunningRule {
                 }
             }
 
+            if (log.isTraceEnabled()) {
+                log.trace("Match count is {}, threshold is {}", matchCount, countThreshold);
+            }
             // Reach the threshold in current bucket.
             return matchCount >= countThreshold;
         }
@@ -322,4 +355,37 @@ public class RunningRule {
             }
         }
     }
+
+    private LinkedList<TraceLogMetric> transformValues(final LinkedList<Metrics> values) {
+        LinkedList<TraceLogMetric> r = new LinkedList<>();
+        values.forEach(m -> {
+            if (m == null) {
+                r.add(null);
+                return;
+            }
+            switch (valueType) {
+                case LONG:
+                    r.add(new TraceLogMetric(m.getTimeBucket(), new Number[] {((LongValueHolder)m).getValue()}));
+                    break;
+                case INT:
+                    r.add(new TraceLogMetric(m.getTimeBucket(), new Number[] {((IntValueHolder)m).getValue()}));
+                    break;
+                case DOUBLE:
+                    r.add(new TraceLogMetric(m.getTimeBucket(), new Number[] {((DoubleValueHolder)m).getValue()}));
+                    break;
+                case MULTI_INTS:
+                    int[] iArr = ((MultiIntValuesHolder)m).getValues();
+                    r.add(new TraceLogMetric(m.getTimeBucket(), Arrays.stream(iArr).boxed().toArray(Number[]::new)));
+                    break;
+            }
+        });
+        return r;
+    }
+
+    @RequiredArgsConstructor
+    @ToString
+    private static class TraceLogMetric {
+        private final long timeBucket;
+        private final Number[] value;
+    }
 }

oap-server/server-alarm-plugin/src/test/resources/log4j2-test.xml

@@ -0,0 +1,36 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+  ~ Licensed to the Apache Software Foundation (ASF) under one or more
+  ~ contributor license agreements.  See the NOTICE file distributed with
+  ~ this work for additional information regarding copyright ownership.
+  ~ The ASF licenses this file to You under the Apache License, Version 2.0
+  ~ (the "License"); you may not use this file except in compliance with
+  ~ the License.  You may obtain a copy of the License at
+  ~
+  ~     http://www.apache.org/licenses/LICENSE-2.0
+  ~
+  ~ Unless required by applicable law or agreed to in writing, software
+  ~ distributed under the License is distributed on an "AS IS" BASIS,
+  ~ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+  ~ See the License for the specific language governing permissions and
+  ~ limitations under the License.
+  ~
+  -->
+
+<Configuration status="INFO">
+    <Appenders>
+        <Console name="Console" target="SYSTEM_OUT">
+            <PatternLayout charset="UTF-8" pattern="%d - %c -%-4r [%t] %-5p %x -  %m%n"/>
+        </Console>
+    </Appenders>
+    <Loggers>
+        <logger name="org.eclipse.jetty" level="INFO"/>
+        <logger name="org.apache.zookeeper" level="INFO"/>
+        <logger name="org.elasticsearch.common.network.IfConfig" level="INFO"/>
+        <logger name="io.grpc.netty" level="INFO"/>
+        <logger name="org.apache.skywalking.oap.server.core.alarm.provider" level="TRACE"/>
+        <Root level="INFO">
+            <AppenderRef ref="Console"/>
+        </Root>
+    </Loggers>
+</Configuration>