fix: Correctly log Exceptions

Adds bunyan Error serializer (to log {err:err} correctly with stack trace etc.
Fix log messages to include error message in log message

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();

src/autoscaler-common/logger.js

@@ -46,6 +46,7 @@ const logger = bunyan.createLogger({
  streams: [
  loggingBunyan.stream(getLogLevel()),
  ],
+ serializers: bunyan.stdSerializers,
 });
 
 module.exports = {

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

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();

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

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();

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

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 {

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;
  }

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