[APM] Kibana errors on "constructor" keyword in APM stack trace documents

[adpeters]

Versions
Kibana: 7.12.1
APM Server: 7.12.1
Elasticsearch: 7.12.1

Kibana cannot view certain error documents sent by APM. I am using the latest python APM agent (6.1.3) with a Flask application. When there are error stack traces sent by APM the documents contain the variables at the time of the error, which sometimes contain a "constructor" field. In particular, in my case this is true for SQL-Alchemy errors, but it could exist in many cases. With recent changes to the elasticsearch-js library, Kibana errors when trying to parse these documents, so they cannot be viewed in the APM error view. I believe this is related to elastic/elasticsearch-js#1408. There is a configuration value for that library to get around this issue by allowing the "constructor" keyword, but I'm not sure if there's a way to specify this configuration in Kibana.

A simple way to reproduce this is:

• Run latest Elastic stack with Elastic, Kibana, APM-Server
• Run a python application with the python APM agent
• Trigger an error within a function that has a parameter called "constructor"
• Attempt to view that particular error in the Kibana APM error view (it displays in the list view fine, but cannot be displayed in detail).

The error in the Kibana logs is:
{"type":"log","@timestamp":"2021-05-06T16:43:44+00:00","tags":["error","http"],"pid":6,"message":"WrappedElasticsearchClientError: Object contains forbidden prototype property\n at /usr/share/kibana/x-pack/plugins/observability/server/utils/unwrap_es_response.js:66:11\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (internal/process/task_queues.js:93:5)\n at /usr/share/kibana/x-pack/plugins/apm/server/lib/errors/get_error_group_sample.js:75:18\n at /usr/share/kibana/x-pack/plugins/apm/server/routes/create_api/index.js:180:26\n at Router.handle (/usr/share/kibana/src/core/server/http/router/router.js:163:30)\n at handler (/usr/share/kibana/src/core/server/http/router/router.js:124:50)\n at exports.Manager.execute (/usr/share/kibana/node_modules/@hapi/hapi/lib/toolkit.js:60:28)\n at Object.internals.handler (/usr/share/kibana/node_modules/@hapi/hapi/lib/handler.js:46:20)\n at exports.execute (/usr/share/kibana/node_modules/@hapi/hapi/lib/handler.js:31:20)\n at Request._lifecycle (/usr/share/kibana/node_modules/@hapi/hapi/lib/request.js:370:32)\n at Request._execute (/usr/share/kibana/node_modules/@hapi/hapi/lib/request.js:279:9) {\n originalError: DeserializationError: Object contains forbidden prototype property\n at Serializer.deserialize (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Serializer.js:43:13)\n at onBody (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:299:41)\n at IncomingMessage.onEnd (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:260:11)\n at IncomingMessage.emit (events.js:327:22)\n at endReadableNT (internal/streams/readable.js:1327:12)\n at processTicksAndRejections (internal/process/task_queues.js:80:21)..."}

I'm not sure exactly where the best place to address this issue is, or if there is a configuration workaround of some sort.

[elasticmachine]

Pinging @elastic/apm-ui (Team:apm)

[sorenlouv]

Hi @adpeters

Thanks for the detailed report. Can you add a screenshot of the error so we have the full context? Thanks.

[adpeters]

Hi @sqren, thanks for responding. Here's a screenshot of the error showing up in Kibana:

Let me know if you need any other information or have any suggestions!

[sorenlouv]

Great, thanks. One more thing: can you add a sample document that causes this issue?
You should be able to find a sample doc for this error via Kibana's Dev Tools:

GET apm*/_search
{
  "size": 1, 
  "query": {
    "term": {
      "error.grouping_key": "641d2..."
    }
  }
}

[adpeters]

Sure, here's a sample error document:

kibana_error_sample.txt

[sorenlouv]

Great, I can repro now with the following:

