StatsdMeterRegistry infinite reconnect loop with Reactor 2020.0

[shakuzen]

In some ad hoc testing, I noticed that behavior like described in #2177 is back again in 1.5.8, which contains #2359 upgrading reactor, reactor-netty, and netty. Since there were no other related changes in 1.5.8, it seems very likely that change is causing this issue to resurface. I will have to investigate more to understand why previously applied measures are no longer working.

Reverting the upgrade until a fix can be worked out may be the best course of action.

When the issue happens, which seems to be some variable amount of time after startup, with the statsd server down the whole time, DEBUG logs like the following are output rapidly and until the application is stopped:

2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125] Connected new channel
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125] onStateChange([connected], SimpleConnection{channel=[id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.shaded.reactor.netty.udp.UdpClient   : [id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125] Handler is being applied: io.micrometer.statsd.StatsdMeterRegistry$$Lambda$649/0x0000000800ea8f80@6b45cdee
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0xa0f006f1, L:/127.0.0.1:55452 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.netty.transport.TransportConfig  : [id: 0x5615037c] Initialized pipeline DefaultChannelPipeline{(io.micrometer.shaded.reactor.right.reactiveBridge = io.micrometer.shaded.reactor.netty.channel.ChannelOperationsHandler)}
2020-12-10 10:41:46.375 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xa0f006f1, L:/127.0.0.1:55452 ! R:localhost/127.0.0.1:8125] onStateChange([disconnecting], SimpleConnection{channel=[id: 0xa0f006f1, L:/127.0.0.1:55452 ! R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125] Connected new channel
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125] onStateChange([connected], SimpleConnection{channel=[id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.shaded.reactor.netty.udp.UdpClient   : [id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125] Handler is being applied: io.micrometer.statsd.StatsdMeterRegistry$$Lambda$649/0x0000000800ea8f80@6b45cdee
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0x5615037c, L:/127.0.0.1:55453 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.netty.transport.TransportConfig  : [id: 0xfd49a57c] Initialized pipeline DefaultChannelPipeline{(io.micrometer.shaded.reactor.right.reactiveBridge = io.micrometer.shaded.reactor.netty.channel.ChannelOperationsHandler)}
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x5615037c, L:/127.0.0.1:55453 ! R:localhost/127.0.0.1:8125] onStateChange([disconnecting], SimpleConnection{channel=[id: 0x5615037c, L:/127.0.0.1:55453 ! R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125] Connected new channel
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125] onStateChange([connected], SimpleConnection{channel=[id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.shaded.reactor.netty.udp.UdpClient   : [id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125] Handler is being applied: io.micrometer.statsd.StatsdMeterRegistry$$Lambda$649/0x0000000800ea8f80@6b45cdee
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0xfd49a57c, L:/127.0.0.1:55454 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.376 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.netty.transport.TransportConfig  : [id: 0x72c101b0] Initialized pipeline DefaultChannelPipeline{(io.micrometer.shaded.reactor.right.reactiveBridge = io.micrometer.shaded.reactor.netty.channel.ChannelOperationsHandler)}
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0xfd49a57c, L:/127.0.0.1:55454 ! R:localhost/127.0.0.1:8125] onStateChange([disconnecting], SimpleConnection{channel=[id: 0xfd49a57c, L:/127.0.0.1:55454 ! R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125] Connected new channel
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125] onStateChange([connected], SimpleConnection{channel=[id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.shaded.reactor.netty.udp.UdpClient   : [id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125] Handler is being applied: io.micrometer.statsd.StatsdMeterRegistry$$Lambda$649/0x0000000800ea8f80@6b45cdee
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0x72c101b0, L:/127.0.0.1:55455 - R:localhost/127.0.0.1:8125]}})
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.netty.transport.TransportConfig  : [id: 0x0361c72a] Initialized pipeline DefaultChannelPipeline{(io.micrometer.shaded.reactor.right.reactiveBridge = io.micrometer.shaded.reactor.netty.channel.ChannelOperationsHandler)}
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x72c101b0, L:/127.0.0.1:55455 ! R:localhost/127.0.0.1:8125] onStateChange([disconnecting], SimpleConnection{channel=[id: 0x72c101b0, L:/127.0.0.1:55455 ! R:localhost/127.0.0.1:8125]})
2020-12-10 10:41:46.377 DEBUG 81279 --- [      udp-nio-2] i.m.s.r.n.r.NewConnectionProvider        : [id: 0x0361c72a, L:/127.0.0.1:55456 - R:localhost/127.0.0.1:8125] Connected new channel

[shakuzen]

This is obviated in 1.5.x and 1.6.x for now by reverting the upgrade to Reactor 2020.0 for 1.5.9 and 1.6.2 - it was only ever released in version 1.5.8. Considering the apparent risk, the Reactor 2020.0 upgrade will be made for 1.7 instead of in patch versions, and we will need to figure out how to avoid this issue when making that upgrade.

[jonatan-ivanov]

@shakuzen I was able to repro the micrometer issue using reactor-core and reactor-netty-core only (no spring, no micrometer but reusing BufferingFlux from micrometer and the setup part of StatsdMeterRegistry): https://github.com/jonatan-ivanov/micrometer-gh-2378-minimal

There are three remarks, I would like to highlight:

1. The issue is "Heisenbug"-ish, depending on where do I stop the execution and release it again, the issue can disappear
2. BufferingFlux definitely has effect on it, if I switch the Publisher from BufferingFlux to the non-buffered Flux: this.manySink.asFlux(), the issue disappears: see publisher setup
3. The error is emitted here

[marcingrzejszczak]

@jonatan-ivanov can we replicate this with the latest versions?

[github-actions]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[github-actions]

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open.