Add more logs

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,16 +647,15 @@ 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.
 		return findContainer( {
 			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}`);
 		}
 	}
 

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,19 +160,19 @@ 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 );
 		const branch = await repo.createBranch( 'dserve', commit, true );
 		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 ) {

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();

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);
-    }
-}
+

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;