Wednesday, October 3, 2018

Dreamforce 2018 Roundup / Summary

The recap for this Dreamforce is going to come across as a bit of a photo journal as I go back through my phones timeline to piece back together what I got up to. Somehow, even on my 5th time attending this conference things still went past at a frantic pace.

Table of Contents

  1. Preconference
  2. Day One
    • My Presentation
    • Main Keynote
  3. Day Two
    • The Lightning Platform Roadmap
    • Dreamfest
  4. Day Three
    • Developer Keynote
    • Meet the Developers
    • True to the Core
  5. Day Four
    • Mulesoft
  6. Deployment Fish

Preconference

A visit to the Salesforce Tower for the Tooling Partner meeting. Then a quick visit to the Salesforce Park (the day before it was closed due to structural damage).

Day One

Testing Lightning Flow Automations

  • Usage of Test.loadData() to prep records for testing from a static resource.
  • Starting auto launched flows from a testing context.
  • In Winter'19 - Use the FlowTestCoverage and FlowElementTestCoverage from the Tooling API to get coverage details for flows. See Track Process and Flow Test Coverage

DX Super Session (Video)

New scratch org "snapshots" to use as the starting point for creating additional scratch orgs. The snapshot can be used to pre-configure the scratch org in a known state. E.g. with the dependent packages installed and test data loaded. They are currently using the 0TT Trailforce Template keyprefix. Note that any orgPreferences are additive over what is already present in the snapshot.

spinners

FORCE_SHOW_SPINNER and FORCE_SPINNER_DELAY environment options that can make automating the CLI easier. They prevent the spinner coming back on the standard output.

Naming for unlocked package versions.

My Presentation

I've done a whole separate blog post to cover my talk - Dreamforce 2018 Presentation - Understand your Org shape via visualization of Metadata Component Dependencies.

Main keynote

Demo's of Einstein voice to convert speech, to text, to actions within Salesforce.

Customer 360 - Create a canonical view of the customer across Marketing Cloud, Commerce Cloud, and Service Cloud.

MVP Party

This year it was at the Tonga Room & Hurricane Bar. The band on the boat was 👌.

Day Two

The Lightning Platform Roadmap - Part I and Part II

Day Three

Developer Keynote

Lightning Developer Pro Sandboxes - Spin up faster than a traditional Sandbox. Approx 5 minutes to activate (versus a few hours to even days).

Another example of a named package version.

True to the Core

Lots of coverage of how Salesforce will work towards reinvigorating the idea exchange to handle the current scale. In particular, limiting each users ability to vote of every possible idea. Forcing them to focus on what is most important to them. Salesforce will then commit to working on the highest rated ideas.

Everything that's Awesome with Apex

(Slides)

Roadmap for Spring '19 and Summer '19

  • Exposing the Org Limit details in Apex. E.g. Daily Asysnc Apex executions.
  • Support for creating Scratch Orgs with access to Platform Cache.
  • Support for "rename symbol" refactoring in Apex via the Apex Language Services, and by extension Visual Studio Code. Longer term, this may expand to implementing interfaces and extracting variables.
  • Improved support for enforcing Field Level Security (FLS) and Create,Read,Update,Delete (CRUD) in Apex. Goal is to reduce the amount of processing that was historically required to do this. It's particularly important for those publishing on the App Exchange. https://twitter.com/FishOfPrey/status/1044978778684841984

Quip Party

The August Hall was a great venue. Including a bowling alley and mini arcade downstairs.

Day 4

MuleSoft


Deployment Fish Bottle Openers

To catch up on

See Also

Wednesday, September 26, 2018

Dreamforce 2018 Presentation - Understand your Org shape via visualization of Metadata Component Dependencies

At Dreamforce this year I gave a theater presentation on using the Metadata Component Dependency Pilot API along with Gephi to explore ways of untangling the "Happy Soup" that makes up a Salesforce org.

In this post I'll cover the contents of that talk and expanded on some areas that I'd like to cover in more depth.

Session recording

Why Visualize an Orgs Metadata?

All four sets are identical when examined using simple
summary statistics, but vary considerably when graphed - Source

If you've ever seen the Anscombe's quartet you'd know a compelling reason to visualize information in addition to straight out numerical analysis. Visualizations can reveal patterns and features in the data that otherwise might not be readily apparent.

