Add debug timeout logging

Signed-off-by: jsetton <[email protected]>

lambda/alexa/smarthome/index.js

@@ -13,6 +13,7 @@
 
 import { AxiosError } from 'axios';
 import config from '#root/config.js';
+import Debug from '#root/debug.js';
 import log from '#root/log.js';
 import OpenHAB from '#openhab/index.js';
 import AlexaDirective from './directive.js';
@@ -22,16 +23,22 @@ import { AlexaError, InvalidDirectiveError } from './errors.js';
 /**
  * Handles alexa smart home skill request
  * @param  {Object}  request
+ * @param  {Object}  context
  * @return {Promise}
  */
-export const handleRequest = async (request) => {
+export const handleRequest = async (request, context) => {
+  // Initialize debug object
+  const debug = new Debug();
   // Initialize directive object
   const directive = new AlexaDirective(request.directive);
   // Initialize openhab object
-  const openhab = new OpenHAB(config.openhab, directive.auth.token, AlexaResponse.TIMEOUT);
+  const openhab = new OpenHAB(config.openhab, debug, directive.auth.token, AlexaResponse.TIMEOUT);
 
   let response;
 
+  // Start debug timeout timer
+  debug.startTimer(directive, context);
+
   try {
     // Get directive handler function
     const handler = directive.getHandler();
@@ -47,12 +54,16 @@ export const handleRequest = async (request) => {
     }
 
     // Get alexa response from handler function
-    response = await handler(directive, openhab);
+    await debug.captureAsyncFunc(handler.name, async () => {
+      response = await handler(directive, openhab);
+    });
 
     // Add response context properties if directive has endpoint
     if (directive.hasEndpoint) {
-      const properties = await directive.endpoint.getContextProperties(openhab);
-      response.setContextProperties(properties);
+      await debug.captureAsyncFunc('addContextProperties', async () => {
+        const properties = await directive.endpoint.getContextProperties(openhab);
+        response.setContextProperties(properties);
+      });
     }
   } catch (error) {
     // Log error if not alexa error
@@ -64,6 +75,9 @@ export const handleRequest = async (request) => {
     response = directive.error(error instanceof AlexaError ? error : AlexaError.from(error));
   }
 
+  // Cancel debug timeout timer
+  debug.cancelTimer();
+
   // Log response object
   log.info('Response:', response.toJSON());
   // Return response object

lambda/debug.js

@@ -0,0 +1,129 @@
+/**
+ * Copyright (c) 2010-2024 Contributors to the openHAB project
+ *
+ * See the NOTICE file(s) distributed with this work for additional
+ * information.
+ *
+ * This program and the accompanying materials are made available under the
+ * terms of the Eclipse Public License 2.0 which is available at
+ * http://www.eclipse.org/legal/epl-2.0
+ *
+ * SPDX-License-Identifier: EPL-2.0
+ */
+
+import log from '#root/log.js';
+
+/**
+ * Defines debug class
+ */
+export default class Debug {
+  /**
+   * Constructor
+   */
+  constructor() {
+    this._traces = [];
+  }
+
+  /**
+   * Starts a trace
+   * @param {String} name
+   * @return {Object}
+   */
+  startTrace(name) {
+    const trace = new Trace(name);
+    this._traces.push(trace);
+    return trace;
+  }
+
+  /**
+   * Ends a trace
+   * @param {String} name
+   * @param {String} error
+   */
+  endTrace(name, error) {
+    const trace = this._traces.find((trace) => trace.name == name && !trace.end);
+    if (trace) {
+      if (error) trace.addError(error);
+      trace.close();
+    }
+  }
+
+  /**
+   * Captures asynchronous function
+   * @param {String} name
+   * @param {Function} func
+   */
+  async captureAsyncFunc(name, func) {
+    const trace = this.startTrace(name);
+    try {
+      await func();
+    } catch (error) {
+      trace.addError(error.message);
+      throw error;
+    } finally {
+      trace.close();
+    }
+  }
+
+  /**
+   * Starts timeout timer
+   * @param {Object} directive
+   * @param {Object} context
+   */
+  startTimer(directive, context) {
+    this._timer = setTimeout(
+      () => log.error('Timed out', { directive, traces: this._traces }),
+      context.getRemainingTimeInMillis() - 10
+    );
+  }
+
+  /**
+   * Cancels timeout timer
+   */
+  cancelTimer() {
+    clearTimeout(this._timer);
+  }
+}
+
+/**
+ * Defines trace class
+ */
+class Trace {
+  /**
+   * Constructor
+   * @param {String} name
+   */
+  constructor(name) {
+    this.name = name;
+    this.start = new Date().toISOString();
+  }
+
+  /**
+   * Adds error message
+   * @param {String} error
+   */
+  addError(error) {
+    this.error = error;
+  }
+
+  /**
+   * Closes trace
+   */
+  close() {
+    this.end = new Date().toISOString();
+    this.duration = new Date(this.end) - new Date(this.start);
+  }
+
+  /**
+   * Returns serialized object
+   * @return {Object}
+   */
+  toJSON() {
+    return {
+      name: this.name,
+      start: this.start,
+      ...(this.end && { end: this.end, duration: this.duration }),
+      ...(this.error && { error: this.error })
+    };
+  }
+}

lambda/index.js

@@ -17,13 +17,14 @@ import { handleRequest } from './alexa/smarthome/index.js';
 /**
  * Defines skill event handler
  * @param  {Object}  event
+ * @param  {Object}  context
  * @return {Promise}
  */
-export const handler = async (event) => {
+export const handler = async (event, context) => {
   log.info('Received event:', event);
 
   if (event.directive?.header.payloadVersion === '3') {
-    return handleRequest(event);
+    return handleRequest(event, context);
   }
 
   log.warn('Unsupported event:', event);

lambda/openhab/index.js

@@ -31,11 +31,12 @@ export default class OpenHAB {
   /**
    * Constructor
    * @param {Object} config
+   * @param {Object} debug
    * @param {String} token
    * @param {Number} timeout
    */
-  constructor(config, token, timeout) {
-    this._client = OpenHAB.createClient(config, token, timeout);
+  constructor(config, debug, token, timeout) {
+    this._client = OpenHAB.createClient(config, debug, token, timeout);
   }
 
   /**
@@ -205,11 +206,12 @@ export default class OpenHAB {
   /**
    * Returns request client
    * @param  {Object} config
+   * @param  {Object} debug
    * @param  {String} token
    * @param  {Number} timeout
    * @return {Object}
    */
-  static createClient(config, token, timeout) {
+  static createClient(config, debug, token, timeout) {
     const client = axios.create({
       baseURL: config.baseURL,
       headers: {
@@ -237,8 +239,22 @@ export default class OpenHAB {
       client.defaults.headers.common.Authorization = `Bearer ${token}`;
     }
 
+    // Set request interceptor
+    client.interceptors.request.use((config) => {
+      debug.startTrace(`${config.method.toUpperCase()} ${config.url}`);
+      return config;
+    });
     // Set response interceptor
-    client.interceptors.response.use((response) => response.data);
+    client.interceptors.response.use(
+      (response) => {
+        debug.endTrace(`${response.config.method.toUpperCase()} ${response.config.url}`);
+        return response.data;
+      },
+      (error) => {
+        debug.endTrace(`${error.config.method.toUpperCase()} ${error.config.url}`, error.message);
+        return Promise.reject(error);
+      }
+    );
 
     return client;
   }