Getting URL name twice within Transaction name on Node.js Expresss

[mohit3081989]

Describe the bug

We have been getting url pathname twice within transaction name. Like below :

{
    "id": "80f3992656079e6c",
    "trace_id": "d819dfef1f971a7003a2420d5a9b87eb",
    "name": "POST /logging-service/pushLogs/logging-service/pushLogs",
    "type": "request",
    "subtype": null,
    "action": null,
    "duration": 9.196,
    "timestamp": 1588258195545002,
    "result": "HTTP 2xx",
    "sampled": true,
    "context": {
        "user": {},
        "tags": {},
        "custom": {},
        "request": {
            "http_version": "1.1",
            "method": "POST",
            "url": {
                "raw": "/logging-service/pushLogs",
                "protocol": "http:",
                "hostname": "localhost",
                "port": "8001",
                "pathname": "/logging-service/pushLogs",
                "full": "http://localhost:8001/logging-service/pushLogs"
            },
            "socket": {
                "encrypted": false
            },
            "headers": {
                "host": "localhost:8001",
                "connection": "keep-alive",
                "content-type": "application/json",
                "content-length": "63"
            },
            "body": "[REDACTED]"
        },
        "response": {
            "status_code": 200,
            "headers": {
                "x-powered-by": "Express",
                "content-type": "application/json; charset=utf-8",
                "content-length": "15",
                "etag": "W/\"f-VaSQ4oDUiZblZNAEkkN+sX+q3Sg\"",
                "date": "Thu, 30 Apr 2020 14:49:51 GMT",
                "connection": "keep-alive"
            }
        }
    },
    "sync": false,
    "span_count": {
        "started": 0
    }
}

To Reproduce

Steps to reproduce the behavior:

1. Use this code :

var express = require('express');
var bodyParser = require('body-parser');
var validator = require('swagger-express-validator');
var expandSchemaRef = require('expand-swagger-refs').expanded;
var schema = require('schema.json');  // defined below. Refer to point number 3
var expected_paths = _.keys(schema.paths);

  expected_paths.forEach(function (path) {
    var method_name = path.substring(1);
    var method_url = '/' + service_id + '/' + method_name;

    app.use(method_url, validator({
      schema: expandSchemaRef(schema),
      validateRequest: true,
      validateResponse: true,
      requestValidationFn: function(req, data, errors) {
        throw errors
      },
      responseValidationFn: function(req, data, errors) {
     
        throw errors
      }
    }));

 
    app.post(method_url, function(req, res, next) {
      req.method_name = method_name;
      getMethodImplementation(method_name, service)(req.body)
        .then(function(result) {
          req.result = result;
          next();
        })
        .catch(function (err) {
          next(err);
        });
    });

    // success
    app.use(method_url, function(req, res, next) {
      res.status(200).json(req.result);
    });

    // failure
    app.use(method_url, function(err, req, res, next) {

      res.status(500).json({ error: 'err'});
    });
  });

  app.get('/healthcheck', function(req, res, next) {
    res.status(200).json({ message: 'health check passed!!!' });
  });
var server = app.listen(port, function() {
    
  });
  server.keepAliveTimeout = 0;

2. calling /healthcheck won't create any issue it creates following output where name is not repeated in transaction name, below is payload to be sent to apm:

{
    "id": "c77ceedb33d0a4e8",
    "trace_id": "66d029b15ce907911ed6fef70b4fb6ee",
    "name": "GET /healthcheck",
    "type": "request",
    "subtype": null,
    "action": null,
    "duration": 1.756,
    "timestamp": 1588258326466002,
    "result": "HTTP 2xx",
    "sampled": true,
    "context": {
        "user": {},
        "tags": {},
        "custom": {},
        "request": {
            "http_version": "1.1",
            "method": "GET",
            "url": {
                "raw": "/healthcheck",
                "protocol": "http:",
                "hostname": "localhost",
                "port": "8001",
                "pathname": "/healthcheck",
                "full": "http://localhost:8001/healthcheck"
            },
            "socket": {
                "encrypted": false
            },
            "headers": {
                "host": "localhost:8001",
                "connection": "keep-alive"
            }
        },
        "response": {
            "status_code": 200,
            "headers": {
                "x-powered-by": "Express",
                "content-type": "application/json; charset=utf-8",
                "content-length": "36",
                "etag": "W/\"24-g+P9lgt1vz560Vc8hskJuNyHH5E\"",
                "date": "Thu, 30 Apr 2020 14:52:06 GMT",
                "connection": "keep-alive"
            }
        }
    },
    "sync": false,
    "span_count": {
        "started": 0
    }
}

