fix(fileimport): return timeout error message to server & suppress noisy logging (#1703)

* fix(fileimport): reduce noisiness of logging
* fix(fileimport): return timeout error message to server

packages/fileimport-service/ifc/api.js

@@ -123,13 +123,17 @@ module.exports = class ServerAPI {
     // step 1: insert objects
     if (objsToInsert.length > 0) {
       const batches = chunk(objsToInsert, objectsBatchSize)
-      for (const batch of batches) {
+      for (const [index, batch] of batches) {
         this.prepInsertionObjectBatch(batch)
         await knex.transaction(async (trx) => {
           const q = Objects().insert(batch).toString() + ' on conflict do nothing'
           await trx.raw(q)
         })
-        this.logger.info(`Inserted ${batch.length} objects`)
+        this.logger.info(
+          `Inserted ${batch.length} objects from batch ${index + 1} of ${
+            batches.length
+          }`
+        )
       }
     }
 
@@ -137,13 +141,17 @@ module.exports = class ServerAPI {
     if (closures.length > 0) {
       const batches = chunk(closures, closureBatchSize)
 
-      for (const batch of batches) {
+      for (const [index, batch] of batches) {
         this.prepInsertionClosureBatch(batch)
         await knex.transaction(async (trx) => {
           const q = Closures().insert(batch).toString() + ' on conflict do nothing'
           await trx.raw(q)
         })
-        this.logger.info(`Inserted ${batch.length} closures`)
+        this.logger.info(
+          `Inserted ${batch.length} closures from batch ${index + 1} of ${
+            batches.length
+          }`
+        )
       }
     }
     return ids

packages/fileimport-service/ifc/parser_v2.js

@@ -83,7 +83,7 @@ module.exports = class IFCParser {
 
   async populateSpatialNode(node, chunks, closures, depth) {
     depth++
-    process.stdout.write(`${this.spatialNodeCount++} nodes generated \r`)
+    this.logger.debug(`${this.spatialNodeCount++} nodes generated.`)
     closures.push([])
     await this.getChildren(node, chunks, PropNames.aggregates, closures, depth)
     await this.getChildren(node, chunks, PropNames.spatial, closures, depth)
@@ -247,7 +247,7 @@ module.exports = class IFCParser {
     const allLinesIDs = await this.ifcapi.GetAllLines(this.modelId)
     const allLinesCount = allLinesIDs.size()
     for (let i = 0; i < allLinesCount; i++) {
-      process.stdout.write(`${((i / allLinesCount) * 100).toFixed(3)}% props \r`)
+      this.logger.debug(`${((i / allLinesCount) * 100).toFixed(3)}% props.`)
       const id = allLinesIDs.get(i)
       if (!geometryIds.has(id)) {
         const props = await this.getItemProperty(id)
@@ -380,7 +380,7 @@ module.exports = class IFCParser {
           speckle_type: 'reference',
           referencedId: speckleMesh.id
         })
-        process.stdout.write(`${(count++).toFixed(3)} geoms generated\r`)
+        this.logger.debug(`${(count++).toFixed(3)} geoms generated.`)
       }
     })
 

packages/fileimport-service/src/daemon.js

@@ -233,11 +233,21 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs)
 
     boundLogger = boundLogger.child({ pid: childProc.pid })
     childProc.stdout.on('data', (data) => {
-      boundLogger.info('Parser: %s', data.toString())
+      try {
+        JSON.parse(data.toString()) // data is already in JSON format
+        process.stdout.write(data.string())
+      } catch {
+        boundLogger.info('Parser: %s', data.toString())
+      }
     })
 
     childProc.stderr.on('data', (data) => {
-      boundLogger.info('Parser: %s', data.toString())
+      try {
+        JSON.parse(data.toString()) // data is already in JSON format
+        process.stderr.write(data.string())
+      } catch {
+        boundLogger.info('Parser: %s', data.toString())
+      }
     })
 
     let timedOut = false
@@ -247,13 +257,21 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs)
 
       timedOut = true
       childProc.kill(9)
-      reject(`Timeout: Process took longer than ${timeoutMs} ms to execute`)
+      const rejectionReason = `Timeout: Process took longer than ${timeoutMs} milliseconds to execute.`
+      const output = {
+        success: false,
+        error: rejectionReason
+      }
+      fs.writeFileSync(TMP_RESULTS_PATH, JSON.stringify(output))
+      reject(rejectionReason)
     }, timeoutMs)
 
     childProc.on('close', (code) => {
       boundLogger.info({ exitCode: code }, `Process exited with code ${code}`)
 
-      if (timedOut) return // ignore `close` calls after killing (the promise was already rejected)
+      if (timedOut) {
+        return // ignore `close` calls after killing (the promise was already rejected)
+      }
 
       clearTimeout(timeout)