POST apm-8.0.0-error-000002/_doc
{
  "parent": {
    "id": "efe30657a4e6c4f8"
  },
  "agent": {
    "name": "python",
    "version": "6.1.3"
  },
  "process": {
    "args": [
      "REDACTED/python3.9/site-packages/flask/__main__.py",
      "run"
    ],
    "pid": 53002,
    "ppid": 52763
  },
  "source": {
    "ip": "127.0.0.1"
  },
  "error": {
    "exception": [
      {
        "stacktrace": [
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "filename": "flask/app.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask/app.py",
            "line": {
              "number": 2446,
              "context": "                response = self.full_dispatch_request()"
            },
            "function": "wsgi_app",
            "module": "flask.app",
            "context": {
              "pre": [
                "            try:",
                "                ctx.push()"
              ],
              "post": [
                "            except Exception as e:",
                "                error = e"
              ]
            },
            "vars": {
              "start_response": "<function WSGIRequestHandler.run_wsgi.<locals>.start_response at 0x12151e1f0>",
              "e": "Exception('error raised')",
              "ctx": "<RequestContext 'http://localhost:5000/login' [GET] of REDACTED.app>",
              "self": "<Flask 'REDACTED.app'>",
              "error": "Exception('error raised')",
              "environ": {
                "wsgi.version": [
                  "1",
                  "0"
                ],
                "wsgi.multiprocess": false,
                "<truncated>": "(22 more elements)",
                "wsgi.run_once": false,
                "wsgi.url_scheme": "http",
                "wsgi.multithread": true,
                "werkzeug.socket": "<socket.socket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 5000), raddr=('127.0.0.1', 64653)>",
                "wsgi.input": "<_io.BufferedReader name=5>",
                "SERVER_SOFTWARE": "Werkzeug/2.0.0",
                "werkzeug.server.shutdown": "<function WSGIRequestHandler.make_environ.<locals>.shutdown_server at 0x12151e280>",
                "wsgi.errors": "<_pydevd_bundle.pydevd_io.IORedirector object at 0x101c4aee0>"
              }
            }
          },
          {
            "exclude_from_grouping": false,
            "library_frame": true,
            "filename": "flask/app.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask/app.py",
            "line": {
              "number": 1951,
              "context": "            rv = self.handle_user_exception(e)"
            },
            "function": "full_dispatch_request",
            "module": "flask.app",
            "context": {
              "pre": [
                "                rv = self.dispatch_request()",
                "        except Exception as e:"
              ],
              "post": [
                "        return self.finalize_request(rv)",
                ""
              ]
            },
            "vars": {
              "self": "<Flask 'REDACTED.app'>"
            }
          },
          {
            "exclude_from_grouping": false,
            "library_frame": true,
            "filename": "flask/app.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask/app.py",
            "line": {
              "number": 1820,
              "context": "            reraise(exc_type, exc_value, tb)"
            },
            "module": "flask.app",
            "function": "handle_user_exception",
            "context": {
              "pre": [
                "",
                "        if handler is None:"
              ],
              "post": [
                "        return handler(e)",
                ""
              ]
            },
            "vars": {
              "e": "Exception('error raised')",
              "self": "<Flask 'REDACTED.app'>",
              "exc_type": "<class 'Exception'>",
              "exc_value": "Exception('error raised')",
              "tb": "<traceback object at 0x121511f00>"
            }
          },
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "filename": "flask/_compat.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask/_compat.py",
            "line": {
              "number": 39,
              "context": "        raise value"
            },
            "module": "flask._compat",
            "function": "reraise",
            "context": {
              "pre": [
                "        if value.__traceback__ is not tb:",
                "            raise value.with_traceback(tb)"
              ],
              "post": [
                "",
                "    implements_to_string = _identity"
              ]
            },
            "vars": {
              "tp": "<class 'Exception'>",
              "value": "Exception('error raised')",
              "tb": "<traceback object at 0x121511f00>"
            }
          },
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "filename": "flask/app.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask/app.py",
            "line": {
              "number": 1949,
              "context": "                rv = self.dispatch_request()"
            },
            "module": "flask.app",
            "function": "full_dispatch_request",
            "context": {
              "pre": [
                "            rv = self.preprocess_request()",
                "            if rv is None:"
              ],
              "post": [
                "        except Exception as e:",
                "            rv = self.handle_user_exception(e)"
              ]
            },
            "vars": {
              "self": "<Flask 'REDACTED.app'>"
            }
          },
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "abs_path": "REDACTED/python3.9/site-packages/flask/app.py",
            "filename": "flask/app.py",
            "line": {
              "number": 1935,
              "context": "        return self.view_functions[rule.endpoint](**req.view_args)"
            },
            "module": "flask.app",
            "function": "dispatch_request",
            "context": {
              "pre": [
                "            return self.make_default_options_response()",
                "        # otherwise dispatch to the handler for that endpoint"
              ],
              "post": [
                "",
                "    def full_dispatch_request(self):"
              ]
            },
            "vars": {
              "rule": "<Rule '/login' (OPTIONS, HEAD, POST, GET) -> auth.login>",
              "self": "<Flask 'REDACTED.app'>",
              "req": "<Request 'http://localhost:5000/login' [GET]>"
            }
          },
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "filename": "flask_limiter/extension.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask_limiter/extension.py",
            "line": {
              "number": 702,
              "context": "                    return obj(*a, **k)"
            },
            "function": "__inner",
            "module": "flask_limiter.extension",
            "context": {
              "pre": [
                "                        self.__check_request_limit(False)",
                "                        g._rate_limiting_complete = True"
              ],
              "post": [
                "                return __inner",
                "        return _inner"
              ]
            },
            "vars": {
              "obj": "<function login at 0x1072e6670>",
              "self": "<flask_limiter.extension.Limiter object at 0x1072492b0>"
            }
          },
          {
            "library_frame": true,
            "exclude_from_grouping": false,
            "abs_path": "REDACTED/python3.9/site-packages/flask_limiter/extension.py",
            "filename": "flask_limiter/extension.py",
            "line": {
              "number": 702,
              "context": "                    return obj(*a, **k)"
            },
            "module": "flask_limiter.extension",
            "function": "__inner",
            "context": {
              "pre": [
                "                        self.__check_request_limit(False)",
                "                        g._rate_limiting_complete = True"
              ],
              "post": [
                "                return __inner",
                "        return _inner"
              ]
            },
            "vars": {
              "obj": "<function login at 0x1072e65e0>",
              "self": "<flask_limiter.extension.Limiter object at 0x1072492b0>"
            }
          },
          {
            "exclude_from_grouping": false,
            "library_frame": true,
            "filename": "flask_limiter/extension.py",
            "abs_path": "REDACTED/python3.9/site-packages/flask_limiter/extension.py",
            "line": {
              "number": 702,
              "context": "                    return obj(*a, **k)"
            },
            "module": "flask_limiter.extension",
            "function": "__inner",
            "context": {
              "pre": [
                "                        self.__check_request_limit(False)",
                "                        g._rate_limiting_complete = True"
              ],
              "post": [
                "                return __inner",
                "        return _inner"
              ]
            },
            "vars": {
              "obj": "<function login at 0x1072e6550>",
              "self": "<flask_limiter.extension.Limiter object at 0x1072492b0>"
            }
          },
          {
            "library_frame": false,
            "exclude_from_grouping": false,
            "filename": "REDACTED/auth/views.py",
            "abs_path": "REDACTED/auth/views.py",
            "line": {
              "number": 168,
              "context": """    error("test")"""
            },
            "module": "REDACTED.auth.views",
            "function": "login",
            "context": {
              "pre": [
                "@failed_login_limit",
                "def login():"
              ],
              "post": [
                "",
                "    # instead of using @anonymous_user_required, which will redirect to / if the user is logged in."
              ]
            }
          },
          {
            "exclude_from_grouping": false,
            "library_frame": false,
            "abs_path": "REDACTED/auth/views.py",
            "filename": "REDACTED/auth/views.py",
            "line": {
              "number": 162,
              "context": """    raise Exception("error raised")"""
            },
            "module": "REDACTED.auth.views",
            "function": "error",
            "context": {
              "pre": [
                "",
                "def error(constructor):"
              ],
              "post": [
                "",
                """@auth.route("/login", methods=["GET", "POST"])"""
              ]
            },
            "vars": {
              "constructor": "test"
            }
          }
        ],
        "module": "builtins",
        "handled": false,
        "message": "Exception: error raised",
        "type": "Exception"
      }
    ],
    "culprit": "REDACTED.auth.views.error",
    "custom": {
      "app": "<Flask 'REDACTED.app'>"
    },
    "id": "e3fd608548a9e76d7a3dac000f7477bd",
    "grouping_key": "f6429c7c5daebb948f8d579719554a93"
  },
  "processor": {
    "name": "error",
    "event": "error"
  },
  "url": {
    "path": "/login",
    "scheme": "http",
    "port": 5000,
    "domain": "localhost",
    "full": "http://localhost:5000/login"
  },
  "observer": {
    "hostname": "3fa2d45725f0",
    "id": "a92b5677-843b-4c50-9054-3979a231e7c5",
    "type": "apm-server",
    "ephemeral_id": "5af79b75-8e84-4524-b9e9-eadaa1664752",
    "version": "7.12.1",
    "version_major": 7
  },
  "trace": {
    "id": "292c11aafb79bf4d470474bcf6a1c65c"
  },
  "@timestamp": "2021-06-02T16:42:22.186Z",
  "ecs": {
    "version": "1.8.0"
  },
  "service": {
    "node": {
      "name": "REDACTED"
    },
    "framework": {
      "name": "flask",
      "version": "1.1.1"
    },
    "name": "opbeans-node2",
    "runtime": {
      "name": "CPython",
      "version": "3.9.2"
    },
    "language": {
      "name": "python",
      "version": "3.9.2"
    }
  },
  "host": {
    "hostname": "REDACTED",
    "os": {
      "platform": "darwin"
    },
    "ip": "192.168.2.10",
    "name": "REDACTED",
    "architecture": "arm64"
  },
  "http": {
    "request": {
      "headers": {
        "Cookie": [
          "csrftoken=[REDACTED]; djdt=hide; session_expires=[REDACTED]; 5egO7j=eyJzYWx0IjogIkluWFlpZkFPSGlYcUdOcDAzMHdlWGc9PSIsICJub25jZSI6ICIwWW90akZuR3l1ZWkrK0pjUTZsakJ3PT0iLCAidGFnIjogIlYvNDE2czVEdCt2cGlMUWQ3ays0RHc9PSIsICJjaXBoZXJfdGV4dCI6ICJOcUVlRkYybzFGVzU5a1BTSnpaM0lycElnWjg9In0=; session=[REDACTED]"
        ],
        "Cache-Control": [
          "no-cache"
        ],
        "Accept": [
          "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"
        ],
        "Upgrade-Insecure-Requests": [
          "1"
        ],
        "User-Agent": [
          "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:88.0) Gecko/20100101 Firefox/88.0"
        ],
        "Connection": [
          "keep-alive"
        ],
        "Host": [
          "localhost:5000"
        ],
        "Accept-Encoding": [
          "gzip, deflate"
        ],
        "Accept-Language": [
          "en-US,en;q=0.5"
        ],
        "Pragma": [
          "no-cache"
        ]
      },
      "method": "GET",
      "socket": {
        "encrypted": false,
        "remote_address": "127.0.0.1"
      },
      "env": {
        "SERVER_PORT": "5000",
        "REMOTE_ADDR": "127.0.0.1",
        "SERVER_NAME": "127.0.0.1"
      },
      "cookies": {
        "session_expires": "[REDACTED]",
        "session": "[REDACTED]",
        "djdt": "hide",
        "5egO7j": "eyJzYWx0IjogIkluWFlpZkFPSGlYcUdOcDAzMHdlWGc9PSIsICJub25jZSI6ICIwWW90akZuR3l1ZWkrK0pjUTZsakJ3PT0iLCAidGFnIjogIlYvNDE2czVEdCt2cGlMUWQ3ays0RHc9PSIsICJjaXBoZXJfdGV4dCI6ICJOcUVlRkYybzFGVzU5a1BTSnpaM0lycElnWjg9In0=",
        "csrftoken": "[REDACTED]"
      }
    }
  },
  "client": {
    "ip": "127.0.0.1"
  },
  "user_agent": {
    "original": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:88.0) Gecko/20100101 Firefox/88.0",
    "os": {
      "name": "Mac OS X",
      "version": "10.15",
      "full": "Mac OS X 10.15"
    },
    "name": "Firefox",
    "device": {
      "name": "Mac"
    },
    "version": "88.0."
  },
  "transaction": {
    "id": "efe30657a4e6c4f8",
    "type": "request",
    "sampled": true
  },
  "timestamp": {
    "us": 1622652142186746
  }
}

[sorenlouv]

@watson I think you have some context here. You added some security hardening in Kibana that prevents certain reserved keywords (like "constructor") and thus causes the following error:

{
    "statusCode": 500,
    "error": "Internal Server Error",
    "message": "Object contains forbidden prototype property",
}

How should we treat APM data that contains the "constructor" keyword?

[sorenlouv]

I believe this is related to elastic/elasticsearch-js#1408. There is a configuration value for that library to get around this issue by allowing the "constructor" keyword, but I'm not sure if there's a way to specify this configuration in Kibana.

Sorry, I completely missed this initially. I agree, it looks like this is caused by the elasticsearch client.
I'll look into the best way to work around this.

[sorenlouv]

This should be solved by upgrading to the latest elasticsearch client. Kibana is working on this in #98266 and I expect that to solve it.