Debugging unit-tests with Honeycomb
Since last week we’re collecting unit-test results and acceptance test runs in honeycomb, a tool for introspecting and interrogating production systems. In our team’s case, CI is the “production” environment we manage. Today Daniel pointed out that there was a curious issue with one of our test suites:
NoMethodError: undefined method `message_lines' for #<RSpec::Core::Notifications::SkippedExampleNotification:0x00007f8407ac3018> # /Users/danielcarabas/.rvm/gems/ruby-2.6.3/gems/rspec_honeycomb_formatter-0.2.0/lib/rspec_honeycomb_formatter.rb:95:in `example_pending'
That clearly rings a bell, but a trivial try at reproducing this using
pending brought up a weird issue:
From: /home/david/git/rspec_honeycomb_formatter/lib/rspec_honeycomb_formatter.rb @ line 99 RSpecHoneycombFormatter#example_pending: 95: def example_pending(notification) 96: @example_span.add_field('rspec.result', 'pending') 97: @example_span.add_field('name', notification.example.description) 98: @example_span.add_field('rspec.description', notification.example.description) => 99: require'pry';binding.pry 100: @example_span.add_field('rspec.message', strip_ansi(notification.message_lines.join("\n"))) 101: @example_span.add_field('rspec.backtrace', notification.formatted_backtrace.join("\n")) 102: @example_span.send 103: end  pry(#<RSpecHoneycombFormatter>)> notification.class => RSpec::Core::Notifications::PendingExampleFailedAsExpectedNotification  pry(#<RSpecHoneycombFormatter>)>
The class here is not the same as the initial report is complaining about.
And this does not fail.
PendingExampleFailedAsExpectedNotification does have
Since the original report didn’t have any more information attached (and for the sake of the pacing of this blog post) I went to honeycomb to see if other modules were exhibiting the same problem.
After a couple of clicks this was what I had:
The query selects by the error message and returns all examples with that error message. Clearly this has been going on for a while. Clicking through to the raw data I could jump to the full log of one of the runs:
Which brings us to this failure on github actions:
================ unlikely-toxin.delivery.puppetlabs.net, win-2008r2-x86_64 **F****FFFFFF Pending: (Failures listed here are expected and do not affect your suite's status) 1) package task install installs pry # Don't run on Windows On host `unlikely-toxin.delivery.puppetlabs.net' Failure/Error: @example_span.add_field('rspec.message', strip_ansi(notification.message_lines.join("\n"))) NoMethodError: undefined method `message_lines' for #<RSpec::Core::Notifications::SkippedExampleNotification:0x00007fe474773368>
This in turn I can look up in the source code. I’m assuming the following clause is the issue:
before(:each) do skip "Don't run on Windows" if operating_system_fact == 'windows' end
Putting that into the manual test case quickly confirmed that this was indeed the problem.
After being able to reproduce this locally, it was a matter of poking pry to figure out what needs to be done about it.
SkippedExampleNotification doesn’t have a
message_lines method, and needs to be handled differently.
The result has been posted in the “Fix missing message_lines method” PR and should be merged and released by the time you read this post.
Finally, to cross-check that this is the only problem we’ve been seeing, I’ve added a
rspec.message does-not-contain SkippedExampleNotification clause to the honeycomb query.
That new query did not return any results, increasing my confidence in having addressed all currently visible issues with the formatter.