Additionally, when we start drilling into all the metadata in an org and the relationships within that metadata we can very quickly be overwhelmed by the share volume of it. There can be thousands of metadata items and many more relationships between them.

The Soup and the Polar Bear

The concept of the metadata in your production org existing as a "Happy Soup" was introduced at TrailheadDX 2017 by Wade Wegner. It describes the scenario where all the conceptual apps that make up your production org intermingle without any strongly defined boundaries between them. Essentially, the org becomes one big melting pot of metadata. This has been the status quo for some time now (if you ignore managed packages and the relatively new addition of Packaging 2.0).

Soup chef at work on your production org - a Marvelous Metadata Mixing Pot

Now, take one of the production orgs that I work in day-to-day as an example. It was forged 11 years ago when the seasonal release logo was a polar bear and the API version was v8.0. Ever since then it's been accumulating metadata changes as multiple people have come and gone. Each person leaving a distinct mark on the metadata that makes up that org.

Back to our soup metaphor, that org is a decade old soup. Different soup chefs have been mixing ingredients in via a pinch of declarative UI changes, a dash of changes sets, a smidgen of metadata API deploys, and maybe the odd unmanaged package thrown in for good measure. Over the years an org can seem less like a carefully conceived soup recipe and more like a marvelous concoction with everything thrown in and reacting together in weird and wonderful ways.

Which kind of leaves you wondering - If you were presented with just the resulting happy soup, how would you identify the ingredients that went into it and how they need to interact so you could replicate it again? How can we unmake the happy soup?

The goal of our metadata visualizations will be to use the minds ability to quickly perceive and derive meaning from details such as size, color, position, and proximity to find insights that might not be apparent in tabular data. That might sound complicated, but the objective is to make otherwise complicated relationships readily apparent.

“By visualizing information, we turn it into a landscape that you can explore with your eyes. A sort of information map. And when you’re lost in information, an information map is kind of useful.” - David McCandless

So, we know we want to make visualizations of the metadata and the dependencies within, but where do we start gathering that data?

The Metadata Component Dependency API

Luckily for us the new Metadata Dependencies pilot introduced in Summer '18 at TrailheadDX allows for the use of Tooling API SOQL queries to quickly find dependencies between metadata components. You can signup for the pilot via your AE as per the release notes: Untangle Your Dependencies with MetadataComponentDependency Queries (Pilot)

The benefit of this pilot is that it is much faster and easier than trying to assemble the same information yourself. I've tried extracting similar details via the ApexClassMember.SymbolTable. While possible, it is a path that is thwart with multiple API calls per ApexClass. And at the end of all that you will still only have a fraction of the possible relationships covered.

Once you are in the pilot it is pretty simple to use. A single SOQL query can bring back the majority of relationships for an org. For example, using the Tooling API via the sfdx cli:

sfdx force:data:soql:query --usetoolingapi --query "SELECT MetadataComponentId, MetadataComponentName, MetadataComponentType, RefMetadataComponentId, RefMetadataComponentName, RefMetadataComponentType FROM MetadataComponentDependency Where RefMetadataComponentType = 'CustomField'" -u devorg

Supported Dependencies

As this is a pilot feature the types of dependencies it can reveal isn't 100% yet. Below is a small subset of what can and can't be tracked: (as at the time of posting)

TypeUsed IdSupported
CustomObjectApex Class
CustomObjectProcess Builder
CustomObjectLookup Relationship Field
CustomObjectReports
CustomFieldLayout
CustomFieldReports
FlowProcess Builder
FlowFlow

You can see the complete list of supported metadata relationships in https://github.com/afawcett/dependencies-sample

Augmenting the Graph

Using the results from the Metadata Component Dependency query as a starting point we can then augment the resulting graph with additional metrics. Here are some of the additional details that can be merged in as meta-metadata.

  • CustomField.Metadata - can be used to show lookup relationships
  • ApexClass.ApiVersion - useful for finding Apex classes with mismatched API versions
  • The code coverage results for each Apex class
  • The number of lines of code in each Apex Class
  • Where available, the created date for the Metadata
  • The number of records in a CustomObject
  • The number of Triggers per sObject

Tooling to create the Dependency Graph

