Pinpoint: SpanEvents with negative sequence should be filtered at collector side and may also need to be eliminated at agent side.

[tankilo]

Prerequisites

Please check the FAQ, and search existing issues for similar questions before creating a new issue.YOU MAY DELETE THIS PREREQUISITES SECTION.

• [x] I have checked the FAQ, and issues and found no answer.

What version of pinpoint are you using?

master

Describe the bug

In issue https://github.com/naver/pinpoint/issues/5840 , pinpoint's official developer has already realized that the value of SpanEvent's sequence can be negative due to com.navercorp.pinpoint.common.server.bo.SpanEventBo#sequence's data type being short.

But the problem has not been fixed completely.

1. If com.navercorp.pinpoint.common.server.bo.filter.SequenceSpanEventFilter#filter rejects SpanEvents with sequence greater than 10000 (default), why negative ones are still reserved?
   
   Negative ones are those method calls who happen after those whose sequence are between 0 and Short.MAX_VALUE, so they should also be filterd.
2. When negative sequence occurs, the Pinpoint Web UI can't show the transaction info correctly, this can be avoided if the previous problem is fixed. But in pinpoint 1.7.3 ,the web ui can replace those polluted spanEvents as one line Corrupted(invalid Sequence. This is a regression.
   

What did you do to trigger the bug?

1. make a demo

import java.io.IOException;

public class InvalidSequenceTest {
    public static void main(String[] args) throws IOException {
        test();
        System.in.read();
    }

    public static void test() {
        InvalidSequenceTest invalidSequenceTest = new InvalidSequenceTest();
        for (int i = 0; i < Short.MAX_VALUE+1; i++) {
            invalidSequenceTest.echo(i);
        }
    }

    public void echo(int i) {
        System.out.println(i);
    }
}

In pinpoint.cfg

###########################################################
# user defined classes                                    # 
###########################################################
# Specify classes and methods you want to profile here.

# Needs to be a comma separated list of fully qualified class names, or fully qualified package names with wild card class.
profiler.include=InvalidSequenceTest
# Ex: foo.bar.MyClass, foo.baz.*

# Needs to be a comma separated list of fully qualified method names. Wild card not supported.
profiler.entrypoint=InvalidSequenceTest.test,InvalidSequenceTest.echo
# Ex: foo.bar.MyClass.myMethod, foo.bar.MyClass.anotherMethod

1. Run the code
2. Visit web ui and select that request in scatter chart
3. loading indicator is always there and page stucks
   

