tokio-compat: sinks::statsd::test::test_send_to_statsd fails tracking issue

[MOZGIII]

This issue is to gather all the data related to the sinks::statsd::test::test_send_to_statsd fails. It's related to #1922 and is designed to be a sort of separate thread where we focus on the sinks::statsd::test::test_send_to_statsd specifically.

I gathered some relevant info from before, shared at the #1922:

Notable failed CI runs:

• perf: Tokio compat #1922 (comment):

  • https://circleci.com/gh/timberio/vector/86630 ❌

• perf: Tokio compat #1922 (comment)

  • https://circleci.com/gh/timberio/vector/86075 ✔️
  • https://circleci.com/gh/timberio/vector/86365 ❌

• https://circleci.com/gh/timberio/vector/87162 ❌

From tokio-compat-statsd-debug branch:

• https://circleci.com/gh/timberio/vector/88246 ❌ (might not be related, fails at test_max_size test)

[MOZGIII]

I managed to reproduce the issue locally.

e717a45872c677a57c69cc97aec8b21991bfd3e3

It fails/passes randomly. Fails much more rarely than passes actually.

Falied:

running 1 test
Mar 10 13:45:57.369 TRACE vector::sinks::statsd::test: TR 1
Mar 10 13:45:57.381 TRACE mio::poll: registering with poller    
Mar 10 13:45:57.382 TRACE mio::poll: registering with poller    
Mar 10 13:45:57.382 TRACE vector::sinks::statsd::test: TR 2
Mar 10 13:45:57.382 TRACE vector::sinks::statsd::test: TR 3
Mar 10 13:45:57.383 TRACE vector::sinks::statsd::test: TR 6
Mar 10 13:45:57.383 TRACE vector::sinks::statsd::test: TR 7
Mar 10 13:45:57.383 TRACE vector::sinks::util: request succeeded. response=()
Mar 10 13:45:57.383 TRACE vector::sinks::statsd::test: TR 4
Mar 10 13:45:57.383 DEBUG tokio_reactor: adding I/O source: 0    
Mar 10 13:45:57.383 TRACE mio::poll: registering with poller    
Mar 10 13:45:57.383 DEBUG tokio_reactor::registration: scheduling Read for: 0    
Mar 10 13:45:57.383 TRACE tokio_reactor: event Writable Token(0)    
Mar 10 13:45:57.383 TRACE tokio_reactor: loop process - 1 events, 0.000s    
test sinks::statsd::test::test_send_to_statsd ... test sinks::statsd::test::test_send_to_statsd has been running for over 60 seconds
^C

Successful:

running 1 test
Mar 10 13:50:47.818 TRACE vector::sinks::statsd::test: TR 1
Mar 10 13:50:47.819 TRACE mio::poll: registering with poller    
Mar 10 13:50:47.819 TRACE mio::poll: registering with poller    
Mar 10 13:50:47.820 TRACE vector::sinks::statsd::test: TR 2
Mar 10 13:50:47.820 TRACE vector::sinks::statsd::test: TR 3
Mar 10 13:50:47.820 TRACE vector::sinks::statsd::test: TR 6
Mar 10 13:50:47.820 TRACE vector::sinks::statsd::test: TR 7
Mar 10 13:50:47.820 TRACE vector::sinks::util: request succeeded. response=()
Mar 10 13:50:47.820 DEBUG tokio_reactor: adding I/O source: 0    
Mar 10 13:50:47.821 TRACE vector::sinks::statsd::test: TR 4
Mar 10 13:50:47.821 TRACE mio::poll: registering with poller    
Mar 10 13:50:47.821 DEBUG tokio_reactor::registration: scheduling Read for: 0    
Mar 10 13:50:47.821 TRACE tokio_reactor: event Readable | Writable Token(0)    
Mar 10 13:50:47.821 TRACE tokio_reactor: loop process - 1 events, 0.000s    
Mar 10 13:50:47.821 TRACE tokio_udp::frame: received 85 bytes, decoding    
Mar 10 13:50:47.821 TRACE tokio_udp::frame: frame decoded from buffer    
Mar 10 13:50:47.821 DEBUG tokio_reactor::registration: scheduling Read for: 0    
Mar 10 13:50:47.821 TRACE vector::sinks::statsd::test: TR 5
Mar 10 13:50:47.821 DEBUG tokio_reactor::registration: scheduling Read for: 0    
Mar 10 13:50:47.821 TRACE mio::poll: deregistering handle with poller    
Mar 10 13:50:47.821 DEBUG tokio_reactor: dropping I/O source: 0    
Mar 10 13:50:47.822 TRACE tokio_reactor: event Readable Token(4194303)    
Mar 10 13:50:47.822 TRACE tokio_reactor: loop process - 1 events, 0.000s    
test sinks::statsd::test::test_send_to_statsd ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 504 filtered out

[MOZGIII]

Ok, I think it's a race too.

@LucioFranco, @lukesteensen can you confirm?

[LucioFranco]

So it looks like the event isn't coming through as readable but only writeable?

Mar 10 13:45:57.383 TRACE tokio_reactor: event Writable Token(0)    

where as when it passes this is:

Mar 10 13:50:47.821 TRACE tokio_reactor: event Readable | Writable Token(0)    

[LucioFranco]

If possible we should try to reproduce this and get a strace output to see what tokio's reactor is actually submitting.