ripped out logging, switched to monitoring-based system

Author: toptobes

package-lock.json

@@ -98,8 +98,8 @@
     "axios": "^1.6.7",
     "bson": "^6.3.0",
     "object-hash": "^3.0.0",
-    "uuidv7": "^0.6.3",
-    "winston": "^3.7.2"
+    "typed-emitter": "^2.1.0",
+    "uuidv7": "^0.6.3"
   },
   "engines": {
     "node": ">=14.0.0"

package.json

@@ -11,17 +11,17 @@
 // 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.
+// noinspection ExceptionCaughtLocallyJS
 
-import { DEFAULT_NAMESPACE, DEFAULT_TIMEOUT, HttpClient, HttpMethods, RawDataApiResponse } from '@/src/api';
+import { DEFAULT_NAMESPACE, DEFAULT_TIMEOUT, hrTimeMs, HttpClient, HttpMethods, RawDataApiResponse } from '@/src/api';
 import { DataAPIResponseError, DataAPITimeout, mkRespErrorFromResponse, ObjectId, UUID } from '@/src/data-api';
-import { logger } from '@/src/logger';
-import {
-  MkTimeoutError,
-  TimeoutManager,
-  TimeoutOptions,
-} from '@/src/api/timeout-managers';
-
-interface DataApiRequestInfo {
+import { MkTimeoutError, TimeoutManager, TimeoutOptions } from '@/src/api/timeout-managers';
+import { CommandFailedEvent, CommandStartedEvent, CommandSucceededEvent } from '@/src/data-api/events';
+
+/**
+ * @internal
+ */
+export interface DataApiRequestInfo {
   url: string;
   collection?: string;
   namespace?: string;
@@ -48,58 +48,68 @@ export class DataApiHttpClient extends HttpClient {
   public async executeCommand(command: Record<string, any>, options: ExecuteCommandOptions | undefined) {
     const timeoutManager = options?.timeoutManager ?? mkTimeoutManager(options?.maxTimeMS);
 
-    const response = await this._requestDataApi({
+    return await this._requestDataApi({
       url: this.baseUrl,
       timeoutManager: timeoutManager,
       collection: options?.collection,
       namespace: options?.namespace,
       command: command,
     });
-
-    handleIfErrorResponse(response, command);
-    return response;
   }
 
-  protected async _requestDataApi(info: DataApiRequestInfo): Promise<RawDataApiResponse> {
+  private async _requestDataApi(info: DataApiRequestInfo): Promise<RawDataApiResponse> {
+    let started = 0;
+
     try {
       info.collection ||= this.collection;
       info.namespace ||= this.namespace || DEFAULT_NAMESPACE;
 
       const keyspacePath = `/${info.namespace}`;
       const collectionPath = info.collection ? `/${info.collection}` : '';
-      const url = info.url + keyspacePath + collectionPath;
+      info.url += keyspacePath + collectionPath;
+
+      if (this.monitorCommands) {
+        started = hrTimeMs();
+        this.emitter.emit('commandStarted', new CommandStartedEvent(info));
+      }
 
       const response = await this._request({
-        url: url,
+        url: info.url,
         data: JSON.stringify(info.command, replacer),
         timeoutManager: info.timeoutManager,
         method: HttpMethods.Post,
         reviver: reviver,
       });
 
       if (response.status === 401 || (response.data?.errors?.length > 0 && response.data?.errors[0]?.message === 'UNAUTHENTICATED: Invalid token')) {
-        return mkFauxErroredResponse('Authentication failed; is your token valid?');
+        const fauxResponse = mkFauxErroredResponse('Authentication failed; is your token valid?');
+        throw mkRespErrorFromResponse(DataAPIResponseError, info.command, fauxResponse);
       }
 
       if (response.status === 200) {
-        return {
+        if (response.data?.errors && response.data?.errors.length > 0) {
+          throw mkRespErrorFromResponse(DataAPIResponseError, info.command, response.data);
+        }
+
+        const respData = {
           status: response.data?.status,
           data: response.data?.data,
           errors: response.data?.errors,
-        };
+        }
+
+        if (this.monitorCommands) {
+          this.emitter.emit('commandSucceeded', new CommandSucceededEvent(info, respData, started));
+        }
+
+        return respData;
       } else {
-        logger.error(info.url + ": " + response.status);
-        logger.error("Data: " + JSON.stringify(info.command));
-        return mkFauxErroredResponse(`Some non-200 status code was returned. Check the logs for more information. ${response.status}, ${JSON.stringify(response.data)}`);
+        const fauxResponse = mkFauxErroredResponse(`Some non-200 status code was returned. Check the logs for more information. ${response.status}, ${JSON.stringify(response.data)}`);
+        throw mkRespErrorFromResponse(DataAPIResponseError, info.command, fauxResponse);
       }
     } catch (e: any) {
-      logger.error(info.url + ": " + e.message);
-      logger.error("Data: " + JSON.stringify(info.command));
-
-      if (e?.response?.data) {
-        logger.error("Response Data: " + JSON.stringify(e.response.data));
+      if (this.monitorCommands) {
+        this.emitter.emit('commandFailed', new CommandFailedEvent(info, e, started));
       }
-
       throw e;
     }
   }
@@ -111,7 +121,7 @@ const mkTimeoutManager = (maxMs: number | undefined) => {
 }
 
 const mkTimeoutErrorMaker = (timeout: number): MkTimeoutError => {
-  return (info) => new DataAPITimeout(info.data!, timeout);
+  return () => new DataAPITimeout(timeout);
 }
 
 const mkFauxErroredResponse = (message: string): RawDataApiResponse => {
@@ -157,12 +167,3 @@ export function reviver(_: string, value: any): any {
   }
   return value;
 }
-
-/**
- * @internal
- */
-export function handleIfErrorResponse(response: any, command: Record<string, any>) {
-  if (response.errors && response.errors.length > 0) {
-    throw mkRespErrorFromResponse(DataAPIResponseError, command, response);
-  }
-}

src/api/data-api-http-client.ts

@@ -12,26 +12,35 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-import { HttpClient } from '@/src/api/http-client';
+import { hrTimeMs, HttpClient } from '@/src/api/http-client';
 import { AxiosError, AxiosResponse } from 'axios';
 import { HTTPClientOptions, HttpMethodStrings } from '@/src/api/types';
 import { HTTP1AuthHeaderFactories, HTTP1Strategy } from '@/src/api/http1';
 import { DevopsApiResponseError, DevopsApiTimeout, DevopsUnexpectedStateError } from '@/src/devops/errors';
-import { AdminBlockingOptions, PollBlockingOptions } from '@/src/devops/types';
-import {
-  MkTimeoutError, TimeoutManager,
-  TimeoutOptions,
-} from '@/src/api/timeout-managers';
+import { AdminBlockingOptions } from '@/src/devops/types';
+import { MkTimeoutError, TimeoutManager, TimeoutOptions } from '@/src/api/timeout-managers';
 import { HttpMethods } from '@/src/api/constants';
+import {
+  AdminCommandFailedEvent,
+  AdminCommandPollingEvent,
+  AdminCommandStartedEvent,
+  AdminCommandSucceededEvent,
+} from '@/src/devops';
 
-interface DevopsApiRequestInfo {
+/**
+ * @internal
+ */
+export interface DevopsApiRequestInfo {
   path: string,
   method: HttpMethodStrings,
   data?: Record<string, any>,
   params?: Record<string, any>,
 }
 
-interface LongRunningRequestInfo {
+/**
+ * @internal
+ */
+export interface LongRunningRequestInfo {
   id: string | ((resp: AxiosResponse) => string),
   target: string,
   legalStates: string[],
@@ -48,19 +57,41 @@ export class DevopsApiHttpClient extends HttpClient {
     this.requestStrategy = new HTTP1Strategy(HTTP1AuthHeaderFactories.DevopsApi);
   }
 
-  public async request(info: DevopsApiRequestInfo, options: TimeoutOptions | undefined): Promise<AxiosResponse> {
+  public async request(req: DevopsApiRequestInfo, options: TimeoutOptions | undefined, started: number = 0): Promise<AxiosResponse> {
+    const isLongRunning = started !== 0;
+
     try {
       const timeoutManager = options?.timeoutManager ?? mkTimeoutManager(options?.maxTimeMS);
-      const url = this.baseUrl + info.path;
+      const url = this.baseUrl + req.path;
 
-      return await this._request({
+      if (this.monitorCommands && !isLongRunning) {
+        this.emitter.emit('adminCommandStarted', new AdminCommandStartedEvent(req, isLongRunning, timeoutManager.ms));
+      }
+
+      started ||= hrTimeMs();
+
+      const resp = await this._request({
         url: url,
-        method: info.method,
-        params: info.params,
-        data: info.data,
+        method: req.method,
+        params: req.params,
+        data: req.data,
         timeoutManager,
-      }) as any;
+      }) as AxiosResponse;
+
+      if (this.monitorCommands && !isLongRunning) {
+        this.emitter.emit('adminCommandSucceeded', new AdminCommandSucceededEvent(req, false, resp, started));
+      }
+
+      return resp;
     } catch (e) {
+      if (!(e instanceof Error)) {
+        throw e;
+      }
+
+      if (this.monitorCommands) {
+        this.emitter.emit('adminCommandFailed', new AdminCommandFailedEvent(req, isLongRunning, e, started));
+      }
+
       if (!(e instanceof AxiosError)) {
         throw e;
       }
@@ -70,38 +101,72 @@ export class DevopsApiHttpClient extends HttpClient {
 
   public async requestLongRunning(req: DevopsApiRequestInfo, info: LongRunningRequestInfo): Promise<AxiosResponse> {
     const timeoutManager = mkTimeoutManager(info.options?.maxTimeMS);
-    const resp = await this.request(req, { timeoutManager });
+    const isLongRunning = info?.options?.blocking !== false;
+
+    if (this.monitorCommands) {
+      this.emitter.emit('adminCommandStarted', new AdminCommandStartedEvent(req, isLongRunning, timeoutManager.ms));
+    }
+
+    const started = hrTimeMs();
+    const resp = await this.request(req, { timeoutManager }, started);
 
     const id = (typeof info.id === 'function')
       ? info.id(resp)
       : info.id;
 
-    if (info?.options?.blocking !== false) {
-      await this._awaitStatus(id, info.target, info.legalStates, info.options, info.defaultPollInterval, timeoutManager);
+    await this._awaitStatus(id, req, info, timeoutManager, started);
+
+    if (this.monitorCommands && isLongRunning) {
+      this.emitter.emit('adminCommandSucceeded', new AdminCommandSucceededEvent(req, true, resp, started));
     }
 
     return resp;
   }
 
-  private async _awaitStatus(id: string, target: string, legalStates: string[], options: PollBlockingOptions | undefined, defaultPollInterval: number, timeoutManager: TimeoutManager): Promise<void> {
+  private async _awaitStatus(id: string, req: DevopsApiRequestInfo, info: LongRunningRequestInfo, timeoutManager: TimeoutManager, started: number): Promise<void> {
+    if (info.options?.blocking === false) {
+      return;
+    }
+
+    const pollInterval = info.options?.pollInterval || info.defaultPollInterval;
+    let waiting = false;
+
     for (;;) {
+      if (waiting) {
+        continue;
+      }
+      waiting = true;
+
+      if (this.monitorCommands) {
+        this.emitter.emit('adminCommandPolling', new AdminCommandPollingEvent(req, started, pollInterval));
+      }
+
       const resp = await this.request({
         method: HttpMethods.Get,
         path: `/databases/${id}`,
       }, {
         timeoutManager: timeoutManager,
-      });
+      }, started);
 
-      if (resp.data?.status === target) {
+      if (resp.data?.status === info.target) {
         break;
       }
 
-      if (!legalStates.includes(resp.data?.status)) {
-        throw new DevopsUnexpectedStateError(`Created database is not in any legal state [${[target, ...legalStates].join(',')}]`, resp)
+      if (!info.legalStates.includes(resp.data?.status)) {
+        const error = new DevopsUnexpectedStateError(`Created database is not in any legal state [${[info.target, ...info.legalStates].join(',')}]`, resp);
+
+        if (this.monitorCommands) {
+          this.emitter.emit('adminCommandFailed', new AdminCommandFailedEvent(req, true, error, started));
+        }
+
+        throw error;
       }
 
       await new Promise<void>((resolve) => {
-        setTimeout(resolve, options?.pollInterval || defaultPollInterval);
+        setTimeout(() => {
+          waiting = false;
+          resolve();
+        }, pollInterval);
       });
     }
   }

src/api/devops-api-http-client.ts

@@ -17,7 +17,8 @@ import { GuaranteedAPIResponse, HTTPClientOptions, HTTPRequestInfo, HTTPRequestS
 import { HTTP1AuthHeaderFactories, HTTP1Strategy } from '@/src/api/http1';
 import { HTTP2Strategy } from '@/src/api/http2';
 import { Mutable } from '@/src/data-api/types/utils';
-import { Caller } from '@/src/client';
+import { Caller, DataApiClientEvents } from '@/src/client';
+import TypedEmitter from 'typed-emitter';
 
 /**
  * @internal
@@ -26,24 +27,15 @@ export class HttpClient {
   public readonly baseUrl: string;
   public readonly userAgent: string;
   public requestStrategy: HTTPRequestStrategy;
+  public emitter: TypedEmitter<DataApiClientEvents>;
+  public monitorCommands: boolean;
   #applicationToken: string;
 
   constructor(options: HTTPClientOptions) {
-    if (typeof window !== "undefined") {
-      throw new Error("not for use in a web browser");
-    }
-
-    if (!options.baseUrl) {
-      throw new Error("baseUrl required for initialization");
-    }
-
-    if (!options.applicationToken) {
-      throw new Error("applicationToken required for initialization");
-    }
-
     this.#applicationToken = options.applicationToken;
-
     this.baseUrl = options.baseUrl;
+    this.emitter = options.emitter;
+    this.monitorCommands = options.monitorCommands;
 
     this.requestStrategy =
       (options.requestStrategy)
@@ -77,6 +69,8 @@ export class HttpClient {
       applicationToken: this.#applicationToken,
       requestStrategy: this.requestStrategy,
       userAgent: this.userAgent,
+      emitter: this.emitter,
+      monitorCommands: this.monitorCommands,
     });
     initialize(clone);
     return clone;
@@ -109,6 +103,11 @@ export class HttpClient {
   }
 }
 
+export function hrTimeMs(): number {
+  const hrtime = process.hrtime();
+  return Math.floor(hrtime[0] * 1000 + hrtime[1] / 1000000);
+}
+
 function buildUserAgent(client: string, caller?: Caller | Caller[]): string {
   const callers = (
     (!caller)