DDTrace Connection Refused

[s33dunda]

Expected Behavior

The lambda runs without datadog tracer errors

Actual Behavior

The lambda has a connection error error, see stack trace.

Steps to Reproduce the Problem

1.Create a lambda

1. Give minimal code for logging with trace ids

require 'logger'
require 'datadog/lambda'

def lambda_handler(event:, context:)
    Datadog::Lambda.wrap(event, context) do
        time = Time.new
        logger = Logger.new($stdout, formatter: proc {|severity, datetime, progname, msg|
            "#{time.strftime("%Y-%m-%dT%H:%M:%S.%3NZ")} #{context.aws_request_id} [#{severity}] [dd.trace_id=#{Datadog.tracer.active_correlation.trace_id} dd.span_id=#{Datadog.tracer.active_correlation.span_id}] #{msg}"})
        logger.info(event.to_json)
    end
end

1. Lambda Config:

{
    "FunctionName": "EventBridgeLoggerDev",
    "FunctionArn": "arn:aws:lambda:us-west-2:127579856528:function:EventBridgeLoggerDev",
    "Runtime": "ruby2.5",
    "Role": "arn:aws:iam::127579856528:role/AWSLambdaBasicExecutionRole",
    "Handler": "main.lambda_handler",
    "CodeSize": 649,
    "Description": "Logs all events for an EventBridge to CloudWatch Logs",
    "Timeout": 10,
    "MemorySize": 128,
    "LastModified": "2020-10-29T20:34:28.917+0000",
    "CodeSha256": "Z7Lyamqk7gF+RgJXWFb5j+7AuboztcVR0EhVL115PhE=",
    "Version": "$LATEST",
    "Environment": {
        "Variables": {
            "DD_SERVICE": "EventBridgeLogger",
            "DD_LOGS_INJECTION": "true",
            "DD_ENV": "dev",
            "DD_LOG_LEVEL": "debug"
        }
    },
    "TracingConfig": {
        "Mode": "PassThrough"
    },
    "RevisionId": "fabd3c5b-e3e5-4aa4-ab0b-ec32c4a9c822",
    "Layers": [
        {
            "Arn": "arn:aws:lambda:us-west-2:464622532012:layer:Datadog-Ruby2-5:11",
            "CodeSize": 6891257
        }
    ],
    "State": "Active",
    "LastUpdateStatus": "Successful"
}

Specifications

• Datadog Lambda Layer version: 11 (arn:aws:lambda:us-west-2:464622532012:layer:Datadog-Ruby2-5:11)

• Ruby version: 2.5

Stacktrace

Response:
true

Request ID:
"243aa928-a647-486e-9054-ae0f7bd815ba"

