fix: Correctly log Exceptions (#268)

Adds bunyan Error serializer (to log {err:err} correctly with stack trace etc. Fix log messages to include exception in log message
cloudspannerecosystem · Apr 4, 2024 · 713969b · 713969b
1 parent 3db7ce5
commit 713969b
Show file tree

Hide file tree

Showing 10 changed files with 89 additions and 83 deletions.
diff --git a/src/autoscaler-common/counters_base.js b/src/autoscaler-common/counters_base.js
@@ -443,8 +443,8 @@ async function tryFlush() {
         EXPORTER_PARAMETERS[exporterMode].FLUSH_MAX_ATTEMPTS
       } attempts - see OpenTelemetry logging`);
     }
-  } catch (e) {
-    logger.error('Error while flushing counters', e);
+  } catch (err) {
+    logger.error({err: err, message: `Error while flushing counters: ${err}`});
   } finally {
     // Release any waiters...
     resolveFlushInProgress();

diff --git a/src/autoscaler-common/logger.js b/src/autoscaler-common/logger.js
@@ -46,6 +46,7 @@ const logger = bunyan.createLogger({
   streams: [
     loggingBunyan.stream(getLogLevel()),
   ],
+  serializers: bunyan.stdSerializers,
 });
 
 module.exports = {

diff --git a/src/forwarder/index.js b/src/forwarder/index.js
@@ -59,10 +59,11 @@ async function forwardFromHTTP(req, res) {
     res.status(200).end();
   } catch (err) {
     logger.error({
-      message: `An error occurred in the Autoscaler forwarder (HTTP)`,
-      err: err});
-    logger.error({message: `JSON payload`, payload: payloadString});
-    res.status(500).end(err.toString());
+      message: `An error occurred in the Autoscaler forwarder (HTTP): ${err}`,
+      err: err,
+      payload: payloadString,
+    });
+    res.status(500).end('An exception occurred');
   }
 }
 
@@ -87,10 +88,10 @@ async function forwardFromPubSub(pubSubEvent, context) {
     });
   } catch (err) {
     logger.error({
-      message:
-        `An error occurred in the Autoscaler forwarder (PubSub)`,
-      err: err});
-    logger.error({message: `JSON payload`, payload: payload});
+      message: `An error occurred in the Autoscaler forwarder (PubSub): ${err}`,
+      err: err,
+      payload: payload,
+    });
   }
 }
 

diff --git a/src/index.js b/src/index.js
@@ -60,8 +60,9 @@ async function main() {
     }
   } catch (err) {
     logger.error({
-      message: 'Error in unified poller/scaler wrapper:',
-      err: err});
+      message: 'Error in unified poller/scaler wrapper: ${err}',
+      err: err,
+    });
   } finally {
     CountersBase.setTryFlushEnabled(true);
     await CountersBase.tryFlush();

diff --git a/src/poller/index.js b/src/poller/index.js
@@ -49,8 +49,9 @@ async function main() {
         JSON.stringify(yaml.load(config)));
   } catch (err) {
     logger.error({
-      message: 'Error in Poller wrapper:',
-      err: err});
+      message: `Error in Poller: ${err}`,
+      err: err,
+    });
   }
 }
 

diff --git a/src/poller/poller-core/index.js b/src/poller/poller-core/index.js
@@ -302,10 +302,10 @@ async function postPubSubMessage(spanner, metrics) {
       .catch((err) => {
         logger.error({
           message: `An error occurred when publishing the message to ${
-            spanner.scalerPubSubTopic}`,
+            spanner.scalerPubSubTopic}: $[err}]`,
           projectId: spanner.projectId,
           instanceId: spanner.instanceId,
-          payload: err,
+          payload: spanner,
           err: err,
         });
       });
