Logger context (#1073)

* Basic implementation

* more tests and docs

Author: adrianmroz-allegro

docs/extending-turnilo.md

@@ -12,6 +12,28 @@ Turnilo lets you extend its behaviour in three ways:
 * Query decorator for all Plywood queries sent to Druid cluster
 * Plugins for backend application
 
+## turniloMetadata
+
+Turnilo adds `turniloMetadata` object to every `Request` object. 
+It is a namespace for you to keep any values necessary that live with requests.
+
+`turniloMetadata` has special properties:
+
+### `loggerContext` 
+
+It is a `Record` of values that will be added by logger for every message.
+
+You could use it to log User Agent of browser that requested view with a simple [plugin](#plugins):
+
+```javascript
+app.use(function(req, res, next) {
+  req.turniloMetadata.loggerContext.userAgent = req.get('User-Agent');
+  next();
+});
+```
+
+
+
 ## Request decorator
 
 In the cluster config add a key `druidRequestDecorator` with property `path` that points to a relative js file.
@@ -131,5 +153,4 @@ This function will be called at the start of application with following paramete
 Worth to look into !(express documentation)[https://expressjs.com/en/api.html#app]. 
 Use `get`, `post` etc. to define new endpoints. Use `use` to define middleware.
 
-Additionally, Turnilo defines empty object on Request object under `turniloMetadata` key. 
-Here you can pass values between your plugins and not pollute headers.
+Use [`turniloMetadata`](#turniloMetadata) object on `Request` to pass values between your plugins and not pollute headers.

src/server/app.ts

@@ -38,7 +38,9 @@ import { errorLayout } from "./views";
 
 declare module "express" {
   export interface Request {
-    turniloMetadata: object;
+    turniloMetadata: {
+      loggerContext: Record<string, unknown>
+    };
   }
 }
 
@@ -94,7 +96,9 @@ export default function createApp(serverSettings: ServerSettings, settingsManage
   }
 
   app.use((req: Request, res: Response, next: Function) => {
-    req.turniloMetadata = {};
+    req.turniloMetadata = {
+      loggerContext: {}
+    };
     next();
   });
 

src/server/routes/query/query.mocha.ts

@@ -47,6 +47,13 @@ const app = express();
 
 app.use(bodyParser.json());
 
+app.use((req: any, res, next) => {
+  req.turniloMetadata = {
+    loggerContext: {}
+  };
+  next();
+});
+
 app.use("/", queryRouter(settingsManagerFixture));
 
 describe("query router", () => {

src/server/routes/query/routes/visualization.ts

@@ -28,11 +28,11 @@ function getQuery(essence: Essence, timekeeper: Timekeeper): Expression {
   return essence.visualization.name === "grid" ? makeGridQuery(essence, timekeeper) : makeQuery(essence, timekeeper);
 }
 
-export default async function visualizationRoute({ context }: QueryRouterRequest, res: Response) {
+export default async function visualizationRoute({ turniloMetadata, context }: QueryRouterRequest, res: Response) {
   const { dataCube, essence, decorator, timekeeper, logger } = context;
   const query = getQuery(essence, timekeeper);
   const queryTimeStart = Date.now();
   const result = await executeQuery(dataCube, query, essence.timezone, decorator);
-  logQueryInfo(essence, timekeeper, logger.setLoggerId("turnilo-visualization-query"), Date.now() - queryTimeStart);
+  logQueryInfo(essence, timekeeper, logger.setLoggerId("turnilo-visualization-query"), Date.now() - queryTimeStart, turniloMetadata.loggerContext);
   res.json({ result });
 }

src/server/utils/query/log-query.mocha.ts

@@ -50,7 +50,7 @@ describe("log-query-info", () => {
   };
 
   it("Should log all basic variables", () => {
-    logQueryInfo(baseEssence, timekeeper, logger, executionTime);
+    logQueryInfo(baseEssence, timekeeper, logger, executionTime, {});
     expect(logger.log.calledWith(
       expectedMessage,
       expectedBasicVariables
@@ -59,7 +59,7 @@ describe("log-query-info", () => {
 
   it("Should log additional time shift variables", () => {
     const essence = baseEssence.set("timeShift", TimeShift.fromJS("P1D"));
-    logQueryInfo(essence, timekeeper, logger, executionTime);
+    logQueryInfo(essence, timekeeper, logger, executionTime, {});
     expect(logger.log.calledWith(
       expectedMessage,
       {
@@ -73,7 +73,7 @@ describe("log-query-info", () => {
 
   it("Should log additional time split variables", () => {
     const essence = baseEssence.addSplit(timeSplitCombine("time", "P2D"), VisStrategy.FairGame);
-    logQueryInfo(essence, timekeeper, logger, executionTime);
+    logQueryInfo(essence, timekeeper, logger, executionTime, {});
     expect(logger.log.calledWith(
       expectedMessage,
       {
@@ -85,4 +85,15 @@ describe("log-query-info", () => {
     )).to.be.true;
   });
 
+  it("Should log additional logger context", () => {
+    logQueryInfo(baseEssence, timekeeper, logger, executionTime, { contextName: "context-value" });
+    expect(logger.log.calledWith(
+      expectedMessage,
+      {
+        ...expectedBasicVariables,
+        contextName: "context-value"
+      }
+    )).to.be.true;
+  });
+
 });

src/server/utils/query/log-query.ts

@@ -65,10 +65,11 @@ function timeVariables(essence: Essence, timekeeper: Timekeeper): Record<string,
   return variables;
 }
 
-export function logQueryInfo(essence: Essence, timekeeper: Timekeeper, logger: Logger, executionTime: number) {
+export function logQueryInfo(essence: Essence, timekeeper: Timekeeper, logger: Logger, executionTime: number, context: Record<string, unknown>) {
   const nonTimeFilters = essence.filter.removeClause(essence.getTimeDimension().name);
 
   logger.log(`Visualization query ${essence.description(timekeeper)}`, {
+    ...context,
     executionTime,
     ...timeVariables(essence, timekeeper),
     dataCube: essence.dataCube.name,