Current time must greater than start time

[taotao365s]

Describe the bug

java.lang.IllegalArgumentException: Current time must greater than start time
        at com.alipay.common.tracer.core.utils.AssertUtils.isTrue(AssertUtils.java:42)
        at com.alipay.common.tracer.core.span.SofaTracerSpan.log(SofaTracerSpan.java:218)
        at com.alipay.common.tracer.core.span.SofaTracerSpan.log(SofaTracerSpan.java:213)
        at com.alipay.common.tracer.core.tracer.AbstractTracer.clientReceiveTagFinish(AbstractTracer.java:172)
        at com.alipay.common.tracer.core.tracer.AbstractTracer.clientReceive(AbstractTracer.java:157)

Expected behavior

as its role of framework， sofa-tracer should eat low level exception , thanks

Actual behavior

Steps to reproduce

Minimal yet complete reproducer code (or GitHub URL to code)

Environment

• SOFATracer version: 3.0.12
• JVM version (e.g. java -version):
• OS version (e.g. uname -a):
• Maven version:
• IDE version:

[chenmudu]

@spyvip Maybe you can give more use cases to facilitate troubleshooting. It seems like a time disorder, we need to determine what caused the abnormal time comparison.The correct cs & cr times should be distinguished by time.

[taotao365s]

@chenmudu so am I, but no more log in production machine, sorry brother

[chenmudu]

@chenmudu so am I, but no more log in production machine, sorry brother

No problem. Let's keep waiting.

[taotao365s]

oh, it happens again in one jvm process.

here is our custom Tracer plugin and biz system aop, plz help me.

I think thatthis.clientReceive(resultCode); code is broken, but don't know why.

• SimpleTracer

public class SimpleTracer extends AbstractClientTracer {
    private static final Logger log = LoggerFactory.getLogger(SimpleTracer.class);
    public static final String SIMPLE_TRACER_JSON_FORMAT_OUTPUT = "simple_tracer_json_format_output";
    public static final String RESULT_CODE_SUC = "success";
    public static final String RESULT_CODE_FAIL = "fail";
    public static final String SEA_SOFA_TRACER = "sea.sofa.simple.tracer";
    public static final String SEA_SOFA_TRACER_MODE_CUSTOM = "custom";
    public static final String SEA_SOFA_TRACER_ERROR_MSG = "sea.sofa.simple.tracer.error.msg";
    private static volatile SimpleTracer tracer = null;

    public static SimpleTracer getTracerSingleton() {
        if (tracer == null) {
            Class var0 = SimpleTracer.class;
            synchronized(SimpleTracer.class) {
                if (tracer == null) {
                    tracer = new SimpleTracer();
                }
            }
        }

        return tracer;
    }

    public SimpleTracer() {
        super("SimpleTracer");
    }

    protected String getClientDigestReporterLogName() {
        return SimpleLogEnum.DIGEST.getDefaultLogName();
    }

    protected String getClientDigestReporterRollingKey() {
        return SimpleLogEnum.DIGEST.getRollingKey();
    }

    protected String getClientDigestReporterLogNameKey() {
        return SimpleLogEnum.DIGEST.getDefaultLogName();
    }

    protected SpanEncoder<SofaTracerSpan> getClientDigestEncoder() {
        return (SpanEncoder)(Boolean.TRUE.toString().equalsIgnoreCase(SofaTracerConfiguration.getProperty("simple_tracer_json_format_output")) ? new SimpleDigestJsonEncoder() : new SimpleDigestEncoder());
    }

    protected AbstractSofaTracerStatisticReporter generateClientStatReporter() {
        return this.generateSofaSimpleStatReporter();
    }

