RocketMQ Client DEADLINE_EXCEEDED in the Cloud: Tracing It to Container Memory

Posted on Edited on Views: Word count in article: 4.4k Reading time ≈ 4 mins.
A RocketMQ Java client failed with gRPC DEADLINE_EXCEEDED only in one cloud test cluster. Packet capture and resource-limit tests traced it to container memory pressure, not the network.

A RocketMQ client started throwing timeouts in a cloud test cluster while the exact same code ran fine locally. This post walks through the investigation, the wrong turns included, and how a gRPC DEADLINE_EXCEEDED turned out to have nothing to do with the network.

One possible explanation for this class of problem

Symptoms and the stack trace

A colleague hit a strange one yesterday. After adding RocketMQ consumer code to the service, a program that ran perfectly fine locally started throwing the following exception when deployed to cloud test cluster A1:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
time,cluster,namespace,service,pod,log
2023-12-14 09:36:00,cluster-test,did-test,jiankunking-test,jiankunking-test-6b86565dbb-lzt9d,2023-12-14 09:36:00.595  INFO 1 --- [  XNIO-1 task-1] c.h.d.i.rocket.PdmRocketMqConsumer       : [TID:95e19b4533204903a985c90b068cddcc_64_17025177603380033] --- 构建mq5.0消费者：proxy:10.163.240.237:8080, topic:product_material_topic_uat_center, group:product_material_group_center
2023-12-14 09:36:40,cluster-test,did-test,jiankunking-test,jiankunking-test-6b86565dbb-lzt9d,2023-12-14 09:36:39.995 ERROR 1 --- [  XNIO-1 task-1] c.h.d.i.rocket.PdmRocketMqConsumer       : [TID:95e19b4533204903a985c90b068cddcc_64_17025177603380033] --- 构建mq5.0消费者异常：proxy:10.163.240.237:8080, topic:product_material_topic_uat_center, group：product_material_group_center
2023-12-14 09:36:40,cluster-test,did-test,jiankunking-test,jiankunking-test-6b86565dbb-lzt9d,
2023-12-14 09:36:40,cluster-test,did-test,jiankunking-test,jiankunking-test-6b86565dbb-lzt9d,java.lang.IllegalStateException: Expected the service PushConsumerImpl-0 [FAILED] to be RUNNING, but the service has FAILED
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractService.checkCurrentState(AbstractService.java:381) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractService.awaitRunning(AbstractService.java:305) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractIdleService.awaitRunning(AbstractIdleService.java:165) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.client.java.impl.consumer.PushConsumerBuilderImpl.build(PushConsumerBuilderImpl.java:128) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at com.jiankunking.issuemanage.rocket.PdmRocketMqConsumer.initConsumer(PdmRocketMqConsumer.java:89) ~[classes!/:na]
	at com.jiankunking.issuemanage.controller.IssueTagInfoController.initRocketMq$original$l28F75DZ(IssueTagInfoController.java:103) ~[classes!/:na]
	at com.jiankunking.issuemanage.controller.IssueTagInfoController.initRocketMq$original$l28F75DZ$accessor$0D0TSRNs(IssueTagInfoController.java) ~[classes!/:na]
	at com.jiankunking.issuemanage.controller.IssueTagInfoController$auxiliary$Rnw73z4x.call(Unknown Source) ~[classes!/:na]
	at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86) ~[skywalking-agent.jar:8.12.0]
	at com.jiankunking.issuemanage.controller.IssueTagInfoController.initRocketMq(IssueTagInfoController.java) ~[classes!/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.24.jar!/:5.3.24]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1071) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:964) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:645) ~[javax.servlet-api-4.0.1.jar!/:4.0.1]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.24.jar!/:5.3.24]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:750) ~[javax.servlet-api-4.0.1.jar!/:4.0.1]
	at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.24.jar!/:5.3.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar!/:5.3.24]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.24.jar!/:5.3.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar!/:5.3.24]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.24.jar!/:5.3.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar!/:5.3.24]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:275) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:79) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:134) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:131) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:255) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:79) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:100) ~[undertow-servlet-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:387) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:852) ~[undertow-core-2.2.20.Final.jar!/:2.2.20.Final]
	at org.apache.skywalking.apm.plugin.undertow.v2x.SWRunnable.run(SWRunnable.java:45) ~[na:na]
	at org.apache.skywalking.apm.plugin.undertow.v2x.SWRunnable.run(SWRunnable.java:45) ~[na:na]
	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) ~[jboss-threads-3.1.0.Final.jar!/:3.1.0.Final]
	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019) ~[jboss-threads-3.1.0.Final.jar!/:3.1.0.Final]
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558) ~[jboss-threads-3.1.0.Final.jar!/:3.1.0.Final]
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1449) ~[jboss-threads-3.1.0.Final.jar!/:3.1.0.Final]
	at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282) ~[xnio-api-3.8.7.Final.jar!/:3.8.7.Final]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: java.util.concurrent.ExecutionException: org.apache.rocketmq.shaded.io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: ClientCall started after deadline exceeded: -2.591386886s from now
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:588) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:547) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.FluentFuture$TrustedFuture.get(FluentFuture.java:91) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.client.java.impl.ClientImpl.startUp(ClientImpl.java:188) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.client.java.impl.consumer.PushConsumerImpl.startUp(PushConsumerImpl.java:161) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.AbstractIdleService$DelegateService$1.run(AbstractIdleService.java:62) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.com.google.common.util.concurrent.Callables.lambda$threadRenaming$3(Callables.java:103) ~[rocketmq-client-java-5.0.5.jar!/:na]
	... 1 common frames omitted
