bug: Non-managed package actions grouped with managed package entries

[damiantx77]

Summary

When debug logs include ENTERING_MANAGED_PKG, the actions that occur after the managed package are rolled up into the managed package entry. This causes the time in the other actions to appear as though they occurred in the managed package

Steps To Reproduce:

1. Have a managed package installed that takes action when a record is updated.
2. Have a flow or other automation setup to run when a record is updated.
3. Turn on debug logs
4. Update the record.
5. In the debug logs you'll see the entering managed package lines and separate lines for the other automation
6. In the call tree in log analyzer you'll see the additional automation grouped under the managed package line and the time rolled up to the managed package.

Expected result

The additional automation should appear in it's own block and the managed package should stand alone.

Actual result

In the call tree in log analyzer you'll see the additional automation grouped under the managed package line and the time rolled up to the managed package.

Additional information

Sample debug logs and screenshot of log analyzer attached
VS Code Version: 1.80.0

Log Analyzer Extension Version: 1.6.0

OS and version: macOS 13.4.1 (c) (22F770820d)

apex-07LHr00005Zjt3DMAR.log

[lcottercertinia]

Thanks for reporting this, the shared log will really help 👏🏻
The managed package event collapse logic is a little sensitive. A lot of assumptions have to be made because there is no exit event, so I am not surprised we have some cases with some issues.

Is the log you shared the full logs as retrieved from the org? because there is no EXECUTION_STARTED and EXECUTION_FINISHED. If there is more to the log would it be possible to share the rest?

In the meantime I will see what we can do to tighten up the ENTERING_MANAGED_PKG handling and get something in for v1.7.0 😄

[damiantx77]

Thank for the quick reply. We're the providers for the managed package listed and have had a couple customers reference our package as taking too much time based on the log rollup.

The original attached log was the entire log... strangely there are 3 logs generated when I do the update but only 1 contained the managed package lines. The flow as my setup to attempt to reproduce but found I could with the default dupecheck in Salesforce and the flow logged elsewhere. We don't often work with manual update logs, so this may be me not understanding. I've attached all 3.
log3.log
log2.log
Log1.log

[lcottercertinia]

The log you shared is a bit weird compared to what I am used to seeing. We sometimes see something similar to this in the skipped section of a log when some entries have been removed, but not normally in a full log.

You tend to get ENTERING_MANAGED_PKG events between two others e.g

09:45:32.0 (541499524)|METHOD_ENTRY|[19]|anId|MyNS.Myclass.Myclass()
09:45:32.0 (541521486)|ENTERING_MANAGED_PKG|MyNS
09:45:32.0 (541550468)|METHOD_EXIT|[19]|MyNS.Myclass
09:45:32.0 (541582671)|METHOD_ENTRY|[1054]|anId|MyNS.MyClass.scaleAmount(Decimal)
09:45:32.0 (541591219)|ENTERING_MANAGED_PKG|MyNS
09:45:32.0 (541634402)|ENTERING_MANAGED_PKG|MyNS
09:45:32.0 (541720881)|METHOD_EXIT|[1054]|anId|MyNS.MyClass.scaleAmount(Decimal)

It is this assumption that is causing issues. Basically the log has no indication of what event caused the package entry and without an exit we rely on the surrounding exit events.

I have raised an idea to improve the debug log out to make this simpler.

I have reproduced this with my own logs and I am going to try improve things for cases like this.
I do not think we will be able to get it perfect until they improve the log output for managed packages but I will see what can be done.