3. Then do call sample API defined in schema like below using POST localhost:$PORT/logging-service/pushLogs -H 'Content-Type=application/json' {"source_id" : "test-ui","log_level" : "info","log_data" : {"error" : "dfsf"}} :

{
    "swagger": "2.0",
    "basePath": "/logging-service",
    "info": {
      "description": "Push logs.",
      "version": "0",
      "title": "LoggingService"
      },
    "paths": {
        "/pushLogs": {
          "post": {
            "consumes": [
              "application/json"
            ],
            "parameters": [
              {
                "in": "body",
                "name": "body",
                "description": "Request body for pushLogs.",
                "required": true,
                "schema": {
                  "$ref": "#/definitions/pushLogs"
                }
              }
            ],
            "responses": {
              "200": {
                "description": "Response body for pushLogs",
                "schema": {
                  "$ref": "#/definitions/successResponse"
                }
              }
            }
          }
        }
      },
      "definitions": {
        "successResponse": {
          "type": "object",
          "properties": {
            "status": {
              "type": "string",
              "enum": [
                "ok"
              ]
            }
          }
        },
        "pushLogs": {
          "type": "object",
          "properties": {
            "source_id": {
              "type": "string" ,
              "enum": ["test"]
            },
            "log_level": { 
              "type": "string",
              "enum": ["error", "info"]
            },
            "log_data": {
              "type": "object",
              "properties": {
                "error": { "type": [ "string", "null" ] }
              },
              "additionalProperties": false
            }
          },
          "additionalProperties": false,
          "required": [
            "source_id",
            "log_level",
            "log_data"
          ]
        }
      }
    }

Expected behavior
There should not be any repeated string in name :

{
    "id": "80f3992656079e6c",
    "trace_id": "d819dfef1f971a7003a2420d5a9b87eb",
    "name": "POST /logging-service/pushLogs",
    "type": "request",
    "subtype": null,
    "action": null,
    "duration": 9.196,
    "timestamp": 1588258195545002,
    "result": "HTTP 2xx",
    "sampled": true,
    "context": {
        "user": {},
        "tags": {},
        "custom": {},
        "request": {
            "http_version": "1.1",
            "method": "POST",
            "url": {
                "raw": "/logging-service/pushLogs",
                "protocol": "http:",
                "hostname": "localhost",
                "port": "8001",
                "pathname": "/logging-service/pushLogs",
                "full": "http://localhost:8001/logging-service/pushLogs"
            },
            "socket": {
                "encrypted": false
            },
            "headers": {
                "host": "localhost:8001",
                "connection": "keep-alive",
                "content-type": "application/json",
                "content-length": "63"
            },
            "body": "[REDACTED]"
        },
        "response": {
            "status_code": 200,
            "headers": {
                "x-powered-by": "Express",
                "content-type": "application/json; charset=utf-8",
                "content-length": "15",
                "etag": "W/\"f-VaSQ4oDUiZblZNAEkkN+sX+q3Sg\"",
                "date": "Thu, 30 Apr 2020 14:49:51 GMT",
                "connection": "keep-alive"
            }
        }
    },
    "sync": false,
    "span_count": {
        "started": 0
    }
}

Environment (please complete the following information)

• OS: ubuntu 18.04
• Node.js version: 8.17.0
• APM Server version: 7.4.2
• Agent version: 3.5.0

How are you starting the agent? (please tick one of the boxes)

• Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
• Requiring elastic-apm-node/start from within the source code
• Starting node with -r elastic-apm-node/start

[mohit3081989]

This is reference to a ticket raised 1 year ago which didn't get resolved that time https://discuss.elastic.co/t/transaction-name-have-url-repeated-twice/182157.
@watson can you help here, this issue seems to be dragging since starting.

Thanks

[mohit3081989]

Can anyone please have a look at this one ? I tried to provide as much on information as possible here.

[astorm]

@mohit3081989 hello there -- and our apologies. This issues seems to have fallen through the cracks. That's our fault.

If you're still seeing this problem we're happy to reengage now.

We spent this afternoon trying to reproduce your behavior and we couldn't. Your sample program wouldn't run for us as written.

• There's no defined _ or service_id variable.

• Also, there's no getMethodImplementation function.

• Also, the first middleware by itself caused express to send an odd looking response,

This

app.use(method_url, validator({
    schema: expandSchemaRef(schema),
    validateRequest: true,
    validateResponse: true,
    requestValidationFn: function(req, data, errors) {
      throw errors
    },
    responseValidationFn: function(req, data, errors) {

      throw errors
    }
  }));

gave us this

% curl -i -X POST -H 'Content-Type=application/json' -d '{"source_id" : "test-ui","log_level" : "info","log_data" : {"error" : "dfsf"}}' http://localhost:3000/logging-service/pushLogs
HTTP/1.1 500 Internal Server Error
X-Powered-By: Express
Content-Security-Policy: default-src 'none'
X-Content-Type-Options: nosniff
Content-Type: text/html; charset=utf-8
Content-Length: 142
Date: Tue, 10 Nov 2020 00:29:53 GMT
Connection: keep-alive

<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="utf-8">
<title>Error</title>
</head>
<body>
<pre>[object Object]</pre>
</body>
</html>

and when used with the others it just caused an error.

When we took some guesses as to the missing variables and tried the following program down to the following

var express = require('express');
var bodyParser = require('body-parser');
var validator = require('swagger-express-validator');
var expandSchemaRef = require('expand-swagger-refs').expanded;
var schema = require('./schema.json');  // defined below. Refer to point number 3
const _ = require('underscore')
const app = express()
const port = 3000
var expected_paths = _.keys(schema.paths);

expected_paths.forEach(function (path) {
  const service_id = 'logging-service'
  var method_name = path.substring(1);
  var method_url = '/' + service_id + '/' + method_name;

  // app.post(method_url, (req, res) => {
  //   res.send('hello')
  // })
  // app.use(method_url, validator({
  //   schema: expandSchemaRef(schema),
  //   validateRequest: true,
  //   validateResponse: true,
  //   requestValidationFn: function(req, data, errors) {
  //     throw errors
  //   },
  //   responseValidationFn: function(req, data, errors) {

  //     throw errors
  //   }
  // }));


  // app.post(method_url, function(req, res, next) {
  //   req.method_name = method_name;
  //   getMethodImplementation(method_name, service)(req.body)
  //     .then(function(result) {
  //       req.result = result;
  //       next();
  //     })
  //     .catch(function (err) {
  //       next(err);
  //     });
  // });

  // // success
  app.use(method_url, function(req, res, next) {
    res.status(200).json(req.result);
  });

  // failure
  app.use(method_url, function(err, req, res, next) {

    res.status(500).json({ error: 'err'});
  });
});

app.get('/healthcheck', function(req, res, next) {
  res.status(200).json({ message: 'health check passed!!!' });
});
var server = app.listen(port, function() {

});
server.keepAliveTimeout = 0;

We couldn't reproduce the behavior you reported.

Looking at the agent code that handles capturing the express route/path names

apm-agent-nodejs/lib/instrumentation/modules/express.js

Line 45 in 8a5e908

shimmer.wrap(layer, 'handle', function (orig) {

Our best guess as to why this is happening is something unexpectedly invoked express.Router.Layer.handle twice

@mohit3081989 do you think you can get us a stand alone reproduction? With that in hand we should be able to figure out what's going on and address the bug.