The first part of the visualization process will be to query the MetadataComponentDependency records and convert the results into a graph. I didn't go into this step in any detail in my talk as it isn't very interesting to watch. At it's simplest, you can use one of the following options.

CLI Generation of the Gephi graph

NOTE: At the time of publishing the Github repo wasn't fully up to date with the latest public build. I'll aim to have this done shortly after Dreamforce.

Run the following command:

sfdx fitdx:dependencies:report -u DeveloperOrg > DeveloperOrg.gexf

And that's pretty much it. The command from the FitCLI plugin will run the query, build the graph, and export it ready for opening in Gephi. You only need to point it at the correct Salesforce Org and redirect the output into a file.

If you want to add the augmented graph metrics you can supply the -a option. Note that this will take significantly longer to complete as it involves a number of additional tooling API queries. It's also beneficial to run all the Apex Tests before exporting the graph so it has complete coverage details.

GUI option for creating the Gephi file

As an alternative to using the command line you can also using the FuseIT SFDC Explorer from v3.10 onwards. This now includes the Metadata Dependencies tab to generate Gephi file. It's pretty much exactly the same as the command line version and will prompt for where you want to save the resulting file.

Ideally with either the CLI or the GUI options the target org will have access to MetadataComponentDependency records. If that isn't the case you can still use the augmented option to get some graph details. It won't be as fast or as complete, but you will get a good deal of the relationships based on other data exposed via the Tooling API.

Examples

Now we can get into the interesting part of loading the graphs into Gephi to see what we can discover. You can open the .gexf files directly into Gephi and then start manipulating them.

This video quickly goes through the Field Usage and Packages examples that are expanded on below.

Field Usage

Lets say we want to find what will be impacted if changes are made to the Property__c.Address__c field in the Dreamhouse app. The steps would be as follows:

  1. Partition the Node color by Type. This will make it more apparent what type of nodes you are looking at.
  2. Size the nodes based on the Betweenness Centrality. Which is a fancy way of saying "make the nodes that appear on the shortest paths between other nodes bigger". This is one possible indication of how important a node is to all the other nodes in the graph. Before we can do this we need to run the Network Diameter statistics.
  3. Apply a layout to arrange the nodes. I've used the "Force Atlas" layout with the Repulsion strength set to 1500 and Adjust by Sizes checked.
  4. Show the Node Labels and scale to fit
  5. Switch to the Data Table window and filter to the Address field.
  6. Zoom out a bit, and you will be able to see the the Metadata that references the Property__c.Address__c field.

Potential Packages

  1. Run the "Modularity" Statistics. This algorithm will look for metadata communities based on the dependencies between them. You can adjust the Resolution up or down if you want more or less communities.
  2. Change the appearance of the Nodes to be partitioned by the resulting "Modularity Class". With the correct resolution and layout it will given you a reasonable guide to where potential packages are located. You will likely need to make some finer adjustments along the boundaries.
  3. One way to export the nodes for the package is to select them and then copy to a new workspace. The new data table can then be exported as a csv.

API Versions

  1. Filter to just those bits of metadata that have an API version defined. One way to do this is to drag a "Non-null (ApiVersion)" filter down onto the Queries.
  2. Under Appearance > Nodes, set the node size to rank by Degree. The degree is a measure of how many edges go in or out of the node. So more connected nodes will be larger.
  3. Set the Nodes color to be ranked by API version. Choose a color pallete that emphasizes lower API versions as being problematic.
  4. Set the Node Label to "API Version" and size as required.

Code Coverage

  1. Size the nodes by "LengthWithoutComments" to give an indication of how much code is in each Apex class.
  2. Color the nodes by ranking of the "PercentCovered". Use the slider to roughly indicate code with 75% coverage.
  3. It can be useful to filter to just the test classes and assign them a different node color. They won't have any coverage themselves.
  4. Set the node label to the "PercentCovered"
  5. A circular layout sorted by the coverage percent can be useful to separate out the problem nodes. Move the text classes into a seperate ring so you can see the relationships between the tests and the classes they cover.

Classes with excessive lines of code

As an experiment I drastically increased the amount of node scaling that was possible. This can really emphasis the differences in the size of Apex classes.

Friday, August 24, 2018

Dreamforce 2018 Session picks