Caused by: org.apache.rocketmq.shaded.io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: ClientCall started after deadline exceeded: -2.591386886s from now
	at org.apache.rocketmq.shaded.io.grpc.Status.asRuntimeException(Status.java:539) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:544) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:563) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:744) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:723) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at org.apache.rocketmq.shaded.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[rocketmq-client-java-5.0.5.jar!/:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	... 1 common frames omitted

Since the code was identical locally and on the server, the error message pointed to:

1
2
3
Expected the service PushConsumerImpl-0 [FAILED] to be RUNNING, but the service has FAILED

org.apache.rocketmq.shaded.io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: ClientCall started after deadline exceeded: -2.591386886s from now

Initial investigation: code or network?

My colleague’s first suspicion was the cluster’s network environment. My own first reaction was that it was not the network — why?

Because if it were a network problem, there would be plenty of errors across the cluster, not just from this one service.

So where was the problem? Was it the code?

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
@Slf4j
@Component
@Configuration
@EnableConfigurationProperties(RocketMqProperties.class)
public class DemoConsumer {

    private final ClientServiceProvider provider = ClientServiceProvider.loadService();
    private final List<PushConsumer> pushConsumers = Collections.synchronizedList(new LinkedList<>());

    private final RestTemplate restTemplate;
    private final String endpoints;
    private final String accessKey;
    private final String secretKey;
    private final String topic;
    private final String group;

    @Autowired
    public DemoConsumer(RestTemplate restTemplate, RocketMqProperties properties) {
        this.restTemplate = restTemplate;
        this.accessKey = properties.getAccessKey();
        this.secretKey = properties.getSecretKey();
        this.endpoints = properties.getEndpoints();
        this.topic = properties.getTopic();
        this.group = properties.getGroup();
        listener();
    }

    public void listener() {
        try {
            log.info("开始构建mq5.0消费者");
            SessionCredentialsProvider sessionCredentialsProvider = new StaticSessionCredentialsProvider(accessKey, secretKey);
            ClientConfiguration clientConfiguration = ClientConfiguration.newBuilder()
                    .setEndpoints(endpoints)
                    .setCredentialProvider(sessionCredentialsProvider)
                    .build();
            PushConsumer pushConsumer = provider.newPushConsumerBuilder()
                    .setClientConfiguration(clientConfiguration)
                    .setConsumerGroup(group)
                    .setSubscriptionExpressions(Collections.singletonMap(topic, new FilterExpression("*", FilterExpressionType.TAG)))
                    .setMessageListener(messageView -> {
                        String tagInfo = messageView.getTag().orElse("");
                        String code = StandardCharsets.UTF_8.decode(messageView.getBody()).toString();
                        log.info("tagInfo:{} 消息内容:{}", tagInfo, StandardCharsets.UTF_8.decode(messageView.getBody()));
                        if (StringUtils.isBlank(tagInfo) || StringUtils.isBlank(code)) {
                            return ConsumeResult.SUCCESS;
                        }
                        // split tagInfo to get the material type
                        return ConsumeResult.SUCCESS;
                    }).build();
            log.info("构建mq5.0消费者成功：proxy:{}, topic:{}, group：{}", endpoints, topic, group);
            pushConsumers.add(pushConsumer);
        } catch (ClientException e) {
            log.info("构建mq5.0消费者失败：proxy:{}, topic:{}, group：{}, error:{}", endpoints, topic, group, e);
        }
    }


    @PreDestroy
    public void destroy() {
        pushConsumers.forEach(pushConsumer -> {
            try (pushConsumer) {
                log.info("关闭mq5.0消费者：proxy:{}, topic:{}, group：{}", endpoints, topic, group);
            } catch (Exception e) {
                log.error("关闭mq5.0消费者失败：proxy:{}, topic:{}, group：{}, error:{}", endpoints, topic, group, e);
            }
        });
    }
}

I compared it against the official demo, and it matched exactly:

https://github.com/apache/rocketmq-clients/blob/master/java/client/src/main/java/org/apache/rocketmq/client/java/example/PushConsumerExample.java

On top of that, another colleague’s identical code ran fine on a different cluster, B1.

Packet capture and the CPU hypothesis

Could it really be a network problem after all?

The exception above was thrown while the service was starting, so it never came up. At that point the container wasn’t ready either — no process to attach to — so we couldn’t yet run a packet capture to rule the network out.

I asked my colleague to move the RocketMQ initialization logic behind an API call, so the service could start normally and I could capture the network traffic. (How to capture packets in a k8s cluster: https://jiankunking.blog.csdn.net/article/details/125189956)

Packet capture screenshot:

01

The capture shows the network connection being established normally, then the service actively resetting it about 2.7 seconds in — exactly when the exception was thrown.

The packet capture confirmed our suspicion: at least at the TCP level, the network was fine.

Even with that verified, I still deployed the same broken image to cluster B1 — and the problem was still there.

So where was the problem? The investigation stalled.

Along the way I also tried:

  • Switching the RocketMQ address to https://…
  • Toggling enableSsl off and on

…and the problem still wasn’t resolved.

The service’s configuration in the test environment was:

1
2
Memory limit: 800m, request 600m
CPU limit 0.3 cores, request 0.1 core

Startup in the test environment took over four minutes. Could too little CPU be the problem — JIT consuming too many resources during startup, preventing the RocketMQ network connection from being scheduled, and causing timeouts?

Raising the CPU limit to 1 core got the service up in under a minute, but the exception remained.

The key clue: not enough memory

The investigation stalled again. Then I remembered:

  1. The container platform injects agents like SkyWalking and Prometheus into our applications by default
  2. In earlier, less rigorous testing, I found that SkyWalking alone occupies 200–300 MB of memory
  3. The java command gets rewritten; the default heap is 65% of the memory limit

800 × 0.65 = 520m, minus 200–300m, leaves roughly 220–320m for the service itself. Could too little memory be the problem?

Raising the memory request/limit step by step to 1200m made the error disappear.

Going back through the exception logs, I noticed that around the time the RocketMQ exception appeared, HikariPool was also failing to create database connections:

HikariPool initializes after the rocketmq init

1
2
3
4
5
6
7
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.098  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@5c4719b1 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.101  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@33b9b407 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.103  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@59c237c9 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.196  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@4c517517 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.198  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@28bf77bd (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.203  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@59d2c94b (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-12-14 09:43:24,cluster-test,did-test,jiankunking,jiankunking-6b86565dbb-lzt9d,2023-12-14 09:43:24.296  WARN 1 --- [  XNIO-1 task-1] com.zaxxer.hikari.pool.PoolBase          : [TID:95e19b4533204903a985c90b068cddcc_65_17025182033670077] --- HikariPool-1 - Failed to validate connection com.MySQL.cj.jdbc.ConnectionImpl@a835f53 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.

Repeated verification and the memory threshold

I then told my colleague the fix, assuming that was the end of it…

But that afternoon, he found that the service also started fine with the memory limit put back to 800m. Had something gone differently that morning?

I redeployed the original broken image with the lowered memory limit — and the service really did start normally.

我的天呐

Since the service could now start with the original configuration, how much memory does it actually need when no agents are injected by default?

I first replaced the startup command, removing the injected SkyWalking, Prometheus, and other agents:

1
2
3
4
5
6
7
java2
-server
-Xms300m
-Xmx300m
-jar
application.jar
--spring.profiles.active=test

The service started fine on 300m.

Then I switched back to the startup command with agents, and found:

  • limit = request = 500m: the service starts normally
  • limit = request = 450m: the exception above reappears
  • limit = request = 400m: the container gets OOMKilled

Conclusions and open questions

Two conclusions are solid by now:

  • The exception was caused by insufficient memory
  • The exact threshold that triggers it remains unclear
    • Two suspects:
      • The memory usage of injected agents like SkyWalking swings significantly with other factors
      • The service’s own memory footprint differed between morning and afternoon runs

I also suspected the cluster was overcommitting memory requests. Checking:

1
2
3
4
5
6
spec:
  ratio:
    limits.cpu: 500
    limits.memory: 500
    requests.cpu: 100
    requests.memory: 100

The requests were not overcommitted — the limits were.

Because of time constraints, I have not yet profiled the service’s memory usage or the memory usage of agents like SkyWalking; I will pick that up when I have time.

This article is the English edition of a post originally published in Chinese.