Friday, September 8, 2017

Back to the command line - FitDx Apex debug log parser

Love it or loathe it, there are times in a developers day where you are going to find yourself at the command line. I'll leave the GUI vs command line debate to others to sort out.

My general position is they both have their strengths and weaknesses and we as developers should try and use the right tool for the job. Very much like clicks and code with Salesforce. Use them together where possible to get the most done in the least amount of effort.

Tooling shouldn't be a zero sum game.

Debug logs

Salesforce Debug logs have been a pet project area for me for some time now E.g. 2011, 2014, 2017. They form such a fundamental part of the development process but don't get a lot of love. Let me paint you a picture for a typical day in development ...

Earlier in the day something broke badly in production and you’ve only just been provided a raw 2MB text version of the debug log to diagnose the problem from. What do you do?

You can’t use any of the tooling that the Developer Console provides for log inspection on a text file. There is no way of opening it. So there will be no stack tree or execution overview to help you process a file approximately the same size as a 300 page ebook. I say approximately here because there are so many factors that could affect the size in bytes for a book. The general point is that a 2MB text file contains a lot of information that you aren't going to read in a few minutes.

The interactive debugger isn't any help for a production fault and you don't even know the steps to reproduce the problem let alone if the same thing would happen in a sandbox.

You could start combing the log file with a variety of text processing tools, or, or...

It's normally about this point that I'd direct you to the FuseIT SFDC Explorer debug log tooling which gives you:

  • (somewhat retro) GUI tooling for grouping and filtering events by category.
  • Helps highlight important events such as fatal errors and failed validations.
  • And, my current favorite, gives you a timeline view to make more sense of execution time measured in nanoseconds.

But I'm not going to cover any of that in this post. Instead we're going to cover something more experimental than the software that's been in perpetual beta for who knows how many years.

Fit DX

The FuseIT DX CLI, or FitDx in usage, is a proof of concept that I could take the debug log parser from the explorer product mentioned above and apply it directly to debug logs at the command line. I'm just putting it out there to see if there is any interest in such a thing.

You can get it right now as part of the zip download for the FuseIT SFDC Explorer.

There are certainly areas for improvement. First and foremost is the executable size. It's swollen up a fair bit from features that it doesn't expose. I'll look at whipping those out in a future release and should result in a significantly smaller package.

But enough about how big FitDx is. What's more important is how you use it.

Summary Command

If you ask sfdx for a debug log, that's exactly what you'll get. The complete, raw, unabridged debug log dumped to the command line. An experienced command line person would at this stage type out some grep regex wizardry to just show them what they wanted to see. Such is the power of the command line, but it isn't always clear where to start.

I wanted something simpler that would give you a very quick overview of what is in the log.

>sfdx force:apex:log:get -i 07L7000004G0U8kEAF -u DeveloperOrg | fitdx --summary

28.0 : 28.0 APEX_CODE,FINE;APEX_PROFILING,FINEST;CALLOUT,ERROR;DB,FINEST;SYSTEM,FINE;VALIDATION,DEBUG;VISUALFORCE,FINER;WORKFLOW,INFO
CODE_UNIT_FINISHED : 14
CODE_UNIT_STARTED : 14
CONSTRUCTOR_ENTRY : 14
CONSTRUCTOR_EXIT : 14
CUMULATIVE_LIMIT_USAGE : 14
CUMULATIVE_LIMIT_USAGE_END : 14
CUMULATIVE_PROFILING : 4
CUMULATIVE_PROFILING_BEGIN : 1
CUMULATIVE_PROFILING_END : 1
ENTERING_MANAGED_PKG : 184
EXCEPTION_THROWN : 2
EXECUTION_FINISHED : 14
EXECUTION_STARTED : 14
FATAL_ERROR : 4
LIMIT_USAGE_FOR_NS : 14
METHOD_ENTRY : 73
METHOD_EXIT : 73
SYSTEM_CONSTRUCTOR_ENTRY : 33
SYSTEM_CONSTRUCTOR_EXIT : 33
SYSTEM_METHOD_ENTRY : 165
SYSTEM_METHOD_EXIT : 165
TOTAL_EMAIL_RECIPIENTS_QUEUED : 14
USER_INFO : 14

The summary will currently give you a count for the events that are covered in the piped input. In this case I can see that there were 4 FATAL_ERROR events

