Reconnect loop for stream producer, confusing logging, high ETS table memory #330

plewam · 2023-11-28T09:33:20Z

plewam
Nov 28, 2023

Hi,
I have some new findings around RMQ producers and streams. I have a variety of stream queues that have a TTL of 21 days. The sum of all queued entities is around 1 billion.
The more data I collect the more I am struggling with RabbitMQ. This has some weird side effect that you can see below.

RabbitMQ Version: 3.13.0-rc.2
Erlang Version: 26.1.2
Client Version: 1.7.4
OS: Windows Server 2019

Now my question: Is there anything I can do to prevent this continuous reconnecting? I have the feeling this is filling up the ETS tables within RabbitMQ until the high watermark is reached, but thats just a guess.

Furthermore is it possible to improve the logging at some points, e.g.

Raw Producer: null created for Stream (Why null here?)
Producer reference: , stream: Stream_DataAgentEntityStatisticsAirMeasurementEvent " reconnected successfully (Why no producer reference?)
Publisher 0 closed (What is publisher 0? Has this to do anything with the producer?)

2023-11-27 19:07:47.179487 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.189501 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.189393 [INF] [051_010] Published <343> entities of type <"DataAgentEntityOrderTransitionEvent"> to stream <"Stream_DataAgentEntityOrderTransitionEvent"> in <99> ms  
2023-11-27 19:07:47.191377 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.192169 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.190719 [DBG] [051_010] Start publishing <639> entities of type <"DataAgentEntityOrderItemEvent"> to stream <"Stream_DataAgentEntityOrderItemEvent">  
2023-11-27 19:07:47.193708 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsAirMeasurementEvent"  
2023-11-27 19:07:47.196766 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsAirMeasurementEvent " reconnected successfully  
2023-11-27 19:07:47.198484 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.206141 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.208190 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.211638 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.215554 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.216515 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsAPWorkstationGroupGeneralEvent"  
2023-11-27 19:07:47.217261 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.218083 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.219872 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.218190 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsAPWorkstationGroupGeneralEvent " reconnected successfully  
2023-11-27 19:07:47.220466 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.225778 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.227439 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.222694 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.236578 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.237156 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.238133 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsADPInspectionGeneralEvent"  
2023-11-27 19:07:47.240378 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsADPInspectionGeneralEvent " reconnected successfully  
2023-11-27 19:07:47.245362 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.246540 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.248028 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.248766 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.250114 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsFlowSensorEvent"  
2023-11-27 19:07:47.251383 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsFlowSensorEvent " reconnected successfully  
2023-11-27 19:07:47.244903 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.253211 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.260039 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.260325 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.261083 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.261577 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.260397 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.262852 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.263486 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.265555 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.266795 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsEntryPointEvent"  
2023-11-27 19:07:47.268852 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsEntryPointEvent " reconnected successfully  
2023-11-27 19:07:47.274157 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.275145 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.277064 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.277715 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.272823 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.279706 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsPackloopGeneralEvent"  
2023-11-27 19:07:47.284222 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsPackloopGeneralEvent " reconnected successfully  
2023-11-27 19:07:47.290200 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.293669 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.294961 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.295448 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.296279 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsScaleEvent"  
2023-11-27 19:07:47.290540 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.298689 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsScaleEvent " reconnected successfully  
2023-11-27 19:07:47.305692 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.306687 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.308273 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityOrderItemEvent " is disconnected. Client will try reconnect  
2023-11-27 19:07:47.302366 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.314071 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.314838 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.317097 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.317755 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.318783 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsADPInspectionDirtEvent"  
2023-11-27 19:07:47.324058 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.320336 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsADPInspectionDirtEvent " reconnected successfully  
2023-11-27 19:07:47.324842 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.348966 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.325475 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.350108 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.351751 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.352997 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.354363 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityOrderItemStateSnapshotEvent"  
2023-11-27 19:07:47.356632 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityOrderItemStateSnapshotEvent " reconnected successfully  
2023-11-27 19:07:47.358894 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.359652 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.364635 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.358473 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.365560 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.367393 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.368674 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.369711 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsADPInspectionTurningEvent"  
2023-11-27 19:07:47.372054 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsADPInspectionTurningEvent " reconnected successfully  
2023-11-27 19:07:47.374142 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.394353 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.395136 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.395304 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.393716 [WRN] [051_010] ProcessIncomingFrames reader task did not exit in 00:00:03  
2023-11-27 19:07:47.396104 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.396622 [DBG] [051_010] Publisher 0 closed  
2023-11-27 19:07:47.400912 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.401667 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.402967 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.403532 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.405087 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsTPReaderEvent"  
2023-11-27 19:07:47.408710 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsTPReaderEvent " reconnected successfully  
2023-11-27 19:07:47.413731 [DBG] [051_010] Server properties: [("cluster_name": "rabbit@myserver"), ("copyright": "Copyright (c) 2007-2023 VMware, Inc. or its affiliates."), ("information": "Licensed under the MPL 2.0. Website: https://rabbitmq.com"), ("platform": "Erlang/OTP 26.1.2"), ("product": "RabbitMQ"), ("version": "3.13.0-rc.2")]  
2023-11-27 19:07:47.414915 [DBG] [051_010] Sasl mechanism: ["AMQPLAIN", "PLAIN"]  
2023-11-27 19:07:47.416344 [DBG] [051_010] Open: ConnectionProperties: [("advertised_port": "5552"), ("advertised_host": "myserver")]  
2023-11-27 19:07:47.416991 [DBG] [051_010] Extracted BrokerVersion version: "3.13.0"  
2023-11-27 19:07:47.418179 [DBG] [051_010] Raw Producer: null created for Stream: "Stream_DataAgentEntityStatisticsFlexBufferGeneralEvent"  
2023-11-27 19:07:47.420166 [INF] [051_010] "Producer reference: , stream: Stream_DataAgentEntityStatisticsFlexBufferGeneralEvent " reconnected successfully  
2023-11-27 19:07:47.412188 [DBG] [051_010] TCP Connection Closed  
2023-11-27 19:07:47.422112 [DBG] [051_010] TCP Connection Closed

