feat: core extension command log #5856

jgellin-sf · 2024-09-18T21:15:05Z

What does this PR do?

This PR logs commands, including exit codes and errors from CLI command executions, in the workspaceState Memento of the core extension. Additional arbitrary data can also be logged with the commands, but this is not currently used. It also allows dependent extensions to query the command log from the API.

Command events are streamed using the new CommandEventStream class. A START event, including the commandId signals the beginning of logging for a given command, and an END event signals the end, at which point the command log entry is written to the log which includes duration information as well as any data, error, or exit code events logged between the START and END. For some long-running events, there is a chance of overlapping streams from multiple commands, so it is possible that data/errors/exit codes from one event are written to multiple events. The risk of incorrect data for overlapping commands is there, but a fully traced command log would be difficult to achieve without a major refactor. This solution attempts to achieve as much as possible as a general solution.

What issues does this PR fix or reference?

@W-16486962@

Functionality Before

Functionality After

gbockus-sf · 2024-09-23T14:24:12Z

packages/salesforcedx-utils-vscode/src/commands/commandEventStream.ts

+
+export class CommandEventStream {
+  private static instance: CommandEventStream;
+  private readonly eventEmitter = new vscode.EventEmitter<CommandEvent>();


should this be assigned in the constructor for testability?

TS complains somewhere about the member not being initialized if I do that, when I write the tests I'll see if I can refactor to make everything happy.

gbockus-sf · 2024-09-23T14:28:11Z

packages/salesforcedx-vscode-core/src/commands/util/commandWrapper.ts

+import * as vscode from 'vscode';
+
+export const registerCommand = (commandId: string, callback: (...args: any[]) => any, thisArg?: any): vscode.Disposable => {
+  return vscode.commands.registerCommand(commandId, wrapCommandCallback(commandId, callback), thisArg);


Just to verify. B/c we're all arrow functions here the thisArg will still be applied to the eventual run of the callback b/c it's basically going to passthrough to the func returned by wrapCommandCallback. right?

gbockus-sf · 2024-09-23T14:29:30Z

packages/salesforcedx-utils-vscode/src/commands/commandEventStream.ts

+  public readonly onCommandEvent: vscode.Event<CommandEvent> = this.eventEmitter.event;
+
+  public post(event: CommandEvent) {
+    this.eventEmitter.fire(event);


Should we wrap this in a try/catch and log, but not fail on the error if on occurs? It'd be good to avoid failing command execution due to monitoring code.

yes. good call

gbockus-sf · 2024-09-23T14:33:27Z

packages/salesforcedx-vscode-core/src/commands/util/commandWrapper.ts

+const wrapCommandCallback = (commandId: string, callback: (...args: any[]) => any): (...args: any[]) => any => {
+  return async (...args: any[]) => {
+    CommandEventStream.getInstance().post({ type: CommandEventType.START, commandId });
+    await callback(...args);


I think we need to return the result of this. One thing I'm not clear about...what if the caller doesn't want to wait on the promise to complete.

Should this be something like:

... return Promise.resolve(callback(...args)).then((result) => { CommandEventStream.getInstance().post({ type: CommandEventType.END, commandId }); return result; });

That way we always get the END event recorded, but the caller has control on awaiting the promise, and access to the result of the call when desired.

Having a .catch is a bit stickier b/c you'll then be intercepting all errors from command calls, but I guess you could and then record the error happened and rethrow...now sure how that will impact stack traces and such

Something like:

try { return await callback(...args); } finally { CommandEventStream.getInstance().post({ type: CommandEventType.END, commandId }); }

would work. The END event always gets issued and the exception doesn't have to be caught and rethrown.

gbockus-sf · 2024-09-23T14:35:44Z

packages/salesforcedx-vscode-core/src/index.ts

-    }
+    },
+    getCommandLog,
+    getLastCommandLogEntry


These seems they they should be wrapped in a service vs just exported as standalone function to following the existing shared services pattern. CommandService on like 679 instead?

Good idea I'll give that a whorl.

gbockus-sf · 2024-09-23T14:37:07Z

packages/salesforcedx-vscode-core/src/index.ts

    'sf.folder.diff',
    sourceFolderDiff
  );

-  const forceRefreshSObjectsCmd = vscode.commands.registerCommand(
+  const forceRefreshSObjectsCmd = registerCommand(


How would you feel about only doing this for sobject refresh for the initial release, but expanding to other services after we've had a couple of week to ensure there are no surprises with just wrapping sobjectRefresh?

This is a great idea @gbockus-sf

gbockus-sf · 2024-09-23T14:42:18Z

packages/salesforcedx-vscode-core/src/context/workspaceContext.ts

  }

  public async initialize(extensionContext: vscode.ExtensionContext) {
    await WorkspaceContextUtil.getInstance().initialize(extensionContext);
+    this.workspaceStore = extensionContext.workspaceState;
+    CommandEventStream.getInstance().initialize(extensionContext);
+    CommandLog.getInstance().initialize();


Registering with another service doesn't seem like a business WorkspaceContext should be in.
Move to the initializeProject function?

salesforcedx-vscode/packages/salesforcedx-vscode-core/src/index.ts

Line 714 in c7aa878

const initializeProject = async (extensionContext: vscode.ExtensionContext) => {

gbockus-sf · 2024-09-23T14:45:59Z

packages/salesforcedx-vscode-core/src/commands/util/commandLogEntry.ts

+  duration: number;
+  exitCode?: number;
+  error?: string;
+  data?: any;


unknown would be better for consuming the data in a type safe way.

gbockus-sf · 2024-09-23T14:47:14Z

packages/salesforcedx-vscode-core/src/commands/util/commandLog.ts

+  return CommandLog.getInstance().getCommandLog(commandIdFilter, exitCodeFilter);
+};
+
+export const getLastCommandLogEntry = (commandIdFilter?: string, exitCodeFilter?: number): CommandLogEntry | undefined => {


Any reason this doesn't go in utils.

Also what's the use case for getting the last commandLogEntry? Seems error prone as there can always be a bunch of command running in parallel

Yeah it's really not necessary. It's easy enough for a client of this to find the last one. I'm thinking about just having getCommandLog and an options parameter that has the commandIdFilter and exitCodeFilter and maybe a timestamp sort order as well. Overkill?

gbockus-sf · 2024-09-23T14:51:41Z

packages/salesforcedx-vscode-core/src/commands/util/commandLog.ts

+import { CommandEvent, CommandEventStream, CommandEventType } from '@salesforce/salesforcedx-utils-vscode';
+import { WorkspaceContext } from '../../context';
+import { CommandLogEntry } from './commandLogEntry';
+


The stand alone methods...should they be static methods on CommandLog?

My goal was to hide the CommandLog implementation from the API. If I move a new service to the API, I can get rid of the standalone methods.

gbockus-sf · 2024-09-23T14:56:47Z

packages/salesforcedx-vscode-core/src/commands/util/commandLog.ts

+    await this.updateCommandLog();
+  }
+
+  public getCommandLog(commandIdFilter?: string, exitCodeFilter?: number): CommandLogEntry[] {


is commandIdFilter purposely optional?
I guess it comes with the benefit that I could get all command with -1 exit code, but I'm more concerned with code that would accidentally pass undefined as the commandId then react as if they got back command that's weren't expected.

let startCmd = undefined; let failedStartCommands = getCommandLog(startCmd, -1) console.log('All failed start commands', failedStartCommands);

Yeah I wanted to leave open the option for clients to get multiple types of commands. But parameter order makes it seem like it shouldn't be undefined. It seems to me like an argument for:

Yeah it's really not necessary. It's easy enough for a client of this to find the last one. I'm thinking about just having getCommandLog and an options parameter that has the commandIdFilter and exitCodeFilter and maybe a timestamp sort order as well. Overkill?

gbockus-sf · 2024-09-23T15:02:54Z

packages/salesforcedx-vscode-core/src/commands/util/commandLog.ts

+
+  private commandLogEntries: CommandLogEntry[] = [];
+  private inProgressCommands: Map<string, number> = new Map();
+  private inProgressData: any = {};


Instead of tracking this via instance var why not have two functions for recording a log. That that doesn't take progressData for logs that don't need it (Start) and another that will take progressData (stop). That way we don't have to worry about the async parallel nature of commands.

Any call to record data would need to return the progressData.

Not sure I understand the question completely. But the reason things are set up like this is because of where the code knows what the commandId is and where the code does not. The code only knows the commandId at command registration. But for other information that can get logged (errors, exit codes, misc data), that data is coming from implementation code where we don't have the commandId. The inProgressCommands keeps track for commands for which a START event has been issued but no END yet. The inProgressData keeps track of any EXIT_CODE, DATA, ERROR` events that are issued in between those events.

If the log simply logged the raw events, it would be harder to pull the data like EXIT_CODE and associate it with a given command.

gbockus-sf · 2024-09-23T15:04:56Z

packages/salesforcedx-utils-vscode/src/cli/commandExecutor.ts

    this.exitSubject.next(0);
  }

  public failureExit(e?: {}) {
    if (e) {
+      // eslint-disable-next-line @typescript-eslint/no-base-to-string, @typescript-eslint/restrict-template-expressions
+      CommandEventStream.getInstance().post({ type: CommandEventType.ERROR, error: `${e}` });


Is there a safer way to do this without all the eslint bypasses?

I'll see what I can do.

jgellin-sf added 3 commits September 18, 2024 12:00

feat: command log

e828408

chore: command event stream

e7a6202

chore: lint

a6f8463

gbockus-sf reviewed Sep 23, 2024

View reviewed changes

chore: command executor posting to command stream

43ec575

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: core extension command log #5856

feat: core extension command log #5856

jgellin-sf commented Sep 18, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024 •

edited

Loading

jgellin-sf Sep 23, 2024 •

edited

Loading

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

peternhale Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024 •

edited

Loading

jgellin-sf Sep 23, 2024

gbockus-sf Sep 23, 2024

jgellin-sf Sep 23, 2024

feat: core extension command log #5856

Are you sure you want to change the base?

feat: core extension command log #5856

Conversation

jgellin-sf commented Sep 18, 2024

What does this PR do?

What issues does this PR fix or reference?

Functionality Before

Functionality After

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

gbockus-sf Sep 23, 2024 • edited Loading

Choose a reason for hiding this comment

jgellin-sf Sep 23, 2024 • 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

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

gbockus-sf Sep 23, 2024 • 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

gbockus-sf Sep 23, 2024 •

edited

Loading

jgellin-sf Sep 23, 2024 •

edited

Loading

gbockus-sf Sep 23, 2024 •

edited

Loading