@W-10459671@ Provide progress information of SFGE on verbose mode #792

rmohan20 · 2022-08-10T19:13:17Z

This PR helps provide more insight into how SFGE's analysis is progressing.

ProgressListener is a new class that observes various steps in SFGE's analysis and posts messages to CliMessager. To help control how often path progress updates are provided, SFGE_PROGRESS_INCREMENTS_ON_VERBOSE env variable can be tweaked. Default value is 50.
CliMessagerAppender is a new custom log appender that takes log4j events and translates them into CliMessager posts. This treats Warnings as Info, Errors as Warnings, and Fatal as Errors to keep output information relevant. Also, by default, Warnings are turned off for all users and can be turned on using SFGE_LOG_WARNINGS_ON_VERBOSE env variable.
Typescript and CliMessager layers have been modified to post messages in realtime. Messaging behavior for existing posts remains intact.
Relevant tests

There's still some verbosity coming in while generating catalogs to use for rule execution and this decreases the clarity of SFGE's actual progress. I've logged a separate work item to address this issue.

rmohan20 · 2022-08-11T21:12:00Z

cli-messaging/src/main/java/com/salesforce/messaging/CliMessager.java

+     * @param eventKey    EventKey to display to user
+     * @param args        String args passed to the EventKey to make the displayed message meaningful
+     */
+    public static void postMessage(String internalLog, EventKey eventKey, String... args) {


Creating an alternate method to post realtime messages. I've marked the other entry points as deprecated and we can eventually make them realtime as well.

rmohan20 · 2022-08-11T21:12:34Z

cli-messaging/src/main/java/com/salesforce/messaging/EventKey.java

+
+
+
+    /** SFGE RELATED **/


New event keys to match the new messages

rmohan20 · 2022-08-11T21:14:37Z

messages/EventKeyTemplates.js

+		"unmatchedPathExtensionCpd": "Path extensions for the following files will not be processed by CPD: %s",
+		"sfgeInfoLog": "%s",
+		"sfgeMetaInfoCollected": "Loaded %s: [ %s ]",
+		"sfgeFinishedCompilingFiles": "Compiled %s files.",
+		"sfgeStartedBuildingGraph": "Building graph . . .",
+		"sfgeFinishedBuildingGraph": "Added all compilation units to graph.",
+		"sfgePathEntryPointsIdentified": "Identified %s path entry point(s).",
+		"sfgeViolationsInPathProgress": "Detected %s violation(s) from %s path(s) on %s entry point(s) so far.",
+		"sfgeCompletedPathAnalysis": "Overall, analyzed %s path(s) from %s entry point(s). Detected %s violation(s)."


New messages to be displayed during verbose calls.
@teresa-allen-sfdc Please do let me your thoughts on the verbose messages.

rmohan20 · 2022-08-11T21:15:20Z

sfge/src/main/java/com/salesforce/CliMessagerAppender.java

+        name = "CliMessagerAppender",
+        category = Core.CATEGORY_NAME,
+        elementType = Appender.ELEMENT_TYPE)
+public class CliMessagerAppender extends AbstractAppender {


New log appender that steps in to pass realtime messages when needed.

rmohan20 · 2022-08-11T21:18:15Z

sfge/src/main/java/com/salesforce/config/SfgeConfig.java


    /** Indicates if a Jorje parse error causes the entire process to stop. */
    boolean shouldIgnoreParseErrors();
+


New config values to control verbose behavior.
LogWarningsOnVerbose would make the output noisier by including all the warnings from SFGE as info events.
ProgressIncrementsOnVerbose controls how often we post updates on number of paths analyzed.

Do we need these config values anymore? Would removing them simplify the code?

rmohan20 · 2022-08-11T21:19:29Z

sfge/src/main/java/com/salesforce/rules/ops/ProgressListener.java

+import java.util.Set;
+import java.util.TreeSet;
+
+public interface ProgressListener {


Will add javadocs

rmohan20 · 2022-08-11T21:27:52Z

sfge/src/main/java/com/salesforce/rules/ops/ProgressListenerImpl.java

+import java.util.TreeSet;
+
+/** Publishes information to CLI on the progress of analysis. */
+public class ProgressListenerImpl implements ProgressListener {


All action happens here

rmohan20 · 2022-08-11T21:30:33Z

sfge/src/main/resources/log4j2.xml

+		<CliMessagerAppender name="LogToCliMessager">
+			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %m%n"/>
+		</CliMessagerAppender>


Configuring the new log appender.

rmohan20 · 2022-08-11T21:31:31Z

src/lib/services/CommandLineSupport.ts

 			// When data is passed back up to us, pop it onto the appropriate string.
 			cp.stdout.on('data', data => {
-				stdout += data;
+				if (!this.handleLiveOut(String(data))) {


Handle live output if relevant.

rmohan20 · 2022-08-11T21:33:12Z

src/lib/services/OutputProcessor.ts

+		const regex = new RegExp(`^${startTag}(.*)${endTag}`, 'g');
+		const headerLength = startTag.length;
+		const tailLength = endTag.length;


Steps are the same as regular CliMessager updates, except we allow different tags to mean different things.

rmohan20 · 2022-08-11T21:33:44Z

src/lib/sfge/SfgeWrapper.ts

+		if (this.outputProcessor.isRealtimeOutput(data)) {
+			return this.outputProcessor.processRealtimeOutput(data);
+		}
+		return false;


SFGE overrides live output handling.

rmohan20 · 2022-08-11T21:35:47Z

test/commands/scanner/run.dfa.test.ts

+	expect(isSubstr(output, substring), `Output "${output}" should not contain substring "${substring}"`).is.false;
+}
+
+describe('scanner:run:dfa', function () {


New end-to-end tests for dfa. Directly testing sfge's Main.java was getting problematic because of the multithreading. These new tests are more reliable.
Though I'm seeing an issue where each verbose like is printed 6 times. Still investigating to understand the cause.

jfeingold35

The SFGE portion has more than we strictly need, but the design itself is sound. I'll keep an eye out for the refactor.

jfeingold35 · 2022-08-15T19:05:23Z

sfge/src/main/java/com/salesforce/config/SfgeConfig.java

+    boolean shouldLogWarningsOnVerbose();
+
+    /**
+     * Should be used to set the level of increments at which path analysis progress update is
+     * provided
+     */
+    int getProgressIncrementsOnVerbose();


Unnecessary, since we're making the progress report happen all the time instead of just on Verbose.

Since the functionality has been modified, this can be renamed to not include "OnVerbose". Though I still think this is a useful variable to have so that users could increase or decrease depending on their convenience. For now, I haven't surfaced these new variables as scanner:run:dfa's flags.

jfeingold35 · 2022-08-15T19:05:47Z

sfge/src/main/java/com/salesforce/config/EnvUtil.java

+    @VisibleForTesting static final boolean DEFAULT_LOG_WARNINGS_ON_VERBOSE = false;
+    @VisibleForTesting static final int DEFAULT_PROGRESS_INCREMENTS_ON_VERBOSE = 50;


Unnecessary, since progress logging should happen all the time instead of just on Verbose.

jfeingold35 · 2022-08-15T19:05:57Z

sfge/src/main/java/com/salesforce/config/SfgeConfigImpl.java

+    public boolean shouldLogWarningsOnVerbose() {
+        return EnvUtil.shouldLogWarningsOnVerbose();
+    }
+
+    @Override
+    public int getProgressIncrementsOnVerbose() {
+        return EnvUtil.getProgressIncrementsOnVerbose();
+    }
+


Unnecessary.

jfeingold35 · 2022-08-15T19:12:05Z

sfge/src/main/java/com/salesforce/graph/ops/GraphUtil.java

            }
        }

+        final ProgressListener progressListener = ProgressListenerProvider.get();


Could we have the listener be a static final property to avoid the need to keep declaring a variable for it?

static final would force instantiation at the earliest and not use the lazy loading functionality as intended.

https://www.imperva.com/learn/performance/lazy-loading/

jfeingold35 · 2022-08-15T19:22:18Z

sfge/src/main/java/com/salesforce/rules/ops/ProgressListenerImpl.java

+ */
+public class ProgressListenerImpl implements ProgressListener {
+
+    @VisibleForTesting static final String NONE_FOUND = "none found";


As mentioned in scrum, having this many individual events feels like overkill for now, but the strategy itself is sound.

jfeingold35 · 2022-08-15T19:22:53Z

sfge/src/test/java/com/salesforce/config/SfgeConfigProviderTest.java

+                        public boolean shouldLogWarningsOnVerbose() {
+                            return !EnvUtil.DEFAULT_LOG_WARNINGS_ON_VERBOSE;
+                        }
+
+                        @Override
+                        public int getProgressIncrementsOnVerbose() {
+                            return -1 * EnvUtil.DEFAULT_PROGRESS_INCREMENTS_ON_VERBOSE;


Unnecessary

jfeingold35 · 2022-08-15T19:23:00Z

sfge/src/test/java/com/salesforce/config/TestSfgeConfig.java

+    public boolean shouldLogWarningsOnVerbose() {
+        return SfgeConfigImpl.getInstance().shouldLogWarningsOnVerbose();
+    }
+
+    @Override
+    public int getProgressIncrementsOnVerbose() {


Unnecessary

jfeingold35 · 2022-08-15T20:11:36Z

messages/EventKeyTemplates.js

+		"sfgeInfoLog": "%s",
+		"sfgeMetaInfoCollected": "Loaded %s: [ %s ]",
+		"sfgeFinishedCompilingFiles": "Compiled %s files.",
+		"sfgeStartedBuildingGraph": "Building graph . . .",


The periods don't need spaces between them.

jfeingold35 · 2022-08-15T20:13:18Z

sfge/src/main/java/com/salesforce/config/EnvUtil.java

+    static boolean shouldLogWarningsOnVerbose() {
+        return getBoolOrDefault(ENV_LOG_WARNINGS_ON_VERBOSE, DEFAULT_LOG_WARNINGS_ON_VERBOSE);
+    }
+
+    /**
+     * Gets the level of increments at which path analysis progress update is provided. Applicable
+     * only with --verbose.
+     *
+     * @return value of {@link #ENV_PROGRESS_INCREMENTS_ON_VERBOSE} environment variable if set,
+     *     else {@link #DEFAULT_PROGRESS_INCREMENTS_ON_VERBOSE}
+     */
+    static int getProgressIncrementsOnVerbose() {
+        return getIntOrDefault(
+                ENV_PROGRESS_INCREMENTS_ON_VERBOSE, DEFAULT_PROGRESS_INCREMENTS_ON_VERBOSE);
+    }


Why is this still here? We don't need it anymore, right?

jfeingold35 · 2022-08-15T20:14:07Z

sfge/src/main/java/com/salesforce/config/SfgeConfig.java


    /** Indicates if a Jorje parse error causes the entire process to stop. */
    boolean shouldIgnoreParseErrors();
+


Do we need these config values anymore? Would removing them simplify the code?

jfeingold35 · 2022-08-15T20:21:49Z

src/lib/services/CommandLineSupport.ts

 			// When data is passed back up to us, pop it onto the appropriate string.
 			cp.stdout.on('data', data => {
-				stdout += data;
+				if (!this.handleLiveOut(String(data))) {


I don't love this check.
If live output and at-the-end output use different start and end strings, couldn't we just pass all output through both at the appropriate times? The output processor would process real time output as it's received, and then it would process at-the-end output at the end, right?

jfeingold35 · 2022-08-15T20:24:15Z

src/lib/sfge/SfgeWrapper.ts

 		let intervalCount = 0;
 		this.intervalId = setInterval(() => {
-			uxEvents.emit(EVENTS.UPDATE_SPINNER, "Please wait." + ".".repeat(intervalCount));
+			uxEvents.emit(EVENTS.WAIT_ON_SPINNER, 'message is unused');


You can remove everything with the interval, here. The point of this was to add a period to the end of the please wait string every 30 seconds. Now that we're adding more informative progress reports, this is redundant.

The extra dots still look like something is happening especially when waiting on the next update. Let me know how you like it during QA. Based on that, we can keep it or remove it.

jfeingold35 · 2022-08-15T20:26:10Z

src/lib/services/OutputProcessor.ts



 	private emitUxEvent(eventType: string, messageKey: string, args: string[]): void {
+		if (eventType === '') {


How can this happen?

Previously, we had an if/else to filter only valid eventTypes to go in. The filter has been restructured to not always check for eventTypes. This check should possibly never be invoked, but this is just being defensive to avoid unexpected issues.

rmohan20 commented Aug 11, 2022

View reviewed changes

rmohan20 marked this pull request as ready for review August 11, 2022 21:37

ranekere-sfdc requested a review from jfeingold35 August 11, 2022 21:49

jfeingold35 reviewed Aug 15, 2022

View reviewed changes

rmohan20 added 11 commits August 15, 2022 16:26

Basic changes to bubble up realtime progress information

07bf137

Added more progress information and stats

2def31f

Config related changes

56fed64

Adding more tests + fixing minor issues

e97100d

Improving javadocs

3b5a855

Modifying spinner message to display SFGE progress

88bd84f

PR feedback + fixed end to end tests

978e49c

Reordered verbose test

fd3af9c

remove conditional on handleLiveOut

8fd2044

Minor changes

5acf779

Fixing issues introduced in previous commit

805ca8c

rmohan20 force-pushed the rm/returnTimelyResults branch from 4d68616 to 805ca8c Compare August 15, 2022 23:26

rmohan20 added 2 commits August 15, 2022 21:12

Creating an alternate test provider for ProgressImpl

6776803

--verbose in test issue

a995ba5

jfeingold35 approved these changes Aug 16, 2022

View reviewed changes

jfeingold35 merged commit 566a0b6 into dev-3 Aug 16, 2022

stephen-carter-at-sf deleted the rm/returnTimelyResults branch May 17, 2024 14:32


		/** Indicates if a Jorje parse error causes the entire process to stop. */
		boolean shouldIgnoreParseErrors();

		@VisibleForTesting static final boolean DEFAULT_LOG_WARNINGS_ON_VERBOSE = false;
		@VisibleForTesting static final int DEFAULT_PROGRESS_INCREMENTS_ON_VERBOSE = 50;



		private emitUxEvent(eventType: string, messageKey: string, args: string[]): void {
		if (eventType === '') {

@W-10459671@ Provide progress information of SFGE on verbose mode #792

@W-10459671@ Provide progress information of SFGE on verbose mode #792

Uh oh!

Conversation

rmohan20 commented Aug 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

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!

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!

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!

jfeingold35 left a comment

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!

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!

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!

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!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

rmohan20 commented Aug 10, 2022 •

edited

Loading