Webstorm Freezing when refreshing metadata

[Justin Julicher]

In the retrieval dialog box it is freezing trying to populate the contents.

It’s happened a few times and I’m not getting much information out of the logs.

I’ll have to revert to using the sfdx command line for the time being.

‌

[Scott Wells]

Ugh...and I know this is likely all on the latest builds. Do you mind attaching/emailing any thread dumps so I can see if there's a deadlock of some form?

[Justin Julicher]

I’ve attached the logs. Seems to do it everytime I hit the little refresh button in the top left corner. Probably related to something specific about the org.

‌

I’ll try adding back the original refresh always thing to see if it fixes it.

‌

[Scott Wells]

Justin, can you install this build and see whether it resolves the issue for you or not? Please let me know either way. Thanks!

[Justin Julicher]

Looks like that solved it thanks! Was it some sort of locking/contention issue?

[Scott Wells]

Okay, good. Yeah, your provided thread dump was invaluable. What confuses me is why I've never seen it, and why I'm not hearing about it from every single user. Long story short, it has to do with some of the crazy threading states you can get into with a combination of the Swing event thread (EDT) and background threads displaying progress indicators. I just moved a critical section so that it's always guaranteed to run on the EDT before the progress indicator is displayed--it's not a time-consuming operation so it can happen beforehand--and that removed the potential deadlock.

Go ahead and sit on that build for now. I've already included that change in the branch for the next build which I plan to get out Thursday morning this week. Then you'll be good to update safely. Thanks again for providing the diagnostic info.

[Justin Julicher]

that’s ok.

‌

Look I had a DNS issue when I was running this - and so I wanted to cancel the request except when I clicked cancel it just hung but didn’t freeze - and I had to kill webstorm to resolve it. Any idea why that is? Do I have to wait longer? I would think a cancel should be almost immediate.

‌

thanks

[Justin Julicher]

arghh… so webstorm isn’t freezing but the process isn’t completing.

The process has stopped logging for the last 4 minutes now and just out put this:

2020-06-30 09:08:24,911 [ 338119]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,911 [ 338119]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,911 [ 338119]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,911 [ 338119]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,912 [ 338120]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,915 [ 338123]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,915 [ 338123]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,917 [ 338125]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,917 [ 338125]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,918 [ 338126]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,918 [ 338126]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,920 [ 338128]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,920 [ 338128]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 
2020-06-30 09:08:24,922 [ 338130]   INFO - cloud.client.ForceComApiClient - Logging into Salesforce DX as [e-mail]. 
2020-06-30 09:08:24,922 [ 338130]   INFO - cloud.client.ForceComApiClient - Retrieving org details from Salesforce CLI. 

‌

The last timestamp is now 5 minutes ago. Doesn’t seem like it’s going to finish the process now - and there is no thread dump.

‌

[Scott Wells]

Those are probably secondary threads in a spin lock against the main thread that's currently running the CLI. Sounds like the CLI is taking an exorbitant amount of time to run. If you're on Mac OS or Linux you might try killall node. If you're on Windows you might use Task Manager to find and kill the node.exe process.

As for why cancel might not take effect immediately, basically you check for a user-requested cancellation after each step. In the case of an API request to the server via an HTTPS connection, the client is configured for a five minute timeout. Unfortunately that's a single config across all API requests and not tuned per-request. It's that high because some API requests can take quite a while to fulfill, especially against big orgs or even against moderate orgs but for large amounts of (meta)data. So basically you click Cancel and it tells the event system that the next time it transitions, it can cancel the overarching operation. Again, perhaps more than you wanted to know...

[Justin Julicher]

Yeah I killed all the node instances and it didn’t release Webstorm so had to kill Webstorm too.

‌

No it’s good to understand the process.

[Justin Julicher]

Ok seems to be working good. however after updating and changing the context I got this:

‌

2020-06-30 12:17:52,840 [6545314]   WARN - .IlluminatedCloudExceptionUtil -  
java.lang.NullPointerException
    at com.illuminatedcloud.intellij.builder.BuildOptionsDialog$2.run(SourceFile:836)
    at com.intellij.openapi.progress.impl.CoreProgressManager$TaskRunnable.run(CoreProgressManager.java:932)
    at com.intellij.openapi.progress.impl.CoreProgressManager$4.run(CoreProgressManager.java:482)
    at com.intellij.openapi.progress.impl.ProgressRunner.lambda$new$0(ProgressRunner.java:77)
    at com.intellij.openapi.progress.impl.ProgressRunner.lambda$null$3(ProgressRunner.java:233)
    at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$runProcess$2(CoreProgressManager.java:166)
    at com.intellij.openapi.progress.impl.CoreProgressManager.registerIndicatorAndRun(CoreProgressManager.java:627)
    at com.intellij.openapi.progress.impl.CoreProgressManager.executeProcessUnderProgress(CoreProgressManager.java:572)
    at com.intellij.openapi.progress.impl.ProgressManagerImpl.executeProcessUnderProgress(ProgressManagerImpl.java:61)
    at com.intellij.openapi.progress.impl.CoreProgressManager.runProcess(CoreProgressManager.java:153)
    at com.intellij.openapi.progress.impl.ProgressRunner.lambda$submit$4(ProgressRunner.java:233)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)

[Scott Wells]

