feat: emit all shell logging to publishProgressListener #295

HBobertz · 2025-01-09T22:23:51Z

Closes #196

Removes quiet flag and also ensures all events are routed to the progressListener.

removeD the existing logger callback and replaces it with shellEventPublisher which will route the message back to the configured progressListener if configured. The default behavior is stdio for the new subprocessOutputDestination option, which essentially is the old behavior. Where shells write directly to stdout/stderr

bin/publish.ts

lib/private/handlers/container-images.ts

test/shell-logging.test.ts

bin/logging.ts

lib/private/handlers/container-images.ts

lib/private/shell.ts

lib/progress.ts

test/mock-progress-listener.ts

lib/private/handlers/files.ts

bin/publish.ts

lib/progress.ts

bin/logging.ts

bin/publish.ts

lib/private/asset-handler.ts

lib/private/shell.ts

lib/progress.ts

lib/private/shell.ts

rix0rrr · 2025-01-13T09:11:53Z

test/mock-progress-listener.ts

@@ -0,0 +1,67 @@
+import { LogLevel } from '../bin/logging';


Noooooooo

😂 😂 😂

I still feel this export shouldn't exist. I guess you didn't write it, so I can't fault you for that.

Can you explain further why this is bad? I get that generally speaking it's bad to export stuff from bin just on the principle that it's mean to be the executable and thus only ever consumes stuff. But it seems valid to me to export from bin for testing purposes

It's that. bin is not intended to be library, so it shouldn't be used as a library.

Maybe it is justifiable if this MockProgressListener is intended to be used to test exclusively one of the CLI tools, but I don't think it is. And even then, if the logic in that CLI tools is complex and interesting enough to warrant testing, it's probably interesting enough to lift it into the lib directory wholesale.

lib/private/docker-credentials.ts

lib/private/handlers/container-images.ts

lib/private/shell.ts

rix0rrr · 2025-01-13T18:36:11Z

lib/private/shell.ts

