certinia / debug-log-analyzer

Salesforce Apex debug log analyzer for Visual Studio Code - Visualize code execution via a Flame chart and identify performance and SOQL/DML problems via Method and Database analysis
https://marketplace.visualstudio.com/items?itemName=financialforce.lana
BSD 3-Clause "New" or "Revised" License
79 stars 17 forks source link

feat: Namespace should be correctly tracked for managed packages (ENTERING_MANAGED_PKG) #508

Open biswajith-s-pso-maxval opened 3 months ago

biswajith-s-pso-maxval commented 3 months ago

Under the Analysis tab or under the Call Tree tab, if we Group By Namespace then it shows up image image

But unfortunately, under the Database tab, the group by feature or filtering on Namespace doesn't work. It only shows default. image image

lcottercertinia commented 3 months ago

Hi @biswajith-s-pso-maxval thanks for the report. Can you share this additional information? and if you can could you share the debug log?

VS Code Version: Log Analyzer Extension Version: OS and version:

Early analysis My early thoughts is that I do not think that this is a bug but rather due to a lack of information in the debug log. Here is the salesforce idea I raised to improve this.

Briefly the issue is we only get ENTERING_MANAGED_PKG events in the log and salesforce do not give us EXIT events. So in the below example we do not know at which point the managed package exited, it could be before or after the SOQL. So we default to the default namespace.

17:36:50.157 (87157640387)|ENTERING_MANAGED_PKG|NS
17:36:50.157 (87157640387)|ENTERING_MANAGED_PKG|NS2
17:36:50.157 (87158398182)|SOQL_EXECUTE_BEGIN|[2]|Aggregations:0|SELECT Id, Name  FROM Account WHERE Id = :tmpVar1

We could be in either default, NS or NS2 in the above case since we could have exited ns before entering ns2 or we could have called ns2 from ns. If you have the METHOD_ENTRY + METHOD_EXIT events for the global method call that the SOQL occurred in we do correctly assign the SOQL to the right namespace.

If you share your log I can confirm this. We have discussed various options to handle this but we really need Salesforce to provide more information to get it correct. If they do not fix it we are limited to

  1. Show a message to explain the above behaviour.
  2. Show all the possible namespace that the SOQL could be in
  3. Guess at which we think is the most likely and risk getting it wrong
lcottercertinia commented 2 months ago

@biswajith-s-pso-maxval Here is an example of some SOQL that will be grouped under the default namespace by that was actually in MyNs

image

I believe this is what is happening in your case and is not a bug but really due to a lack of information in the logs.

Here is the order

  1. DML occurs on MyObject__c from some unmanaged code
  2. There is a trigger on MyObject__c in the namespace MyNs
  3. DML always switches us to the default namespace since we can have multiple triggers on an object in multiple namespaces
  4. We get a ENTERING_MANAGED_PKG|MyNs event next, because we have a trigger on MyObject__c in the MyNs namespace
  5. We next get the SOQL, BUT since we never get an EXITING_MANAGED_PKG event we might have left the trigger in MyNs, we really have no idea.
  6. Since we are unable to know whether we are in MyNs or default we play it safe and assume default.

This obviously becomes a huge issue when there are multiple nested namespaces, because we have no idea of knowing when the exit occurred.

  1. ENTERING_MANAGED_PKG|MyNs
  2. ENTERING_MANAGED_PKG|MyNs2
  3. ENTERING_MANAGED_PKG|MyNs3
  4. SOQL_EXECUTE_BEGIN

Does this seem like you case? Can you review the previous comment and then I can take another looks? If not I will have to close due to no response.

biswajith-s-pso-maxval commented 2 months ago

Hi Luke, You are correct. It's happening since there is no exit for Managed package name space. Let's raise a idea exchange to have this exit event for Managed package. Given the popularity of your application, your team should raise it and we all can upvote it.

On Wed, 5 Jun, 2024, 12:42 am Luke Cotter, @.***> wrote:

@biswajith-s-pso-maxval https://github.com/biswajith-s-pso-maxval Here is an example of some SOQL that will be grouped under the default namespace by that was actually in MyNs image.png (view on web) https://github.com/certinia/debug-log-analyzer/assets/81575432/51cb8799-cb16-4a02-addc-67f5fff369a7 I believe this is what is happening in your case and is not a bug but really due to a lack of information in the logs.

Here is the order

  1. DML occurs on MyObject__c from some unmanaged code
  2. There is a trigger on MyObject__c in the namespace MyNs
  3. DML always switches us to the default namespace since we can have multiple triggers on an object in multiple namespaces
  4. We get a ENTERING_MANAGED_PKG|MyNs event next, because we have a trigger on MyObject__c in the MyNs namespace
  5. We next get the SOQL, BUT since we never get an EXITING_MANAGED_PKG event we might have left the trigger in MyNs, we really have no idea.
  6. Since we are unable to know whether we are in MyNs or default we play it safe and assume default.

This obviously becomes a huge issue when there are multiple nested namespaces, because we have no idea of knowing when the exit occurred.

  1. ENTERING_MANAGED_PKG|MyNs
  2. ENTERING_MANAGED_PKG|MyNs2
  3. ENTERING_MANAGED_PKG|MyNs3
  4. SOQL_EXECUTE_BEGIN

Does this seem like you case? Can you review the previous comment and then I can take another looks? If not I will have to close due to no response.

— Reply to this email directly, view it on GitHub https://github.com/certinia/debug-log-analyzer/issues/508#issuecomment-2148223706, or unsubscribe https://github.com/notifications/unsubscribe-auth/A4X6WKKNPIIC7XYELFV6L7LZFYGQ7AVCNFSM6AAAAABG47HOQWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCNBYGIZDGNZQGY . You are receiving this because you were mentioned.Message ID: @.***>

lcottercertinia commented 2 months ago

@biswajith-s-pso-maxval I have done a full analysis to show the issue in various cases by creating managed packages that call to one another (lc01 -> lc02 -> lc03). A method in lc01 is called from unmanaged and each package has a trigger on Account.

Trigger in a managed pkg This is within the DML_BEGIN + DML_END but we do not get a CODE_UNIT_STARTED to separate the triggers across packages for the same object. So we can not tell where one pkg trigger starts and another ends

Screenshot 2024-06-14 at 14 49 42

nested calls from one pkg to another No pkg_exit so can not tell if control returned to the caller or we have nested calls.

Screenshot 2024-06-14 at 12 29 15

Sequential pkg calls from unmanaged If we call methods directly from unmanaged e can see the method_entry for the global methods.

Screenshot 2024-06-14 at 13 50 01

Here is what the classes in the mock packages look like

global class MyClass {

    global MyClass(){

    }

    global void myMethod(boolean doSoql, boolean doDML, boolean doMethod, boolean callChildPkg){
        if(callChildPkg) {
            new lc02.MyClass().myMethod(doSoql, doDML, doMethod);
        }

        if(doSoql){
            List<Account> accounts = [SELECT id FROM Account LIMIT 200];
        }

        if(doDML){
            insert new Account(Name = 'A1');
        }

        if(doMethod) {
            publicMethod();
        }
    }

    public void publicMethod(){
        Integer count = 0;
    }

}

ns_issues.log

Next actions I will change this issue into a feature and keep it open for a future enhancement and for others who may come across similar issues. But unless Salesforce change the log output there is not much more we can do