    private SimpleStatReporter generateSofaSimpleStatReporter() {
        SimpleLogEnum springMvcLogEnum = SimpleLogEnum.STAT;
        String statLog = springMvcLogEnum.getDefaultLogName();
        String statRollingPolicy = SofaTracerConfiguration.getRollingPolicy(springMvcLogEnum.getRollingKey());
        String statLogReserveConfig = SofaTracerConfiguration.getLogReserveConfig(springMvcLogEnum.getLogNameKey());
        return (SimpleStatReporter)(Boolean.TRUE.toString().equalsIgnoreCase(SofaTracerConfiguration.getProperty("simple_tracer_json_format_output")) ? new SimpleStatJsonReporter(statLog, statRollingPolicy, statLogReserveConfig) : new SimpleStatReporter(statLog, statRollingPolicy, statLogReserveConfig));
    }

    public SofaTracerSpan begin(String operationName) {
        SofaTracerSpan span = this.clientSend(operationName);
        String appName = SofaTracerConfiguration.getProperty("spring.application.name");
        if (log.isDebugEnabled()) {
            log.debug("appName={}", appName);
        }

        span.setTag("local.app", appName);
        span.setTag("sea.sofa.simple.tracer", "custom");
        return span;
    }

    public void setErrorMsg(String errorMsg) {
        SofaTraceContext sofaTraceContext = SofaTraceContextHolder.getSofaTraceContext();
        if (sofaTraceContext != null) {
            SofaTracerSpan span = sofaTraceContext.getCurrentSpan();
            if (span != null) {
                span.setTag("sea.sofa.simple.tracer.error.msg", errorMsg);
            }
        }

    }

    public void end(String resultCode) {
        if ("fail".equalsIgnoreCase(resultCode)) {
            SofaTraceContext sofaTraceContext = SofaTraceContextHolder.getSofaTraceContext();
            if (sofaTraceContext != null) {
                SofaTracerSpan span = sofaTraceContext.getCurrentSpan();
                if (span != null) {
                    span.setTag("error", true);
                }
            }
        }

        this.clientReceive(resultCode); // broken?? 
    }

}

• out biz system spring AOP

       tracerName.append(className)
                .append(".")
                .append(methodName);
        SimpleTracer tracer = SimpleTracer.getTracerSingleton();
        tracer.begin(tracerName.toString());
        String tracerResultCode = SimpleTracer.RESULT_CODE_SUC;

        Object proceed;
        try {
            proceed = joinPoint.proceed();
        } catch (Throwable e) {
            tracerResultCode = SimpleTracer.RESULT_CODE_FAIL;
            tracer.setErrorMsg(ExceptionUtils.getMessage(e));
            throw e;
        } finally {
            tracer.end(tracerResultCode);
        }

[chenmudu]

Can you show me how to put the current SimpleTracer into the Spring container?

[taotao365s]

public class SimpleTracer extends AbstractClientTracer 

AbstractClientTracer is com.alipay.common.tracer.core.tracer.AbstractClientTracer

[chenmudu]

@spyvip
Could you give me more information?

For example, how AOP is currently placed in the spring container? Do you Annotate(Aspect) the class directly? Or use the SpringBoot Auto Configuration mechanism and so on. The most effective way is to give a reproducible example.It may be possible to pinpoint the exact cause.

First of all, according to the current given phenomenon, we see end time < start time.But in the HTTP Server I/O thread, you can see in your AOP that the flow of code execution under a single thread is linear.
So to the best of my knowledge, there are no instances where this principle has been violated.

Next,Your begin() call com.alipay.common.tracer.core.tracer.AbstractTracer#clientSend(), The method call(SofaTracerSpan) this.sofaTracer.buildSpan(operationName).asChildOf(serverSpan).start() .
At this time, com.alipay.common.tracer.core.SofaTracer.SofaTracerSpanBuilder#start() will determine the current start time.

The start time as a member attribute is already generated before the end time, So start time < end time normally exists.

So, if we want to identify the problem and fixes it, I think it's a good idea to provide a reproducible example and include your customized SOFA-Tracer plugin, and then debug it.

End, I'd be happy to follow it up if you'd like.