2019-10-25 15:00:40,121 [http-nio-28080-exec-9id] WARN  [ControllerExceptionHandler.java:56] com.navercorp.pinpoint.web.controller.ControllerExceptionHandler null - Failed to execute controller methods. message:sequence overflow agentId:invalidsequencetest-1, request:{method=POST, heads={sec-fetch-mode=[cors], content-length=[66], referer=[http://localhost:28080/], sec-fetch-site=[same-origin], accept-language=[], cookie=[_ga=GA1.1.1211383005.1571970839; _gid=GA1.1.1478412996.1571970839; _gat=1], origin=[http://localhost:28080], accept=[application/json, text/plain, */*], host=[localhost:28080], connection=[keep-alive], content-type=[application/x-www-form-urlencoded], accept-encoding=[gzip, deflate, br], user-agent=[Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36]}, parameters={I0=[invalidsequencetest-1^1571986738740^1], T0=[1571986781978], R0=[38173]}, url=http://localhost:28080/transactionmetadata.pinpoint}.
java.lang.IllegalStateException: sequence overflow agentId:invalidsequencetest-1
    at com.navercorp.pinpoint.common.server.bo.serializer.trace.v2.SpanDecoderV0.readQualifier(SpanDecoderV0.java:419)
    at com.navercorp.pinpoint.common.server.bo.serializer.trace.v2.SpanDecoderV0.readSpan(SpanDecoderV0.java:92)
    at com.navercorp.pinpoint.common.server.bo.serializer.trace.v2.SpanDecoderV0.decode(SpanDecoderV0.java:55)
    at com.navercorp.pinpoint.web.mapper.TargetSpanDecoder.decode(TargetSpanDecoder.java:50)

Expected behavior

1. com.navercorp.pinpoint.common.server.bo.filter.SequenceSpanEventFilter#filter
   negative ones should also be filterd.
   

2. Should agent code prevent sequence to be oveflowed? When sequence reach Short.MAX_VALUE, no more SpanEvents should be created, warning log should be recorded in agent's logs.

Screenshots

If applicable, add screenshots to help explain your problem.

Logs

If applicable, please attach agent/collector/web DEBUG log that includes the code execution that led to the bug. In case of agents, including the start-up log may be of great help.

Additional context

Add any other context about the problem here, such as affected library for agents, how your collector/web/hbase is set up if applicable.

[tankilo]

If you agree with what i have said , i can make a PR to fix it.

[emeroad]

I completely agree with you.
I didn't think about negative sequence.

Contributions are welcome.

[tankilo]

I try to modify the code as follow:

1. At Collector side, com.navercorp.pinpoint.collector.dao.hbase.filter.SequenceSpanEventFilter#filter
   SpanEventBo with negative sequence will be filterd.

1. At Agent side, when SpanEvent's sequence reached Short.MAX_VALUE
   no more method calls will be traced, including both local and remote ones.

When i work on the second point above, i found that i can't prevent the plugin from invoking a remote node.

com.navercorp.pinpoint.profiler.context.DefaultTrace#traceBlockBegin0
I try to add a flag to indicate that the sequence has reach or exceeded


I found that making StackOperation#traceBlockBegin() is not enough, the plugin can still invoke a remote node since Trace#canSampled return true.

So i modify com.navercorp.pinpoint.profiler.context.DefaultTrace#canSampled

If we mark the interceptor with SpanEvent's sequence equal to Short.MAX_VALUE as [Interceptor A]
and the interceptor with SpanEvent's sequence exceededing Short.MAX_VALUE as [Interceptor B]

Both Interceptor A's after method and Interceptor B's before method will visit TraceContext#currentTraceObject and then visit DefaultTrace#canSampled

You can't tell one from another. So Interceptor A's after method may be mistakenly blocked.

[emeroad]

I have the following idea about problem #2(agent side).

• Change the seuqence field of SpanEvent from short to int
  
  
  
  • Thrfit : short
  
  
  • Protocolbuffer : int
  
  
  • PB does not support short.
  
  
  • Change to resovle sequence overflow problem
  
  
• DataSender performs sequence filtering.
  
  
  
  • Discard SpanEvent with a sequence greater than the limit.
  
  
  • Binding int to short field of Thrift
  
  
  • Limitations: limit should be smaller than Short.MAX
  
  
  • Protocolbuffer: No change
  
  

I'm not completely sure about this idea yet.

[tankilo]

I have the following idea about problem #2(agent side).

• Change the seuqence field of SpanEvent from short to int

  • Thrfit : short

  • Protocolbuffer : int

  • PB does not support short.

  • Change to resovle sequence overflow problem

• DataSender performs sequence filtering.

  • Discard SpanEvent with a sequence greater than the limit.

  • Binding int to short field of Thrift

  • Limitations: limit should be smaller than Short.MAX

  • Protocolbuffer: No change

I'm not completely sure about this idea yet.

I haven't known pinpoint for a long time.
I make an inelegant modification.
I directly filter these SpanEvents with negative sequence in com.navercorp.pinpoint.profiler.context.storage.Storage#store(com.navercorp.pinpoint.profiler.context.SpanEvent).

[emeroad]

At Agent side, when SpanEvent's sequence reached Short.MAX_VALUE
no more method calls will be traced, including both local and remote ones.

Agent side issue will be resolved on other issues.