@@ -337,7 +337,7 @@ async function callScalerHTTP(spanner, metrics) {
           })
       .catch((err) => {
         logger.error({
-          message: `An error occurred when calling the scaler`,
+          message: `An error occurred when calling the scaler: ${err}`,
           projectId: spanner.projectId,
           instanceId: spanner.instanceId,
           payload: err,
@@ -469,11 +469,13 @@ async function parseAndEnrichPayload(payload) {
       spannersFound.push(spanners[sIdx]);
     } catch (err) {
       logger.error({
-        message: `Unable to retrieve Spanner metadata for ${
-          spanners[sIdx].projectId}/${spanners[sIdx].instanceId}`,
+        message:
+            `Unable to retrieve Spanner metadata for ${
+              spanners[sIdx].projectId}/${spanners[sIdx].instanceId}: ${err}`,
         projectId: spanners[sIdx].projectId,
         instanceId: spanners[sIdx].instanceId,
-        payload: err,
+        err: err,
+        payload: spanners[sIdx],
       });
     }
   }
@@ -550,10 +552,11 @@ async function forwardMetrics(forwarderFunction, spanners) {
       await Counters.incPollingSuccessCounter(spanner);
     } catch (err) {
       logger.error({
-        message: `Unable to retrieve metrics for ${spanner.projectId}/${
-          spanner.instanceId}`,
+        message: `Unable to retrieve metrics for ${
+          spanner.projectId}/${spanner.instanceId}: ${err}`,
         projectId: spanner.projectId,
         instanceId: spanner.instanceId,
+        payload: spanner,
         err: err,
       });
       await Counters.incPollingFailedCounter(spanner);
@@ -576,10 +579,11 @@ async function aggregateMetrics(spanners) {
       await Counters.incPollingSuccessCounter(spanner);
     } catch (err) {
       logger.error({
-        message: `Unable to retrieve metrics for ${spanner.projectId}/${
-          spanner.instanceId}`,
+        message: `Unable to retrieve metrics for ${
+          spanner.projectId}/${spanner.instanceId}: ${err}`,
         projectId: spanner.projectId,
         instanceId: spanner.instanceId,
+        spanner: spanner,
         err: err,
       });
       await Counters.incPollingFailedCounter(spanner);
@@ -607,16 +611,20 @@ async function checkSpannerScaleMetricsPubSub(pubSubEvent, context) {
       await Counters.incRequestsSuccessCounter();
     } catch (err) {
       logger.error({
-        message: `An error occurred in the Autoscaler poller function (PubSub)`,
-        err: err});
-      logger.error({message: `JSON payload`, payload: payload});
+        message:
+            `An error occurred in the Autoscaler poller function (PubSub): ${
+              err}`,
+        payload: payload,
+        err: err,
+      });
       await Counters.incRequestsFailedCounter();
     }
   } catch (err) {
     logger.error({
-      message: `An error occurred in the Autoscaler poller function (PubSub)`,
-      err: err});
-    logger.error({message: `Pubsub data`, payload: pubSubEvent.data});
+      message: `An error occurred parsing pubsub payload: ${err}`,
+      payload: pubSubEvent.data,
+      err: err,
+    });
     await Counters.incRequestsFailedCounter();
   } finally {
     await Counters.tryFlush();
@@ -646,11 +654,12 @@ async function checkSpannerScaleMetricsHTTP(req, res) {
     await Counters.incRequestsSuccessCounter();
   } catch (err) {
     logger.error({
-      message: `An error occurred in the Autoscaler poller function (HTTP)`,
-      err: err});
-    logger.error({message: `JSON payload`, payload: payload});
-    res.status(500).end(err.toString());
-    res.end(err.toString());
+      message: `An error occurred in the Autoscaler poller function (HTTP): ${
+        err}`,
+      payload: payload,
+      err: err,
+    });
+    res.status(500).contentType('text/plain').end('An Exception occurred');
     await Counters.incRequestsFailedCounter();
   } finally {
     await Counters.tryFlush();
@@ -673,9 +682,11 @@ async function checkSpannerScaleMetricsJSON(payload) {
   } catch (err) {
     logger.error({
       message:
-        `An error occurred in the Autoscaler poller function (JSON/HTTP)`,
-      err: err});
-    logger.error({message: `JSON payload`, payload: payload});
+          `An error occurred in the Autoscaler poller function (JSON/HTTP): ${
+            err}`,
+      payload: payload,
+      err: err,
+    });
     await Counters.incRequestsFailedCounter();
   } finally {
     await Counters.tryFlush();
@@ -700,9 +711,11 @@ async function checkSpannerScaleMetricsLocal(payload) {
   } catch (err) {
     logger.error({
       message:
-        `An error occurred in the Autoscaler poller function (JSON/Local)`,
-      err: err});
-    logger.error({message: `JSON payload`, payload: payload});
+          `An error occurred in the Autoscaler poller function (JSON/Local): ${
+            err}`,
+      payload: payload,
+      err: err,
+    });
     await Counters.incRequestsFailedCounter();
   } finally {
     await Counters.tryFlush();

diff --git a/src/scaler/index.js b/src/scaler/index.js
@@ -40,8 +40,9 @@ function main() {
     app.listen(port);
   } catch (err) {
     logger.error({
-      message: 'Error in Scaler wrapper:',
-      err: err});
+      message: 'Error startting Scaler: ${err}',
+      err: err,
+    });
   }
 }
 