Here are some of my current picks for Dreamforce 2018 sessions. I'm aiming for a mix of developer related topics in areas I want to learn more about plus anything that sounds informative. It isn't an exhaustive list and there are certainly some other session that I'll be adding.

Most important session that I'm definitely going to attend

I might be biased, but this session is on my must attend list.

Tell your friends, tell your neighbors, tell your family, bring your mum along. There will be something for everyone!
Who doesn't like pretty pictures, metadata, and a sprinkling of graph theory?

Keynotes

Meet The *'s

Apex

  • Everything that's Awesome with Apex
    Get a sneak peak into Apex plans, roadmap and how we are making secure development easier. We'll share some of our newest concepts (async Apex anyone?) and get your feedback on hot IdeaExchange features.
    👀Async Apex, maybe something to help with FLS and CRUD in managed packages. Yes please!
  • Test Your Visual Workflow and Process Builder Automations. I'm assuming there will be some Apex involved in this testing process.

APIs

Salesforce DX

IDE

Platform Events

Platform

Einstein / AI

Security

Fun

  • Flood the Trailblazer Community Cove: Swag & Sticker Meetup
    Got too much swag or something you can't get home - swap it! Last year I gave a bunch of stuff away that I'd collected but couldn't actually put in my luggage. I'm looking at you oversized Codey. And the rose seed in soil that NZ customs would have opinions on.

Lightning

  • TODO - Need something to fill out this area to be a well rounded developer. Lightning Roadmap maybe?

See also

Monday, July 23, 2018

FuseIT SFDC Explorer 3.9.18190.1 - Summer '18

Another roundup of some of the changes to the FuseIT SFDC Explorer since the 3.7.17230.1 release.

Display additional columns for the Apex Log timeline (Experimental)

Let's say you just ran all the tests in your org in parallel and captured the debug logs for each transaction. Now you have a huge number of debug logs to peruse, but where to start?

Experimental features that I've only tried a few times to the rescue!

By double clicking in the Timeline column cells the full debug log will be pulled down and converted to a timeline. I'm still experimenting with this. Certainly having all the timelines shown at different scales is a bit problematic. It's hard to get a sense of how long the actual transaction took relative to the adjacent ones.

I might instead take a different approach here and extract some metadata from the debug log and just show the core details. I'd look for things like hitting limits, throwing exceptions, slow DML, etc...

Button to delete ALL ApexLog's in an org.

It's a small thing, but currently with Summer '18 it is all to easy to run into a message like:

The Developer Console didn't set the DEVELOPER_LOG trace flag on your user. Having an active trace flag triggers debug logging. You have 318 MB of the maximum 250 MB of debug logs. Before you can edit trace flags, delete some debug logs.

Then you get to play a game of whack-a-moleApexLog with the Tooling API to clear them all out and then get on with your day. This button on the Apex Logs tab reduces it to a single click.

You might also like to vote for the idea: Allow TraceFlags to indicate that Debug logs can be deleted automatically. Adding a TTL and automatic purge of older logs would avoid most of these issues while still being flexible if you needed longer term logging.

Show total counts per log category

The percentage that each log category contributes to the overall log size has been added to the footer. This can be useful for adjusting the log levels when the logs are getting too noisy or large.

Skip Code Coverage

With Summer '18 it is possible to opt out of collecting code coverage with a test run. This can save some time when running the test cases if you don't require the coverage data.

Additional metadata deployment details

When selecting individual metadata files to deploy details such as path, local file system data modified, and CRC are displayed.

