Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore: emit Docker and Shell logging to ProgressListener #221

Closed
wants to merge 21 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 13 additions & 9 deletions bin/publish.ts
Original file line number Diff line number Diff line change
Expand Up @@ -7,30 +7,34 @@ import {
EventType,
IPublishProgress,
IPublishProgressListener,
globalOutputHandler,
} from '../lib';

export async function publish(args: { path: string; assets?: string[]; profile?: string }) {
let manifest = AssetManifest.fromPath(args.path);
log('verbose', `Loaded manifest from ${args.path}: ${manifest.entries.length} assets found`);

if (args.assets && args.assets.length > 0) {
const selection = args.assets.map((a) => DestinationPattern.parse(a));
manifest = manifest.select(selection);
log('verbose', `Applied selection: ${manifest.entries.length} assets selected.`);
}

// AssetPublishing will assign the global output handler
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// AssetPublishing will assign the global output handler
// AssetPublishing will assign the progress listener to the global output handler

const pub = new AssetPublishing(manifest, {
aws: new DefaultAwsClient(args.profile),
progressListener: new ConsoleProgress(),
throwOnError: false,
});

globalOutputHandler.verbose(
`Loaded manifest from ${args.path}: ${manifest.entries.length} assets found`
);

if (args.assets && args.assets.length > 0) {
const selection = args.assets.map((a) => DestinationPattern.parse(a));
manifest = manifest.select(selection);
globalOutputHandler.verbose(`Applied selection: ${manifest.entries.length} assets selected.`);
}

await pub.publish();

if (pub.hasFailures) {
for (const failure of pub.failures) {
// eslint-disable-next-line no-console
console.error('Failure:', failure.error.stack);
globalOutputHandler.error(`Failure: ${failure.error.stack}`);
}

process.exitCode = 1;
Expand Down
11 changes: 3 additions & 8 deletions lib/private/docker.ts
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@ import * as fs from 'fs';
import * as os from 'os';
import * as path from 'path';
import { cdkCredentialsConfig, obtainEcrCredentials } from './docker-credentials';
import { Logger, shell, ShellOptions, ProcessFailedError } from './shell';
import { shell, ShellOptions, ProcessFailedError } from './shell';
import { createCriticalSection } from './util';
import { IECRClient } from '../aws';

Expand Down Expand Up @@ -55,8 +55,6 @@ export interface DockerCacheOption {
export class Docker {
private configDir: string | undefined = undefined;

constructor(private readonly logger?: Logger) {}

/**
* Whether an image with the given tag exists
*/
Expand Down Expand Up @@ -200,10 +198,8 @@ export class Docker {
const pathToCdkAssets = path.resolve(__dirname, '..', '..', 'bin');
try {
await shell([getDockerCmd(), ...configArgs, ...args], {
logger: this.logger,
...options,
env: {
...process.env,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why?

...options.env,
PATH: `${pathToCdkAssets}${path.delimiter}${options.env?.PATH ?? process.env.PATH}`,
},
Expand Down Expand Up @@ -234,7 +230,6 @@ export class Docker {
export interface DockerFactoryOptions {
readonly repoUri: string;
readonly ecr: IECRClient;
readonly logger: (m: string) => void;
}

/**
Expand All @@ -249,7 +244,7 @@ export class DockerFactory {
* Gets a Docker instance for building images.
*/
public async forBuild(options: DockerFactoryOptions): Promise<Docker> {
const docker = new Docker(options.logger);
const docker = new Docker();

// Default behavior is to login before build so that the Dockerfile can reference images in the ECR repo
// However, if we're in a pipelines environment (for example),
Expand All @@ -268,7 +263,7 @@ export class DockerFactory {
* Gets a Docker instance for pushing images to ECR.
*/
public async forEcrPush(options: DockerFactoryOptions) {
const docker = new Docker(options.logger);
const docker = new Docker();
await this.loginOncePerDestination(docker, options);
return docker;
}
Expand Down
2 changes: 0 additions & 2 deletions lib/private/handlers/container-images.ts
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,6 @@ export class ContainerImageAssetHandler implements IAssetHandler {

const dockerForBuilding = await this.host.dockerFactory.forBuild({
repoUri: initOnce.repoUri,
logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m),
ecr: initOnce.ecr,
});

Expand Down Expand Up @@ -85,7 +84,6 @@ export class ContainerImageAssetHandler implements IAssetHandler {

const dockerForPushing = await this.host.dockerFactory.forEcrPush({
repoUri: initOnce.repoUri,
logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m),
ecr: initOnce.ecr,
});

Expand Down
49 changes: 26 additions & 23 deletions lib/private/shell.ts
Original file line number Diff line number Diff line change
@@ -1,23 +1,23 @@
import * as child_process from 'child_process';
import { EventType, globalOutputHandler } from '../progress';
Copy link
Contributor

@rix0rrr rix0rrr Jan 9, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do not have this import here.

What was wrong with the Logger we had? That was a fully decoupled mechanism already. You might want to extend it with the notion of "types of message" (command line about to start, stdout chunk, stderr chunk, command finished), but you definitely don't want to use Asset Progress messages here just yet.

Pretend the following:

  • The shell helper already has the logging/notification features that you need, written by some other developer that knew exactly what you needed in advance.
  • Crucially: pretend it's a library we downloaded from NPM! It doesn't know anything about assets, and can't rely on anything else in our code. It cannot import any of the assets-specific files, and cannot use any of the types there.

Do this:

image

The "dependencies" strictly go to the right:

  • CLI knows about, and can depend on, asset publishing (but not the reverse!)
  • Asset publishing knows about, and can depend on, the shell helper (but not the reverse!)

If you need data to flow in the opposite direction, then you will have to use a callback mechanism with its own dedicated interface/type definitions.

As for this PR: I think I would actually recommend you start again from scratch with this in mind, and potentially copy/paste bits over from this PR if you decide you need them. Whatever you do, no global variables!


export type Logger = (x: string) => void;

export interface ShellOptions extends child_process.SpawnOptions {
readonly quiet?: boolean;
readonly logger?: Logger;
readonly input?: string;
}

/**
* OS helpers
*
* Shell function which both prints to stdout and collects the output into a
* string.
* Shell function which both emits the output to the configured output handler, and collects the output
* to return it as a string.
*/
export async function shell(command: string[], options: ShellOptions = {}): Promise<string> {
if (options.logger) {
options.logger(renderCommandLine(command));
}
globalOutputHandler.publishEvent(EventType.START, command.join(' '));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why? This seems like a new log message which i'm not sure is correct (or belongs in this PR).

globalOutputHandler.info(renderCommandLine(command));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So from what I could gather, it used to be that this message would eventually be logged as:

logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m),

But now it changed to:

cdk-assets/lib/progress.ts

Lines 125 to 127 in cacbcf4

public info(text: string) {
this.publishEvent(EventType.SUCCESS, text);
}

Is this what you meant to happen? Also, it used to be that this message was logged via the implenentation of IHostHandler:

emitMessage(t, m) {
self.progressEvent(t, m);
},

Which does some additional stuff apart from just logging. But now it just invokes the progress listener and it doesn't seem to be equivalent.


const child = child_process.spawn(command[0], command.slice(1), {
...options,
stdio: [options.input ? 'pipe' : 'ignore', 'pipe', 'pipe'],
Expand All @@ -29,39 +29,42 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom
child.stdin!.end();
}

const stdout = new Array<any>();
const stderr = new Array<any>();
const stdoutChunks = new Array<any>();
const stderrChunks = new Array<any>();

// Both write to stdout and collect
child.stdout!.on('data', (chunk) => {
if (!options.quiet) {
process.stdout.write(chunk);
globalOutputHandler.publishEvent(chunk, EventType.DEBUG);
}
stdout.push(chunk);
stdoutChunks.push(chunk);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We probably want to stream output to the logger. Docker builds can take 10 minutes, and it's not very helpful if you're sitting there, waiting, not knowing what's going on...

And then after 10 minutes you get a 2MB log dump of everything that happepend.

});

child.stderr!.on('data', (chunk) => {
if (!options.quiet) {
process.stderr.write(chunk);
globalOutputHandler.publishEvent(chunk, EventType.DEBUG);
}

stderr.push(chunk);
stderrChunks.push(chunk);
});

child.once('error', reject);
child.once('error', (error) => {
globalOutputHandler.publishEvent(EventType.FAIL, error.message);
reject(error);
});

child.once('close', (code, signal) => {
if (code === 0) {
resolve(Buffer.concat(stdout).toString('utf-8'));
const output = Buffer.concat(stdoutChunks).toString('utf-8');
resolve(output);
} else {
const out = Buffer.concat(stderr).toString('utf-8').trim();
reject(
new ProcessFailed(
code,
signal,
`${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${out}`
)
const errorOutput = Buffer.concat(stderrChunks).toString('utf-8').trim();
const error_message = `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}`;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
const error_message = `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}`;
const errorMessage = `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}`;

globalOutputHandler.publishEvent(EventType.FAIL, error_message);
const error = new ProcessFailed(
code,
signal,
error_message,
);
reject(error);
}
});
});
Expand Down
48 changes: 48 additions & 0 deletions lib/progress.ts
Original file line number Diff line number Diff line change
Expand Up @@ -84,3 +84,51 @@ export interface IPublishProgress {
*/
abort(): void;
}

class GlobalOutputHandler {
private progressListener: IPublishProgressListener | undefined;
private completionProgress: number;

constructor(completionProgress: number = 0, progressListener?: IPublishProgressListener) {
this.progressListener = progressListener;
this.completionProgress = completionProgress;
}

public setListener(listener: IPublishProgressListener) {
this.progressListener = listener;
}

public setCompletionProgress(progress: number) {
this.completionProgress = progress;
}

public publishEvent(eventType: EventType = EventType.DEBUG, text: string) {
const progressEvent: IPublishProgress = {
message: text,
abort: () => {},
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is bizarre. I think it might be functionally ok but signals a modeling problem IMO.

percentComplete: this.completionProgress,
};
// if no listener is passed we just swallow everything.
if (this.progressListener) {
this.progressListener.onPublishEvent(eventType, progressEvent);
}
}

public verbose(text: string) {
this.publishEvent(EventType.DEBUG, text);
}

public error(text: string) {
this.publishEvent(EventType.FAIL, text);
}

public info(text: string) {
this.publishEvent(EventType.SUCCESS, text);
Copy link
Contributor

@iliapolo iliapolo Dec 31, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Mapping info to EventType.SUCCESS doesnt seem right. SUCCESS indicates that asset publishing has successfully finished, at least according to the doc string:

/**
* When an asset is successfully finished
*/
SUCCESS = 'success',

It might be the code currently doesn't make assumption on the event type being emitted, but thats likely to change and at some point calls to info will stop making sense. Also I see this is only used in shell.ts once, does it really merit a public method for it?

}

public hasListener() {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not used. Should it be?

return this.progressListener !== undefined;
}
}

export let globalOutputHandler = new GlobalOutputHandler();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Executing code on module load is not a great idea. Sure, right now all this code does is instantiate an empty object, but this can easily turn more heavy over time and either slow down or completely crash during import.

Instead, you can use the singleton pattern so that this code is only executed (once) whenever the first consumer needs it. That access pattern would be something like:

// for bits of the code that only read it
GlobalOutputHandler.get().verbose(...)

// for bits of the code that create and read it
GlobalOutputHandler.getOrCreate(listener)

21 changes: 16 additions & 5 deletions lib/publishing.ts
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,12 @@ import { IAssetHandler, IHandlerHost, type PublishOptions } from './private/asse
import { DockerFactory } from './private/docker';
import { makeAssetHandler } from './private/handlers';
import { pLimit } from './private/p-limit';
import { EventType, IPublishProgress, IPublishProgressListener } from './progress';
import {
EventType,
IPublishProgress,
IPublishProgressListener,
globalOutputHandler,
} from './progress';

export interface AssetPublishingOptions {
/**
Expand Down Expand Up @@ -113,6 +118,10 @@ export class AssetPublishing implements IPublishProgress {
},
dockerFactory: new DockerFactory(),
};
if (options.progressListener) {
globalOutputHandler.setListener(options.progressListener);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So what happens if the CDK (or any consumer) instantiates two instances of AssetPublishing with different listeners? If this is not expected behavior - protect against it. If this is expected behavior, how would it work?

Right now, this is a subtle bug waiting to happen.

}
globalOutputHandler.setCompletionProgress(this.percentComplete);
}

/**
Expand Down Expand Up @@ -249,10 +258,12 @@ export class AssetPublishing implements IPublishProgress {
}

public get percentComplete() {
if (this.totalOperations === 0) {
return 100;
}
return Math.floor((this.completedOperations / this.totalOperations) * 100);
const completionProgress =
this.totalOperations === 0
? 100
: Math.floor((this.completedOperations / this.totalOperations) * 100);
globalOutputHandler.setCompletionProgress(completionProgress);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same problem as with setting the listener, breaks on multiple instances of AssetPublishing

return completionProgress;
}

public abort(): void {
Expand Down
Loading
Loading