aws / aws/aws-xray-sdk-ruby

Missing context error breaks Logger

Open
#47 2 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
Ruby
Stars
60
Forks
54
PR merge metrics
No merged PRs in 30d

Description

Please forgive me if this is deeply confused, but I've spent the entire day trying to pin down the source of this without much success.

I was trying to figure out why my Cloudfront logs looked like my lambda functions had just died without warning. It turns out that the functions were fine, but my `$logger` instance had stopped outputting to `STDOUT`.

I believe this handler reproduces the issue:

```ruby
require "aws-sdk-s3"
require "logger"
$logger = Logger.new($stdout)
require "aws-xray-sdk/lambda"

TEST_BUCKET = "my-s3-test-bucket

def lambda_handler(event:, context:)
$logger.info('## EVENT')
$logger.info(event.to_json)

# create a large file so that S3 upload uses multipart threads:
File.open("/tmp/testfile", "w"){ |f| 2000.times{ f.write "abcdefg" * 2000 } }
$logger.info "Uploading #{File.size '/tmp/testfile'} bytes"

# up to this point, everything is fine, $logger logs appear in Cloudwatch
Aws::S3::Resource.new.bucket(TEST_BUCKET).object("tmptest").upload_file("/tmp/testfile")

# And now $logger is broken, logs no longer appear in Cloudwatch
STDOUT.puts "Done (from STDOUT)" # this appears in cloudwatch
STDERR.puts "Done (from STDERR)" # this appears in cloudwatch
$logger.info "Done!" # this doesn't appear in cloudwatch!

return { status: "OK!", type: "tester" }

rescue Exception => e
$logger.error e.inspect
STDERR.puts e.inspect
raise
ensure
STDOUT.flush
STDERR.flush
end
```

after the S3 upload completes, `$logger.info` (or `$logger.fatal` etc) don't cause anything to appear in the Cloudwatch logs. However, STDOUT & STDERR continue to work fine.

If I remove the XRay library, or if I set `ENV["AWS_XRAY_CONTEXT_MISSING"] = "IGNORE_ERROR"`, then the logger continues to work fine. It seems to be something to do with XRay triggering in the threaded S3 multipart uploader, but I've been unable to reproduce it just by creating my own threads and trying to log from there.

An alternate fix/hack seems to be to add a Thread subclass in `Aws::S3` that automatically injects the XRay context:

```ruby
module Aws::S3
class Thread < ::Thread
def self.new(&block)
entity = XRay.recorder.current_entity
super { XRay.recorder.inject_context(entity, &block) }
end
end
end
```

Any suggestions what's happening here?

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.