Gsantomaggio · 2023-11-28T10:19:59Z

Gsantomaggio
Nov 28, 2023
Maintainer

Thank you for reporting the issue. We can improve the messages log of course.
It would be useful to understand why the client tries to reconnect so often and why the client is not able to reconnect entering in a loop.

You could implement your ReconnectStrategy see:

rabbitmq-stream-dotnet-client/Tests/ReliableTests.cs

Line 423 in b237f59

private class MyReconnection : IReconnectStrategy

Or you can implement your strategy from scratch starting from the RawProducer class.

2 replies

Gsantomaggio Nov 28, 2023
Maintainer

@plewam you can find me on Rabbitmq Community Discord Server if you want to discuss about that

plewam Nov 30, 2023
Author

@Gsantomaggio Thanks for mentioning the reconnect strategy. Will have a look at this. Currently I am thinking the problem lies with streams itself. There is currently a discussion going on here rabbitmq/rabbitmq-server#9998 about this error as well.

Gsantomaggio · 2023-11-28T16:54:57Z

Gsantomaggio
Nov 28, 2023
Maintainer

We will add a client identity to better understand the logs. The identifier will be only client side, something like:

ProducerConfing(){
  identifier = "my_producer_22"
}

So in the logs you will see:

2023-11-27 19:07:47.395304 [DBG] [051_010] Publisher my_producer_22 closed

instead of:

2023-11-27 19:07:47.396104 [DBG] [051_010] Publisher 0 closed

1 reply

plewam Nov 30, 2023
Author

@Gsantomaggio That would help, thanks :)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Reconnect loop for stream producer, confusing logging, high ETS table memory #330

Uh oh!

{{title}}

Uh oh!

Replies: 2 comments 3 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Reconnect loop for stream producer, confusing logging, high ETS table memory #330

Uh oh!

plewam Nov 28, 2023

Replies: 2 comments · 3 replies

Uh oh!

Gsantomaggio Nov 28, 2023 Maintainer

Uh oh!

Gsantomaggio Nov 28, 2023 Maintainer

Uh oh!

plewam Nov 30, 2023 Author

Uh oh!

Gsantomaggio Nov 28, 2023 Maintainer

Uh oh!

plewam Nov 30, 2023 Author

plewam
Nov 28, 2023

Replies: 2 comments 3 replies

Gsantomaggio
Nov 28, 2023
Maintainer

Gsantomaggio Nov 28, 2023
Maintainer

plewam Nov 30, 2023
Author

Gsantomaggio
Nov 28, 2023
Maintainer

plewam Nov 30, 2023
Author