Add build timestamps and add section timings to slack messages, and improve error handling

README.md

@@ -68,7 +68,7 @@ It is possible to change the behaviour of the data builder by defining environme
 
 Each router directory under `configs/` has a `config.js` file that defines that
 router's data sources as a plain JS object (no factory function — just named
-fields). It is validated by `src/utils/validateConfigSources.js`
+fields). It is validated by `src/utils/configSourceValidationUtils.js`
 (`yarn run validate-configs`, also run as part of `yarn test` in CI, and again
 at runtime when the data builder starts), which rejects unknown/misspelled
 fields and duplicate feed ids. Its exported shape is:

scripts/validate-config-sources.js

@@ -8,7 +8,7 @@ const fs = require('fs');
 const path = require('path');
 const {
   validateConfigSources,
-} = require('../src/utils/validateConfigSources.js');
+} = require('../src/utils/configSourceValidationUtils.js');
 
 const configsDir = path.resolve(__dirname, '../configs');
 

src/config.js

@@ -1,7 +1,9 @@
 const assert = require('assert');
 const path = require('path');
 const { applyExtraSrc, buildIdMap } = require('./utils/configUtils.js');
-const { validateConfigSources } = require('./utils/validateConfigSources.js');
+const {
+  validateConfigSources,
+} = require('./utils/configSourceValidationUtils.js');
 
 // OBA filter erases files which it does not recognize from GTFS packages
 // this array specifies the file names which should be preserved

src/index.js

@@ -1,14 +1,56 @@
 const {
   postSlackMessage,
+  finalizeBuild,
   getStartBuildMessage,
   waitForNetwork,
 } = require('./utils/builderUtils.js');
 const { update } = require('./tasks/Update');
 const { SPLIT_BUILD_TYPE, timezone } = require('./config.js');
 const logger = require('./logger');
 
+/**
+ * Safety net for crashes/unexpected termination that happen outside the
+ * normal try/catch in Update.js#update (which already reports failures and
+ * posts the section-timing summary itself). If a build is in flight and
+ * hasn't been finalized yet, report whatever section timings were recorded
+ * so far as a thread reply, and mark the main message as interrupted, so the
+ * "Starting build..." message doesn't just look stuck forever.
+ */
+async function reportUnexpectedTermination(err, exitCode) {
+  logger.error(`Fatal error: ${err && err.stack ? err.stack : err}`);
+  if (global.buildFinalized) {
+    // finalizeBuild (called from update() or a previous invocation of this
+    // function) always calls process.exit itself right after setting this
+    // flag, so if we get here with buildFinalized already true, the build
+    // must have succeeded (a failure's finalizeBuild call would already
+    // have exited the process with code 1 before this could fire). Don't
+    // let an unrelated stray crash/signal flip that successful outcome to a
+    // failure exit code (and don't post a misleading "interrupted" message
+    // for a build that already finished).
+    process.exit(0);
+    return;
+  }
+  if (global.messageTimeStamp) {
+    await finalizeBuild({
+      statusMessage: 'Build interrupted unexpectedly',
+      statusLevel: 'error',
+      summaryPrefix: 'Build interrupted unexpectedly. Section timings so far',
+      summaryLevel: 'error',
+      exitCode,
+    });
+    return;
+  }
+  process.exit(exitCode);
+}
+
 logger.info(`Using timezone: ${timezone}`);
 
+process.on('uncaughtException', err => reportUnexpectedTermination(err, 1));
+process.on('unhandledRejection', err => reportUnexpectedTermination(err, 1));
+process.on('SIGTERM', () =>
+  reportUnexpectedTermination(new Error('Received SIGTERM'), 0),
+);
+
 waitForNetwork().then(() => {
   postSlackMessage(getStartBuildMessage(SPLIT_BUILD_TYPE))
     .then(response => {

src/tasks/BuildOTPGraph.js

@@ -2,6 +2,7 @@ const fs = require('fs');
 const { exec, execSync } = require('child_process');
 const del = require('del');
 const { otpMatching, postSlackMessage } = require('../utils/builderUtils.js');
+const { formatCodeBlock } = require('../utils/formatUtils.js');
 const { zipWithGlobIntoDir } = require('./ZipTask');
 const {
   dataDir,
@@ -68,7 +69,7 @@ const buildGraph = function (router) {
       } else {
         const log = lastLog.join('');
         postSlackMessage(
-          `${router.id} build failed: ${status}:${log}`,
+          `${router.id} build failed: ${status}\n${formatCodeBlock(log)}`,
           'error',
         );
         reject('could not build');

src/tasks/OSMPreprocessing.js

@@ -4,6 +4,7 @@ const exec = require('child_process').exec;
 const through = require('through2');
 const { dataDir, constants, dataToolImage, timezone } = require('../config');
 const { postSlackMessage, createDir } = require('../utils/builderUtils.js');
+const { formatCodeBlock } = require('../utils/formatUtils.js');
 const logger = require('../logger');
 
 /**
@@ -64,7 +65,7 @@ function preprocessWithFile(
               } else {
                 const log = lastLog.join('');
                 postSlackMessage(
-                  `${osmFile} + ${preprocessingInstructionsFile} OSM preprocessing failed: ${log}`,
+                  `${osmFile} + ${preprocessingInstructionsFile} OSM preprocessing failed:\n${formatCodeBlock(log)}`,
                   'warn',
                 );
                 global.hasFailures = true;
@@ -93,7 +94,7 @@ function preprocessWithFile(
           } catch (e) {
             const log = lastLog.join('');
             postSlackMessage(
-              `${osmFile} + ${preprocessingInstructionsFile} OSM preprocessing failed: ${log} ${e}`,
+              `${osmFile} + ${preprocessingInstructionsFile} OSM preprocessing failed:\n${formatCodeBlock(`${log}\n${e}`)}`,
               'error',
             );
             fse.removeSync(folder);

src/tasks/OTPTest.js

@@ -4,6 +4,7 @@ const exec = require('child_process').exec;
 const through = require('through2');
 const { dataDir, constants, timezone } = require('../config');
 const { postSlackMessage, createDir } = require('../utils/builderUtils.js');
+const { formatCodeBlock } = require('../utils/formatUtils.js');
 const logger = require('../logger');
 const testTag = process.env.OTP_TAG || 'v2';
 const JAVA_OPTS = process.env.JAVA_OPTS || '-Xmx9g';
@@ -37,7 +38,10 @@ function testWithOTP(otpFile, quiet = false) {
                 logger.info(otpFile + ' Test SUCCESS');
               } else {
                 const log = lastLog.join('');
-                postSlackMessage(`${otpFile} test failed: ${log}`, 'warn');
+                postSlackMessage(
+                  `${otpFile} test failed:\n${formatCodeBlock(log)}`,
+                  'warn',
+                );
                 global.hasFailures = true;
                 resolve(false);
               }
@@ -63,7 +67,10 @@ function testWithOTP(otpFile, quiet = false) {
             });
           } catch (e) {
             const log = lastLog.join('');
-            postSlackMessage(`${otpFile} test failed: ${log}`, 'error');
+            postSlackMessage(
+              `${otpFile} test failed:\n${formatCodeBlock(log)}`,
+              'error',
+            );
             fse.removeSync(folder);
             reject(e);
           }