Merge pull request #903 from snyk/feat/telemetry

[RUN-1850] feat: collect telemetry to understand time spent scanning images

Author: ivanstanev

src/scanner/index.ts

@@ -12,11 +12,16 @@ import {
   constructDepGraph,
   constructScanResults,
 } from '../transmitter/payload';
-import { IWorkload, ILocalWorkloadLocator } from '../transmitter/types';
+import {
+  IWorkload,
+  ILocalWorkloadLocator,
+  Telemetry,
+} from '../transmitter/types';
 import { IPullableImage, IScanImage } from './images/types';
 
 export async function processWorkload(
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): Promise<void> {
   // every workload metadata references the same workload name, grab it from the first one
   const workloadName = workloadMetadata[0].name;
@@ -27,20 +32,24 @@ export async function processWorkload(
     'pulling unique images',
   );
   const imagesWithFileSystemPath = getImagesWithFileSystemPath(uniqueImages);
+  const imagePullStartTimestampMs = Date.now();
   const pulledImages = await pullImages(imagesWithFileSystemPath);
+  const imagePullDurationMs = Date.now() - imagePullStartTimestampMs;
   if (pulledImages.length === 0) {
     logger.info(
       { workloadName },
       'no images were pulled, halting scanner process.',
     );
     return;
   }
+  telemetry.imagePullDurationMs = imagePullDurationMs;
 
   try {
     await scanImagesAndSendResults(
       workloadName,
       pulledImages,
       workloadMetadata,
+      telemetry,
     );
   } finally {
     await removePulledImages(pulledImages);
@@ -105,8 +114,11 @@ async function scanImagesAndSendResults(
   workloadName: string,
   pulledImages: IPullableImage[],
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): Promise<void> {
+  const imageScanStartTimestampMs = Date.now();
   const scannedImages = await scanImages(pulledImages);
+  const imageScanDurationMs = Date.now() - imageScanStartTimestampMs;
 
   if (scannedImages.length === 0) {
     logger.info(
@@ -116,6 +128,8 @@ async function scanImagesAndSendResults(
     return;
   }
 
+  telemetry.imageScanDurationMs = imageScanDurationMs;
+
   logger.info(
     { workloadName, imageCount: scannedImages.length },
     'successfully scanned images',
@@ -124,6 +138,7 @@ async function scanImagesAndSendResults(
   const scanResultsPayloads = constructScanResults(
     scannedImages,
     workloadMetadata,
+    telemetry,
   );
   const success = await sendScanResults(scanResultsPayloads);
   if (!success) {

src/supervisor/watchers/handlers/pod.ts

@@ -4,7 +4,7 @@ import { logger } from '../../../common/logger';
 import { config } from '../../../common/config';
 import { processWorkload } from '../../../scanner';
 import { sendWorkloadMetadata } from '../../../transmitter';
-import { IWorkload } from '../../../transmitter/types';
+import { IWorkload, Telemetry } from '../../../transmitter/types';
 import { constructWorkloadMetadata } from '../../../transmitter/payload';
 import { buildMetadataForWorkload } from '../../metadata-extractor';
 import { PodPhase } from '../types';
@@ -13,6 +13,13 @@ import { FALSY_WORKLOAD_NAME_MARKER } from './types';
 import { WorkloadKind } from '../../types';
 import { deleteWorkload } from './workload';
 
+export interface ImagesToScanQueueData {
+  workloadMetadata: IWorkload[];
+  imageKeys: string[];
+  /** The timestamp when this workload was added to the image scan queue. */
+  enqueueTimestampMs: number;
+}
+
 function deleteFailedKeysFromState(keys): void {
   try {
     for (const key of keys) {
@@ -33,10 +40,19 @@ function deleteFailedKeysFromState(keys): void {
   }
 }
 
-async function queueWorkerWorkloadScan(task, callback): Promise<void> {
-  const { workloadMetadata, imageKeys } = task;
+async function queueWorkerWorkloadScan(
+  task: ImagesToScanQueueData,
+  callback,
+): Promise<void> {
+  const { workloadMetadata, imageKeys, enqueueTimestampMs } = task;
+  /** Represents how long this workload spent waiting in the queue to be processed. */
+  const enqueueDurationMs = Date.now() - enqueueTimestampMs;
+  const telemetry: Partial<Telemetry> = {
+    enqueueDurationMs,
+    queueSize: workloadsToScanQueue.length(),
+  };
   try {
-    await processWorkload(workloadMetadata);
+    await processWorkload(workloadMetadata, telemetry);
   } catch (err) {
     logger.error(
       { err, task },
@@ -46,7 +62,7 @@ async function queueWorkerWorkloadScan(task, callback): Promise<void> {
   }
 }
 
-const workloadsToScanQueue = async.queue(
+const workloadsToScanQueue = async.queue<ImagesToScanQueueData>(
   queueWorkerWorkloadScan,
   config.WORKLOADS_TO_SCAN_QUEUE_WORKER_COUNT,
 );
@@ -82,7 +98,11 @@ function handleReadyPod(workloadMetadata: IWorkload[]): void {
   }
 
   if (imagesToScan.length > 0) {
-    workloadsToScanQueue.push({ workloadMetadata: imagesToScan, imageKeys });
+    workloadsToScanQueue.push({
+      workloadMetadata: imagesToScan,
+      imageKeys,
+      enqueueTimestampMs: Date.now(),
+    });
   }
 }
 

src/transmitter/payload.ts

@@ -12,6 +12,7 @@ import {
   ScanResultsPayload,
   IDependencyGraphPayload,
   IWorkloadEventsPolicyPayload,
+  Telemetry,
 } from './types';
 import { state } from '../state';
 
@@ -51,6 +52,7 @@ export function constructDepGraph(
 export function constructScanResults(
   scannedImages: IScanResult[],
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): ScanResultsPayload[] {
   return scannedImages.map<ScanResultsPayload>((scannedImage) => {
     // We know that .find() won't return undefined
@@ -72,6 +74,7 @@ export function constructScanResults(
     };
 
     return {
+      telemetry,
       imageLocator,
       agentId: config.AGENT_ID,
       scanResults: scannedImage.scanResults,

src/transmitter/types.ts

@@ -42,6 +42,7 @@ export interface ScanResultsPayload {
   imageLocator: IImageLocator;
   agentId: string;
   scanResults: ScanResult[];
+  telemetry: Partial<Telemetry>;
 }
 
 export interface IWorkloadMetadataPayload {
@@ -96,3 +97,10 @@ export interface IRequestError {
   code: string;
   message: string;
 }
+
+export interface Telemetry {
+  enqueueDurationMs: number;
+  queueSize: number;
+  imagePullDurationMs: number;
+  imageScanDurationMs: number;
+}

test/system/kind.spec.ts

@@ -250,6 +250,12 @@ test('Kubernetes-Monitor with KinD', async (jestDoneCallback) => {
       try {
         expect(requestBody).toEqual<transmitterTypes.ScanResultsPayload>({
           agentId,
+          telemetry: {
+            enqueueDurationMs: expect.any(Number),
+            imagePullDurationMs: expect.any(Number),
+            imageScanDurationMs: expect.any(Number),
+            queueSize: expect.any(Number),
+          },
           imageLocator: expect.objectContaining({
             imageId: expect.any(String),
           }),

test/unit/transmitter-payload.spec.ts

@@ -60,8 +60,14 @@ describe('transmitter payload tests', () => {
         },
       ];
 
+      const telemetry: Record<string, number> = {};
+
       expect(() =>
-        payload.constructScanResults(scannedImages, workloadMetadata),
+        payload.constructScanResults(
+          scannedImages,
+          workloadMetadata,
+          telemetry,
+        ),
       ).toThrow();
     },
   );
@@ -97,6 +103,7 @@ describe('transmitter payload tests', () => {
         podSpec: podSpecFixture,
       },
     ];
+    const telemetry: Record<string, number> = {};
 
     // These values are populated at runtime (injected by the deployment) so we have to mock them
     // to make sure the function uses them to construct the payload (otherwise they are undefined).
@@ -110,6 +117,7 @@ describe('transmitter payload tests', () => {
     const payloads = payload.constructScanResults(
       scannedImages,
       workloadMetadata,
+      telemetry,
     );
     expect(payloads).toHaveLength(1);