Unable to retrieve metadata from sandboxes

[Sara Schmidt]

When pulling metadata from my sandboxes using Illuminated Cloud 2 in IntelliJ, I am only able to pull from some sandboxes, not my developer sandboxes. The experience is that the metadata retrieval just spins indefinitely and does not retrieve or deploy anything. I am able to pull via CLI, but not IntelliJ/IC.

[Scott Wells]

Hi. Please enable debug logging for Metadata Retrieval and Salesforce DX, reproduce the behavior, and attach the resulting idea.log file. My guess is that it's just server-side queueing as all that IC2 does is create a retrieve API request, post it to the server, and poll for completion. Queueing gets signficantly worse during the seasonal release preview period, especially in sandbox orgs because they're the first to receive preview code. A log would show whether that's the case or not, though.

[René Görgens]

For info, I’m also seeing abysmally long-running Metadata API operations today (retrieve, compare with server, etc.). This is why I’m here and checking if other people experience such issues :)

For example,

• 3 m 50 s 324 ms to perform a Compare with Server operation on 6 customMetadata
• 11 m 30 s 371 ms to perform a Compare with Server operation on 23 flexipages

‌

[René Görgens]

Scott it is, as you say, the polling.

• I repeated the first operation mentioned above after enabling debug logging for Metadata Retrieval and Salesforce DX, and the simple operation needed 49 polling intervals of increasing length.

2024-01-23 18:19:53,389 [3248706] FINE - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Retrieving metadata for module […]

[…]

2024-01-23 18:22:28,473 [3403790] FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - C:/Program Files/sf/bin/sf.cmd force:source:retrieve -u rene.goergens@[…].net.dbrdev -x C:/Users/[…]/AppData/Local/JetBrains/IntelliJIdea2023.3/tmp/[…]-retrieve63/tmp/manifest/[…]-package.xml --json: Using polling interval 5000 ms for polling iteration 49.

[…]

2024-01-23 18:22:33,477 [3408794] INFO - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Retrieve completed in 2 m 40 s 52 ms.

[Scott Wells]

Yeah, that’s what I’d expect to see. Like I said, IC2 doesn’t really do anything locally for these batch retrieval and deployment jobs other than submit and poll…with one notable exception. When files are retrieved, it does organize them locally to mimic the local project structure so that things are properly aligned, and there was a bug in the past where that could be quite time-consuming for very large sets of retrieved files, but that should be resolved. And that would be clearly reflected in the logs vs. what you’re showing which is just IC2 polling for completion, whether that’s polling the API for a terminal job state or for the CLI to exit.

Assuming that’s the case for both René and Sara, it would be best to log a support case with Salesforce. The one thing that’s curious about Sara’s original description is that she said retrieval via the CLI doesn’t take as long. I would like to see the CLI command execution alongside the IC2 debug log so I can see what’s different. Sometimes the difference can be in how the retrieval request is formulated; sometimes it’s just a matter of being lucky/unlucky with the job queues when the respective request is submitted. I’d need to see more details to know such a difference exists.

[René Görgens]

I understand this is not a new phenomenon, it’s just that I haven’t experienced it in the past. Not sure that I understand the explanation for queueing to become so slow. Do you mean that during seasonal release preview, sandbox instances get overloaded with Metadata API requests due to increased developer activity? If so, how does Salesforce tolerate this impact, even if only a temporary peak issue?

[Scott Wells]

That’s really a question for Salesforce honestly. There’s just a very consistent pattern of long queueing during the pre-release period, so it’s not a surprise to see right now only weeks before the final release of Spring ‘24. I’d also already seen folks saying as much on various forums over the past few weeks. Once it has been clearly identified as jobs spending excess time in queue, the best thing to do is to raise a case with Salesforce with your org ID, instance name, and ideally a few specific job IDs so they can see what might be (or have been) happening in their own logs.

[Sara Schmidt]

It looks like the issue is happening in the CLI now, too. It’s not consistently working or failing. This is the only log I can seem to generate from the CLI in IntelliJ

2024-01-23 13:01:22,789 [93061805]   INFO - #c.i.w.i.i.j.s.JpsGlobalModelSynchronizerImpl - Saving global entities to files

Here is my log from the Illuminated Cloud retrieve command (i tried to take out any identifying info)

2024-01-23 12:10:20,022 [89999038]   FINE - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Retrieving metadata for module [my repo]
2024-01-23 12:10:20,035 [89999051]   INFO - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Using the Salesforce CLI to retrieve metadata for project '[my repo]' from connection 'sschmidt3'.
2024-01-23 12:10:20,035 [89999051]   FINE - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Attempting to create a temporary package.xml file for selective retrieval or missing package.xml file.
2024-01-23 12:10:20,103 [89999119]   FINE - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataUtil - Created temporary package.xml file for selective deployment/retrieval:
<?xml version="1.0" encoding="UTF-8"?>
<Package xmlns="http://soap.sforce.com/2006/04/metadata">
    <types>
        <members>[MyClassName]</members>
        <name>ApexClass</name>
    </types>
    <version>58.0</version>