Other changes 3.9

  • ApexLogContentControl - Format "SkippedBytesOfDetailedLog". Shortcut to line. Protected against parsing multiple log models at the same time.
  • Expose the Duration in the ApexLogTreeViewUserControl. Color code the Event column
  • ApexLogEntry - Prevent recursion in the model. New properties for Text, Message. Dedicated LimitUsageForNsApexLogEntry ApexLogEntry
  • Option to display timeline bookmarks over thumbs. Detect and highlight LimitUsage warnings and highlight in timeline. Display log running events (> 500ms) as lines in the timeline.
  • Make CSV field name checking case insensitive.
  • When searching for a term in a debug log, ensure that line scrolls into view.
  • When listing Apex classes include an "Uncovered Lines" column
  • Emphasize the Warning and Error entries with larger bars
  • ApexLogModel: Handle CODE_UNIT_STARTED for Validation. Reparent when transitioning from CUMULATIVE_LIMIT_USAGE_END to CODE_UNIT_STARTED without intermediate CODE_UNIT_FINISHED
  • PackageCreation - Include additional metadata when performing a HashDiff on a folder.
  • WSDL2Apex: Skip Complex Content Restrictions (with a warning) rather than throw an exception.
  • WSDL2Apex: Reset stored web service metadata between runs.
  • ApexLogService - Expand LogMessage enum with missing records
  • Update SalesforceSession to use Summer '18 v43.0 API version
  • T4 Code Generator - Allow for sObjects with no record types defined
  • SalesforceSession - Support for visualforce.com as a SOAP Partner URL
  • SalesforceServiceWrapper - Improve performance of ObjectTypeFromId(string id) for looking up the sObject type based on the keyprefix. EntityServiceGenerator.tt - Don't include a custom objects keyPrefix in RegisterKeyPrefixObjectType by default.
  • Include dedicated columns when listing Apex classes for Lines covered and Total lines
  • ApexClassService - Handling missing SOSL search results when looking for test classes.
  • MetadataServiceWrapper - include support for deployment of permissionsets
  • SalesforceException - Log direct web request with cookie exceptions.
  • Wsdl2Apex - handle services that require specific casing on the service URL query string
  • ToolingServiceWrapper - Check for API access to sObjects ApexOrgWideCoverage and ApexCodeCoverageAggregate before querying.

Other changes 3.8

  • Data Export Console: Support for connection strings using RefreshTokens rather than usernames and passwords.
  • Options to metadata deploy Aura components
  • Apex Test Results - Expand nodes to show test case failures initially.
  • UI - Improve menu overflow options
  • UI - Track selected log event as the DataGrid scrolls
  • Data Export Console - Improvements to parameter validation. Especially cases where the wrong number of parameters are provided.
  • Option to collapse/expand the log selection with the log viewer.
  • MetadataServiceWrapper: deploy aura components in packages.

Other changes 3.7.17251.2

  • FitDx: --filter option for user defined events. --summary option for count by event type.
  • Add optional allowExistingSObjectsWithoutId="true" to the binding configuration element to allow sObjects to be created with a null Id. Typically this isn't allowed as the ID is used to control insert/update operations and to identify relationship types. This setting can be used for more basic SOQL queries where the results won't be subsequently used for DML.

Wednesday, June 27, 2018

Speeding up Salesforce unit testing performance

For many years I've had this thorn in my side with Apex test cases. It goes by the name of "Disable Parallel Apex Testing" and since Spring `13 (v27.0) it has needed to be enabled constantly else I'd get a UNABLE_TO_LOCK_ROW error due to the custom hierarchy settings that get updated in the test cases.

Leap forward to Summer/Winter `18 (v42.0/v43.0) and I'm still tangling with this. That's five years of waiting for all the test classes to run sequentially one after another. That's about the right amount of procrastination to finally fix this problem! So hold on, were going to raise a support case and keep at this until the bitter end1.

What follows is a true story. The namespaces and class names have been changed to protect the innocent, but the snippets of messages with support are real.

Step 1 - Turning off "Disable Parallel Apex Testing"

This was simple enough. Uncheck a checkbox, run all the tests, and... Uh oh.

Could not run tests on class 01p400000000001 because: connection was cancelled here

With that setting checked all my tests were passing. Now some of my previously passing test classes are falling over when run in parallel. Worse still, the specific test classes to fail were intermittent. It wasn't just one specific class causing a problem. Any one of a dozen or so classes could fail in this manner and they would change from run to run.

Step 2 - Winter `18 @isTest isParallel annotation to the rescue

Winter 18 added the new @isTest(isParallel=true) annotation to:

indicate test classes that can run in parallel and aren’t restricted by the default limits on the number of concurrent tests.

That's great, except I don't want to modify 90% of my test classes to deal with the 10% that are having issues. No, I'll just use @isTest(isParallel=false) and explicitly exclude the problem cases... except that doesn't work. At least not at the time of writing. Please vote for the idea Parallel Tests Option (isParallel) on the @IsTest Annotation to exclude tests to make this a viable approach.

