Skip to content

Server panic when sending events to APM server #245

Closed
@richcto

Description

@richcto

Extension version 1.1.0, elastic-apm version 6.10.0

Even though all errors are sent to Elastic APM endpoint, I still get errors logged in lambda log group. See below:

`

{ "log.level": "info", "@timestamp": "2022-07-18T17:17:41.973Z", "log.origin": { "file.name": "extension/http_server.go", "file.line": 48 }, "message": "Extension listening for apm data on :8200", "ecs.version": "1.6.0" }

{ "log.level": "info", "@timestamp": "2022-07-18T17:17:43.124Z", "log.origin": { "file.name": "logsapi/subscribe.go", "file.line": 123 }, "message": "Extension listening for Lambda Logs API events on 169.254.79.130:42187", "ecs.version": "1.6.0" }
LOGS Name: elastic-apm-extension State: Subscribed Types: [platform]
{ "log.level": "info", "@timestamp": "2022-07-18T17:17:43.277Z", "log.origin": { "file.name": "apm-lambda-extension/main.go", "file.line": 129 }, "message": "Waiting for next event...", "ecs.version": "1.6.0" }
START RequestId: 3dccf0cb-7d34-4cfd-b73e-f562ad914351 Version: $LATEST
EXTENSION Name: elastic-apm-extension State: Ready Events: [SHUTDOWN,INVOKE]
{"time_stamp": "2022-07-18 17:17:51,677","log_level": "INFO","log_message": Processing event: {'key1': 'value1', 'key2': 'value2', 'key3': 'value3'}}
{"time_stamp": "2022-07-18 17:17:51,678","log_level": "INFO","log_message": Initialising for event: {'key1': 'value1', 'key2': 'value2', 'key3': 'value3'}}
2022/07/18 17:17:51 http: panic serving 127.0.0.1:58162: send on closed channel
goroutine 40 [running]:
net/http.(*conn).serve.func1()
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:1802 +0xb9
panic({0x7948e0, 0x87ea20})
/usr/local/Cellar/go/1.17.6/libexec/src/runtime/panic.go:1047 +0x266
elastic/apm-lambda-extension/extension.handleIntakeV2Events.func1({0x88acf0, 0xc00032c700}, 0xc0000f2f00)
/Users/richardjones/Documents/CTO/scratch/apm-aws-lambda/apm-lambda-extension/extension/route_handlers.go:97 +0x485
net/http.HandlerFunc.ServeHTTP(0xc0ad834fe8b93d8b, {0x88acf0, 0xc00032c700}, 0xc00032c700)
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:2047 +0x2f
net/http.(*ServeMux).ServeHTTP(0xc0000ca797, {0x88acf0, 0xc00032c700}, 0xc0000f2f00)
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:2425 +0x149
net/http.serverHandler.ServeHTTP({0x889f10}, {0x88acf0, 0xc00032c700}, 0xc0000f2f00)
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:2879 +0x43b
net/http.(*conn).serve(0xc000246000, {0x88cfe0, 0xc000278780})
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:1930 +0xb08
created by net/http.(*Server).Serve
/usr/local/Cellar/go/1.17.6/libexec/src/net/http/server.go:3034 +0x4e8
[ERROR] KeyError: 'Records'Traceback (most recent call last):  File "/var/lang/lib/python3.8/site-packages/elasticapm/contrib/serverless/aws.py", line 116, in decorated    self.response = func(*args, **kwds)  File "/var/task/lambda_function.py", line 93, in lambda_handler    class_instance = globals()[cls](logger, event)  File "/var/task/processors/cloudwatch_distributor.py", line 44, in init    self.event = event['Records']
{"time_stamp": "2022-07-18 17:17:51,684","log_level": "ERROR","log_message": Failed to submit message: "Unable to reach APM Server: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response')) (url: http://localhost:8200/intake/v2/events)"}
Traceback (most recent call last):
File "/var/runtime/urllib3/connectionpool.py", line 699, in urlopen
httplib_response = self._make_request(
File "/var/runtime/urllib3/connectionpool.py", line 445, in _make_request
six.raise_from(e, None)
File "", line 3, in raise_from
File "/var/runtime/urllib3/connectionpool.py", line 440, in _make_request
httplib_response = conn.getresponse()
File "/var/lang/lib/python3.8/http/client.py", line 1348, in getresponse
response.begin()
File "/var/lang/lib/python3.8/http/client.py", line 316, in begin
version, status, reason = self._read_status()
File "/var/lang/lib/python3.8/http/client.py", line 285, in _read_status
raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/var/lang/lib/python3.8/site-packages/elasticapm/transport/http.py", line 84, in send
response = self.http.urlopen(
File "/var/runtime/urllib3/poolmanager.py", line 375, in urlopen
response = conn.urlopen(method, u.request_uri, **kw)
File "/var/lang/lib/python3.8/site-packages/elasticapm/instrumentation/packages/base.py", line 205, in call_if_sampling
return wrapped(*args, **kwargs)
File "/var/runtime/urllib3/connectionpool.py", line 755, in urlopen
retries = retries.increment(
File "/var/runtime/urllib3/util/retry.py", line 532, in increment
raise six.reraise(type(error), error, _stacktrace)
File "/var/runtime/urllib3/packages/six.py", line 769, in reraise
raise value.with_traceback(tb)
File "/var/runtime/urllib3/connectionpool.py", line 699, in urlopen
httplib_response = self._make_request(
File "/var/runtime/urllib3/connectionpool.py", line 445, in _make_request
six.raise_from(e, None)
File "", line 3, in raise_from
File "/var/runtime/urllib3/connectionpool.py", line 440, in _make_request
httplib_response = conn.getresponse()
File "/var/lang/lib/python3.8/http/client.py", line 1348, in getresponse
response.begin()
File "/var/lang/lib/python3.8/http/client.py", line 316, in begin
version, status, reason = self._read_status()
File "/var/lang/lib/python3.8/http/client.py", line 285, in _read_status
raise RemoteDisconnected("Remote end closed connection without"
urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/var/lang/lib/python3.8/site-packages/elasticapm/transport/base.py", line 275, in _flush
self.send(data, forced_flush=forced_flush)
File "/var/lang/lib/python3.8/site-packages/elasticapm/transport/http.py", line 98, in send
raise TransportException(message, data, print_trace=print_trace)
{ "log.level": "info", "@timestamp": "2022-07-18T17:17:51.705Z", "log.origin": { "file.name": "apm-lambda-extension/main.go", "file.line": 129 }, "message": "Waiting for next event...", "ecs.version": "1.6.0" }

`

ELASTIC_APM_LAMBDA_APM_SERVER variable: https://.apm.us-east-1.aws.cloud.es.io:443

It is odd that is working perfectly but still reporting this exception. I could live with it but it's making a mess of the logs and making it difficult to read the real error.

Any ideas?

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingcommunityIssues and PRs created by the community

Type

No type

Projects

No projects

Relationships

None yet

Development

No branches or pull requests

Issue actions