Function logs:
-ruby25","functionname:EventBridgeLoggerDev","region:us-west-2","account_id:127579856528","memorysize:128","cold_start:true","runtime:Ruby 2.5.8","resource:EventBridgeLoggerDev","datadog_lambda:1.11.0","dd_trace:0.41.0"],"v":1}
2020-10-29T20:34:49.475Z 243aa928-a647-486e-9054-ae0f7bd815ba [INFO] [dd.trace_id=3637116462645295449 dd.span_id=1572314633988182015] {"key1":"value1","key2":"value2","key3":"value3"}D, [2020-10-29T20:34:49.495486 #9] DEBUG -- ddtrace: [ddtrace] (/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/patch_http.rb:41:in `rescue in request') couldn't add tracing context  to request odd number of arguments for Hash:
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/xray.rb:71:in `[]'
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/xray.rb:71:in `current_trace_context'
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/patch_http.rb:34:in `request'
/var/lang/lib/ruby/2.5.0/net/http.rb:1481:in `send_entity'
/var/lang/lib/ruby/2.5.0/net/http.rb:1269:in `post'
/var/lang/lib/ruby/2.5.0/net/http.rb:506:in `block in post'
/var/lang/lib/ruby/2.5.0/net/http.rb:910:in `start'
/var/lang/lib/ruby/2.5.0/net/http.rb:609:in `start'
/var/lang/lib/ruby/2.5.0/net/http.rb:504:in `post'
/var/runtime/lib/lambda_server.rb:47:in `send_response'
/var/runtime/lib/runtime.rb:48:in `<main>'
E, [2020-10-29T20:34:49.515616 #9] ERROR -- ddtrace: [ddtrace] (/opt/ruby/gems/2.5.0/gems/ddtrace-0.41.0/lib/ddtrace/transport/http/client.rb:35:in `rescue in send_request') Internal error during HTTP transport request. Cause: Failed to open TCP connection to 127.0.0.1:8126 (Connection refused - connect(2) for "127.0.0.1" port 8126) Location: /var/lang/lib/ruby/2.5.0/net/http.rb:939:in `rescue in block in connect'
I, [2020-10-29T20:34:49.516104 #9]  INFO -- ddtrace: [ddtrace] DATADOG TRACER CONFIGURATION - {"date":"2020-10-29T20:34:49+00:00","os_name":"x86_64-pc-linux-gnu","version":"0.41.0","lang":"ruby","lang_version":"2.5.8","env":"dev","enabled":true,"service":"EventBridgeLogger","agent_url":"http://127.0.0.1:8126?timeout=1","agent_error":"Datadog::Transport::InternalErrorResponse ok?: unsupported?:, not_found?:, client_error?:, server_error?:, internal_error?:true, payload:, error_type:Errno::ECONNREFUSED error:Failed to open TCP connection to 127.0.0.1:8126 (Connection refused - connect(2) for \"127.0.0.1\" port 8126)","debug":false,"analytics_enabled":false,"tags":"env:dev","runtime_metrics_enabled":false,"vm":"ruby-2.5.8","partial_flushing_enabled":false,"priority_sampling_enabled":false,"health_metrics_enabled":false}
W, [2020-10-29T20:34:49.516159 #9]  WARN -- ddtrace: [ddtrace] DATADOG TRACER DIAGNOSTIC - Agent Error: Datadog::Transport::InternalErrorResponse ok?: unsupported?:, not_found?:, client_error?:, server_error?:, internal_error?:true, payload:, error_type:Errno::ECONNREFUSED error:Failed to open TCP connection to 127.0.0.1:8126 (Connection refused - connect(2) for "127.0.0.1" port 8126)
D, [2020-10-29T20:34:49.535445 #9] DEBUG -- ddtrace: [ddtrace] (/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/patch_http.rb:41:in `rescue in request') couldn't add tracing context  to request odd number of arguments for Hash:
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/xray.rb:71:in `[]'
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/xray.rb:71:in `current_trace_context'
/opt/ruby/gems/2.5.0/gems/datadog-lambda-1.11.0/lib/datadog/lambda/trace/patch_http.rb:34:in `request'
/var/lang/lib/ruby/2.5.0/net/http.rb:1216:in `get'
/var/runtime/lib/lambda_server.rb:21:in `block in next_invocation'
/var/lang/lib/ruby/2.5.0/net/http.rb:910:in `start'
/var/runtime/lib/lambda_server.rb:20:in `next_invocation'
/var/runtime/lib/runtime.rb:30:in `<main>'
END RequestId: 243aa928-a647-486e-9054-ae0f7bd815ba
REPORT RequestId: 243aa928-a647-486e-9054-ae0f7bd815ba	Duration: 73.74 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 57 MB	Init Duration: 583.78 ms	

[tianchu]

@s33dunda this might be mistake in our doc, you also need to add the following code

Datadog::Lambda.configure_apm do |c|
# Enable the instrumentation
end

See https://docs.datadoghq.com/serverless/installation/ruby/#monitor-custom-business-logic for the complete code sample.

Sorry for the confusion, we are going to fix the doc now. Let me know if that fixes your issue.

[s33dunda]

@tianchu thanks for this. Now does it matter if you have no custom business logic you want to add?
Also, it looks as if there are no instrumentations to implement on a lambda this simple.
Am I missing sometihng?

[tianchu]

You need Datadog::Lambda.configure_apm to configure the Datadog APM tracer properly for Lambda, that's why the tracer was trying to send traces to the agent rather than logs.

You should be able to get traces for your functions by default. https://docs.datadoghq.com/serverless/installation/ruby/#monitor-custom-business-logic shows how to submit custom metrics or spans in addition to the auto instrumentation.

BTW, also make sure you do set up the forwarder lambda and the log subscription, in order for the forwarder to rely traces from logs to datadog https://docs.datadoghq.com/serverless/installation/ruby/#subscribe-the-datadog-forwarder-to-the-log-groups

[tianchu]

Do you mind letting me know whether the connection issue goes away after adding the code I mentioned?

[s33dunda]

Do you mind letting me know whether the connection issue goes away after adding the code I mentioned?

Yes this worked like a charm. FWIW I had to use a custom log formatter to have them correlate. The default format (and format suggested in the docs) do not suffice.

    logger = Logger.new($stdout, formatter: proc {|severity, datetime, progname, msg|
      "#{time.strftime("%Y-%m-%dT%H:%M:%S.%3NZ")} #{context.aws_request_id} [#{severity}] [dd.trace_id=#{Datadog.tracer.active_correlation.trace_id} dd.span_id=#{Datadog.tracer.active_correlation.span_id}] #{msg}\n"})

This validates with the default lambda grok parser for node:

node_json_rule %{_timestamp}\s+%{notSpace:lambda.request_id}\s+([)?+%{word:level}+(])?%{_trace_context}?(\sInvoke Error\s)?%{data::json}

The newline at the end was key.
Thank you @tianchu !

[tianchu]

Thanks @s33dunda I will take a look at the correlation issue, do you mind letting me know where you found the "format suggested in the docs" so I can fix it?

[s33dunda]

@tianchu thank you again! 👍

https://docs.datadoghq.com/tracing/connect_logs_and_traces/ruby#for-logging-in-ruby-applications
maybe the format should match the lambda ruby grok parser:

ruby_basic %{regex("[\w]")},\s[%{date("yyyy-MM-dd'T'HH:mm:ss.SSSSSS"):timestamp} #%{number}]\s+%{word:level} --\s*: %{data::keyvalue}

[tianchu]

Thanks, I'll log a ticket in our backlog to fix that!

[tianchu]

Closing, as the original issue has been resolved, while the trace and log correlation issue being tracked internally as a feature request.