riemann-ruby-client icon indicating copy to clipboard operation
riemann-ruby-client copied to clipboard
verified publisher icon riemann

Possibly flakey test

Open jamtur01 opened this issue 3 years ago • 3 comments

https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true

[69](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:70)
  - should raise Riemann::Client::Unsupported exception on query
[70](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:71)
[71](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:72)
RuntimeError: wait_for condition never realized
[72](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:73)
	spec/client.rb:35:in `wait_for': Riemann::Client (UDP transport) - should send a state without time nor time_micros
[73](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:74)
	spec/client.rb:155:in `block (2 levels) in <top (required)>'
[74](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:75)
	spec/client.rb:149:in `block in <top (required)>'
[75](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:76)
	spec/client.rb:334:in `block in <top (required)>'
[76](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:77)
	spec/client.rb:328:in `<top (required)>'
[77](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:78)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli/exec.rb:58:in `load'
[78](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:79)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli/exec.rb:58:in `kernel_load'
[79](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:80)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli/exec.rb:23:in `run'
[80](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:81)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli.rb:479:in `exec'
[81](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:82)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
[82](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:83)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
[83](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:84)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
[84](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:85)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli.rb:31:in `dispatch'
[85](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:86)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
[86](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:87)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/cli.rb:25:in `start'
[87](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:88)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/exe/bundle:48:in `block in <top (required)>'
[88](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:89)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
[89](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:90)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/lib/ruby/gems/3.1.0/gems/bundler-2.3.16/exe/bundle:36:in `<top (required)>'
[90](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:91)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/bin/bundle:25:in `load'
[91](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:92)
	/opt/hostedtoolcache/Ruby/3.1.2/x64/bin/bundle:25:in `<main>'
[92](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:93)
[93](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:94)
49 specifications (107 requirements), 0 failures, 1 errors
[94](https://github.com/riemann/riemann-ruby-client/runs/7054304294?check_suite_focus=true#step:5:95)
Error: Process completed with exit code 1.

jamtur01 avatar Jun 25 '22 14:06 jamtur01

I can reproduce the issue.

By keeping a track of the time before we send the event and the time_micros of the event we found, there seems to be some rounding: all time_micros for the events I see ends with 000.

Real world example, the time recorded at the beginning of the test is 1656185604104042. Then the event is sent.

First found event has 1656185602001000, it is the one from the previous test because the one we just sent is not in the index yet:

[#<Riemann::Event time=1656185602 state="ok" service="timeless test" host="zappy.blogreen.org" description="" tags=[] ttl=60.0 attributes=[] time_micros=1656185602001000 metric_sint64=0 metric_d=0.0 metric_f=0.0>]

Next found event is the expected one, but the time_micros field is 1656185604104000 and appears to be older that the timestamp at the beginning of the test: 1656185604104042

[#<Riemann::Event time=1656185604 state="ok" service="timeless test" host="zappy.blogreen.org" description="" tags=[] ttl=60.0 attributes=[] time_micros=1656185604104000 metric_sint64=0 metric_d=0.0 metric_f=0.0>]

Reverting 5ab5de4198d03e1b71de2e1da2eabef556baef79 events have "better" resolution:

  - should send a state without time nor time_micros
---> 1656186828800656
[<Riemann::Event time: 1656186826, state: "ok", service: "timeless test", host: "zappy.blogreen.org", ttl: 60.0, time_micros: 1656186826388166>]
[<Riemann::Event time: 1656186828, state: "ok", service: "timeless test", host: "zappy.blogreen.org", ttl: 60.0, time_micros: 1656186828800753>]

So the root issue seems to be in the protobuf gem.

smortex avatar Jun 25 '22 19:06 smortex

@smortex Happy to have you revert the gem change? Or investigate with them upstream?

jamtur01 avatar Jun 25 '22 20:06 jamtur01

Let's do this for now while we investigate. I am still searching where the magic of setting time_micros happen: can't find it in riemann, nor the protocol buffers gems…

The same issue is triggered with the google-protobuf gem (I have some WIP here, but it is only partially functional ATM, I was thinking that using the implementation from google may be a better choice for the long term, also it has less dependencies, is written in C and triggers less errors when running the tests with RSpec :smile:).

smortex avatar Jun 25 '22 22:06 smortex