Webstorm Freezing when refreshing metadata

Issue #1650 resolved
Justin Julicher created an issue

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.

Comments (25)

  1. Scott Wells repo owner

    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?

  2. Justin Julicher reporter

    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.

  3. Scott Wells repo owner

    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.

  4. Justin Julicher reporter

    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

  5. Justin Julicher reporter

    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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 2jjulicher@fortherecord.com.cortexfull. 
    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.

  6. Scott Wells repo owner

    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...

  7. Justin Julicher reporter

    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.

  8. Justin Julicher reporter

    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)
    

    🙂

  9. Scott Wells repo owner

    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.

  10. Scott Wells repo owner

    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.

  11. Justin Julicher reporter

    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.

  12. Scott Wells repo owner

    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?

  13. Justin Julicher reporter

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

    Was using your latest build.

  14. Justin Julicher reporter

    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.

  15. Scott Wells repo owner

    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.

  16. Scott Wells repo owner

    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.

  17. Scott Wells repo owner

    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.

  18. Justin Julicher reporter

    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.

  19. Log in to comment