Step 3 - Once more unto the support case, dear friends, once more

[Day 1 - 2018-05-09] Desperate times. Let's raise a support case to see if they can isolate the underlying issue.

[Day 6 - 2018-05-14] After a bit of back and forth with tier 2 to establish how to reproduce the problem (press the run all test cases in the org) the initial advice back was:

The root cause of this issue?
Answer: - Parallel test execution is the root cause of this issue.

Solution?
Answer: - Disable Parallel test execution.

Question: - Why do you need to Disable Parallel Apex Testing?
Answer: - As per the salesforce document, Tests that are started from the Salesforce user interface (including the Developer Console) run in parallel. Parallel test execution can speed up test run time. Sometimes, parallel test execution results in data contention issues, and you can turn off parallel execution in those cases.

Huh. Well, yes I knew that already (as per the case description when I raised it). That would work, but it's been five years of this situation, so lets push a bit harder. SHIBBOLEET!

Step 4 - How bad is the problem empirically?

Before responding with a kiwi yeah-nah to support I timed the total test run time for both parallel and synchronous test execution:

As it stood, the parallel test execution was marginally faster as long as I reran any initially failed test cases immediately after the first run completed. That was an interesting result, and I think I can explain the similar timing between the two later on.

The general consensus on twitter was that updates to custom hierarchy settings were probably to blame for the contention and subsequent timeouts.

Step 5 - Isolating Custom Hierarchy Settings using the Stubbing API

I use a number of hierarchy custom settings to toggle various functions in the app. All interactions with those settings from Apex are done via a single class. This allows for sensible defaults etc...

Those with particular feelings on how mock testing should be performed or a sensitive testing disposition may want to look away now...

To prevent any potentially blocking DML operations on the custom hierarchy settings I've injected a StubProvider when in a testing context. The StubProvider prevents any DML occuring when altering the settings in Apex tests. This isn't the typical usage for a test mocking framework, but it serves my needs here to help avoid database locking issues.

Here is a shortened version of how it looks:

And after all that the result on the asynchronous test execution was..... not much really. The tests were marginally faster, but the underlying problem with the test classes having the connection closed remains. At least I can rule out DML on the custom settings as being the problem.

Step 6 - Back to the drawing board

Blaming the problem on the custom hierarchy settings made sense from a historical perspective, but it doesn't appear to be the source of my challenges.

I went back and had a closer look at the debug logs from the tests in the run. That's when I saw it:

"What?", you may ask, "Am I currently looking at?"

That colorful image is a selection of debug log timelines from various parallel test runs. Ignoring the majority of the markings, the important thing is a purple line representing a DML operation that is taking more and more of each transaction. Right up until the point that Salesforce starts terminating it. If we drill into one of those logs we can see it is a DML operation to insert 6 records taking 3 minutes 52 seconds (for 6 records!):

14:14:15.0 (325578801)|DML_BEGIN|[992]|Op:Insert|Type:DFB__OpportunityPriceType__c|Rows:6
14:18:07.376 (232376043557)|DML_END|[992]

Step 7 - Returning to the support case with proof

[Day 9 - 2018-05-17] If that isn't a smoking gun then I don't know what is. Let's take this new evidence back to the support case.

Me to support:

I've just noticed something else odd in the debug logs for the running tests. Inserts to DFB__OpportunityPriceType__c for 6 rows are taking an excessive amount of time.

I'm seeing times for the CommonTestSetup.createPriceTypeMappings() method of between 20 and 45 seconds to complete.
Attached Log1.txt - Look for the lines:
16:18:58.0 (150146460)|DML_BEGIN|[941]|Op:Insert|Type:DFB__OpportunityPriceType__c|Rows:6
16:19:19.214 (21214892238)|DML_END|[941]

It isn't clear to me why the inserts for those records are taking so long. The fields on it are [reasonably] basic and it is only 6 rows.
The only thing I can think of is that all the test classes are trying to use the same records and they all have the same indexed values in the PriceTypeID__c field.

A bit more context as you dear reader can't see into the org like support can.

I have a custom object DFB__OpportunityPriceType__c with a unique external id field. That field is indexed. Just about every single test class I have requires data in this custom object as it contains configuration that gets linked to from Opportunity records. I thought I was being clever and used a @TestSetup method to insert 6 of these records once for all the other test methods to use. There are no triggers, workflow outbound messages or other automatons hanging off this custom object. None of the test classes use SeeAllData=true.

