fix: Improve logging and error handling

.changeset/smooth-days-fold.md

@@ -0,0 +1,5 @@
+---
+"@kopflos-cms/core": patch
+---
+
+Improve logging and error handling

packages/core/lib/Kopflos.ts

@@ -84,7 +84,7 @@ export default class Impl implements Kopflos {
     ])
 
     log.info('Kopflos initialized')
-    log.debug('Options %O', {
+    log.debug('Options', {
       sparqlEndpoints: Object.keys(this.env.sparql),
       resourceShapeLookup: options.resourceShapeLookup?.name ?? 'default',
       resourceLoaderLookup: options.resourceLoaderLookup?.name ?? 'default',
@@ -135,26 +135,42 @@ export default class Impl implements Kopflos {
   }
 
   async handleRequest(req: KopflosRequest<Dataset>): Promise<ResultEnvelope> {
+    log.info(`${req.method} ${req.iri.value}`)
+    log.debug('Request headers', req.headers)
+
     let result: KopflosResponse
     try {
       result = await this.getResponse(req)
-    } catch (e: Error | unknown) {
-      const error = e instanceof Error ? e : new Error(String(e))
+    } catch (cause: Error | unknown) {
+      const error = cause instanceof Error
+        ? cause
+        : typeof cause === 'string'
+          ? new Error(cause)
+          : new Error('Unknown error', { cause })
       log.error(error)
       return {
         status: 500,
         body: error,
       }
     }
 
-    if (this.isEnvelope(result)) {
-      return result
+    if (!result) {
+      log.error('Undefined result returned from handler')
+      return {
+        status: 500,
+        body: new Error('Handler did not return a result'),
+      }
     }
 
-    return {
-      status: 200,
-      body: result,
+    if (!this.isEnvelope(result)) {
+      result = {
+        status: 200,
+        body: result,
+      }
     }
+
+    log.info('Response status', result.status)
+    return result
   }
 
   async findResourceShape(iri: NamedNode): Promise<ResourceShapeMatch | KopflosResponse> {
@@ -165,12 +181,12 @@ export default class Impl implements Kopflos {
       return candidates
     }
     if (candidates.length === 0) {
-      log.info('Resource shape not found for %s', iri.value)
+      log.info(`Resource shape not found for ${iri.value}`)
       return { status: 404 }
     }
 
     if (candidates.length > 1) {
-      log.error('Multiple resource shapes found %O', candidates.map(c => c.resourceShape.value))
+      log.error('Multiple resource shapes found:', candidates.map(c => c.resourceShape.value))
       return new Error('Multiple resource shapes found')
     }
 
@@ -184,7 +200,7 @@ export default class Impl implements Kopflos {
         logMatch.object = candidates[0].object.value
       }
 
-      log.debug('Resource shape matched %O', logMatch)
+      log.debug('Resource shape matched:', logMatch)
     }
     return candidates[0]
   }
@@ -229,7 +245,7 @@ export default class Impl implements Kopflos {
 
   static async fromGraphs(kopflos: Impl, ...graphs: Array<NamedNode | string>): Promise<void> {
     const graphsIris = graphs.map(graph => typeof graph === 'string' ? kopflos.env.namedNode(graph) : graph)
-    log.info('Loading graphs %O', graphsIris.map(g => g.value))
+    log.info('Loading graphs', graphsIris.map(g => g.value))
 
     const quads = CONSTRUCT`?s ?p ?o `
       .WHERE`
@@ -246,6 +262,6 @@ export default class Impl implements Kopflos {
 
     await insertShorthands(kopflos)
 
-    log.info('Graphs loaded. Dataset now contains %d quads', kopflos.dataset.size)
+    log.info(`Graphs loaded. Dataset now contains ${kopflos.dataset.size} quads`)
   }
 }

packages/core/lib/env/CodeLoadersFactory.ts

@@ -17,7 +17,7 @@ export class CodeLoadersFactory {
     esmLoader.register(this.registry)
     cjsLoader.register(this.registry)
 
-    log.info('Code loader initialized. Base code path: %s', this.codeBase)
+    log.info(`Code loader initialized. Base code path: ${this.codeBase}`)
   }
 
   load<T>(code: AnyPointer): Promise<T> | T | undefined {

packages/core/lib/log.ts

@@ -14,9 +14,9 @@ export function logCode(code: AnyPointer, kind: string) {
     return
   }
   if (isNamedNode(code)) {
-    return log.debug('Loading %s %s', kind, code.value)
+    return log.debug(`Loading ${kind} ${code.value}`)
   }
-  log.debug('Loading %s from %s', kind, code.out(ns.code.link).value)
+  log.debug(`Loading ${kind} from ${code.out(ns.code.link).value}`)
 }
 
 export function decorateClient<C extends ParsingClient | StreamClient>(client: C): C {
@@ -39,7 +39,7 @@ export function decorateClient<C extends ParsingClient | StreamClient>(client: C
 function queryLogger<Q extends(query: string) => ReturnType<Q>>(query: Q): Q {
   return ((q: string) => {
     if (queryLog.enabledFor('debug')) {
-      queryLog.debug('Executing query %s', q)
+      queryLog.debug('Executing query', q)
     }
     return query(q)
   }) as Q

packages/core/test/lib/Kopflos.test.ts

@@ -4,7 +4,7 @@ import 'mocha-chai-rdf/snapshots.js'
 import rdf from '@zazuko/env-node'
 import type { Stream } from '@rdfjs/types'
 import sinon from 'sinon'
-import type { KopflosConfig, Body, Options } from '../../lib/Kopflos.js'
+import type { KopflosConfig, Body, Options, KopflosResponse } from '../../lib/Kopflos.js'
 import Kopflos from '../../lib/Kopflos.js'
 import { ex } from '../../../testing-helpers/ns.js'
 import type { ResourceShapeObjectMatch } from '../../lib/resourceShape.js'
@@ -80,6 +80,32 @@ describe('lib/Kopflos', () => {
       expect(response).toMatchSnapshot()
     })
 
+    it('guards against falsy handler result', async function () {
+      // given
+      const kopflos = new Kopflos(config, {
+        dataset: this.rdf.dataset,
+        resourceShapeLookup: async () => [{
+          api: ex.api,
+          resourceShape: ex.FooShape,
+          subject: ex.foo,
+        }],
+        handlerLookup: async () => () => undefined as unknown as KopflosResponse,
+        resourceLoaderLookup: async () => () => rdf.dataset().toStream(),
+      })
+
+      // when
+      const response = await kopflos.handleRequest({
+        iri: ex.foo,
+        method: 'GET',
+        headers: {},
+        body: {} as Body,
+        query: {},
+      })
+
+      // then
+      expect(response.status).to.eq(500)
+    })
+
     context('headers', () => {
       it('are always forwarded to handler', async function () {
         // given