DT-135: Add logging logic to capture clean logs and errors #135

.env.test

@@ -8,5 +8,9 @@ CLIENT_SECRET=GOC...test
 GOOGLE_CLIENT_ID=...test.apps.googleusercontent.com
 PORT=3021
 REDIRECT_URI=http://localhost:7737/api/auth/google
+STORE_URL=http://localhost:3021
+STORE_SECRET=store_secret_test
+GEMINI_API_KEY=gemini_api_key_test
+GEMINI_API_URL=https://gemini.api.url/test
 # Get values from `deno task dev:env`
 # then copy missing variables and replace APP_ENV to the matching values

api/auth.ts

@@ -11,6 +11,7 @@ import { respond } from '@01edu/api/response'
 import { authenticateOauthUser } from '/api/user.ts'
 import { savePicture } from '/api/picture.ts'
 import type { RequestContext } from '@01edu/api/context'
+import { log } from '/api/lib/logger.ts'
 
 interface GoogleTokens {
   access_token: string
@@ -46,6 +47,7 @@ const GOOGLE_CONFIG = {
 export function initiateGoogleAuth() {
   const { state } = generateStateToken()
   const authUrl = getGoogleAuthUrl(state)
+  log.info('oauth-redirect-initiated', { state })
   return new Response(null, {
     status: 302,
     headers: { 'Location': authUrl },
@@ -59,6 +61,7 @@ export async function handleGoogleCallback(
   const state = ctx.url.searchParams.get('state')
 
   if (!code) {
+    log.warn('oauth-callback-missing-code')
     throw new respond.BadRequestError({
       message: 'Missing authorization code',
       details: 'The authorization code from Google OAuth is required',
@@ -67,6 +70,7 @@ export async function handleGoogleCallback(
 
   // Verify the state parameter
   if (!verifyState(state || undefined)) {
+    log.warn('oauth-callback-invalid-state', { state })
     throw new respond.UnauthorizedError({
       message: 'Invalid state parameter',
       details: 'The state parameter is invalid or has expired',
@@ -89,6 +93,11 @@ export async function handleGoogleCallback(
   })
 
   if (!tokenResponse.ok) {
+    const errorBody = await tokenResponse.text().catch(() => 'unknown')
+    log.error('oauth-token-exchange-failed', {
+      status: tokenResponse.status,
+      body: errorBody,
+    })
     throw new respond.UnauthorizedError({
       message: 'Failed to exchange authorization code',
       details: 'Could not obtain access token from Google',
@@ -103,6 +112,12 @@ export async function handleGoogleCallback(
   userInfo.picture &&= await savePicture(userInfo.picture)
   const sessionId = await authenticateOauthUser(userInfo)
 
+  log.info('oauth-login-success', {
+    userId: userInfo.sub,
+    email: userInfo.email,
+    domain: userInfo.hd,
+  })
+
   // Return response with session cookie
   return new Response(null, {
     status: 302,

api/fix-query.ts

@@ -2,6 +2,7 @@ import { render } from '@deno/gfm'
 import { promptTemplate } from '/api/fix-query-prompt.ts'
 import { GEMINI_API_KEY, GEMINI_MODEL } from '/api/lib/env.ts'
 import { AIAnalysisCacheCollection } from '/api/schema.ts'
+import { log } from '/api/lib/logger.ts'
 
 const GEMINI_URL =
   `https://generativelanguage.googleapis.com/v1beta/models/${GEMINI_MODEL}:streamGenerateContent?alt=json&key=${GEMINI_API_KEY}`
@@ -29,6 +30,11 @@ function cacheKey(deployment: string, metric: Metric) {
 async function callGemini(payload: string, thinkingLevel: string) {
   const prompt = promptTemplate.replace('{{QUERY_DETAILS_JSON}}', payload)
 
+  log.info('gemini-request-start', {
+    thinkingLevel,
+    promptLength: prompt.length,
+  })
+
   const res = await fetch(GEMINI_URL, {
     method: 'POST',
     headers: { 'Content-Type': 'application/json' },
@@ -40,6 +46,7 @@ async function callGemini(payload: string, thinkingLevel: string) {
 
   if (!res.ok) {
     const body = await res.text()
+    log.error('gemini-request-failed', { status: res.status, body })
     throw new Error(`Gemini API error ${res.status}: ${body}`)
   }
 
@@ -65,7 +72,16 @@ export async function analyzeQueryWithAI(
 ) {
   const key = await cacheKey(deployment, metric)
   const cached = !forceRefresh && AIAnalysisCacheCollection.get(key)
-  if (cached) return cached.analysis
+  if (cached) {
+    log.info('ai-analysis-cache-hit', { deployment, query: metric.query })
+    return cached.analysis
+  }
+
+  log.info('ai-analysis-start', {
+    deployment,
+    query: metric.query,
+    forceRefresh,
+  })
 
   const payload = JSON.stringify({ schema, metrics: [metric] }, null, 2)
   const analysis = await callGemini(payload, forceRefresh ? 'HIGH' : 'MINIMAL')
@@ -76,5 +92,7 @@ export async function analyzeQueryWithAI(
   } else {
     AIAnalysisCacheCollection.insert({ cacheKey: key, analysis })
   }
+
+  log.info('ai-analysis-complete', { deployment, query: metric.query })
   return analysis
 }

api/lib/functions.ts

@@ -1,6 +1,7 @@
 import { batch } from '/api/lib/json_store.ts'
 import { join } from '@std/path'
 import { ensureDir } from '@std/fs'
+import { log } from '/api/lib/logger.ts'
 
 // Define the function signatures
 export type FunctionContext = {
@@ -45,7 +46,7 @@ export async function init() {
 }
 
 async function loadAll() {
-  console.info('Loading project functions...')
+  log.info('loading-project-functions')
   for await (const entry of Deno.readDir(functionsDir)) {
     if (entry.isDirectory) {
       await reloadProjectFunctions(entry.name)
@@ -73,7 +74,11 @@ async function reloadProjectFunctions(slug: string) {
             loaded.push({ name: entry.name, module: fns })
           }
         } catch (e) {
-          console.error(`Failed to import ${entry.name} for ${slug}:`, e)
+          log.error('failed-to-import-function', {
+            file: entry.name,
+            project: slug,
+            error: e instanceof Error ? e.message : String(e),
+          })
         }
       }
     })
@@ -83,21 +88,27 @@ async function reloadProjectFunctions(slug: string) {
 
     if (loaded.length > 0) {
       functionsMap.set(slug, loaded)
-      console.info(`Loaded ${loaded.length} functions for project: ${slug}`)
+      log.info('loaded-project-functions', {
+        count: loaded.length,
+        project: slug,
+      })
     } else {
       functionsMap.delete(slug)
     }
   } catch (err) {
     if (!(err instanceof Deno.errors.NotFound)) {
-      console.error(`Failed to load functions for ${slug}:`, err)
+      log.error('failed-to-load-functions', {
+        project: slug,
+        error: err instanceof Error ? err.message : String(err),
+      })
     }
     functionsMap.delete(slug)
   }
 }
 
 function startWatcher() {
   if (watcher) return
-  console.info(`Starting function watcher on ${functionsDir}`)
+  log.info('starting-function-watcher', { dir: functionsDir })
   watcher = Deno.watchFs(functionsDir, { recursive: true }) // Process events
   ;(async () => {
     for await (const event of watcher!) {

api/lib/json_store.ts

@@ -2,6 +2,7 @@
 import { join } from '@std/path'
 import { APP_ENV } from '@01edu/api/env'
 import { ensureDir } from '@std/fs'
+import { log } from '/api/lib/logger.ts'
 
 const DB_DIR = APP_ENV === 'test' ? './db_test' : './db'
 
@@ -49,7 +50,7 @@ export async function createCollection<
       const rec = JSON.parse(await Deno.readTextFile(recordFile(id))) as T
       records.set(id, rec)
     } catch {
-      // corrupted file, ignore
+      log.warn('json-store-corrupted-file', { collection: name, id })
     }
   })
 
@@ -65,7 +66,10 @@ export async function createCollection<
     async insert(data: T) {
       const id = data[primaryKey]
       if (!id) throw Error(`Missing primary key ${primaryKey}`)
-      if (records.has(id)) throw Error(`${id} already exists`)
+      if (records.has(id)) {
+        log.warn('json-store-insert-duplicate', { collection: name, id })
+        throw Error(`${id} already exists`)
+      }
       Object.assign(data, { createdAt: Date.now(), updatedAt: Date.now() })
       records.set(id, data)
       await saveRecord(data)
@@ -89,7 +93,10 @@ export async function createCollection<
       records.values().filter(predicate).toArray() as (T & BaseRecord)[],
     async update(id: T[K], changes: Partial<Omit<T, K>>) {
       const record = records.get(id)
-      if (!record) throw new Deno.errors.NotFound(`record ${id} not found`)
+      if (!record) {
+        log.warn('json-store-update-not-found', { collection: name, id })
+        throw new Deno.errors.NotFound(`record ${id} not found`)
+      }
       const updated = { ...record, ...changes, updatedAt: Date.now() } as T
       records.set(id, updated)
       await saveRecord(updated)
@@ -98,7 +105,10 @@ export async function createCollection<
 
     async delete(id: T[K]) {
       const record = records.get(id)
-      if (!record) return false
+      if (!record) {
+        log.debug('json-store-delete-not-found', { collection: name, id })
+        return false
+      }
       records.delete(id)
       await Deno.remove(recordFile(id))
       return true

api/lib/logger.ts

@@ -0,0 +1,60 @@
+import type { Log } from '@01edu/api/log'
+import { getContext } from '@01edu/api/context'
+import { insertLogs } from '/api/clickhouse-client.ts'
+
+type LogLevel = 'debug' | 'info' | 'warn' | 'error'
+
+const severityMap: Record<LogLevel, number> = {
+  debug: 5,
+  info: 9,
+  warn: 13,
+  error: 17,
+}
+
+type Params = Record<string, unknown>
+
+export function createLogger(serviceName: string): Log {
+  const batch: Record<string, unknown>[] = []
+
+  const flush = () => {
+    if (batch.length === 0) return
+    const logs = batch.splice(0, batch.length)
+    insertLogs(serviceName, logs as never[]).catch((err) => {
+      console.error('flush-failed', err)
+    })
+  }
+
+  setInterval(flush, 5000)
+
+  const log = (
+    level: LogLevel,
+    event: string,
+    props?: Params,
+  ) => {
+    const ctx = getContext()
+    batch.push({
+      timestamp: Date.now(),
+      trace_id: ctx?.trace ?? Date.now() / 1000,
+      span_id: ctx?.span ?? ctx?.trace ?? Date.now() / 1000,
+      severity_number: severityMap[level],
+      event_name: event,
+      attributes: props ?? {},
+      service_version: null,
+      service_instance_id: null,
+    })
+
+    const c = console[level] || console.info
+    c(event, props)
+
+    if (batch.length >= 50) flush()
+  }
+
+  return Object.assign(log, {
+    error: (e: string, p?: Params) => log('error', e, p),
+    debug: (e: string, p?: Params) => log('debug', e, p),
+    warn: (e: string, p?: Params) => log('warn', e, p),
+    info: (e: string, p?: Params) => log('info', e, p),
+  })
+}
+
+export const log = createLogger('devtools')

api/lmdb-store.ts

@@ -1,21 +1,46 @@
 import { STORE_SECRET, STORE_URL } from '/api/lib/env.ts'
+import { log } from '/api/lib/logger.ts'
 
 const headers = { authorization: `Bearer ${STORE_SECRET}` }
 export const getOne = async <T>(
   path: string,
   id: string,
 ): Promise<T | null> => {
   const url = `${STORE_URL}/${path}/${encodeURIComponent(String(id))}`
-  const res = await fetch(url, { headers })
-  if (res.status === 404) return null
-  return res.json()
+  try {
+    const res = await fetch(url, { headers })
+    if (res.status === 404) return null
+    if (!res.ok) {
+      log.error('store-get-one-failed', { path, id, status: res.status })
+    }
+    return res.json()
+  } catch (err) {
+    log.error('store-get-one-error', {
+      path,
+      id,
+      error: err instanceof Error ? err.message : String(err),
+    })
+    throw err
+  }
 }
 
 export const get = async <T>(
   path: string,
   params?: { q?: string; limit?: number; from?: number },
 ): Promise<T> => {
   const q = new URLSearchParams(params as unknown as Record<string, string>)
-  const res = await fetch(`${STORE_URL}/${path}/?${q}`, { headers })
-  return res.json()
+  const url = `${STORE_URL}/${path}/?${q}`
+  try {
+    const res = await fetch(url, { headers })
+    if (!res.ok) {
+      log.error('store-get-failed', { path, status: res.status })
+    }
+    return res.json()
+  } catch (err) {
+    log.error('store-get-error', {
+      path,
+      error: err instanceof Error ? err.message : String(err),
+    })
+    throw err
+  }
 }