Redis, S3 with Unexpected Results

[allcentury]

I have a code path that looks like this:

def signed_url
  presigned_url = ->(_name) { Aws::S3::Object.new(...).presigned_url(:get, expires_in: ttl.to_i) }
  if FeatureSwitcher.enabled?(:cache_s3_signed_url)
    Rails.cache.fetch("signed_url_#{public_id}", expires_in: ttl, force: skip_cache, race_condition_ttl: 10.seconds, &presigned_url)
  else
    presigned_url.call(nil)
  end
end

When I turn on the feature switch, I see traces in DD flame graph UI that looks like this:

When I turn off the feature switch, I no longer see any AWS commands likes3.get_object in the span list.

I think the first screen shot is a bug, presigned_url makes no external calls to AWS and I'm unsure why using a cache is making it look like it is.

ddtrace 0.31.0
aws-sdk-s3 1.23.0
rails 5.2.2.1

[marcotc]

Hi @allcentury, thank you for the issue report!

I'm able to reproduce the spans you are seeing in APM with this snippet:

mock_credentials = Struct.new(:credentials).new(Struct.new(:access_key_id, :secret_access_key, :session_token).new('access_key', 'secret_key', 'session'))
Aws::S3::Object.new('bucket', 'key', credentials: mock_credentials).presigned_url(:get, expires_in: 600)

It seems like this line calls all request handlers, including our own: https://github.com/aws/aws-sdk-ruby/blob/1c9c0a15c176b603df33b6a0ebd51cc96d3f826a/gems/aws-sdk-s3/lib/aws-sdk-s3/presigner.rb#L90

We'll investigate further to find out what's actually happening internally in aws-sdk-s3.

[allcentury]

@marcotc - wanted to follow up on this request and see what you thought (including tags because this feels like a bug to us). Happy to contribute a fix if you can point me in the right direction.

[sj26]

We're seeing spans for aws.command s3.get_object when using the presigner directly, too:

Aws::S3::Presigner.new.presigned_url(:get_object, bucket: bucket, key: key, expires_in: expiry)

[sj26]

The implementation of presigning within the aws sdk s3 gem:
https://github.com/aws/aws-sdk-ruby/blob/4fb294e2dda448abd28c8d520a75d73303500213/gems/aws-sdk-s3/lib/aws-sdk-s3/presigner.rb#L126

seems to use the regular request cycle but with the guts ripped out and faked:
https://github.com/aws/aws-sdk-ruby/blob/4fb294e2dda448abd28c8d520a75d73303500213/gems/aws-sdk-s3/lib/aws-sdk-s3/presigner.rb#L194-L249

That might be tricking the instrumentation into thinking a regular request is taking place even though it isn't.

[marcotc]

👋 @sj26, I've opened a PR to address this issue, it should be reviewed and shipped in the coming releases: #1494