chore: emit Docker and Shell logging to ProgressListener #221

HBobertz · 2024-12-03T07:19:17Z

Related to #196

There is still a quiet flag however I will do that in another pr.

This change adds a new GlobalOutputHandler which as the name implies, is a global object which will send messages to the progress listener. If invoked from the CLI, the CLI first configures the progress as a ConsoleProgress() listener which prints to stderr by default. If invoked from AssetPublishing (the class which we programmatically interact with from the aws-cdk), then the globalOutputHandler will instead push the messages to the progress listener defined in that class.

This enables us to capture logging from anywhere and emit it to the configured pluggable progress listener.

lib/progress.ts

test/mock-child_process.ts

mrgrain

Please describe what this PR is addressing and how its solving it. If there are follow-up PRs, describe in a bit more detail how they will address it.

Please describe how you've verified the changes.

test/mock-child_process.ts

bin/logging.ts

mrgrain · 2024-12-10T19:58:02Z

Fixes #196

BTW, if it doesn't close the issue, e.g. because a second PR is needed, you cannot put that in like that.

Signed-off-by: github-actions <[email protected]>

Adding some additional tests, so I can verify #221 isn't causing any breaking changes These are LLM generated btw --------- Signed-off-by: github-actions <[email protected]> Co-authored-by: github-actions <[email protected]>

iliapolo

I think we should consider a different approach for this PR. As I understand it, all we're after is to move away from code that directly prints to the screen.

We already have the IPublishProgressListener interface for that, can we not just make sure this listener is being passed to whichever code that needs it? Yeah its a little bit more work but I think avoids some functional complications as mentioned in the comments. Introducing yet another "emitter" makes the code even more convoluted than it is now. We will have:

IPublishProgressListener
GlobalOutputHandler
IHandlerHost

Which all have some message emission capabilities. This is too much. And having GlobalOutputHandler be a global instance adds more limitations on us.

Also - it would be really nice to add a lint rule that prevents direct terminal printouts (and ignore it where needed - like on ConsoleProgress).

iliapolo · 2024-12-31T11:21:46Z

lib/progress.ts

+  }
+}
+
+export let globalOutputHandler = new GlobalOutputHandler();


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)

iliapolo · 2024-12-31T11:24:02Z

lib/publishing.ts

@@ -113,6 +118,10 @@ export class AssetPublishing implements IPublishProgress {
      },
      dockerFactory: new DockerFactory(),
    };
