feature/rich query logger

src/client/utils/download/download.ts

@@ -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";
@@ -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);
 }

src/common/logger/logger.ts

@@ -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 {
@@ -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,
@@ -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);
   }
 

src/common/models/essence/essence.ts

@@ -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";
@@ -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)}`;
+  }
 }

src/common/models/measure/measure.fixtures.ts

@@ -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",

src/common/models/series/used-measures.mocha.ts

@@ -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"]);
+      });
+    });
+  });
+});

src/common/models/series/used-measures.ts

@@ -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];
+  }
+}

src/server/routes/query/query.ts

@@ -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";
@@ -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();
 
@@ -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,
@@ -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;

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

@@ -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";
@@ -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 });