From fb8f9a634ff459058f6070658560a4c6f2803303 Mon Sep 17 00:00:00 2001 From: Sergio Cinos Date: Wed, 28 Jul 2021 08:29:50 +0200 Subject: [PATCH] Add more logs --- src/api.ts | 62 ++++++++++++++++++++++----------------------- src/builder.ts | 22 ++++++++-------- src/daemon.ts | 8 +++--- src/error.ts | 41 ++++++++++++++++++++---------- src/image-runner.ts | 2 +- src/index.ts | 24 +++++++++++++----- src/logger.ts | 6 +---- test/logger.test.ts | 10 +------- 8 files changed, 94 insertions(+), 81 deletions(-) diff --git a/src/api.ts b/src/api.ts index fa58403..f90c1e3 100644 --- a/src/api.ts +++ b/src/api.ts @@ -15,6 +15,7 @@ import { exec } from 'child_process'; import { CONTAINER_EXPIRY_TIME } from './constants'; import { timing } from './stats'; +import { ContainerError, ImageError } from './error'; type APIState = { accesses: Map< ContainerName, number >; @@ -126,7 +127,7 @@ export async function hasHashLocally( hash: CommitHash ): Promise< boolean > { } export async function deleteImage( hash: CommitHash ) { - l.log( { commitHash: hash }, 'attempting to remove image for hash' ); + l.info( { commitHash: hash }, 'attempting to remove image for hash' ); const runningContainer = state.containers.get( getImageName( hash ) ); if ( runningContainer ) { @@ -137,14 +138,14 @@ export async function deleteImage( hash: CommitHash ) { try { img = docker.getImage( getImageName( hash ) ); if ( ! img ) { - l.log( + l.info( { commitHash: hash }, 'did not have an image locally with name' + getImageName( hash ) ); return; } } catch ( err ) { - l.log( + l.info( { commitHash: hash, err }, 'error trying to find image locally with name' + getImageName( hash ) ); @@ -153,20 +154,20 @@ export async function deleteImage( hash: CommitHash ) { try { await img.remove( { force: true } ); - l.log( { commitHash: hash }, 'succesfully removed image' ); + l.info( { commitHash: hash }, 'succesfully removed image' ); } catch ( err ) { l.error( { err, commitHash: hash }, 'failed to remove image' ); } } export async function startContainer( commitHash: CommitHash, env: RunEnv ) { - //l.log( { commitHash }, `Request to start a container for ${ commitHash }` ); + //l.info( { commitHash }, `Request to start a container for ${ commitHash }` ); const image = getImageName( commitHash ); const containerId = `${ env }:${ image }`; // do we have an existing container? const existingContainer = getRunningContainerForHash( commitHash, env ); if ( existingContainer ) { - l.log( + l.info( { commitHash, containerId: existingContainer.Id }, `Found a running container for ${ commitHash }` ); @@ -175,7 +176,7 @@ export async function startContainer( commitHash: CommitHash, env: RunEnv ) { // are we starting one already? if ( state.startingContainers.has( containerId ) ) { - //l.log( { commitHash }, `Already starting a container for ${ commitHash }` ); + //l.info( { commitHash }, `Already starting a container for ${ commitHash }` ); return state.startingContainers.get( containerId ); } @@ -200,7 +201,7 @@ export async function startContainer( commitHash: CommitHash, env: RunEnv ) { const dockerPromise = new Promise( ( resolve, reject ) => { let runError: any; - l.log( { image, commitHash }, `Starting a container for ${ commitHash }` ); + l.info( { image, commitHash }, `Starting a container for ${ commitHash }` ); docker.run( image, @@ -233,7 +234,7 @@ export async function startContainer( commitHash: CommitHash, env: RunEnv ) { } ); return dockerPromise.then( ( { success, freePort } ) => { - l.log( + l.info( { image, freePort, commitHash }, `Successfully started container for ${ image } on ${ freePort }` ); @@ -458,29 +459,28 @@ export async function cleanupExpiredContainers() { await refreshContainers(); const expiredContainers = getExpiredContainers(); for ( let container of expiredContainers ) { - const imageName: string = container.Image; + const containerName = getContainerName( container ) - l.log( - { - imageName, - containerId: container.Id, - }, - 'Cleaning up stale container' - ); + const log = l.child({ + containerId: container.Id, + containerName + }) + + log.info( 'Cleaning up stale container' ); if ( container.State === 'running' ) { try { await docker.getContainer( container.Id ).stop(); - l.log( { containerId: container.Id, imageName }, `Successfully stopped container` ); + log.info( `Successfully stopped container` ); } catch ( err ) { - l.error( { err, imageName, containerId: container.Id }, 'Failed to stop container' ); + log.error( err, 'Failed to stop container' ); } } try { await docker.getContainer( container.Id ).remove(); - l.log( { containerId: container.Id, imageName }, `Successfully removed container` ); + log.info(`Successfully removed container` ); } catch ( err ) { - l.error( { err, imageName, containerId: container.Id }, 'Failed to remove container' ); + log.error( err, 'Failed to remove container' ); } } refreshContainers(); @@ -492,7 +492,7 @@ export async function proxyRequestToHash( req: any, res: any ) { let port = await getPortForContainer( commitHash, runEnv ); if ( ! port ) { - l.log( { port, commitHash, runEnv }, `Could not find port for commitHash` ); + l.info( { port, commitHash, runEnv }, `Could not find port for commitHash` ); res.send( 'Error setting up port!' ); res.end(); return; @@ -503,7 +503,7 @@ export async function proxyRequestToHash( req: any, res: any ) { if ( err && ( err as any ).code === 'ECONNRESET' ) { return; } - l.log( { err, req, res, commitHash }, 'unexpected error occured while proxying' ); + l.info( { err, req, res, commitHash }, 'unexpected error occured while proxying' ); } ); } @@ -547,7 +547,7 @@ export async function proxyRequestToContainer( req: any, res: any, container: Co const containerName = getContainerName( container ); if ( ! container.Ports[ 0 ] ) { - l.log( { containerName }, `Could not find port for container` ); + l.info( { containerName }, `Could not find port for container` ); throw new Error( `Could not find port for container ${ containerName }` ); } const port = container.Ports[ 0 ].PublicPort; @@ -631,7 +631,7 @@ export async function createContainer( imageName: ImageName, env: RunEnv ) { try { freePort = await getPort(); } catch ( err ) { - throw new Error(`Error while attempting to find a free port for ${ imageName }`); + throw new ImageError(imageName, `Error while attempting to find a free port: ${err.message}`); } try { @@ -647,7 +647,7 @@ export async function createContainer( imageName: ImageName, env: RunEnv ) { calypsoEnvironment: env, }, } ); - l.log( { imageName }, `Successfully created container for ${ imageName }` ); + l.info( { imageName }, `Successfully created container for ${ imageName }` ); await refreshContainers(); // Returns a ContainerInfo for the created container, in order to avoid exposing a real Container object. @@ -655,8 +655,7 @@ export async function createContainer( imageName: ImageName, env: RunEnv ) { id: container.id, } ); } catch ( error ) { - error.message = `Failed creating container for ${ imageName }: ${error.message}`; - throw error; + throw new ImageError(imageName, `Failed creating container: ${error.message}`); } } @@ -671,13 +670,12 @@ export async function reviveContainer( containerInfo: ContainerInfo ) { // maybe alredy be starting at this point anyway. try { await container.start(); - l.log( { containerName }, `Successfully started container` ); + l.info( { containerName }, `Successfully started container` ); } catch(error) { if (error.statusCode === 304) { - l.log( { containerName }, `Container already started` ); + l.info( { containerName }, `Container already started` ); } else { - error.message = `Failed reviving ${containerInfo.State} container ${ containerName }: ${error.message}`; - throw error; + throw new ContainerError(containerName, `Failed reviving ${containerInfo.State} container: ${error.message}`); } } diff --git a/src/builder.ts b/src/builder.ts index 247c7b0..d900e70 100644 --- a/src/builder.ts +++ b/src/builder.ts @@ -66,7 +66,7 @@ export function getBuildDir( hash: CommitHash ) { export async function cleanupBuildDir( hash: CommitHash ) { const buildDir = getBuildDir( hash ); - l.log( `removing directory: ${ buildDir }` ); + l.info( `removing directory: ${ buildDir }` ); pendingHashes.delete( hash ); return fs.remove( buildDir ); } @@ -107,7 +107,7 @@ export async function addToBuildQueue( commitHash: CommitHash ) { if ( buildQueue.includes( commitHash ) || pendingHashes.has( commitHash ) ) { return; } - l.log( + l.info( { buildQueueSize: buildQueue.length, commitHash }, 'Adding a commitHash to the buildQueue' ); @@ -126,7 +126,7 @@ export async function buildImageForHash( commitHash: CommitHash ): Promise< void let imageStart: number; if ( await isBuildInProgress( commitHash ) ) { - l.log( { commitHash, buildDir }, 'Skipping build because a build is already in progress' ); + l.info( { commitHash, buildDir }, 'Skipping build because a build is already in progress' ); return; } @@ -148,7 +148,7 @@ export async function buildImageForHash( commitHash: CommitHash ): Promise< void const buildConcurrency = getBuildConcurrency(); try { - l.log( + l.info( { commitHash, buildDir, repoDir, imageName, buildConcurrency }, 'Attempting to build image.' ); @@ -160,7 +160,7 @@ export async function buildImageForHash( commitHash: CommitHash ): Promise< void buildLogger.info( 'Finished cloning repo' ); const cloneTime = Date.now() - cloneStart; timing( 'git.build.clone', cloneTime ); - l.log( { commitHash, cloneTime }, 'Finished cloning repo' ); + l.info( { commitHash, cloneTime }, 'Finished cloning repo' ); const checkoutStart = Date.now(); const commit = await repo.getCommit( commitHash ); @@ -168,11 +168,11 @@ export async function buildImageForHash( commitHash: CommitHash ): Promise< void await repo.checkoutBranch( branch ); const checkoutTime = Date.now() - checkoutStart; timing( 'git.build.checkout', checkoutTime ); - l.log( { commitHash, checkoutTime }, 'Checked out branch' ); + l.info( { commitHash, checkoutTime }, 'Checked out branch' ); buildLogger.info( 'Checked out the correct branch' ); buildLogger.info( 'Placing all the contents into a tarball stream for docker\n' ); - l.log( + l.info( { commitHash, repoDir, imageName, buildConcurrency }, 'Placing contents of repoDir into a tarball and sending to docker for a build' ); @@ -221,9 +221,9 @@ export async function buildImageForHash( commitHash: CommitHash ): Promise< void try { await refreshLocalImages(); } catch ( err ) { - l.log( { commitHash, err }, 'Error refreshing local images' ); + l.info( { commitHash, err }, 'Error refreshing local images' ); } - l.log( + l.info( { commitHash, buildImageTime, repoDir, imageName, buildConcurrency }, `Successfully built image. Now cleaning up build directory` ); @@ -263,7 +263,7 @@ const loop = ( f: Function, delay: number ) => { function warnOnQueueBuildup() { if ( buildQueue.length > MAX_CONCURRENT_BUILDS ) { - l.log( + l.info( { buildQueue }, 'There are images waiting to be built that are stuck because of too many concurrent builds' ); @@ -274,7 +274,7 @@ export function buildFromQueue() { buildQueue .splice( 0, MAX_CONCURRENT_BUILDS - pendingHashes.size ) // grab the next batch of builds .forEach( commitHash => { - l.log( { commitHash }, 'Popping a commitHash off of the buildQueue' ); + l.info( { commitHash }, 'Popping a commitHash off of the buildQueue' ); buildImageForHash( commitHash ); } ); if ( buildQueue.length !== currentLength ) { diff --git a/src/daemon.ts b/src/daemon.ts index 393a836..8cb1133 100644 --- a/src/daemon.ts +++ b/src/daemon.ts @@ -14,19 +14,19 @@ child.on( 'error', err => { } ); child.on( 'restart', () => { - l.log( 'forever: Restarting' ); + l.info( 'forever: Restarting' ); } ); child.on( 'exit:code', ( code, signal ) => { - l.log( { code, signal }, 'forever: exited child', code, signal ); + l.info( { code, signal }, 'forever: exited child', code, signal ); } ); child.on( 'exit', ( child, spinning ) => { - l.log( { child, spinning }, 'forever: really exited', child, spinning ); + l.info( { child, spinning }, 'forever: really exited', child, spinning ); } ); child.on( 'stop', childData => { - l.log( { data: childData }, 'forever: child stopping' ); + l.info( { data: childData }, 'forever: child stopping' ); } ); child.start(); diff --git a/src/error.ts b/src/error.ts index 9149220..dca40f1 100644 --- a/src/error.ts +++ b/src/error.ts @@ -1,9 +1,31 @@ -export class ImageNotFound extends Error { - name: string; + +export class ContainerError extends Error { + containerName: string; + constructor(containerName:string, message:string) { + super(message); + this.containerName = containerName; + Error.captureStackTrace(this, ContainerError); + } +} + +export class ImageError extends Error { + imageName: string; + constructor(imageName:string, message:string) { + super(message); + this.imageName = imageName; + Error.captureStackTrace(this, ImageError); + } +} + +export class ImageNotFound extends ImageError { constructor(name:string) { - super("Docker image not found"); - this.name = name; - Error.captureStackTrace(this, ImageNotFound); + super(name, "Docker image not found"); + } +} + +export class InvalidImage extends ImageError { + constructor(name:string) { + super(name, "Image is invalid"); } } @@ -16,11 +38,4 @@ export class InvalidRegistry extends Error { } } -export class InvalidImage extends Error { - name: string; - constructor(name:string) { - super("Image is invalid"); - this.name = name; - Error.captureStackTrace(this, InvalidImage); - } -} \ No newline at end of file + diff --git a/src/image-runner.ts b/src/image-runner.ts index fec1666..c9d6375 100644 --- a/src/image-runner.ts +++ b/src/image-runner.ts @@ -143,7 +143,7 @@ async function startAndProxyRequestsToContainer( req: express.Request, res: expr if ( shouldDelete ) { const containerRealName = getContainerName( container ); - l.log( { containerRealName }, `Hard reset for ${ containerRealName }` ); + l.info( { containerRealName }, `Hard reset for ${ containerRealName }` ); await deleteContainer( container ); res.send( `Container ${ containerRealName } deleted` ); return; diff --git a/src/index.ts b/src/index.ts index 833858e..258c162 100644 --- a/src/index.ts +++ b/src/index.ts @@ -53,7 +53,7 @@ import { refreshContainers, cleanupExpiredContainers, } from './api'; -import { ImageNotFound, InvalidImage, InvalidRegistry } from './error'; +import { ContainerError, ImageError, ImageNotFound, InvalidImage, InvalidRegistry } from './error'; const startedServerAt = new Date(); increment( 'server_start' ); @@ -66,7 +66,7 @@ calypsoServer.use( session ); // global node process junk - catched unhandled errors process.on( 'uncaughtException', error => { - l.log( { error }, 'Crashing on uncaught error' ); + l.info( { error }, 'Crashing on uncaught error' ); increment( 'uncaught_error' ); } ); @@ -82,7 +82,7 @@ const logRejections = () => { 'unreported' === status && now.getTime() - ts.getTime() > ONE_MINUTE ) .forEach( ( [ promise, [ ts, reason ] ] ) => { - l.log( { reason }, 'Unhandled rejection sitting in queue for at least one minute' ); + l.info( { reason }, 'Unhandled rejection sitting in queue for at least one minute' ); promiseRejections.set( promise, [ ts, reason, 'reported' ] ); } ); @@ -174,7 +174,7 @@ calypsoServer.get( '*', async ( req: express.Request, res: express.Response ) => const shouldReset = req.query.reset; if ( shouldReset ) { - l.log( { commitHash }, `Hard reset for ${ commitHash }` ); + l.info( { commitHash }, `Hard reset for ${ commitHash }` ); increment( 'hash_reset' ); await deleteImage( commitHash ); await cleanupBuildDir( commitHash ); @@ -236,6 +236,18 @@ calypsoServer.use( return; } + if (err instanceof ContainerError) { + l.error( {err, url:req.originalUrl, containerName: err.containerName}); + res.status(500).send(err.message); + return; + } + + if (err instanceof ImageError) { + l.error( {err, url:req.originalUrl, imageName: err.imageName}); + res.status(500).send(err.message); + return; + } + // Catch all for unknown errors l.error(err); res.status(500).send(err.message); @@ -243,7 +255,7 @@ calypsoServer.use( ); const server = calypsoServer.listen( 3000, () => - l.log( + l.info( `✅ dserve is listening on 3000 - started at ${ startedServerAt.toLocaleTimeString( undefined, { timeZoneName: 'long', hour12: true, @@ -257,7 +269,7 @@ server.on( 'error', err => { } ); server.on( 'close', () => { console.log( 'close' ); - l.log( {}, 'Server shutting down' ); + l.info( {}, 'Server shutting down' ); } ); function isBrowser( req: express.Request ): Boolean { diff --git a/src/logger.ts b/src/logger.ts index 88ce4de..de5063e 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -32,11 +32,7 @@ const dserveLogger = bunyan.createLogger( { } ); /* super convenient name */ -export const l = { - log: dserveLogger.info.bind( dserveLogger ), - warn: dserveLogger.warn.bind( dserveLogger ), - error: dserveLogger.error.bind( dserveLogger ), -}; +export const l = dserveLogger; /** * Creates a child logger that outputs to the build directory and diff --git a/test/logger.test.ts b/test/logger.test.ts index d52b989..fafda53 100644 --- a/test/logger.test.ts +++ b/test/logger.test.ts @@ -27,14 +27,6 @@ describe( 'logger', () => { } ); describe( 'l', () => { - test( 'should be an object with two functions: log and error', () => { - const { l, closeLogger, getLoggerForBuild } = require( '../src/logger' ); - expect( l ).toBeInstanceOf( Object ); - expect( l.log ).toBeInstanceOf( Function ); - expect( l.warn ).toBeInstanceOf( Function ); - expect( l.error ).toBeInstanceOf( Function ); - } ); - test( 'should only make one base logger', () => { const bunyan = require( 'bunyan' ); const { l, closeLogger, getLoggerForBuild } = require( '../src/logger' ); @@ -46,7 +38,7 @@ describe( 'logger', () => { jest.setMock( 'bunyan', { createLogger, RingBuffer: jest.fn() } ); const { l, closeLogger, getLoggerForBuild } = require( '../src/logger' ); - l.log( 'testLog' ); + l.info( 'testLog' ); l.warn( 'testLog' ); l.error( 'testLog' );