+    if (options.progressListener) {
+      globalOutputHandler.setListener(options.progressListener);


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.

iliapolo · 2024-12-31T11:26:54Z

lib/publishing.ts

+      this.totalOperations === 0
+        ? 100
+        : Math.floor((this.completedOperations / this.totalOperations) * 100);
+    globalOutputHandler.setCompletionProgress(completionProgress);


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

iliapolo · 2024-12-31T11:33:00Z

bin/publish.ts


+  // AssetPublishing will assign the global output handler


Suggested change

// AssetPublishing will assign the global output handler

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

iliapolo · 2024-12-31T11:35:14Z

lib/private/docker.ts

        ...options,
        env: {
-          ...process.env,


iliapolo · 2024-12-31T11:44:18Z

lib/private/shell.ts

-    options.logger(renderCommandLine(command));
-  }
+  globalOutputHandler.publishEvent(EventType.START, command.join(' '));
+  globalOutputHandler.info(renderCommandLine(command));


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

cdk-assets/lib/private/handlers/container-images.ts

Line 41 in df4fa23

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:

cdk-assets/lib/publishing.ts

Lines 116 to 118 in cacbcf4

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.

iliapolo · 2024-12-31T11:45:52Z

lib/private/shell.ts

-            `${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}`;


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}`;

iliapolo · 2024-12-31T11:49:18Z

lib/progress.ts

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


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

cdk-assets/lib/progress.ts

Lines 22 to 25 in cacbcf4

/**

* 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?

iliapolo · 2024-12-31T11:49:27Z

lib/progress.ts

+    this.publishEvent(EventType.SUCCESS, text);
+  }
+
+  public hasListener() {


Not used. Should it be?

iliapolo · 2024-12-31T11:53:34Z

lib/progress.ts

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


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

HBobertz · 2024-12-31T13:46:32Z

We already have the IPublishProgressListener interface for that, can we not just make sure this listener is being passed to whichever code that needs it? Yeah its a little bit more work but I think avoids some functional complications as mentioned in the comments. Introducing yet another "emitter" makes the code even more convoluted than it is now. We will have:

I originally started down this path but it ballooned into passing around the interface in a lot of places we really didn't need. However I hadn't considered the multiple assetPublishing instances. I think if only for that reason it makes sense to go down that path again. I'll pivot back to that

rix0rrr · 2025-01-09T09:10:13Z

lib/private/shell.ts

      }
-      stdout.push(chunk);
+      stdoutChunks.push(chunk);


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.

rix0rrr · 2025-01-09T09:10:41Z

lib/private/shell.ts

@@ -1,23 +1,23 @@
 import * as child_process from 'child_process';
+import { EventType, globalOutputHandler } from '../progress';


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:

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!

HBobertz · 2025-01-09T22:24:20Z

Close in favor of #295

HBobertz and others added 7 commits December 3, 2024 02:18

initial docker log capturing

98ebc39

Merge branch 'main' into bobertzh/logging

b51fd43

add better testing and error emission

081ce2d

remove unnecessary stuff

1b5a38b

updated log capturing

057644a

better comments and such

5bcdaad

Merge branch 'main' into bobertzh/logging

1dce3bf

HBobertz marked this pull request as ready for review December 8, 2024 22:14

aws-cdk-automation enabled auto-merge December 8, 2024 22:15

update comment again

f16aa2f

mrgrain reviewed Dec 10, 2024

View reviewed changes

lib/progress.ts Outdated Show resolved Hide resolved

mrgrain reviewed Dec 10, 2024

View reviewed changes

test/mock-child_process.ts Outdated Show resolved Hide resolved

mrgrain requested changes Dec 10, 2024

View reviewed changes

test/mock-child_process.ts Outdated Show resolved Hide resolved

bin/logging.ts Outdated Show resolved Hide resolved

bin/logging.ts Outdated Show resolved Hide resolved

HBobertz added 2 commits December 11, 2024 13:44

fix mock child

f5798b8

make logging better

7fee2ff

HBobertz changed the title ~~chore: Modify logging to ensure docker and shell logging is properly emitted to pluggble log publisher~~ chore: Ensure docker and shell logging is properly emitted to log publisher Dec 13, 2024

HBobertz changed the title ~~chore: Ensure docker and shell logging is properly emitted to log publisher~~ chore: Emit Docker and Shell logging to ProgressListener Dec 13, 2024

HBobertz and others added 7 commits December 26, 2024 13:24

remove unnecessary feature

39b52b6

Merge branch 'main' into bobertzh/logging

2860f8d

better capturing of shell logs

b1c7851

chore: self mutation

154951f

Signed-off-by: github-actions <[email protected]>

asset-publishing-tests

d683acf

Merge branch 'main' into bobertzh/logging

b2959f6

global shell logger implementation

35c928d

HBobertz changed the title ~~chore: Emit Docker and Shell logging to ProgressListener~~ chore: emit Docker and Shell logging to ProgressListener Dec 27, 2024

HBobertz mentioned this pull request Dec 30, 2024

chore: add some additional shell logging #272

Merged

HBobertz added 2 commits December 30, 2024 11:04

adjust tests

3b98e84

add comment

91359d1

HBobertz requested a review from mrgrain December 30, 2024 16:16

HBobertz added 2 commits December 30, 2024 14:51

Merge branch 'main' into bobertzh/logging

0aba325

small changes

cacbcf4

iliapolo requested changes Dec 31, 2024

View reviewed changes

rix0rrr requested changes Jan 9, 2025

View reviewed changes

HBobertz closed this Jan 9, 2025

auto-merge was automatically disabled January 9, 2025 22:24
Pull request was closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: emit Docker and Shell logging to ProgressListener #221

chore: emit Docker and Shell logging to ProgressListener #221

HBobertz commented Dec 3, 2024 •

edited

Loading

mrgrain left a comment

mrgrain commented Dec 10, 2024

iliapolo left a comment •

edited

Loading

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024 •

edited

Loading

iliapolo Dec 31, 2024

iliapolo Dec 31, 2024

HBobertz commented Dec 31, 2024 •

edited

Loading

rix0rrr Jan 9, 2025

rix0rrr Jan 9, 2025 •

edited

Loading

HBobertz commented Jan 9, 2025

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

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

	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}`;

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

		@@ -1,23 +1,23 @@
		import * as child_process from 'child_process';
		import { EventType, globalOutputHandler } from '../progress';

chore: emit Docker and Shell logging to ProgressListener #221

chore: emit Docker and Shell logging to ProgressListener #221

Conversation

HBobertz commented Dec 3, 2024 • edited Loading

mrgrain left a comment

Choose a reason for hiding this comment

mrgrain commented Dec 10, 2024

iliapolo left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

iliapolo Dec 31, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HBobertz commented Dec 31, 2024 • edited Loading

Choose a reason for hiding this comment

rix0rrr Jan 9, 2025 • edited Loading

Choose a reason for hiding this comment

HBobertz commented Jan 9, 2025

HBobertz commented Dec 3, 2024 •

edited

Loading

iliapolo left a comment •

edited

Loading

iliapolo Dec 31, 2024 •

edited

Loading

HBobertz commented Dec 31, 2024 •

edited

Loading

rix0rrr Jan 9, 2025 •

edited

Loading