Merge pull request #34 from bldrs-ai/pablo-logging

Add winston tagged logger for full render request logging.

esbuild/build.esb.js

@@ -15,6 +15,8 @@ const externalPackages = [
  'jsdom',
  'pngjs',
  'proxy-from-env',
+ 'winston',
+ '@colors',
  '@sentry',
 ]
 
@@ -24,6 +26,7 @@ esbuild
  .build({
  entryPoints: ['./src/server.js'],
  outfile: './build/server-bundle.js',
+ //outdir: 'build',
  bundle: true,
  format: 'esm',
  target: ['node16'],

package.json

@@ -21,6 +21,7 @@
  "web-ifc": "^0.0.41",
  "web-ifc-three": "^0.0.125",
  "web-worker": "^1.2.0",
+ "winston": "^3.11.0",
  "xhr2": "^0.2.1"
  },
  "devDependencies": {

src/logging.ts

@@ -0,0 +1,44 @@
+import winston from 'winston'
+
+
+export const logger = winston.createLogger({
+ transports: [
+ new winston.transports.Console()
+ ]
+})
+
+
+/**
+ * For example:
+ *
+ * createTaggedLogger('http').info('yo', {foo: 'bar'})
+ *
+ * yields:
+ *
+ * [http] info: yo {foo: 'bar'}
+ */
+export function createTaggedLogger(tag: string, filterCb?: Function) {
+ return winston.createLogger({
+ level: 'info',
+ format: winston.format.combine(
+ winston.format.label({label: tag}),
+ winston.format.colorize(),
+ winston.format.metadata({fillExcept: ['level', 'label', 'message']}),
+ winston.format.simple(),
+ tagFormat(filterCb)
+ ),
+ transports: [
+ new winston.transports.Console()
+ ]
+ })
+}
+
+
+function tagFormat(filterCb?: Function) {
+ return winston.format.printf((info: Record<string, string>) => {
+ const {label, level, message} = info
+ const metadata = filterCb ? filterCb(info.metadata) : info.metadata
+ const metaString = metadata ? `, payload: ${JSON.stringify(metadata)}` : ''
+ return `[${label}] ${level}: ${message}${metaString}`
+ })
+}

src/server.js

@@ -10,8 +10,11 @@ import {
 import {parseUrl} from './urls.js'
 import {load} from './Loader.js'
 import debug, {INFO} from './debug.js'
+import {createTaggedLogger} from './logging'
 
 
+const renderLogger = createTaggedLogger('/render')
+
 const app = express()
 const port = 8001
 
@@ -39,22 +42,65 @@ app.use(Sentry.Handlers.tracingHandler())
 
 // Enable JSON request body middleware
 app.use(express.json())
+
+function loggingHandler(req, res, next) {
+
+ let bytesSent = 0
+ let responseHeaders
+
+ // Patch each of the egress methods to accumulate data for logging.
+ const originalWriteHead = res.writeHead
+ const originalWrite = res.write
+ const originalEnd = res.end
+
+ res.writeHead = function (statusCode, headers) {
+ responseHeaders = {
+ statusCode: statusCode,
+ headers: headers || res.getHeaders(),
+ }
+ return originalWriteHead.apply(res, arguments)
+ }
+
+ res.write = function (chunk, ...rest) {
+ bytesSent += Buffer.isBuffer(chunk) ? chunk.length : Buffer.byteLength(chunk)
+ return originalWrite.call(res, chunk, ...rest)
+ }
+
+ res.end = function (chunk, ...rest) {
+ if (chunk) {
+ bytesSent += Buffer.isBuffer(chunk) ? chunk.length : Buffer.byteLength(chunk)
+ }
+ renderLogger.info('response log stuff', {requestHeaders: req.rawHeaders, responseHeaders, responseSize: bytesSent})
+
+ return originalEnd.call(res, chunk, ...rest)
+ }
+
+ // Don't forget to call next() to pass on to the next middleware/route handler!
+ next()
+}
+app.use(loggingHandler)
+
+
 app.post('/render', handler)
 app.get('/healthcheck', (req, res) => {
  res.status(200).send()
 })
 // Install Sentry error handler after all routes but before any other error handlers
 app.use(Sentry.Handlers.errorHandler())
+
+
 app.listen(port, () => {
  debug(INFO).log(`Listening on 0.0.0.0:${port}`)
 })
 
+
 async function handler(req, res) {
  const [glCtx, renderer, scene, camera] = initThree()
  const modelUrl = new URL(req.body.url)
  const parsedUrl = parseUrl(modelUrl)
- debug().log('server#post, parsedUrl:', parsedUrl)
+ renderLogger.log('debug', 'server#post, parsedUrl:', parsedUrl)
  if (parsedUrl.target === undefined) {
+ renderLogger.warn(msg)
  res.status(404).send(`Cannot parse URL: ${modelUrl}`).end()
  return
  }
@@ -65,31 +111,31 @@ async function handler(req, res) {
  model = await load(targetUrl)
  } catch (e) {
  const msg = `Internal server error ${e}`
- console.trace(e)
+ renderLogger.error(msg)
  res.status(500).send(msg)
  return
  }
  if (model === undefined) {
  const msg = `Could not load model for unknown reason`
- console.trace(msg)
+ renderLogger.error(msg)
  res.status(500).send(msg)
  return
  }
 
- // debug().log('server#post, model:', model)
+ // renderLogger.log('server#post, model:', model)
  scene.add(model)
 
  if (parsedUrl.params.c) {
  const [px, py, pz, tx, ty, tz] = parseCamera(parsedUrl.params.c) || [0,0,0,0,0,0]
- debug().log(`headless#camera setting: camera.pos(${px}, ${py}, ${pz}) target.pos(${tx}, ${ty}, ${tz})`)
+ renderLogger.log('debug', `headless#camera setting: camera.pos(${px}, ${py}, ${pz}) target.pos(${tx}, ${ty}, ${tz})`)
  if (isFinite(px) && isFinite(py) && isFinite(pz)) {
  camera.position.set(px, py, pz)
  }
  if (isFinite(tx) && isFinite(ty) && isFinite(tz)) {
- debug().log(`server#post, camera.pos(${px}, ${py}, ${pz}) target.pos(${tx}, ${ty}, ${tz})`)
+ renderLogger.log('debug', `server#post, camera.pos(${px}, ${py}, ${pz}) target.pos(${tx}, ${ty}, ${tz})`)
  camera.lookAt(tx, ty, tz)
  } else {
- debug().log(`server#post, camera.pos(${px}, ${py}, ${pz}) target.pos(0, 0, 0)`)
+ renderLogger.log('debug', `server#post, camera.pos(${px}, ${py}, ${pz}) target.pos(0, 0, 0)`)
  camera.lookAt(0, 0, 0)
  }
  } else {