NoMethodError: undefined method 'ntuples' for nil with `PG#async_exec`

[agrobbin]

Current behaviour

I'm having trouble tracking down the root cause here, but we've occasionally seen exceptions in CI from ddtrace's PG instrumentation:

NoMethodError: undefined method `ntuples' for nil
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:177:in `annotate_span_with_result!'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:136:in `block in trace'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/trace_operation.rb:199:in `block in measure'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/span_operation.rb:150:in `measure'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/trace_operation.rb:199:in `measure'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/tracer.rb:385:in `start_span'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/tracer.rb:159:in `block in trace'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/context.rb:45:in `activate!'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/tracer.rb:158:in `trace'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing.rb:18:in `trace'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:105:in `trace'
    vendor/bundle/ruby/3.3.0/gems/ddtrace-1.19.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:51:in `async_exec'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:55:in `block (2 levels) in raw_execute'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
    vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:54:in `block in raw_execute'
    vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:53:in `raw_execute'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/database_statements.rb:521:in `internal_execute'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:101:in `begin_db_transaction'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:373:in `materialize!'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:449:in `block in begin_transaction'
    vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/transaction.rb:416:in `begin_transaction'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/database_statements.rb:352:in `begin_transaction'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:149:in `block in setup_fixtures'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:148:in `each'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:148:in `setup_fixtures'
    vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.3.2/lib/active_record/test_fixtures.rb:10:in `before_setup'

We've been unable to track down the specific cause, as it's not consistent, nor reproducible.

Our tracing configuration is:

I, [2024-03-06T02:18:00.036801 #3827]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - PROFILING - {"profiling_enabled":false}
I, [2024-03-06T02:18:00.037976 #3827]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-03-06T02:18:00+00:00","os_name":"x86_64-pc-linux","version":"1.19.0","lang":"ruby","lang_version":"3.3.0","env":null,"service":"atlas-rails","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":true,"vm":"ruby-3.3.0","health_metrics_enabled":false}
I, [2024-03-06T02:18:01.072878 #3827]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - TRACING - {"enabled":true,"agent_url":null,"analytics_enabled":false,"sample_rate":null,"sampling_rules":null,"integrations_loaded":"rails@7.1.3.2,active_record@7.1.3.2,active_support@7.1.3.2,sidekiq@7.2.1,elasticsearch@8.2.2,pg@1.5.3,redis@5.0.8,http@3.3.0,faraday@2.9.0,httpclient@2.8.3,httprb@5.1.1","partial_flushing_enabled":false,"priority_sampling_enabled":false,"integration_rails_analytics_enabled":"","integration_rails_analytics_sample_rate":"1.0","integration_rails_enabled":"true","integration_rails_service_name":"","integration_rails_distributed_tracing":"true","integration_rails_request_queuing":"exclude_request","integration_rails_exception_controller":"","integration_rails_middleware":"true","integration_rails_middleware_names":"false","integration_rails_template_base_path":"views/","integration_active_record_analytics_enabled":"false","integration_active_record_analytics_sample_rate":"1.0","integration_activ

I'm not sure why the startup log was truncated, but hopefully that is helpful. I wish I could provide more detail beyond this, but am not sure where to look for more detail.

Expected behaviour

The PG instrumentation shouldn't raise an exception.

Environment

• ddtrace version: v1.19.0
• Configuration block (Datadog.configure ...):
• Ruby version: v3.3.0
• Operating system: Ubuntu 22.04.4
• Relevant library versions: Rails 7.1.3.2

[shawnacscott]

My application also experienced this error on version 1.20.0 when upgrading from version 1.18.0. We were able to resolve the error by downgrading back to 1.18.0. We intend to debug version 1.20.0 further and will update this report with any findings.

[shawnacscott]

After several hours of debugging, we haven't reached a reproducible and specific cause either. However, we do have a theory that I hope can be helpful to others investigating this issue.

#2505 resulted in #2522 that touched the code that is erroring here, and there was an interesting discussion of that code in that PR:

If the optional code block is given, it will be passed result as an argument, and the PG::Result object will automatically be cleared when the block terminates. In this instance, conn.exec returns the value of the block.

According to the documentation, the PG::Result would be garbage collected once the block ended.

Our theory is that something else about our application state is causing the PG:Result to be garbage collected before this ddtrace code executes, causing the PG:Result to be nil and therefore throwing this error.

This is just a theory, but after tracing through our own application code and several other gem histories, we could not find any other explanation for why we would suddenly be missing a PG:Result object that had previously always been available.

Hope this can help someone else dig deeper than us and decide the right path forward on this! For us, pinning to our current gem version (1.18.0) stopped this error from occurring for now.

Environment

ddtrace version: v1.20.0 (we have since rolled back to 1.18.0, but 1.20.0 is the version that errored)
Running on GitHub Actions for CI. DataDog configuration output:

I, [2024-03-06T19:11:25.309601 #5539]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - PROFILING - {"profiling_enabled":false}
I, [2024-03-06T19:11:25.313572 #5539]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-03-06T19:11:25+00:00","os_name":"x86_64-pc-linux","version":"1.20.0","lang":"ruby","lang_version":"3.3.0","env":null,"service":"rake","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":false,"vm":"ruby-3.3.0","health_metrics_enabled":false}

Configuration block:

# frozen_string_literal: true

if ENV.fetch("DISABLE_DATADOG_AGENT", nil) != "true"
  require "ddtrace"
  require "datadog/statsd"

  # Create a global StatsD client that can be used to
  # record custom metrics in DataDog.
  #
  # Notes about the chosen configuration:
  # This configuration forces DataDog to work in
  # single-threaded mode and to send each metric as it
  # is recorded. This overrides the default behavior of
  # dogstatsd-ruby v5.x+ so that we can avoid the
  # complexities of closing threads.
  #
  # This can have a latency cost because each time the
  # metric buffer receives one item, it will flush the
  # metrics to the agent process via UDP. This will block
  # the process until the metric has been sent, which can
  # take up to 1-2 milliseconds. We should keep an eye on
  # performance as we begin adding custom metrics, and as
  # our traffic increases and tune this if/when needed.
  # More info:
  # https://github.com/DataDog/dogstatsd-ruby/issues/179
  $ddstats = Datadog::Statsd.new(
    "localhost",
    8125,
    single_thread: true,
    buffer_max_pool_size: 1,
  )

  Datadog.configure do |c|
    datadog_service_name = "app name here"

    c.env = ENV.fetch("DD_ENV", Rails.env)
    c.tracing.enabled = Rails.env.production?
    c.tracing.instrument :rails, service_name: datadog_service_name
    c.tracing.instrument :faraday, service_name: datadog_service_name
    c.tracing.instrument :http, service_name: datadog_service_name
  end
end

Ruby version: v3.3.0
Relevant library versions:

• Rails 7.1.3.2
• Puma 6.4.2
• Rack 3.0.9.1

[TonyCTHsu]

👋 @agrobbin @shawnacscott Thanks for reporting, I will have a look!

[TonyCTHsu]

👋 @agrobbin @shawnacscott Unfortunately, I was not able to reproduce this.

I understand this happened sporadically on your CI with 1.20.0, but are you confident that 1.18.0 never occur such error?

I have no clue how rolling back to 1.18.0 mitigates such issue, since there was no changes for pg instrumentation between 1.18.0 and 1.20.0. According to the code stack provided, I have suspicion this might be caused by ActiveRecord's asynchronous API.

Although I was not able to reproduce this scenario with nil instead of PG::Result, I don't mind providing a fix with nil check to safe guard this. #3511

[agrobbin]

@TonyCTHsu I unfortunately can't confirm if this was happening on v1.18.0 or not. We did run v1.18.0 with CI visibility turned on, but it was only for ~10 days in the beginning of January, and I'm just not sure if we saw this error in that time. My gut says we did see the error, but crawling back through those logs is not something I'll be able to do at the moment.

Re: Active Record's async API, we are using load_async in our application (I actually opened another issue related to that in #3465), which was a relatively recent introduction, but I can't say with any degree of certainty whether this error started popping up before / after that was introduced. It being intermittent has definitely made this quite a bit harder to track down!

That said, I really appreciate the quick resolution in #3511! ❤️

[delner]

Agreed with @TonyCTHsu here; nil check is the fastest bandaid. Better to have a span w/o a tag than an error.

It does worry me a little bit that might be covering up some seemingly non-deterministic tagging though. My recommendation is to add a comment to the yield(propagated_sql_statement, proc do |result| statement that explains the possible nil result and links to this issue, so we don't forget about this entirely.

[shawnacscott]

Thank you @TonyCTHsu for the extremely fast mitigation!

I have no clue how rolling back to 1.18.0 mitigates such issue, since there was no changes for pg instrumentation between 1.18.0 and 1.20.0. According to the code stack provided, I have suspicion this might be caused by ActiveRecord's asynchronous API.

I agree, it's unclear to me why that resolved this for us as well. All I can say is that we ran 1.18.0 for two months on an app deployed several times a day and never experienced this error previously 🤷‍♀️ . In addition, we are explicitly and intentionally not using any of ActiveRecord's async functionality in our application, although of course that doesn't preclude some included library from doing so under the hood.

I do agree that I see nothing in ddtrace itself that seems like it should have caused or mitigated the error from version to version, so I am also baffled how rolling back fixed it. But we tried a number of times to force a failure on 1.18.0 after rolling back and didn't observe any failures. That being said, we upgraded ddtrace as part of a monthly bundle update where a number of other gems changed versions as well, so it's totally plausible that the pg gem or ActiveRecord changing is the real culprit.

Regardless, I appreciate your help and you adding the nil check for 1.21!

[ivoanjo]

Hey @agrobbin && @shawnacscott, 1.21.0 has just been released with the fix 🎉! Give it a try 👍