Stop an unreachable Sentry from failing GDK commands or printing errors

José M. Requena Plensrequested to merge
gitlab-community/gitlab-org/gitlab-development-kit:jmrp-gdk-sentry-exit-flush into main

What does this merge request do and why?

With telemetry enabled, a GDK command that succeeded exits with status 1 when an error report could not be sent while it ran and Sentry is still unreachable as the process ends. Each report that cannot be sent also prints two ERROR -- sentry lines in the command's output, whether or not the exit status changes.

Closes #2434 (closed), which reports GDK commands erroring out when Sentry cannot be reached and quotes those two lines. A later note there found the exit code unchanged in its reproduction, and the issue was retitled to suppressing the lines. The exit code does change when the process ends while a report about a failed send is still pending, as the jobs below show, so this merge request fixes both: the first commit stops the exit status from changing, and the second hides the lines unless GDK debugging is enabled.

Sentry.init registers at_exit { Sentry.close }. When a report fails to send, the transport keeps a client report counting it, and close sends that client report on exit. If Sentry is still unreachable, HTTPTransport#send_data raises Sentry::ExternalError inside that exit handler, nothing rescues it, and Ruby exits with status 1. The path (Sentry.close, Client#flush, Transport#flush, send_envelope, send_data) is the same in sentry-ruby 5.28.1, which GDK locks, and in 7.1.0.

