Repository: elastic/apm-agent-python

Issue:
exception logging an error with a big local variable
**Describe the bug**: 
apm python agent tries to log an exception with a big local variable in the execution stack results in unexpected behavior

**To Reproduce**

```python
# serializers.py
from rest_framework import serializers

class UploadFileSerializer(serializers.Serializer):
    myfile = serializers.ListField(child=serializers.FileField())

    def validate_myfile(self, value):
        raise serializers.ValidationError("Document upload size limit is exceeded")
# urls.py 
urlpatterns += [path('upload_file', UploadFile.as_view(), name='upload_file')]

# views.py
class UploadFile(GenericAPIView):
    serializer_class = UploadFileSerializer

    def post(self, request):
        data = request.data            # this local variable is the problem 
        serializer = self.serializer_class(data=data)
        try:
            if serializer.is_valid(raise_exception=True):
                return Response(status=status.HTTP_200_OK)
        except Exception as e:
            logger.exception(e)
            raise e
```
try to upload file > 3 mega (use multipart)
 
**Expected result**
return 400 because of ValidationError exception 
**Actual result**
```python
[ERROR] {'myfile': [ErrorDetail(string='Document upload size limit is exceeded', code='invalid')]}
Traceback (most recent call last):
  File "/home/me/myporject/api/views.py", line 127, in post
    if serializer.is_valid(raise_exception=True):
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/serializers.py", line 242, in is_valid
    raise ValidationError(self.errors)
rest_framework.exceptions.ValidationError: {'myfile': [ErrorDetail(string='Document upload size limit is exceeded', code='invalid')]}
Top level ElasticAPM exception caught - failed creating log record.
[ERROR] Unable to process log entry: cannot pickle '_io.BufferedRandom' object
Traceback (most recent call last):
  File "/home/me/myporject/api/views.py", line 127, in post
    if serializer.is_valid(raise_exception=True):
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/serializers.py", line 242, in is_valid
    raise ValidationError(self.errors)
rest_framework.exceptions.ValidationError: {'myfile': [ErrorDetail(string='Document upload size limit is exceeded', code='invalid')]}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/handlers/logging.py", line 81, in emit
    return self._emit(record)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/contrib/django/handlers.py", line 63, in _emit
    return super(LoggingHandler, self)._emit(record, request=request, **kwargs)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/handlers/logging.py", line 152, in _emit
    exception = handler.capture(self.client, exc_info=record.exc_info)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/events.py", line 96, in capture
    frames = get_stack_info(
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/utils/stacks.py", line 325, in get_stack_info
    result = get_frame_info(
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/utils/stacks.py", line 294, in get_frame_info
    f_locals = {varname: locals_processor_func(var) for varname, var in compat.iteritems(f_locals)}
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/utils/stacks.py", line 294, in <dictcomp>
    f_locals = {varname: locals_processor_func(var) for varname, var in compat.iteritems(f_locals)}
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/events.py", line 103, in <lambda>
    locals_processor_func=lambda local_var: varmap(
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/utils/__init__.py", line 66, in varmap
    name, dict((k, varmap(func, v, context, k, **kwargs)) for k, v in compat.iteritems(var.copy())), **kwargs
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/http/request.py", line 517, in copy
    return self.__deepcopy__({})
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/http/request.py", line 478, in __deepcopy__
    result.setlist(copy.deepcopy(key, memo), copy.deepcopy(value, memo))
  File "/usr/lib/python3.9/copy.py", line 146, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python3.9/copy.py", line 205, in _deepcopy_list
    append(deepcopy(a, memo))
  File "/usr/lib/python3.9/copy.py", line 172, in deepcopy
    y = _reconstruct(x, memo, *rv)
  File "/usr/lib/python3.9/copy.py", line 270, in _reconstruct
    state = deepcopy(state, memo)
  File "/usr/lib/python3.9/copy.py", line 146, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python3.9/copy.py", line 230, in _deepcopy_dict
    y[deepcopy(key, memo)] = deepcopy(value, memo)
  File "/usr/lib/python3.9/copy.py", line 172, in deepcopy
    y = _reconstruct(x, memo, *rv)
  File "/usr/lib/python3.9/copy.py", line 270, in _reconstruct
    state = deepcopy(state, memo)
  File "/usr/lib/python3.9/copy.py", line 146, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python3.9/copy.py", line 230, in _deepcopy_dict
    y[deepcopy(key, memo)] = deepcopy(value, memo)
  File "/usr/lib/python3.9/copy.py", line 161, in deepcopy
    rv = reductor(4)
TypeError: cannot pickle '_io.BufferedRandom' object

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 34, in inner
    response = get_response(request)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 115, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 113, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
    return view_func(*args, **kwargs)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/django/views/generic/base.py", line 71, in view
    return self.dispatch(request, *args, **kwargs)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/views.py", line 505, in dispatch
    response = self.handle_exception(exc)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/views.py", line 465, in handle_exception
    self.raise_uncaught_exception(exc)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/views.py", line 476, in raise_uncaught_exception
    raise exc
  File "/home/me/myporject/venv/lib/python3.9/site-packages/rest_framework/views.py", line 502, in dispatch
    response = handler(request, *args, **kwargs)
  File "/home/me/myporject/api/views.py", line 131, in post
    logger.exception(e)
  File "/usr/lib/python3.9/logging/__init__.py", line 1481, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/lib/python3.9/logging/__init__.py", line 1475, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python3.9/logging/__init__.py", line 1589, in _log
    self.handle(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 1599, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 1661, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 952, in handle
    self.emit(record)
  File "/home/me/myporject/venv/lib/python3.9/site-packages/elasticapm/handlers/logging.py", line 84, in emit
    sys.stderr.write(to_unicode(record.msg + "\n"))
TypeError: unsupported operand type(s) for +: 'ValidationError' and 'str'

During handling of the above exception, another exception occurred:
...

[25/Sep/2021 14:38:21] "POST /api/upload_file HTTP/1.1" 500 27
```

