Skip to content

Commit

Permalink
Logger context (#1073)
Browse files Browse the repository at this point in the history
* Basic implementation

* more tests and docs
  • Loading branch information
adrianmroz-allegro authored Jun 5, 2023
1 parent 3c53849 commit 3fea1d3
Show file tree
Hide file tree
Showing 6 changed files with 54 additions and 10 deletions.
25 changes: 23 additions & 2 deletions docs/extending-turnilo.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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.
8 changes: 6 additions & 2 deletions src/server/app.ts
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,9 @@ import { errorLayout } from "./views";

declare module "express" {
export interface Request {
turniloMetadata: object;
turniloMetadata: {
loggerContext: Record<string, unknown>
};
}
}

Expand Down Expand Up @@ -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();
});

Expand Down
7 changes: 7 additions & 0 deletions src/server/routes/query/query.mocha.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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", () => {
Expand Down
4 changes: 2 additions & 2 deletions src/server/routes/query/routes/visualization.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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 });
}
17 changes: 14 additions & 3 deletions src/server/utils/query/log-query.mocha.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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,
{
Expand All @@ -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,
{
Expand All @@ -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;
});

});
3 changes: 2 additions & 1 deletion src/server/utils/query/log-query.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down

0 comments on commit 3fea1d3

Please sign in to comment.