This has been failing image builds on main. In each of these jobs a GDK Ruby process finished its work and then exited 1 with Net::OpenTimeout (Sentry::ExternalError) raised from sentry-ruby.rb:257:in `block in init':

Each of them also shows the two ERROR -- sentry lines for every report that could not be sent. Those builds run with GDK_DEBUG=true (.gitlab-ci.yml sets it, and the image's Dockerfile sets it as ENV), so with the second commit their logs still show the lines; the first commit is what keeps those processes from exiting 1.

In the first commit, GDK::Telemetry.init_sentry sets config.send_client_reports = false. Client reports only count the events the SDK dropped, and with GDK's configuration they are the only thing close sends, so the exit handler no longer contacts Sentry and the process exits with the command's status. Error reports themselves are sent as before; what GDK gives up is those counts.

I did not rescue the error in an exit handler of our own, which is what !5961 (closed) did. That handler runs before Sentry's and covers a report that failed earlier, but not one still in flight when the process exits: that report fails after the handler ran, and Sentry's own close then sends a client report for it and raises. gdk update can end that way, since check_gdk_available runs in its ensure, after Successfully updated, and reports when the gdk command is missing. Step 3 below shows the difference.

The second commit hides Sentry's own log lines, ERROR -- sentry: ** [Sentry] Event sending failed and ERROR -- sentry: ** [Sentry] exception happened in background worker among them, unless GDK debugging is enabled. init_sentry set Sentry's SDK logger to WARN; it now sets it to FATAL, a level at which Sentry logs nothing, and keeps WARN when GDK debugging is enabled (gdk.debug: true or GDK_DEBUG=true, which GDK::Output.debug checks too), so with debugging enabled the lines show as they do today. Not reaching Sentry says nothing about the command being run, and the lines go to standard output in the middle of the command's own. Error reports are still sent, and nothing GDK prints itself changes.

One more thing I left alone, as context: capture_exception returns early when CI is 1, true or yes (f3b015bd). support/docker passes --build-arg CI="$CI" to both image builds, but neither support/ci/Dockerfile.integration nor support/ci/Dockerfile.verify declares ARG CI, so their RUN steps do not see it and those builds report to Sentry. Whether they should is a separate decision, and the exit status is just as wrong outside CI.

How to set up and validate locally

  1. Make Sentry unreachable. 10.255.255.1 does not route, so the connection times out as it did in CI:

    echo '10.255.255.1 new-sentry.gitlab.net' | sudo tee -a /etc/hosts

  2. From the GDK root, report an exception the way GDK::Telemetry.capture_exception does once its checks pass, and let the process finish normally:

    bundle exec ruby -r ./lib/gdk -e 'GDK::Telemetry.init_sentry; Sentry.capture_exception(StandardError.new("first")); sleep 3; puts "done"'; echo "exit status: $?"

    On main this prints done, the two ERROR -- sentry lines and a Sentry::ExternalError backtrace, and ends with exit status: 1. On this branch it prints done and nothing from Sentry, and ends with exit status: 0.

  3. Report a second exception just before the process ends, so it is still being sent at exit:

    bundle exec ruby -r ./lib/gdk -e 'GDK::Telemetry.init_sentry; Sentry.capture_exception(StandardError.new("first")); sleep 3; Sentry.capture_exception(StandardError.new("second")); sleep 0.2; puts "done"'; echo "exit status: $?"

    On main this ends with exit status: 1, and so it does with an exit handler that rescues Sentry.close. On this branch it prints done and nothing from Sentry, and ends with exit status: 0.

  4. Run the command of step 2 again with GDK debugging enabled:

    GDK_DEBUG=true bundle exec ruby -r ./lib/gdk -e 'GDK::Telemetry.init_sentry; Sentry.capture_exception(StandardError.new("first")); sleep 3; puts "done"'; echo "exit status: $?"

    On this branch the two ERROR -- sentry lines show as they do on main, and it still ends with exit status: 0.

  5. Remove the line from /etc/hosts.

What I ran

All of it in Docker, in ruby:3.3.11 and ruby:3.4.10 (the versions in .tool-versions), with the gems from Gemfile.lock.

  • The first commit's .init_sentry example expects send_client_reports = false. Without that commit's change in lib/gdk/telemetry.rb it is the one failure of the whole suite (2474 examples, 1 failure, seed 4242, Ruby 3.3.11), and it fails on both Ruby versions when the spec file runs on its own.
  • The second commit's .init_sentry examples expect the SDK logger at FATAL, and log the line Sentry logs when it cannot send an event through the logger init_sentry configured: it is not printed, and with GDK debugging enabled it is. Against the first commit's lib/gdk/telemetry.rb, two of the three examples fail on both Ruby versions, and they are the only failures of the whole suite (2476 examples, 2 failures, seed 4242, Ruby 3.3.11). At the first commit, its one .init_sentry example passes on both versions.
  • The whole suite with both commits, bundle exec rspec as make rspec runs it: 2476 examples, 0 failures on both Ruby versions, with seed 4242 and a random seed each, and git diff --exit-code clean afterwards.
  • bundle exec rubocop --config .rubocop-gdk.yml lib/gdk/telemetry.rb spec/lib/gdk/telemetry_spec.rb: no offenses on either version, at either commit.
  • Running spec/lib/gdk/telemetry_spec.rb on its own fails 10 examples on main already, most of them with undefined method for postgresql and, depending on the seed, one with another component setting such as action_cable or siphon: stub_gdk_yaml builds a GDK::Config without the settings components add, which only the real GDK.config patches into the class, so they exist only after another spec has loaded it. The same 10 fail with both commits, which is why I ran the whole suite above.
  • The validation steps exactly as written above, in a container with new-sentry.gitlab.net mapped to 10.255.255.1, twice each on both Ruby versions. main exits 1 in steps 2, 3 and 4 and prints the two ERROR -- sentry lines for each report. With the first commit alone, all three exit 0 and still print the lines. With both commits, steps 2 and 3 exit 0 and print nothing from Sentry, and step 4 exits 0 and prints the two lines. An exit handler rescuing Sentry.close instead of the first commit exits 0 in step 2 and 1 in step 3.
  • A standalone script with the real gem and the second case, with sentry-ruby 5.28.1 and 7.1.0: exit 1 as on main, exit 1 with an exit handler rescuing Sentry.close, and exit 0 with send_client_reports = false. With a local stand-in for Sentry that answers 200, send_client_reports = false still delivers both error reports and exits 0, on both gem versions.

Impacted categories

The following categories relate to this merge request:

Merge request checklist

  • This MR references an issue describing the change.
  • This change is backward compatible. If not, include steps to communicate to users.
  • Tests added for new functionality. If not, raise an issue to follow-up.
  • Observability added/updated (logging, metrics, tracing).
  • Documentation added/updated.
  • Announcement added for notable changes.
  • gdk doctor test added.

Merge request reports