Skip to content

Commit

Permalink
feature/rich query logger (#1034)
Browse files Browse the repository at this point in the history
* add logger to query router context

* log information for viz query

* middleware request is not available in error handler

* add data cube name to logged message

* description method for essence

* method for series that returns used measures

* naming, switch from series to measures and description in log message

* usedMeasures function
  • Loading branch information
adrianmroz-allegro authored Feb 17, 2023
1 parent 27cb187 commit 5ef0710
Show file tree
Hide file tree
Showing 8 changed files with 243 additions and 14 deletions.
7 changes: 1 addition & 6 deletions src/client/utils/download/download.ts
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@ import * as fileSaver from "file-saver";
import { Dataset, TabulatorOptions } from "plywood";
import { Essence } from "../../../common/models/essence/essence";
import { Timekeeper } from "../../../common/models/timekeeper/timekeeper";
import { formatUrlSafeDateTime } from "../../../common/utils/time/time";
import tabularOptions from "../tabular-options/tabular-options";

export type FileFormat = "csv" | "tsv";
Expand Down Expand Up @@ -61,9 +60,5 @@ export function datasetToFileString(dataset: Dataset, fileFormat: FileFormat, op
}

export function fileNameBase(essence: Essence, timekeeper: Timekeeper): string {
const timeFilter = essence.currentTimeFilter(timekeeper);
const { start, end } = timeFilter.values.first();
const timezone = essence.timezone;

return `${essence.dataCube.name}_${formatUrlSafeDateTime(start, timezone)}_${formatUrlSafeDateTime(end, timezone)}`;
return essence.description(timekeeper);
}
10 changes: 5 additions & 5 deletions src/common/logger/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ import { noop, Unary } from "../utils/functional/functional";
import { isNil } from "../utils/general/general";
import { isoNow } from "../utils/time/time";

type LogFn = (msg: string, extra?: Record<string, string>) => void;
type LogFn = (msg: string, extra?: Record<string, unknown>) => void;
type LogLevel = "INFO" | "WARN" | "ERROR";

export function errorToMessage(error: Error): string {
Expand All @@ -41,7 +41,7 @@ class JSONLogger implements Logger {
constructor(private logger = "turnilo") {
}

private logMessage(level: LogLevel, message: string, extra: Record<string, string> = {}) {
private logMessage(level: LogLevel, message: string, extra: Record<string, unknown> = {}) {
console.log(JSON.stringify({
message,
level,
Expand All @@ -51,15 +51,15 @@ class JSONLogger implements Logger {
}));
}

log(message: string, extra: Record<string, string> = {}) {
log(message: string, extra: Record<string, unknown> = {}) {
this.logMessage("INFO", message, extra);
}

error(message: string, extra: Record<string, string> = {}) {
error(message: string, extra: Record<string, unknown> = {}) {
this.logMessage("ERROR", message, extra);
}

warn(message: string, extra: Record<string, string> = {}) {
warn(message: string, extra: Record<string, unknown> = {}) {
this.logMessage("WARN", message, extra);
}

Expand Down
12 changes: 11 additions & 1 deletion src/common/models/essence/essence.ts
Original file line number Diff line number Diff line change
Expand Up @@ -22,14 +22,16 @@ import { serialize as serializeDataCube } from "../../../client/deserializers/da
import { thread } from "../../utils/functional/functional";
import nullableEquals from "../../utils/immutable-utils/nullable-equals";
import { visualizationIndependentEvaluator } from "../../utils/rules/visualization-independent-evaluator";
import { formatUrlSafeDateTime } from "../../utils/time/time";
import { MANIFESTS } from "../../visualization-manifests";
import { ClientAppSettings } from "../app-settings/app-settings";
import {
ClientDataCube,
getDefaultFilter,
getDefaultSeries,
getDefaultSplits,
getMaxTime, getTimeDimension
getMaxTime,
getTimeDimension
} from "../data-cube/data-cube";
import { DateRange } from "../date-range/date-range";
import { Dimension } from "../dimension/dimension";
Expand Down Expand Up @@ -656,4 +658,12 @@ export class Essence extends ImmutableRecord<EssenceValue>(defaultEssence) {
public getPinnedSortSeries(): ConcreteSeries {
return this.findConcreteSeries(this.pinnedSort);
}

public description(timekeeper: Timekeeper): string {
const timeFilter = this.currentTimeFilter(timekeeper);
const { start, end } = timeFilter.values.first();
const timezone = this.timezone;

return `${this.dataCube.name}_${formatUrlSafeDateTime(start, timezone)}_${formatUrlSafeDateTime(end, timezone)}`;
}
}
4 changes: 4 additions & 0 deletions src/common/models/measure/measure.fixtures.ts
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,10 @@ export class MeasureFixtures {
return createMeasure("avg_delta", $("main").average($("delta")));
}

static histogram(): Measure {
return createMeasure("histogram", $("main").quantile($("create_to_collect_duration_histogram"), 0.95, "k=128"));
}

static wikiCountJS(): MeasureJS {
return {
name: "count",
Expand Down
123 changes: 123 additions & 0 deletions src/common/models/series/used-measures.mocha.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,123 @@
/*
* Copyright 2017-2022 Allegro.pl
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

import { expect } from "chai";
import { ArithmeticExpression } from "../expression/concreteArithmeticOperation";
import { ExpressionSeriesOperation } from "../expression/expression";
import { PercentExpression } from "../expression/percent";
import { MeasureFixtures } from "../measure/measure.fixtures";
import { ExpressionSeries } from "./expression-series";
import { MeasureSeries } from "./measure-series";
import { QuantileSeries } from "./quantile-series";
import { usedMeasures } from "./used-measures";

const avgDelta = MeasureFixtures.avgDelta();
const avgAdded = MeasureFixtures.avgAdded();
const histogram = MeasureFixtures.histogram();

describe("usedMeasures", () => {
describe("MeasureSeries", () => {
it("should return array with measure reference", () => {
const series = MeasureSeries.fromMeasure(avgDelta);
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta"]);
});
});

describe("QuantileSeries", () => {
it("should return array with measure reference", () => {
const series = QuantileSeries.fromQuantileMeasure(histogram);
expect(usedMeasures(series)).to.be.deep.equal(["histogram"]);
});
});

describe("ExpressionSeries", () => {
describe("Percent of total", () => {
it("should return array with measure reference", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new PercentExpression({
operation: ExpressionSeriesOperation.PERCENT_OF_TOTAL
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta"]);
});
});

describe("Percent of parent", () => {
it("should return array with measure reference", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new PercentExpression({
operation: ExpressionSeriesOperation.PERCENT_OF_PARENT
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta"]);
});
});

describe("Arithmetic ADD", () => {
it("should return array with measure reference and reference of operand", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new ArithmeticExpression({
operation: ExpressionSeriesOperation.ADD,
reference: avgAdded.name
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta", "avg_added"]);
});
});

describe("Arithmetic SUBTRACT", () => {
it("should return array with measure reference and reference of operand", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new ArithmeticExpression({
operation: ExpressionSeriesOperation.SUBTRACT,
reference: avgAdded.name
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta", "avg_added"]);
});
});

describe("Arithmetic MULTIPLY", () => {
it("should return array with measure reference and reference of operand", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new ArithmeticExpression({
operation: ExpressionSeriesOperation.MULTIPLY,
reference: avgAdded.name
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta", "avg_added"]);
});
});

describe("Arithmetic DIVIDE", () => {
it("should return array with measure reference and reference of operand", () => {
const series = ExpressionSeries.fromJS({
reference: avgDelta.name,
expression: new ArithmeticExpression({
operation: ExpressionSeriesOperation.DIVIDE,
reference: avgAdded.name
})
});
expect(usedMeasures(series)).to.be.deep.equal(["avg_delta", "avg_added"]);
});
});
});
});
44 changes: 44 additions & 0 deletions src/common/models/series/used-measures.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,44 @@
/*
* Copyright 2017-2022 Allegro.pl
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

import { ExpressionSeriesOperation } from "../expression/expression";
import { ExpressionSeries } from "./expression-series";
import { Series } from "./series";
import { SeriesType } from "./series-type";

function usedMeasuresInExpressionSeries(series: ExpressionSeries): string[] {
switch (series.expression.operation) {
case ExpressionSeriesOperation.PERCENT_OF_PARENT:
case ExpressionSeriesOperation.PERCENT_OF_TOTAL:
return [series.reference];
case ExpressionSeriesOperation.ADD:
case ExpressionSeriesOperation.SUBTRACT:
case ExpressionSeriesOperation.MULTIPLY:
case ExpressionSeriesOperation.DIVIDE:
return [series.reference, series.expression.reference];
}
}

export function usedMeasures(series: Series): string[] {
switch (series.type) {
case SeriesType.MEASURE:
return [series.reference];
case SeriesType.EXPRESSION:
return usedMeasuresInExpressionSeries(series);
case SeriesType.QUANTILE:
return [series.reference];
}
}
6 changes: 5 additions & 1 deletion src/server/routes/query/query.ts
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
*/

import { NextFunction, Request, Response, Router } from "express";
import { Logger } from "../../../common/logger/logger";
import { QueryableDataCube } from "../../../common/models/data-cube/queryable-data-cube";
import { Essence } from "../../../common/models/essence/essence";
import { Timekeeper } from "../../../common/models/timekeeper/timekeeper";
Expand All @@ -40,13 +41,15 @@ interface QueryRouterContext {
essence: Essence;
decorator: AppliedQueryDecorator;
timekeeper: Timekeeper;
logger: Logger;
}

export type QueryRouterRequest = Request & {
context?: QueryRouterContext;
};

export function queryRouter(settings: Pick<SettingsManager, "logger" | "getSources" | "appSettings" | "anchorPath" | "getTimekeeper">) {
const logger = settings.logger;

const router = Router();

Expand All @@ -57,6 +60,7 @@ export function queryRouter(settings: Pick<SettingsManager, "logger" | "getSourc
const decorator = getQueryDecorator(req, dataCube, settings);

(req as QueryRouterRequest).context = {
logger,
dataCube,
essence,
decorator,
Expand All @@ -79,7 +83,7 @@ export function queryRouter(settings: Pick<SettingsManager, "logger" | "getSourc
router.post("/pinboard", asyncHandler(pinboardRoute));

router.use((error: Error, req: Request, res: Response, next: NextFunction) => {
handleRequestErrors(error, res, settings.logger);
handleRequestErrors(error, res, logger);
});

return router;
Expand Down
51 changes: 50 additions & 1 deletion src/server/routes/query/routes/visualization.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,10 +14,14 @@
* limitations under the License.
*/

import { Duration } from "chronoshift";
import { Response } from "express";
import { Expression } from "plywood";
import makeGridQuery from "../../../../client/visualizations/grid/make-query";
import { Logger } from "../../../../common/logger/logger";
import { Essence } from "../../../../common/models/essence/essence";
import { FixedTimeFilterClause } from "../../../../common/models/filter-clause/filter-clause";
import { usedMeasures } from "../../../../common/models/series/used-measures";
import { Timekeeper } from "../../../../common/models/timekeeper/timekeeper";
import makeQuery from "../../../../common/utils/query/visualization-query";
import { executeQuery } from "../../../utils/query/execute-query";
Expand All @@ -27,8 +31,53 @@ function getQuery(essence: Essence, timekeeper: Timekeeper): Expression {
return essence.visualization.name === "grid" ? makeGridQuery(essence, timekeeper) : makeQuery(essence, timekeeper);
}

function start(clause: FixedTimeFilterClause): string {
return clause.values.first().start.toUTCString();
}

function intervalLength(clause: FixedTimeFilterClause): number {
const timeRange = clause.values.first();
return timeRange.end.getTime() - timeRange.start.getTime();
}

function timeVariables(essence: Essence, timekeeper: Timekeeper): Record<string, unknown> {
const timeFilter = essence.currentTimeFilter(timekeeper);
const timeDimension = essence.getTimeDimension();
const timeSplit = essence.splits.findSplitForDimension(timeDimension);

const startTime = start(timeFilter);
const interval = intervalLength(timeFilter);

const variables: Record<string, unknown> = { startTime, interval };

if (timeSplit && timeSplit.bucket instanceof Duration) {
variables.granularity = timeSplit.bucket.getDescription();
}

if (essence.hasComparison()) {
const previousTimeFilter = essence.previousTimeFilter(timekeeper);
variables.shiftedStartTime = start(previousTimeFilter);
}

return variables;
}

function logQueryInfo(essence: Essence, timekeeper: Timekeeper, logger: Logger) {
const nonTimeFilters = essence.filter.removeClause(essence.getTimeDimension().name);

logger.log(`Visualization query ${essence.description(timekeeper)}`, {
...timeVariables(essence, timekeeper),
dataCube: essence.dataCube.name,
visualization: essence.visualization.name,
filters: nonTimeFilters.clauses.map(clause => clause.reference).toArray(),
splits: essence.splits.splits.map(split => split.reference).toArray(),
measures: essence.series.series.flatMap(usedMeasures).toSet().toArray()
});
}

export default async function visualizationRoute({ context }: QueryRouterRequest, res: Response) {
const { dataCube, essence, decorator, timekeeper } = context;
const { dataCube, essence, decorator, timekeeper, logger } = context;
logQueryInfo(essence, timekeeper, logger);
const query = getQuery(essence, timekeeper);
const result = await executeQuery(dataCube, query, essence.timezone, decorator);
res.json({ result });
Expand Down

0 comments on commit 5ef0710

Please sign in to comment.