Missing context error breaks Logger

[jdelStrother]

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:

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:

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?

[srprash]

Hi @jdelStrother
Apologies for missing this one. I'm taking a look and will get back soon. Thanks.

[srprash]

Hi @jdelStrother
We are aware of the situation when a S3 multipart upload happens, the background threads do not have the context and fail to begin a subsegment.
We have a task in our backlog to address this issue.