Fix incomplete access logs

[scottinet]

Description

Context: access logs are invoked every time an API route is invoked, to keep a trace about Kuzzle's activity.

There are two problems with how access logs are currently handled:

1. If a connection drops before the end of an API request, then the warning No connection retrieved for connection id: <connection id> is logged. This is a problem, because, even if the connection had since dropped, the query was executed. This means that our access logs are incomplete
2. Whenever we log messages such as the warning previously described, or the ones printed when an authentication token cannot be decoded, this invokes pluginsManager.trigger which creates a promise in the event loop. With enough activity, this can quickly clogs up the event loop and endanger Kuzzle's stability

This PR solves the 1st problem by simply using the provided Request object, which holds basic connection and token informations, when the raw network connection object is not available (meaning that the connection no longer exists).
The second problem is solved by simply removing the usages of the log:xxx events, as those didn't provide valuable information at all.

⚠️ access logging is a sensitive feature of kuzzle, please be extra careful when reviewing this PR

Other changes

When printing an access log, we now print (anonymous) instead of -1 when a query is executed by an unauthenticated user.

How to test

1. Activate access logs by setting server.logs.transports.silent = false in the kuzzlerc configuration file
2. Run a script that stresses Kuzzle to the point that it starts buffering requests to prevent overload
3. Shut down the script suddenly

Before this PR: many No connection retrieved for connection id... warnings are printed on the console. With this PR: access logs are properly printed even on dead connections.

Moreover, Kuzzle takes far less time to recover with this PR than without, because less promises are put on the event loop.

Script that you can use to test this PR:

const WebSocket = require('uws');

const
  nbjobs = 10000,
  ws = new WebSocket('ws://172.18.0.5:7512', {perMessageDeflate: false}),
  payload = JSON.stringify({controller:'server', action:'info'});

ws.on('open', () => {
  let done = 0;
  const start = Date.now();

  ws.on('message', data => {
    done++;

    if (done === nbjobs) {
      clearInterval(interval);
      const elapsed = (Date.now() - start) / 1000;
      console.log(`Elapsed: ${elapsed}s, Throughput: ${Math.round(nbjobs/elapsed)} requests/s`);
      ws.close();
    }
  });

  for (let i = 0; i < nbjobs; i++) {
    ws.send(payload);
  }
});

[scottinet]

Unit tests were broken because they checked that the logger was never called... but sinon's spies were put on the wrong entrypoint property name, so the checks always passed 😑

[codecov-io]

Codecov Report

Merging #1273 into 1-dev will increase coverage by 0.02%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##            1-dev    #1273      +/-   ##
==========================================
+ Coverage   93.75%   93.77%   +0.02%     
==========================================
  Files          98       98              
  Lines        6793     6800       +7     
==========================================
+ Hits         6369     6377       +8     
+ Misses        424      423       -1

Impacted Files	Coverage Δ
lib/api/core/models/repositories/userRepository.js	95% <100%> (ø)	⬆️
lib/api/core/entrypoints/embedded/index.js	97.79% <100%> (+0.66%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f5135ad...a7943d4. Read the comment docs.

[alexandrebouthinon]

Why don't you use string literals?

[scottinet]

Because that would be impractical and hard to read in this very specific case, given the amount of variables used to create an access log message.

[Yoann-Abbes]

I don't understand this comment : how and in wich case the token would be invalid on-purpose ?

[scottinet]

Forgery.

We're dealing with data coming from the outside, so nothing can be trusted.

[ballinette]

very-nitpicking: s/1st form jwt token/1st from jwt token/ ;)