expansion of exception stack trace (#10)

* storage of sha

* parse exceptions

---------

Co-authored-by: Michal Moskal <michal@moskal.me>

Author: pelikhan

devicescript

@@ -145,15 +145,15 @@ export async function fwdSockInitRoute(
                             break
                         }
                         case "exn": {
-                            // TODO PARSE MESSAGE
                             const m = msg as ExnFromDevice
                             conn.socket.send(
                                 JSON.stringify({
                                     type: "exception",
                                     deviceId: m.deviceId,
-                                    message: m.logs[0],
-                                    name: "Error",
-                                    stack: m.logs.slice(1),
+                                    message: msg.exn.message,
+                                    name: msg.exn.name,
+                                    stack: msg.exn.stack,
+                                    logs: msg.logs.join("\n"),
                                 } as SideExceptionFromDevice)
                             )
                             break

src/fwdsock.ts

@@ -13,3 +13,5 @@ export {
     SideUploadJsonFromDevice,
     SideExceptionFromDevice,
 } from "../devicescript/interop/src/interop"
+
+export { parseStackFrame } from "../devicescript/interop/src/debug"

src/interop.ts

@@ -84,6 +84,7 @@ export interface FrameFromDevice extends DeviceMessage {
 
 export interface ExnFromDevice extends DeviceMessage {
     type: "exn"
+    exn: Error
     logs: string[]
 }
 

src/schema.ts

@@ -14,13 +14,15 @@ import { DeviceId, DeviceInfo, DeviceStats, zeroDeviceStats } from "./schema"
 import { delay, throwStatus } from "./util"
 import { createSecretClient } from "./vault"
 import { DebugInfo } from "./interop"
+import { createHash } from "crypto"
 
 const suff = "4"
 
 let devicesTable: TableClient
 let messageHooksTable: TableClient
 let scriptsTable: TableClient
 let scriptVersionsTable: TableClient
+let scriptVersionShaTable: TableClient
 let blobClient: BlobServiceClient
 let scriptsBlobs: ContainerClient
 
@@ -71,6 +73,10 @@ export async function setup() {
         connStr,
         "scrver" + suff
     )
+    scriptVersionShaTable = TableClient.fromConnectionString(
+        connStr,
+        "scrversha" + suff
+    )
 
     blobClient = BlobServiceClient.fromConnectionString(connStr)
     scriptsBlobs = blobClient.getContainerClient("scripts" + suff)
@@ -79,6 +85,7 @@ export async function setup() {
     await messageHooksTable.createTable()
     await scriptsTable.createTable()
     await scriptVersionsTable.createTable()
+    await scriptVersionShaTable.createTable()
     await scriptsBlobs.createIfNotExists()
 
     if (false) {
@@ -269,6 +276,7 @@ interface ScriptInfo {
     name: string
     metaJSON: string
     updated: number
+    sha?: string
 }
 
 export interface ScriptHeader {
@@ -331,6 +339,53 @@ export async function getScript(
     )
 }
 
+function binarySha(hex: string) {
+    if (!hex) return undefined
+    const s = createHash("sha256")
+    s.update(Buffer.from(hex, "hex"))
+    const sha = s.digest("hex")
+    return sha
+}
+
+export async function resolveScriptBodyFromSha(
+    partId: string,
+    sha: string
+): Promise<ScriptBody> {
+    if (!sha) return undefined
+
+    // check sha format, roundtrip throug buffer parser
+    sha = Buffer.from(sha, "hex").toString("hex")
+
+    const res = await scriptVersionShaTable.getEntity(partId, sha)
+    if (!res) return undefined
+
+    const scriptId = res.scriptId as string
+    const scriptVersion = res.scriptVersion as number
+    const body = await getScriptBody(scriptId, scriptVersion)
+    body.program.binarySHA256 = sha
+    return body
+}
+
+async function upsertScriptVersionShaSnapshot(
+    partitionKey: string,
+    scriptId: string,
+    scriptVersion: number,
+    sha: string
+) {
+    // check sha format, roundtrip throug buffer parser
+    sha = Buffer.from(sha, "hex").toString("hex")
+    // TODO: avoid sha collisions
+    await scriptVersionShaTable.upsertEntity(
+        {
+            partitionKey,
+            rowKey: sha,
+            scriptId,
+            scriptVersion,
+        },
+        "Replace"
+    )
+}
+
 function versionKey(version: number) {
     if (!version) throw new Error("bad version")
     return 1e6 - version + ""
@@ -432,7 +487,17 @@ export async function updateScript(
     }
 
     const body = updates.body || (await getScriptBody(scr.id, scr.version))
+    info.sha = binarySha(body?.program?.binary?.hex)
     await createScriptSnapshot(scr.id, newVersion, body)
+    if (info.sha) {
+        // only create index entry after creating blob
+        await upsertScriptVersionShaSnapshot(
+            scr.partition,
+            scr.id,
+            newVersion,
+            info.sha
+        )
+    }
 
     if (newVersion == 1) await scriptsTable.createEntity(info)
     else await scriptsTable.updateEntity(info, "Merge")

src/storage.ts

@@ -58,7 +58,7 @@ export function delay(ms: number) {
 }
 
 export function runInBg(log: FastifyBaseLogger, lbl: string, p: Promise<any>) {
-    log.debug(`bg ${lbl}`)
+    // log.debug(`bg ${lbl}`)
     p.then(
         _ => {},
         err => {

src/util.ts

@@ -25,7 +25,13 @@ import {
     TelemetryType,
     TraceTelemetry,
 } from "applicationinsights/out/Declarations/Contracts"
-import { WsskCmd, WsskDataType, WsskStreamingType } from "./interop"
+import {
+    DebugInfo,
+    WsskCmd,
+    WsskDataType,
+    WsskStreamingType,
+    parseStackFrame,
+} from "./interop"
 import { ingestLogs, ingestMessage } from "./messages"
 
 const JD_AES_CCM_TAG_BYTES = 4
@@ -108,6 +114,8 @@ export class ConnectedDevice {
     private deployCmd: WsskCmd = 0
     streamingMask = WsskStreamingType.DefaultMask
 
+    private lastDbgInfo: DebugInfo
+
     private lastExnBuffer: Buffer
     private exnBuffer: Buffer
     private exnLines: string[]
@@ -509,6 +517,63 @@ export class ConnectedDevice {
         }
     }
 
+    private async parseException(logs: string[]) {
+        let sha = ""
+        let startIdx = 0
+        let exnName = ""
+        let idx = 0
+        for (const l of logs) {
+            let m = /DevS-SHA256:\s+([a-f0-9]{64})/.exec(l)
+            if (m) sha = m[1].toLowerCase()
+            m = /^\* Exception:\s*(\S+)/.exec(l)
+            if (m) {
+                startIdx = idx
+                exnName = m[1]
+            }
+            idx++
+        }
+
+        if (sha) {
+            if (this.lastDbgInfo?.binarySHA256 !== sha) {
+                this.lastDbgInfo = null
+                try {
+                    const body = await storage.resolveScriptBodyFromSha(
+                        this.dev.partitionKey,
+                        sha
+                    )
+                    this.lastDbgInfo = body?.program
+                } catch {}
+            }
+        }
+
+        if (this.lastDbgInfo) {
+            logs = logs.map(l =>
+                parseStackFrame(this.lastDbgInfo, l).markedLine.replace(
+                    /\u001b\[[\d;]+m/g,
+                    ""
+                )
+            )
+        }
+
+        const stack = logs.slice(startIdx).filter(l => l.startsWith("*"))
+        let message = ""
+        for (const l of stack) {
+            const m = /^\*\s+message: (.*)/.exec(l)
+            if (m) message = m[1]
+        }
+
+        const exn: Error = {
+            name: exnName,
+            message,
+            stack: stack.join("\n"),
+        }
+
+        return {
+            exn,
+            logs,
+        }
+    }
+
     private async fastTick() {
         if (this.exnBuffer && this.lastExnBuffer === this.exnBuffer) {
             if (this.exnBuffer.length) {
@@ -517,11 +582,14 @@ export class ConnectedDevice {
             }
             this.exnBuffer = null
             if (this.exnLines?.length) {
-                this.log.info(`exception: ${this.exnLines.join("\n")}`)
-                this.traceException(this.exnLines, {})
+                const { exn, logs } = await this.parseException(this.exnLines)
+                this.log.info(`exception: ${exn.stack}`)
+                // TODO send logs somehow
+                this.traceException(exn, {})
                 await this.notify({
                     type: "exn",
-                    logs: this.exnLines,
+                    exn,
+                    logs,
                 })
                 this.exnLines = null
             }
@@ -604,23 +672,16 @@ export class ConnectedDevice {
             })
     }
 
-    public traceException(exn: string[], options: Partial<ExceptionTelemetry>) {
-        console.log(`trace exception`)
-        console.log(exn)
+    public traceException(
+        exception: Error,
+        options: Partial<ExceptionTelemetry>
+    ) {
+        console.log(`trace exception ${exception.name}(${exception.message})`)
         const { measurements = {}, ...rest } = options
         const deviceMeasurements: any = {}
         if (this.deployNumFail)
             deviceMeasurements.deployNumFail = this.deployNumFail
 
-        const name = "Error"
-        const message = exn[0]
-        const stack = exn.slice(1).join("\n")
-        const exception: Error = {
-            name,
-            message,
-            stack,
-        }
-        console.log(exception)
         this.track(
             {
                 ...rest,