grpc-ecosystem / grpc-spring

Spring Boot starter module for gRPC framework.
https://grpc-ecosystem.github.io/grpc-spring/
Apache License 2.0
3.43k stars 809 forks source link

Received grpc requests twice #1062

Closed gaoxingliang closed 4 months ago

gaoxingliang commented 4 months ago

The context

there should only be at most once grpc request

The bug I found the grpc server we received the same requests twice in less than 40ms. and both finished successfully. I have a grpc client C which send request to a grpc server S: but when I checked the logs and found the server received duplicated request. The versions see below section. Stacktrace and logs

the client logs:

  [][]12-31 11:45:10.689.+0800 [INFO ][http-nio-7076-exec-3][c.s.b.s.a.EmploymentController.entemployrelid:60]准备查询:EnterpriseRequest(enterprises=[], userIdCard=XXXXX, userPhone=null, userName=YYY, correlationId=null)

this will trigger a code, the main stub is a grpc call:


try {
            result = RETRY_TEMPLATE.execute(context -> mainStub.queryEnterpriseEmployment(req.build()));
        } catch (Exception e) {
            LOG.error("主节点查询任职信息异常:{}", enterpriseRequest, e);
        }

the retry template is configured as: note the backoff is 2000 (2 seconds)

    private static final RetryTemplate RETRY_TEMPLATE = RetryTemplate.builder()
            .maxAttempts(3)
            .fixedBackoff(2000)
            .traversingCauses()
            .retryOn(Exception.class)
            .build();

while at the server side, I received twice and the interval is less than 40ms: (the input args, user id card and username are same)

1709263407208

note the time in two machines are not same. and you can see: the first call is 12-31 11:47:30.444.+0800. while the second is : 12-31 11:47:30.486.+0800 (40ms and is less than the retry backoff)

client conf:

    xxx:
      address: "static://localhost:9096"
      enableKeepAlive: true
      keepAliveWithoutCalls: true
      negotiationType: plaintext

server conf:

grpc:
  server:   
    port: 9096     
    enableKeepAlive: true
    permitKeepAliveWithoutCalls: true

no additional java code configuration.

Steps to Reproduce I tried to reproduce locally, but failed.

The application's environment

Which versions do you use?

Additional context

ST-DDT commented 4 months ago

Where do you log? In the service or an interceptor?

gaoxingliang commented 4 months ago

Where do you log? In the service or an interceptor?

@ST-DDT The log is added in normal service log. in order to investigate why it sends twice, I added the log interceptor recently into production environment. and try to check .

gaoxingliang commented 4 months ago

I found the root cause is still in my code. I have a structure like: -- main task call the stub. --- generate a batch of sub tasks with different api calls (which will execute in a seperate thread pool.) one of them will call the stub again.

Sorry for misleading.