That says to me that it couldn't determine the IC config for that module. I just added some defensive handling of that, but in the end it would have resulted in an empty dialog for that context.

[Scott Wells]

Here's another build that's defensive around that NPE. I'm curious, though, why it's unable to get a builder for that module. As I mentioned, that would generally imply some type of project/module config issue.

[Justin Julicher]

Thanks I’ll check it out.

‌

I had another instance of Webstorm freezing (a good 15 minutes before I killed it) when just changing connections to one I actually just set up.

‌

I think whatever you did on this build though has fixed it and it spat out this:

‌

com.sforce.soap.metadata.MetadataApi 
2020-07-01 11:23:20,064 [ 163323]   WARN - onfigCache.FilePropertiesCache - Failed to list metadata as a batch. Will try again one at a time. 
javax.xml.ws.WebServiceException: org.apache.cxf.binding.soap.SoapFault: UNKNOWN_EXCEPTION: invalid parameter value
    at org.apache.cxf.jaxws.JaxWsClientProxy.mapException(JaxWsClientProxy.java:193)
    at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:145)
    at com.sun.proxy.$Proxy187.listMetadata(Unknown Source)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.lambda$process$0(SourceFile:255)
    at com.illuminatedcloud.client.ForceComApiClient.runWithClient(SourceFile:226)
    at com.illuminatedcloud.client.ForceComApiClient.runWithClient(SourceFile:341)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.process(SourceFile:250)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.process(SourceFile:229)
    at com.illuminatedcloud.util.ParallelBatchProcessorExecutor.lambda$execute$0(SourceFile:65)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.apache.cxf.binding.soap.SoapFault: UNKNOWN_EXCEPTION: invalid parameter value
    at org.apache.cxf.binding.soap.interceptor.Soap11FaultInInterceptor.unmarshalFault(Soap11FaultInInterceptor.java:87)
    at org.apache.cxf.binding.soap.interceptor.Soap11FaultInInterceptor.handleMessage(Soap11FaultInInterceptor.java:53)
    at org.apache.cxf.binding.soap.interceptor.Soap11FaultInInterceptor.handleMessage(Soap11FaultInInterceptor.java:42)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
    at org.apache.cxf.interceptor.AbstractFaultChainInitiatorObserver.onMessage(AbstractFaultChainInitiatorObserver.java:112)
    at org.apache.cxf.binding.soap.interceptor.CheckFaultInterceptor.handleMessage(CheckFaultInterceptor.java:70)
    at org.apache.cxf.binding.soap.interceptor.CheckFaultInterceptor.handleMessage(CheckFaultInterceptor.java:35)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
    at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:826)
    at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1695)
    at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1572)
    at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1373)
    at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
    at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673)
    at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
    at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:531)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:440)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:355)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:313)
    at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)
    at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:140)
    ... 11 more
2020-07-01 11:23:30,465 [ 173724]  ERROR - onfigCache.FilePropertiesCache - Failed to list metadata for ManagedTopic: org.apache.cxf.binding.soap.SoapFault: UNKNOWN_EXCEPTION: invalid parameter value 
java.lang.Throwable: Failed to list metadata for ManagedTopic: org.apache.cxf.binding.soap.SoapFault: UNKNOWN_EXCEPTION: invalid parameter value
    at com.intellij.openapi.diagnostic.Logger.error(Logger.java:146)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$3.process(SourceFile:369)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$3.process(SourceFile:339)
    at com.illuminatedcloud.util.ParallelBatchProcessorExecutor.lambda$execute$0(SourceFile:65)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)

Any ideas?

I don’t even have ManagedTopic as a subscribed metadata selection.

[Justin Julicher]

From the documentation at:

https://developer.salesforce.com/docs/atlas.en-us.api_meta.meta/api_meta/meta_managedtopics.htm

‌

The api says it should be folder name managedTopics - there isn’t a ManagedTopic api name.

[Scott Wells]

I think I saw this with another user and it was because the source root was configured one level too high and it saw one of the project-level directories as matching that metadata type. How are your content roots and source roots configured for this project?

[Justin Julicher]

it’s [project dir]/src/

and the source root is the src dir.

‌

[Justin Julicher]

Ok had another freeze while refreshing. Attached the new logs + threaddump.

‌

Was using your latest build.

‌

[Justin Julicher]

Latest thread dump log.

[Justin Julicher]

I don’t know what’s going on but it freezes everytime I refresh again. I reinstalled the last link you provided but it’s happening again.

‌

[Scott Wells]

Okay, here's a slightly updated form of that change for you to try. The most recent provided thread dump was a bit confusing, but this does remove one thing that looked potentially problematic to me.

[Scott Wells]

Oh, and as for that ManagedTopic question, is that just reflected in the log? Assuming so, it should be benign. Perhaps I just need to ratchet down the logging level when that occurs so that it doesn't end up in the log unless you're using debug logging.

[Scott Wells]

I've just posted 2.1.2.8 which includes all of the prospective fixes posted here so far. Once you update please let me know whether you continue to see the freeze or not. I'll leave this case open for a bit while you check it out.

[Justin Julicher]

Yeah since that last updated I haven’t had this happen again. I just did 2 refreshes and both successfully completed!

thanks. I’m confident this can be resolved. I’ll re-open if I experience another freeze like this.

[Justin Julicher]

Bug fix successful