Render being reported during SQL execution

[ghost]

With the following code:

app.get('/sql_promise_all', function (req, res) {
    const start_req = Date.now();
    Promise.all(
          [Array(50)].map(() => client.query('SELECT * from apps LIMIT 1'))
    ).then(() => {
     const stop_db = Date.now() - start_req;
     res.render('index', {weather: null, error: null});
     const stop_req = Date.now() - start_req
     console.log(`DB took: ${stop_db}`);
     console.log(`Req took: ${stop_req}`);
   })
})

The render span is being reported before the end of the client.query span(s):

Payload:

{"tags"=>{"path"=>"/sql_promise_all", "transaction_id"=>"req-1a0a497e-9540-476d-93e5-8a13795ef857"},
    "spans"=>
     [{"type"=>"Standard",
       "identity"=>
        {"id"=>"span-42e9d08c-9b2b-4d2f-8dcd-fd1376dc45a3",
         "parent_id"=>nil,
         "start_instant"=>"2020-02-19T20:53:47.114Z",
         "stop_instant"=>"2020-02-19T20:53:47.247Z",
         "operation"=>"Controller/GET /sql_promise_all"},
       "tags"=>{}},
      {"type"=>"Standard",
       "identity"=>
        {"id"=>"span-1f192408-a2f4-42ce-8d88-09fc42609752",
         "parent_id"=>nil,
         "start_instant"=>"2020-02-19T20:53:47.192Z",
         "stop_instant"=>"2020-02-19T20:53:47.238Z",
         "operation"=>"Template/Render"},
       "tags"=>{"name"=>"/home/dave/nodejs-example/views/index.ejs"}},
      {"type"=>"Standard",
       "identity"=>
        {"id"=>"span-107fa720-ff5b-42f6-adf2-cc21e8be11d7",
         "parent_id"=>"span-42e9d08c-9b2b-4d2f-8dcd-fd1376dc45a3",
         "start_instant"=>"2020-02-19T20:53:47.114Z",
         "stop_instant"=>"2020-02-19T20:53:47.239Z",
         "operation"=>"SQL/App/Select"},
       "tags"=>{"db.statement"=>"SELECT * from apps LIMIT 1"}}],
    "identity"=>
     {"transaction_id"=>"req-1a0a497e-9540-476d-93e5-8a13795ef857",
      "revision"=>"",
      "host"=>"DefaultHostname",
      "start_instant"=>"2020-02-19T20:53:47.114Z",
      "stop_instant"=>"2020-02-19T20:53:47.249Z",
      "type"=>"Web",
      "naming"=>{"path"=>"", "code"=>""},
      "score"=>{"total"=>0, "percentile"=>0, "age"=>0, "memory_delta"=>0, "allocations"=>0}}},

This shouldn't happen, as Promise.all should guarantee that the .then run after all the client.query promises finish.

[ghost]

• [ ] A regular test and a dashboard test should be added for this
• [ ] We should also check that the spans that are sent from the app should exactly match what's shown in the dashboard test (for now it's not automatable, but have the test print out the timings so that it's easy to verify/eyeball in the dashboard)

[ghost]

Hey so it looks like the inital code is actually not quite what you want:

• [Array(50)].map(() => dbClient.query('SELECT RANDOM() * 10')) needs the spread operator to work like range/xrange would -- you need [...Array(50)]. What was actually happening was exactly ONE request was happening.

But there was also a subtle bug in the agent code -- the instrumentation was not creating enough new async namespaces -- it took a while but it's finally fixed, testing it in the dashboard now.