**Environment (please complete the following information)**
- OS: linux
- Python version: 3.9 tested on 3.6 and 3.8
- Framework and version [e.g. Django 2.1]:  django 2.2 and drf 3.10
- Agent version: 6.4.0



Discussion:
apmmachine: 
## :grey_exclamation: Build Aborted
  
  > There is a new build on-going so the previous on-going builds have been aborted.
  


<!-- BUILD BADGES-->
> _the below badges are clickable and redirect to their specific view in the CI or DOCS_
[![Pipeline View](https://img.shields.io/badge/pipeline-pipeline%20-green)](https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-python%2Fapm-agent-python-mbp%2FPR-1568/detail/PR-1568/1//pipeline) [![Test View](https://img.shields.io/badge/test-test-green)](https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-python%2Fapm-agent-python-mbp%2FPR-1568/detail/PR-1568/1//tests) [![Changes](https://img.shields.io/badge/changes-changes-green)](https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-python%2Fapm-agent-python-mbp%2FPR-1568/detail/PR-1568/1//changes) [![Artifacts](https://img.shields.io/badge/artifacts-artifacts-yellow)](https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-python%2Fapm-agent-python-mbp%2FPR-1568/detail/PR-1568/1//artifacts)   [![preview](https://img.shields.io/badge/elastic-observability-blue)](https://ci-stats.elastic.co/app/apm/services/apm-ci/transactions/view?rangeFrom=2022-06-08T08:36:34.626Z&rangeTo=2022-06-08T08:56:34.626Z&transactionName=BUILD+apm-agent-python%2Fapm-agent-python-mbp%2FPR-%7Bnumber%7D&transactionType=job&latencyAggregationType=avg&traceId=b9c357786157a1ebd65c3a244918d36f&transactionId=246dc0d432571900)

<!-- BUILD SUMMARY-->
<details><summary>Expand to view the summary</summary>
<p>

#### Build stats




* Start Time: 2022-06-08T08:46:34.626+0000


* Duration: 5 min 12 sec





</p>
</details>

<!-- TEST RESULTS IF ANY-->


<!-- STEPS ERRORS IF ANY -->












### Steps errors [![84](https://img.shields.io/badge/84%20-red)](https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-python%2Fapm-agent-python-mbp%2FPR-1568/detail/PR-1568/1//pipeline)
  <details><summary>Expand to view the steps failures</summary>
  <p>


> Show only the first 10 steps failures

  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/581/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-httpx-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/586/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-httplib2-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/591/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-prometheus_client-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/596/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-sanic-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/601/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-aiobotocore-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/606/log/?start=0">here</a></li>
<li>Description: <code>coverage-python-3.10-kafka-python-newest</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/612/log/?start=0">here</a></li>
<li>Description: <code>coverage-3.7-none</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/617/log/?start=0">here</a></li>
<li>Description: <code>coverage-3.8-none</code></l1>
</ul>
  
  
  
  
##### `Restore files previously stashed`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/622/log/?start=0">here</a></li>
<li>Description: <code>coverage-3.9-none</code></l1>
</ul>
  
  
  
  
##### `python coverage`
<ul>
<li>Took 0 min 0 sec . View more details <a href="https://apm-ci.elastic.co//blue/rest/organizations/jenkins/pipelines/apm-agent-python/pipelines/apm-agent-python-mbp/pipelines/PR-1568/runs/1/steps/625/log/?start=0">here</a></li>
<li>Description: <code>python3 -m coverage combine && python3 -m coverage xml</code></l1>
</ul>
  
  </p>
  </details>



## :robot: GitHub comments

To re-run your PR in the CI, just comment with:



- `/test` : Re-trigger the build.


- `/test linters` : Run the Python linters only.


- `/test full` : Run the full matrix of tests.


- `/test benchmark` : Run the APM Agent Python benchmarks tests.


- `run` `elasticsearch-ci/docs` : Re-trigger the docs validation. (use unformatted text in the comment!)




<!--COMMENT_GENERATED_WITH_ID_comment.id-->
apmmachine: ### :globe_with_meridians: Coverage report

Name | Metrics % (`covered/total`) | Diff
 --- | --- | ---
Packages | 100.0% (`68/68`) | :green_heart: 
Files | 100.0% (`227/227`) | :green_heart: 
Classes | 100.0% (`227/227`) | :green_heart: 
Lines | 89.574% (`17165/19163`) | :+1: 0.007
Conditionals | 76.632% (`3122/4074`) | :-1: -0.002

<!--COMMENT_GENERATED_WITH_ID_coverage-->

Patch:
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
index 37e0861b..493810f6 100644
--- a/CHANGELOG.asciidoc
+++ b/CHANGELOG.asciidoc
@@ -48,7 +48,7 @@ endif::[]
 * Fix return for `opentelemetry.Span.is_recording()` {pull}1530[#1530]
 * Fix error logging for bad SERVICE_NAME config {pull}1546[#1546]
 * Do not instrument old versions of Tornado > 6.0 due to incompatibility {pull}1566[#1566]
-
+* Fix a problem with our logging handler failing to report internal errors in its emitter {pull}1568[#1568]
 
 [[release-notes-6.x]]
 === Python Agent version 6.x
diff --git a/elasticapm/handlers/logbook.py b/elasticapm/handlers/logbook.py
index 54524d0a..aa7db006 100644
--- a/elasticapm/handlers/logbook.py
+++ b/elasticapm/handlers/logbook.py
@@ -75,15 +75,15 @@ class LogbookHandler(logbook.Handler):
 
         # Avoid typical config issues by overriding loggers behavior
         if record.channel.startswith("elasticapm.errors"):
-            sys.stderr.write(to_unicode(record.message + "\n"))
+            sys.stderr.write(to_unicode(record.message) + "\n")
             return
 
         try:
             return self._emit(record)
         except Exception:
             sys.stderr.write("Top level ElasticAPM exception caught - failed creating log record.\n")
-            sys.stderr.write(to_unicode(record.msg + "\n"))
-            sys.stderr.write(to_unicode(traceback.format_exc() + "\n"))
+            sys.stderr.write(to_unicode(record.message) + "\n")
+            sys.stderr.write(traceback.format_exc() + "\n")
 
             try:
                 self.client.capture("Exception")
diff --git a/elasticapm/handlers/logging.py b/elasticapm/handlers/logging.py
index c06183b5..03b6afc3 100644
--- a/elasticapm/handlers/logging.py
+++ b/elasticapm/handlers/logging.py
@@ -40,7 +40,6 @@ from elasticapm import get_client
 from elasticapm.base import Client
 from elasticapm.traces import execution_context
 from elasticapm.utils import wrapt
-from elasticapm.utils.encoding import to_unicode
 from elasticapm.utils.stacks import iter_stack_frames
 
 
@@ -74,15 +73,15 @@ class LoggingHandler(logging.Handler):
 
         # Avoid typical config issues by overriding loggers behavior
         if record.name.startswith(("elasticapm.errors",)):
-            sys.stderr.write(to_unicode(record.message) + "\n")
+            sys.stderr.write(record.getMessage() + "\n")
             return
 
         try:
             return self._emit(record)
         except Exception:
             sys.stderr.write("Top level ElasticAPM exception caught - failed creating log record.\n")
-            sys.stderr.write(to_unicode(record.msg + "\n"))
-            sys.stderr.write(to_unicode(traceback.format_exc() + "\n"))
+            sys.stderr.write(record.getMessage() + "\n")
+            sys.stderr.write(traceback.format_exc() + "\n")
 
             try:
                 self.client.capture("Exception")


Test patch:
diff --git a/tests/handlers/logbook/logbook_tests.py b/tests/handlers/logbook/logbook_tests.py
index 603c74b2..bf0da287 100644
--- a/tests/handlers/logbook/logbook_tests.py
+++ b/tests/handlers/logbook/logbook_tests.py
@@ -169,6 +169,15 @@ def test_logbook_handler_emit_error(capsys, elasticapm_client):
     assert "Oops" in err
 
 
+def test_logbook_handler_emit_error_non_str_message(capsys, elasticapm_client):
+    handler = LogbookHandler(elasticapm_client)
+    handler._emit = lambda record: 1 / 0
+    handler.emit(LogRecord("x", 1, ValueError("oh no")))
+    out, err = capsys.readouterr()
+    assert "Top level ElasticAPM exception caught" in err
+    assert "oh no" in err
+
+
 def test_logbook_handler_dont_emit_elasticapm(capsys, elasticapm_client):
     handler = LogbookHandler(elasticapm_client)
     handler.emit(LogRecord("elasticapm.errors", 1, "Oops"))
diff --git a/tests/handlers/logging/logging_tests.py b/tests/handlers/logging/logging_tests.py
index 27b44459..b5c0802a 100644
--- a/tests/handlers/logging/logging_tests.py
+++ b/tests/handlers/logging/logging_tests.py
@@ -229,7 +229,7 @@ def test_logger_setup():
 def test_logging_handler_emit_error(capsys, elasticapm_client):
     handler = LoggingHandler(elasticapm_client)
     handler._emit = lambda: 1 / 0
-    handler.emit(LogRecord("x", 1, "/ab/c/", 10, "Oops", [], None))
+    handler.emit(LogRecord("x", 1, "/ab/c/", 10, "Oops", (), None))
     out, err = capsys.readouterr()
     assert "Top level ElasticAPM exception caught" in err
     assert "Oops" in err
@@ -237,11 +237,20 @@ def test_logging_handler_emit_error(capsys, elasticapm_client):
 
 def test_logging_handler_dont_emit_elasticapm(capsys, elasticapm_client):
     handler = LoggingHandler(elasticapm_client)
-    handler.emit(LogRecord("elasticapm.errors", 1, "/ab/c/", 10, "Oops", [], None))
+    handler.emit(LogRecord("elasticapm.errors", 1, "/ab/c/", 10, "Oops", (), None))
     out, err = capsys.readouterr()
     assert "Oops" in err
 
 
+def test_logging_handler_emit_error_non_str_message(capsys, elasticapm_client):
+    handler = LoggingHandler(elasticapm_client)
+    handler._emit = lambda: 1 / 0
+    handler.emit(LogRecord("x", 1, "/ab/c/", 10, ValueError("oh no"), (), None))
+    out, err = capsys.readouterr()
+    assert "Top level ElasticAPM exception caught" in err
+    assert "oh no" in err
+
+
 def test_arbitrary_object(logger):
     logger.error(["a", "list", "of", "strings"])
     assert len(logger.client.events) == 1