Step 8 - More steps in the Support dance

[Day 13 - 2018-05-21] Support responds:

I reviewed your case and ran the test classes to troubleshoot the issue further. I noticed the error in the server log "RunningForTooLongException: connection was canceled here".
The error is thrown because - for asynchronous Apex tests, any test method execution has a timeout limit. Once an Apex test run exceeds 6 minutes, an internal process "kills" it.

After reviewing the logs, it seems that this particular method is taking time to execute when all the tests classes are run asynchronously - CommonTestSetup.minimalSetupWithSettings();

Can you please try to refactor this method and see if it can be optimized?
I see there are many methods being called from this function.

Another frustrating response. They pointed out the method that gets called directly in the @testSetup method. I'd already identified the inner method from that one and even the line in question. That it is a RunningForTooLongException is new information, but I'm no closer to what is blocking those records from inserting.

[Day 15 - 2018-05-23] We try a GoToMeeting. I work through with Tier 2 support in ensuring the external ID's that get assigned to DFB__OpportunityPriceType__c records in the test cases are unique per @testSetup. It didn't seem to help. Beyond that, I think support has a good grasp of the problem now.

[Day 20 - 2018-05-28] The support case has been escalated to Tier 3.

[Day 30 - 2018-06-07] Tier 3 responds:

- When 'Disable Parallel Apex Testing' checkbox is checked in Developer Console.
Result: Running Perfect

- When 'Disable Parallel Apex Testing' checkbox is unchecked in Developer Console.
Result: Exception is thrown

- In Serial Mode, it's working perfectly because it's running in Sync mode and no data contention issue.
However, in Parallel mode, multiple classes and trigger have been invoked in the same context/transaction where performing DML Operation and also making callouts and waiting for a response in Async mode. This may cause some data contention. Also since there is a lot of custom code involved it becomes very difficult for us to analyze the scenario.

- This is WAD as per Salesforce documentation. If Apex Class will take more than 6 minutes of time to complete the transaction, the connection will be closed by Salesforce DB.

- Test classes are run in serial mode during deployment. This error will not occur when you are trying to deploy your package.

Possible workarounds -

- Try to modify the code and remove that many dependencies.
- Else run in Serial Mode as a Workaround.

This seems distinctly like they put it in the too hard basket and are trying to avoid investigating the actual issue. I'll push back to see if I can get a better answer.

Also, I'm not sure what they mean by "making callouts and waiting for a response in Async mode". This is all happening in a test context. There are no callouts or waiting for async responses. I'm not going to pursue that as I don't want to get distracted.

[Day 35 - 2018-06-12] Update from support.

My T3 has officially logged an investigation with our RnD team on this issue. My RnD team is currently reviewing the case.

[Day 36 - 2018-06-13] An update from R&D, as communicated via Tier 2.

I have received an update from the DB team on this case.

As per the DB team, it seems that the parallel sessions are working on common recordsets and causing the wait events.
Because of this waitime the DB team is high and eventually the classes are getting timed out.

May be this explains why the insertion to DFB__OpportunityPriceType__c is taking time. We cannot exactly comment on the common recordsets but DFB__OpportunityPriceType__c records is one of the potential candidate.

Solution -
Have the parallel sessions work on different recordset/dependencies to avoid this situation.

So it appears that all the test cases are trying to work with the same record sets and they are all blocking until they can get exclusive access to those records. They either stack up and run one after another or wait so long they time out. This explains why the parallel test performance is so similar to the serial performance.

I'm fairly certain the DFB__OpportunityPriceType__c records are unique between @testSteup executions, so it must be something else...

Step 9 - Time to regroup

[Day 42 - 2018-06-19] Much to my shame I've closed the case out. I need time to regroup and revisit this from a new approach. I'm certainly not giving up on it yet and have a few ideas to try:

  • Try adjusting the Logging levels used when capturing the logs. Particularly around the Database logging levels. Also try capturing no logs at all.
  • Push the entire packages metadata into a Scratch Org and and retry the tests. The dev org doesn't have much data loaded, but the scratch org can provide a completely empty environment to ensure it isn't a data siloing issue.
  • If it is reproducable in the scratch org, start hacking parts out until it becomes easier to reproduce.
  • Remove the creation of the DFB__OpportunityPriceType__c records from the @testSetup. Only create them when required in the individual test methods.
  • Simplify the test cases where possible. The challenge is almost all of them work with Opportunities and OpportunityLineItems at some level. Which means a large overhead to construct all the dependent records as well.