</Package>
2024-01-23 12:10:20,103 [89999119]   FINE - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Created temporary package.xml file '/Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml'.
2024-01-23 12:10:20,103 [89999119]   FINE - #com.illuminatedcloud.util.CommandLineUtil - Running command line: '/usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json' from working directory: '/Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp'.
2024-01-23 12:10:20,116 [89999132]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 1.
2024-01-23 12:10:21,121 [90000137]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 2.
2024-01-23 12:10:22,127 [90001143]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 3.
2024-01-23 12:10:23,131 [90002147]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 4.
2024-01-23 12:10:24,136 [90003152]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 5.
2024-01-23 12:10:24,737 [90003753]   INFO - #c.i.w.i.i.j.s.JpsGlobalModelSynchronizerImpl - Saving global entities to files
2024-01-23 12:10:25,140 [90004156]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u s[my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 6.

‌

[Scott Wells]

Thanks, Sara. Yeah, that makes more sense. I think when it worked quickly from the CLI before, you were just getting lucky with a temporary short queue. The same thing could very well have happened from IC2, especially since IC2 is just executing the CLI to perform the retrieval anyway.

If you continue to see this and it’s affecting your productivity (and I assume it likely is), I’d recommend getting a support case going with Salesforce. They’ll want the org ID and instance name at a minimum. You might also include the approximate times of the submitted retrieval requests that ran long so they can find them in their own logs.

[René Görgens]

Thank you Scott, I’ll raise a case with Salesforce. Just had to switch to an org where I have prod access.

I checked IntelliJ + IC2 + SF vs SF:

(1) Retrieved 11 flexipages via IC2:

2024-01-23 19:03:23,860 [5859177] INFO - #com.illuminatedcloud.intellij.builder.ForceComSfdxMetadataRetriever - Retrieve completed in 4 m 15 s 70 ms.

(2) Retrieved the same package.xml via SF:

Did not stop the exact time but it also took 3-4 mins

[Scott Wells]

Thanks. To be 100% clear, if the IC2 project is stored in source format (i.e., has an sfdx-project.json file in the project root directory), IC2 is using the CLI for all metadata retrievals. That's why both of your provided logs show entries like the following:

René

2024-01-23 18:22:28,473 [3403790] FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - C:/Program Files/sf/bin/sf.cmd force:source:retrieve -u rene.goergens@[…].net.dbrdev -x C:/Users/[…]/AppData/Local/JetBrains/IntelliJIdea2023.3/tmp/[…]-retrieve63/tmp/manifest/[…]-package.xml --json: Using polling interval 5000 ms for polling iteration 49.

Sara

2024-01-23 12:10:20,103 [89999119]   FINE - #com.illuminatedcloud.util.CommandLineUtil - Running command line: '/usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json' from working directory: '/Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp'.
2024-01-23 12:10:20,116 [89999132]   FINE - #com.illuminatedcloud.util.VariableLengthPollingInterval - /usr/local/bin/sfdx force:source:retrieve -u [my sandbox] -x /Users/[myfolder]/Library/Caches/JetBrains/IntelliJIdea2023.3/tmp/[my repo]-sschmidt3-retrieve1/tmp/manifest/[my repo]-sschmidt3-package.xml --json: Using polling interval 1000 ms for polling iteration 1.

There should therefore be no material difference between retrievals performed by IC2 and those performed by the CLI as they are both actually performed by the CLI. Any differences in timing would be due to Salesforce job queue behavior and not client tooling.

That doesn’t hold 100% true for deployments, though, as even in (non-source-tracked) source format projects, IC2 will try to use the API directly for deployments when it can, specifically for those that benefit from deployment via the (typically faster) Tooling API and when the on-disk file contents are identical between metadata format and source format. Again, I would expect IC2 to be no slower than the CLI in those situations because the CLI is ultimately using the same public APIs and has the overhead of external process execution. But for metadata retrieval specifically, it’s ultimately the same CLI command execution from IC2.

[René Görgens]

For the record, I’m seeing this issue on the SWE28S instance (two different MyDomains)

• Retrieve completed in 4 m 15 s 70 ms.
• 68 polling iterations

On the SWE44S instance, time for 11 flexipages:

• Retrieve completed in 1 m 0 s 141 ms.
• 29 polling iterations
• Better but still excessive

‌

[René Görgens]

Thank you Scott for the clarification.

Yes, I actually took the CLI command from the IntelliJ log and executed it in the shell (operating on a manually created folder of course), so no wonder the results are identical

[René Görgens]

As mentioned above, I had opened a case with SF.

• Support took the issue up with R&D, apparently in consequence the number of threads was increased to make the API more reactive (I did not observe this result as I was on holiday)
• After the release earlier this week, API perf was back to normal thus case closed
• I had asked to show the API performance degradation on the instance in status.salesforce.com but they didn’t do that

‌

[Scott Wells]

Resolving since this was directly attributable to server-side queueing in Salesforce that has hopefully lessened with the completion of the Spring '24 release.

[Scott Wells]

Removing component: IntelliJ IDEA (automated comment)