Filtering

Now that I know I what I'm looking for I want to see it just those events of interest. The --filter command accepts a comma separated list of event types that you want to see. Everything else gets dropped. There is also the --debugOnly option which is a preset to filter for USER_DEBUG only.

>sfdx force:apex:log:get -i 07L7000004G0U8kEAF -u DeveloperOrg | fitdx --filter FATAL_ERROR
28.0 APEX_CODE,FINE;APEX_PROFILING,FINEST;CALLOUT,ERROR;DB,FINEST;SYSTEM,FINE;VALIDATION,DEBUG;VISUALFORCE,FINER;WORKFLOW,INFO
20:25:09.695 (698828931)|FATAL_ERROR|System.AssertException: Assertion Failed: Expected: {"filters":{"footer":{"settings":{"enable":"1","text/plain":"You can haz footers!"}}}}, Actual: {"filters":{"footer":{"settings":{"text/plain":"You can haz footers!","enable":"1"}}}}

Class.DFB.SmtpapiTest.setSetFilters: line 116, column 1
20:25:09.695 (698839161)|FATAL_ERROR|System.AssertException: Assertion Failed: Expected: {"filters":{"footer":{"settings":{"enable":"1","text/plain":"You can haz footers!"}}}}, Actual: {"filters":{"footer":{"settings":{"text/plain":"You can haz footers!","enable":"1"}}}}

Class.DFB.SmtpapiTest.setSetFilters: line 116, column 1
20:25:10.160 (1162726841)|FATAL_ERROR|System.AssertException: Assertion Failed: Expected: {"section":{"set_section_key":"set_section_value","set_section_key_2":"set_section_value_2"}}, Actual: {"section":{"set_section_key_2":"set_section_value_2","set_section_key":"set_section_value"}}

Class.DFB.SmtpapiTest.testAddSection: line 80, column 1
20:25:10.160 (1162743640)|FATAL_ERROR|System.AssertException: Assertion Failed: Expected: {"section":{"set_section_key":"set_section_value","set_section_key_2":"set_section_value_2"}}, Actual: {"section":{"set_section_key_2":"set_section_value_2","set_section_key":"set_section_value"}}

Class.DFB.SmtpapiTest.testAddSection: line 80, column 1

Format Shifting

The final set of alpha features are around changing how the debug log is presented. Options include --json, --csv, and --human. The first two should be fairly self explanatory on what the output will be. The human option was just an idea to use more column like alignment rather than vertical bars (|) to separate the elements.

In hindsight I should probably allow for multiple options at once so you can specify both the required filters and output format in one command. For the time being you can just pipe the filtered output back in.

>sfdx force:apex:log:get -i 07L7000004G0U8kEAF -u DeveloperOrg | fitdx --filter EXCEPTION_THROWN | fitdx --human
28.0                           APEX_CODE,FINE;APEX_PROFILING,FINEST;CALLOUT,ERROR;DB,FINEST;SYSTEM,FINE;VALIDATION,DEBUG;VISUALFORCE,FINER;WORKFLOW,INFO
20:25:09.695    EXCEPTION_THROWN              [116]System.AssertException: Assertion Failed: Expected: {"filters":{"footer":{"settings":{"enable":"1","text/plain":"You can haz footers!"}}}}, Actual: {"filters":{"footer":{"settings":{"text/plain":"You can haz footers!","enable":"1"}}}}
20:25:10.160    EXCEPTION_THROWN               [80]System.AssertException: Assertion Failed: Expected: {"section":{"set_section_key":"set_section_value","set_section_key_2":"set_section_value_2"}}, Actual: {"section":{"set_section_key_2":"set_section_value_2","set_section_key":"set_section_value"}}

The Forward Looking Statements

This is the part where I promise you the world with all the cool things I could potentially do in the future. Things like:

  • Direct integration as a SFDX plugin via a node.js to .NET library
  • Expose other features from the FuseIT SFDC Explorer at the command line, such as the alternative version of WSDL2Apex.
  • I've got a crazy idea for extra things like pulling apex class and trigger definitions directly from a Salesforce StackExchange question or answer and then load them directly into a newly created scratch burner org. The process could then also be reversed with the contents of the scratch org created into the required markdown. This could greatly speed up the process of asking and answering questions on the SFSE.