Footnotes

  1. The bitter end may or may not occur within the timeframe of this blog post.

Wednesday, May 16, 2018

Fiddling with the SFDX CLI API calls

What makes the sfdx CLI tick? Sometimes learning how something works can be as much fun as actually using it.

The goal here is to capture the raw API calls the sfdx CLI is sending to the Salesforce APIs. In addition to a better understanding of what it is doing you can use it to debug the CLI itself.

This post was inspired by a, ahem, very similar post by Christian Carter - SFDX With Charles Proxy. The primary difference is that I'm using Fiddler on Windows rather than Charles Proxy on macOS.

Using the direct sfdx logging support is another option to monitor what is going on. Or even browsing the source directly under %LOCALAPPDATA%\sfdx (seems they are going to some lengths to hide the source now). While something like fiddler is more complicated (some might even say "fiddly") to configure, it is harder to hide anything from it (intentionally or otherwise).

Configure to intercept HTTPS traffic

After installation the first this is to configure Fiddler and Windows to allow interception and decryption of HTTPS traffic.

  1. Tools > Options
  2. HTTPS tab
  3. Check Decrypt HTTPS traffic
  4. Click 'Yes' to reconfigure Windows' Trusted CA Certificate You might want to read up on what a Root Certificate is before doing so.
  5. (Optional) change the drop down from "... from all processes" to "... from non-browsers only"
  6. (Optional) Toggle the "Skip decryption for the following hosts" to "Perform decryption for the following hosts". Then add *.salesforce.com

Now the Fiddler is ready to intercept the traffic you need to configure sfdx to send it to the correct location. The default proxy port of 8888 is configured under Options > Connections > Fiddler listens on port:...

set http_proxy=http://localhost:8888
set https_proxy=https://localhost:8888

If you just stop there and try and call sfdx force:org:list you will find the CONNECTED STATUS comes back as "ECONNRESET". It would appear that node.js doesn't like our self signed root certificate. You can tell node to mind its own business with:

set NODE_TLS_REJECT_UNAUTHORIZED=0

Again, you only want to do this for a single session and not configure that across all processes. It potentially opens you up to all sorts of man in the middle security attacks.

Now what?

Now my friend, now we can see each and every callout to the Salesforce APIs and the corresponding responses.

Lets look at what happens with the command sfdx force:org:list.

This reveals up to four API calls per valid Org. The exact calls will depend on the org types and if you have recently successfully authenticated to them. Generally, you get:

  1. A failed GET /services/data/v42.0 with an invalid token
  2. A POST /services/oauth2/token to refresh the access token
  3. A successful GET /services/data/v42.0
  4. A GET /services/data/v42.0/query?q=... with a SOQL query over ScratchOrgInfo. Presumably this only works with Scratch Orgs at this time.

So every org you register with SFDX needs 3 or 4 API calls with a force:org:list. There is certainly something to be said for dropping unused orgs.

Anyway... Happy Fiddling!

Wednesday, May 9, 2018

Salesforce Log Categories and Events by Level - Revisited

Way back in June 2014 I posted a table to logging events by level and category - Salesforce Log Categories and Events by Level.

I was never really happy with the table layout trying to squeeze that much data in. Also, new logging levels keep getting added and several have been shuffled around recently with respect to the level they occur at.

Here is a hopefully simpler revised attempt using lists. It is compiled directly from the Debug Log Levels detail page, so it should be eaiser to keep up to date.

Similar data can be found in the Debug Log Levels documentation. I found at the time of publishing that I had several in my list that didn't appear on that page, such as CALLOUT_REQUEST_PREPARE, USER_DEBUG_WARN, and DUPLICATE_DETECTION_MATCH_INVOCATION_DETAILS.

The levels are cumulative. So everything that appears at the ERROR level will appear at all the lower levels as well. Everything at the WARN level will appear at INFO, DEBUG, FINE, ... and so on.