diff --git a/src/scaler/scaler-core/index.js b/src/scaler/scaler-core/index.js
@@ -319,18 +319,11 @@ async function processScalingRequest(spanner, autoscalerState) {
     } catch (err) {
       logger.error({
         message: `----- ${spanner.projectId}/${
-          spanner.instanceId}: Unsuccessful scaling attempt.`,
-        projectId: spanner.projectId,
-        instanceId: spanner.instanceId,
-        payload: err,
-        err: err,
-      });
-      logger.error({
-        message:
-          `----- ${spanner.projectId}/${spanner.instanceId}: Spanner payload:`,
+          spanner.instanceId}: Unsuccessful scaling attempt: ${err}.`,
         projectId: spanner.projectId,
         instanceId: spanner.instanceId,
         payload: spanner,
+        err: err,
       });
       eventType = 'SCALING_FAILURE';
       await Counters.incScalingFailedCounter(
@@ -372,22 +365,17 @@ async function scaleSpannerInstancePubSub(pubSubEvent, context) {
       await Counters.incRequestsSuccessCounter();
     } catch (err) {
       logger.error({
-        message: `Failed to process scaling request\n`,
+        message: `Failed to process scaling request: ${err}`,
         projectId: spanner.projectId,
         instanceId: spanner.instanceId,
         payload: spanner,
-      });
-      logger.error({
-        message: `Exception\n`,
-        projectId: spanner.projectId,
-        instanceId: spanner.instanceId,
         err: err,
       });
       await Counters.incRequestsFailedCounter();
     }
   } catch (err) {
     logger.error({
-      message: `Failed to parse pubSub scaling request\n`,
+      message: `Failed to parse pubSub scaling request: ${err}`,
       payload: pubSubEvent.data,
       err: err,
     });
@@ -416,13 +404,17 @@ async function scaleSpannerInstanceHTTP(req, res) {
       res.status(200).end();
       await Counters.incRequestsSuccessCounter();
     } catch (err) {
-      console.error(err);
-      res.status(500).end(err.toString());
+      logger.error({
+        message: `Failed to process scaling request: ${err}`,
+        payload: payload,
+        err: err,
+      });
+      res.status(500).contentType('text/plain').end('An Exception occurred');
       await Counters.incRequestsFailedCounter();
     }
   } catch (err) {
     logger.error({
-      message: `Failed to parse http scaling request\n`,
+      message: `Failed to parse http scaling request: ${err}`,
       err: err,
     });
     await Counters.incRequestsFailedCounter();
@@ -449,16 +441,10 @@ async function scaleSpannerInstanceJSON(req, res) {
     await Counters.incRequestsSuccessCounter();
   } catch (err) {
     logger.error({
-      message: `Failed to process scaling request\n`,
+      message: `Failed to process scaling request: ${err}`,
       projectId: spanner.projectId,
       instanceId: spanner.instanceId,
       payload: spanner,
-    });
-    logger.error({
-      message: `Exception\n`,
-      projectId: spanner.projectId,
-      instanceId: spanner.instanceId,
-      payload: err,
       err: err,
     });
     res.writeHead(500, {
@@ -484,16 +470,10 @@ async function scaleSpannerInstanceLocal(spanner) {
     await Counters.incRequestsSuccessCounter();
   } catch (err) {
     logger.error({
-      message: `Failed to process scaling request\n`,
+      message: `Failed to process scaling request: ${err}`,
       projectId: spanner.projectId,
       instanceId: spanner.instanceId,
       payload: spanner,
-    });
-    logger.error({
-      message: `Exception\n`,
-      projectId: spanner.projectId,
-      instanceId: spanner.instanceId,
-      payload: err,
       err: err,
     });
   } finally {

diff --git a/src/scaler/scaler-core/state.js b/src/scaler/scaler-core/state.js
@@ -335,8 +335,11 @@ class StateFirestore extends State {
         await oldDocRef.delete();
       }
       return snapshot;
-    } catch (e) {
-      logger.error(e, `Failed to migrate docpaths`);
+    } catch (err) {
+      logger.error({
+        message: `Failed to migrate docpaths: ${err}`,
+        err: err,
+      });
     }
     return null;
   }

diff --git a/src/scaler/scaler-core/utils.js b/src/scaler/scaler-core/utils.js
@@ -106,14 +106,19 @@ async function publishProtoMsgDownstream(eventName, jsonData, topicId) {
   const data = Buffer.from(JSON.stringify(message.toJSON()));
   const attributes = {event: eventName};
 
-  return topic.publishMessage({data: data, attributes: attributes})
-      .then( () => logger.info(
-          `Published ${eventName} message downstream to topic: ${topicId}`))
+  return topic
+      .publishMessage({data: data, attributes: attributes})
+      .then(() =>
+        logger.info(
+            `Published ${eventName} message downstream to topic: ${topicId}`,
+        ),
+      )
       .catch((err) => {
         logger.error({
           message: `An error occurred publishing ${
-            eventName} message downstream to topic: ${topicId}`,
-          err: err});
+            eventName} message downstream to topic: ${topicId}: ${err}`,
+          err: err,
+        });
       });
 }