+      break;
+    case 'stdio':
+    default:
+      if (eventType != 'data_stderr') {


This now would print the command line as well, but the old code didn't use to do that. I think you only want to print for data_* events.

It printed the open but you're right about the close being my own design so I'm gonna make sure I ignore that one.

It sent the command line to the logger (as opposed to the stdout and stderr chunks, which always got written to stdio immediately). Did the logger always send it to stdout?

I fixed this yeah the only things that went to stdout was the shell stdout. That is supposed to go to stderr, good catch

It shouldn't go to stderr either I don't think. See my bigger comment down below.

lib/progress.ts

lib/private/docker.ts

lib/private/handlers/container-images.ts

rix0rrr

Almost there!

lib/private/docker.ts

rix0rrr · 2025-01-15T15:04:28Z

lib/private/docker.ts

-    const docker = new Docker(options.logger);
+    const docker = new Docker(options.eventEmitter);


In your mind, is this code churn worth it?

🤷‍♂️ I didn't like the name logger since log to me means "print to stdout/stderr" and that's not always true anymore

I guess this us ascribing different meanings to words. You interpret "logger" to mean "the thing that prints messages to stdio" and I interpret logger to mean "the thing that receives messages and does something with them". Could be printing, could be writing to a file, could be sending over HTTP to a syslog daemon or to CloudWatch.

Strictly speaking, the thing you're passing right now is not an event emitter, but rather an event receiver 😛

lib/private/docker.ts

lib/private/handlers/container-images.ts

rix0rrr · 2025-01-15T15:08:40Z

lib/private/shell.ts

+      break;
+    case 'stdio':
+    default:
+      if (eventType == 'data_stdout' || eventType == 'open') {


I'm still not convinced that the open event used to be sent to stdout in the old code.

How sure are you about that?

good catch, it went to stderr

It went nowhere I'm pretty sure?

rix0rrr

Almost almost there. This is Zeno's request changes 😉

lib/private/docker.ts

rix0rrr · 2025-01-21T08:52:42Z

lib/private/docker.ts

+    const shellEventPublisher = (event: ShellEventType, message: string) => {
+      const eventType = shellEventToEventType(event);
+      this.eventEmitter(eventType, message);
+    };


👨‍🍳💋👌

lib/private/docker.ts

rix0rrr · 2025-01-21T08:58:36Z

lib/private/handlers/files.ts

+    const shellEventPublisher = (event: ShellEventType, message: string) => {
+      const eventType = shellEventToEventType(event);
+      this.host.emitMessage(eventType, message);
+    };


💅 I see this being repeated a couple of times.

In principle it's not too bad, and I'm fine with leaving it this way. We could also make it slightly nicer by packaging that logic up and putting it in a single place:

/** * Create a ShellEventPublisher for an IHandlerHost * * Returns a ShellEventPublisher that translates ShellEvents into messages * emitted via the HandlerHost. Uses `shellEventToEventType` to translate * shell event types to HandlerHost event types. */ function makeHandlerHostEventPublisher(host: IEventHost) { return (event: ShellEventType, message: string) => { const eventType = shellEventToEventType(event); this.host.emitMessage(eventType, message); }; }

if you took the time to write this with a tsdoc I'll put it in lol

changed this up a bit because it takes an event emitter but still

rix0rrr · 2025-01-21T09:06:03Z

lib/private/shell.ts

+    default:
+      if (shellEventType == 'data_stdout') {
+        process.stdout.write(chunk);
+      } else if (shellEventType == 'data_stderr' || shellEventType == 'open') {


I'm still not convinced this is in line with old behavior.

My take

The old code used to do:

cdk-assets/lib/private/shell.ts

Line 19 in c9e3d9b

options.logger(renderCommandLine(command));

So the command line (in your case, the open event) would get sent into the logger exclusively. The only place I can find that options.logger gets a value is like this (via a small detour on Docker object):

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

So the command line didn't use to go to stderr, it got emitted as a DEBUG event over the handler progress protocol.

Your take

You seem pretty convinced that in the old code the commandline used to go to stdout or stderr. Can you point me to the chain of calls that leads to that happening?

Yeah you're right here, when I was thinking about this I was thinking about stdio being the "I'm using this from the CLI option" where this would get emitted to stderr from the console progress listener which prints to sdterr, so might as well handle it here and keep every congruent. However there will be a brief time where the cdk is using stdio before we swap it over to passing publish and so I have to make it backwards compatible there. So yeah went ahead and changed it so it always emits the event on open

Ah I see what you're concerned about. I don't really care about what the cdk-assets CLI does. I care a lot more about what the interface to the CDK CLI does.

(But if we do the same thing across the library protocol, I feel like we can't help but do the same thing for the cdk-assets CLI as well...?)

rix0rrr · 2025-01-21T09:08:38Z

lib/progress.ts

+    case 'data_stdout':
+      return EventType.SHELL_DATA;
+    case 'data_stderr':
+      return EventType.SHELL_DATA;


Do we lose the ability to tell whether it's stdout or stderr data? I would think that's a rather important distinction for consumers...?

(Sorry I didn't pick up on this before)

Yeah since this part is new I honestly figured that it wouldn't be relevant to distinguish between the 2 but I can always break it out in to shell_stderr and shell_stdout if we want

went ahead and did that

rix0rrr · 2025-01-21T09:10:49Z

test/mock-progress-listener.ts

+      type,
+      message: event.message,
+      stream: ['open', 'data_stdout', 'close'].includes(type) ? 'stdout' : 'stderr',
+      level,


Where is level used?

(And if level isn't used, EVENT_TO_LEVEL isn't used, and if EVENT_TO_LEVEL isn't used, you don't need the import of LogLevel).

I can see you have unused symbols in this file. For some reason, the linter setup of this repo doesn't fail on unused imports and unused globals... but this will fail the build once we move this code to a repo with a stricter linter setup.

Can you have a look around and remove variables that have a slightly dimmer color, to indicate they are unused?

Either that, or configure eslint to complain about them.

yeah removed all this though I feel like it may be useful later, we can just add it then

Co-authored-by: Rico Hermans <[email protected]>

remove quiet and improve progress listener

3b7636d

HBobertz mentioned this pull request Jan 9, 2025

chore: emit Docker and Shell logging to ProgressListener #221

Closed

HBobertz commented Jan 9, 2025

View reviewed changes

bin/publish.ts Outdated Show resolved Hide resolved

update comments

2613c7b

HBobertz commented Jan 9, 2025

View reviewed changes

lib/private/handlers/container-images.ts Show resolved Hide resolved

HBobertz marked this pull request as ready for review January 9, 2025 23:05

aws-cdk-automation enabled auto-merge January 9, 2025 23:05

HBobertz added 2 commits January 9, 2025 18:41

remove unnecessary logic

7a23ef0

update comment

2cb1586

HBobertz commented Jan 9, 2025

View reviewed changes

test/shell-logging.test.ts Show resolved Hide resolved

rix0rrr suggested changes Jan 10, 2025

View reviewed changes

HBobertz added 4 commits January 10, 2025 16:00

address feedback

2a94253

shell event publisher

fcaeecd

remove unecessary type

e2bd0d0

refactor unecessary code

2194b76

rix0rrr suggested changes Jan 13, 2025

View reviewed changes

HBobertz added 7 commits January 13, 2025 08:18

remove loglevels export

0560603

address feedback

08e307d

add type tsdoc

a58f0a5

address feedback

663a5fc

add documentation to events

c36b7f8

remoe unecessary export

da98322

add buffer to handle shell output

c510731

rix0rrr changed the title ~~chore: emit all shell logging to publishProgressListener~~ feat: emit all shell logging to publishProgressListener Jan 13, 2025

rix0rrr suggested changes Jan 13, 2025

View reviewed changes

HBobertz added 5 commits January 13, 2025 21:56

fix ecr logger being irrelevant

d929b8a

rename logger to event emitter

4d8c044

address feedback

feadde2

address feedback

44865d4

fix white space

0b49399

rix0rrr suggested changes Jan 15, 2025

View reviewed changes

HBobertz added 3 commits January 19, 2025 12:19

address docker feedback

ac1b0f2

better subprocess destination handling

6cafe1d

address feedback

9a89c65

rix0rrr reviewed Jan 21, 2025

View reviewed changes

HBobertz and others added 6 commits January 21, 2025 09:03

address feedback

a9cd99b

Update lib/private/docker.ts

d81d42a

Co-authored-by: Rico Hermans <[email protected]>

Update lib/private/docker.ts

08aa6df

Co-authored-by: Rico Hermans <[email protected]>

address feedback

fea38d9

add default of empty

f849578

Merge branch 'main' into bobertzh/shell-log-capture

55d4523

HBobertz requested a review from rix0rrr January 21, 2025 14:33

rix0rrr approved these changes Jan 21, 2025

View reviewed changes

aws-cdk-automation added this pull request to the merge queue Jan 21, 2025

Merged via the queue into main with commit 6877039 Jan 21, 2025
7 checks passed

aws-cdk-automation deleted the bobertzh/shell-log-capture branch January 21, 2025 16:01

		const docker = new Docker(options.logger);
		const docker = new Docker(options.eventEmitter);

feat: emit all shell logging to publishProgressListener #295

feat: emit all shell logging to publishProgressListener #295

Uh oh!

Conversation

HBobertz commented Jan 9, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rix0rrr Jan 14, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

rix0rrr left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

HBobertz Jan 20, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

HBobertz commented Jan 9, 2025 •

edited

Loading

rix0rrr Jan 14, 2025 •

edited

Loading

HBobertz Jan 20, 2025 •

edited

Loading

HBobertz Jan 21, 2025 •

edited

Loading