- edited description
Error time out/Test ignored.
Got “Time out” error (everytime) when running test method (or debug).
Testing started at 22:28 ...
Using connection 'connectionName'.
Test ignored.
2020-07-22 22:28:18,238 [ 174546] INFO - .ApexUnitTestRunProcessHandler - Running unit tests synchronously.
2020-07-22 22:28:24,141 [ 180449] INFO - rationStore.ComponentStoreImpl - Saving appFileTypeManager took 40 ms
2020-07-22 22:28:24,321 [ 180629] INFO - rationStore.ComponentStoreImpl - Saving Project (name=FullSandbox, containerState=ACTIVE, componentStore=C:\Users\User\WebstormProjects\projectFolder) RunManager took 51 ms
2020-07-22 22:28:46,412 [ 202720] INFO - rationStore.ComponentStoreImpl - Saving appVcsApplicationSettings took 15 ms
2020-07-22 22:28:46,507 [ 202815] INFO - rationStore.ComponentStoreImpl - Saving Project (name=FullSandbox, containerState=ACTIVE, componentStore=C:\Users\User\WebstormProjects\projectFolder) CommitMessageInspectionProfile took 37 ms
2020-07-22 22:29:51,033 [ 267341] INFO - rationStore.ComponentStoreImpl - Saving appGeneralSettings took 27 ms, IlluminatedCloudSettings took 13 ms
2020-07-22 22:31:22,828 [ 359136] INFO - rationStore.ComponentStoreImpl - Saving Project (name=FullSandbox, containerState=ACTIVE, componentStore=C:\Users\User\WebstormProjects\projectFolder) XDebuggerManager took 11 ms
2020-07-22 22:41:53,833 [ 990141] INFO - rationStore.ComponentStoreImpl - Saving appDiffSettings took 18 ms
2020-07-22 22:41:54,066 [ 990374] INFO - rationStore.ComponentStoreImpl - Saving Project (name=FullSandbox, containerState=ACTIVE, componentStore=C:\Users\User\WebstormProjects\projectFolder) RunManager took 14 ms
2020-07-22 22:43:18,532 [1074840] WARN - .IlluminatedCloudExceptionUtil - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.base/java.net.SocketInputStream.socketRead0(Native Method)
at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:448)
at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:68)
at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1096)
at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:816)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:280)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
at com.illuminatedcloud.client.ForceComApiClient.runWithClient(SourceFile:479)
at com.illuminatedcloud.intellij.unittest.ApexUnitTestRunProcessHandler.runTestsSynchronous(SourceFile:680)
at com.illuminatedcloud.intellij.unittest.ApexUnitTestRunProcessHandler.lambda$startProcessing$5(SourceFile:569)
at com.intellij.util.RunnableCallable.call(RunnableCallable.java:20)
at com.intellij.util.RunnableCallable.call(RunnableCallable.java:11)
at com.intellij.openapi.application.impl.ApplicationImpl$1.call(ApplicationImpl.java:255)
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)
2020-07-22 22:45:25,088 [1201396] INFO - agnostic.FrequentEventDetector - Too many events posted, #1. Event: java.awt.event.InvocationEvent[INVOCATION_DEFAULT,runnable=com.intellij.openapi.application.impl.FlushQueue$FlushNow@37edb2af,notifier=null,catchExceptions=false,when=1595447125079] on sun.awt.windows.WToolkit@116a951d
java.lang.Throwable
at com.intellij.openapi.diagnostic.FrequentEventDetector.generateMessage(FrequentEventDetector.java:83)
at com.intellij.openapi.diagnostic.FrequentEventDetector.getMessageOnEvent(FrequentEventDetector.java:62)
at com.intellij.ide.IdeEventQueue.doPostEvent(IdeEventQueue.java:1377)
at com.intellij.ide.IdeEventQueue.postEvent(IdeEventQueue.java:1270)
at java.desktop/java.awt.EventQueue.invokeLater(EventQueue.java:1318)
at java.desktop/javax.swing.SwingUtilities.invokeLater(SwingUtilities.java:1421)
at com.intellij.openapi.application.impl.FlushQueue.scheduleFlush(FlushQueue.java:37)
at com.intellij.openapi.application.impl.LaterInvocator.requestFlush(LaterInvocator.java:342)
at com.intellij.openapi.application.impl.LaterInvocator.pushRunnableToQueue(LaterInvocator.java:403)
at com.intellij.openapi.application.impl.LaterInvocator.invokeLaterWithCallback(LaterInvocator.java:111)
at com.intellij.openapi.application.impl.ApplicationImpl.invokeLater(ApplicationImpl.java:310)
at com.intellij.openapi.application.impl.ApplicationImpl.invokeLater(ApplicationImpl.java:304)
at com.intellij.codeInsight.daemon.impl.HighlightingSessionImpl$1.schedule(HighlightingSessionImpl.java:63)
at com.intellij.util.containers.TransferToEDTQueue.scheduleUpdate(TransferToEDTQueue.java:156)
at com.intellij.util.containers.TransferToEDTQueue.offer(TransferToEDTQueue.java:135)
at com.intellij.codeInsight.daemon.impl.HighlightingSessionImpl.applyInEDT(HighlightingSessionImpl.java:71)
at com.intellij.codeInsight.daemon.impl.HighlightingSessionImpl.queueHighlightInfo(HighlightingSessionImpl.java:137)
at com.intellij.codeInsight.daemon.impl.DefaultHighlightInfoProcessor.infoIsAvailable(DefaultHighlightInfoProcessor.java:135)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.queueInfoToUpdateIncrementally(GeneralHighlightingPass.java:498)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass$1.queueToUpdateIncrementally(GeneralHighlightingPass.java:483)
at com.intellij.codeInsight.daemon.impl.DefaultHighlightVisitor$1.queueToUpdateIncrementally(DefaultHighlightVisitor.java:87)
at com.intellij.codeInsight.daemon.impl.DefaultHighlightVisitor.runAnnotators(DefaultHighlightVisitor.java:133)
at com.intellij.codeInsight.daemon.impl.DefaultHighlightVisitor.visit(DefaultHighlightVisitor.java:110)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.runVisitors(GeneralHighlightingPass.java:346)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.lambda$collectHighlights$5(GeneralHighlightingPass.java:286)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.analyzeByVisitors(GeneralHighlightingPass.java:306)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.lambda$analyzeByVisitors$6(GeneralHighlightingPass.java:309)
at com.intellij.codeInsight.daemon.impl.DefaultHighlightVisitor.analyze(DefaultHighlightVisitor.java:93)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.analyzeByVisitors(GeneralHighlightingPass.java:309)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.collectHighlights(GeneralHighlightingPass.java:277)
at com.intellij.codeInsight.daemon.impl.GeneralHighlightingPass.collectInformationWithProgress(GeneralHighlightingPass.java:222)
at com.intellij.codeInsight.daemon.impl.ProgressableTextEditorHighlightingPass.doCollectInformation(ProgressableTextEditorHighlightingPass.java:84)
at com.intellij.codeHighlighting.TextEditorHighlightingPass.collectInformation(TextEditorHighlightingPass.java:52)
at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$null$1(PassExecutorService.java:442)
at com.intellij.openapi.application.impl.ApplicationImpl.tryRunReadAction(ApplicationImpl.java:1106)
at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$doRun$2(PassExecutorService.java:435)
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.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.doRun(PassExecutorService.java:434)
at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$run$0(PassExecutorService.java:410)
at com.intellij.openapi.application.impl.ReadMostlyRWLock.executeByImpatientReader(ReadMostlyRWLock.java:168)
at com.intellij.openapi.application.impl.ApplicationImpl.executeByImpatientReader(ApplicationImpl.java:168)
at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.run(PassExecutorService.java:408)
at com.intellij.concurrency.JobLauncherImpl$VoidForkJoinTask$1.exec(JobLauncherImpl.java:171)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
2020-07-22 22:46:34,759 [1271067] INFO - j.ide.actions.RevealFileAction - Exit code 1
Comments (17)
-
reporter -
repo owner Are other other network connections to Salesforce working properly from the IDE? For example, can you deploy/retrieve metadata? If not, it's likely a network configuration issue. If so, though, it sounds like that one REST endpoint is timing out and that would need to be resolved by Salesforce.
-
repo owner Or are you in NA21 perhaps? There's a known issue going on in that instance:
-
reporter Scott,
other functionality working fine.
I find out that issue approximately 1 month ago. I had no time to create ticket )
-
reporter My colleagues(also IC 2 users) can run tests and debug
-
repo owner Okay. And you're on the latest versions of both the base JetBrains IDE and the Illuminated Cloud 2 plugin?
-
reporter Yeap.
Also,
I reinstalled Webstorm and IC 2 plugin (tried even delete caches and settings).
-
repo owner Okay. We can see exactly what's going on with that REST call. Add the following to Help>Diagnostic Tools>Debug Log Settings exactly:
#com.illuminatedcloud.client.ForceComApiClient #com.illuminatedcloud.client.ForceComApiClient!trace
Then reproduce the issue and your
idea.log
should contain the full REST request and response (well, no response in this case because it ultimately times out).Then I think you should try to issue the exact same REST request to the server from outside of the IDE to see if it's an issue in the IDE process or something with your machine. If you have access to
curl
and provide me theidea.log
with the request, I can show you how to issue the request. You can also do it from Workbench if that's available to you as a second data point. -
reporter Request:
URL i changed to hide my client name)
2020-07-23 00:03:03,048 [5859356] INFO - .ApexUnitTestRunProcessHandler - Running unit tests synchronously. 2020-07-23 00:03:03,049 [5859357] DEBUG - cloud.client.ForceComApiClient - Executing REST request: Method: POST URI: https://hidden--qa.my.salesforce.com/services/data/v49.0/tooling/runTestsSynchronous/ Timeout: 900000 2020-07-23 00:03:03,049 [5859357] DEBUG - client.ForceComApiClient!trace - REST request entity is: Content type: <unknown> Content encoding: <unknown> Content length: 116 Body: {"tests":[{"className":"Core_ScriptFlowTest","testMethods":["controllerSaveCurrentLines"]}],"skipCodeCoverage":true} 2020-07-23 00:03:22,005 [5878313] INFO - j.ide.actions.RevealFileAction - Exit code 1
-
repo owner Okay. Let's try one other thing real quick before we dive into trying to reproduce externally. Please open Illuminated Cloud>Configure Application and on the Unit Tests and Code Coverage tab, check Always run unit tests asynchronously. Then please try to run this test again and let me know whether it also hangs via that API. Since this seems isolated to a single operation for you, let's see just how specific it is.
-
reporter Not fixed (
Sometimes i can see result of apex test run (1/5 case) but IDE show me result slightly later (~20s for run with 1 method) than i can see it “log Analyzer”
Debug run - 'Read time out” error always
-
repo owner - attached IlluminatedCloud2.zip
Yeah, I didn't so much expect that to fix it as to let me know whether it's a most consistent issue calling the Tooling REST API from your machine. Let's try it from outside of the IDE now. You'll need to attached build as it also logs the HTTP headers including the session ID which you'll need for the
curl
command.Install this attached build using Settings/Preferences>Plugins>Install plugin from disk (under the gear drop-down menu), then reproduce the issue again. In your
idea.log
you'll see your version of the following:2020-07-22 17:07:47,390 [ 114570] DEBUG - cloud.client.ForceComApiClient - Executing REST request: Method: POST URI: https://<hostname>/services/data/v49.0/tooling/runTestsSynchronous/ Timeout: 900000 Headers: { Content-Type='application/json; charset=UTF-8' Authorization='Bearer <session-id>' } 2020-07-22 17:07:47,391 [ 114571] DEBUG - client.ForceComApiClient!trace - REST request entity is: Content type: <unknown> Content encoding: <unknown> Content length: 131 Body: {"tests":[{"className":"TestClassName","testMethods":["testMethodName"]}],"skipCodeCoverage":true}
Use that to construct the following
curl
command:curl \ -X POST \ -H 'Authorization: Bearer <session-id>' \ -H 'Content-Type: application/json; charset=UTF-8' \ -d '{"tests":[{"className":"<TestClassName>","testMethods":["<testMethodName>"]}],"skipCodeCoverage":true}' \ https://<hostname>/services/data/v49.0/tooling/runTestsSynchronous/
Let's see if that hangs or not. If it doesn't, please make sure that you have the "HTTP Tools" plugin enabled so we can try it from within the IDE, then use Tools>REST Client to open the REST client. Then populate that tool window with the same information:
- HTTP method - POST
- Host/port -
https://<hostname>
- Path -
/services/data/v49.0/tooling/runTestsSynchronous/
- Headers -
Authorization: Bearer <session-id>
andContent-Type: application/json; charset=UTF-8
- Request Body>Text -
{"tests":[{"className":"<TestClassName>","testMethods":["<testMethodName>"]}],"skipCodeCoverage":true}
Then click the Play toolbar button and see if it completes.
Let's gather that diagnostic info and see where that leaves us.
-
reporter I used postman, response:
{ "apexLogId": "07L1w00000AX3pmEAD", "codeCoverage": [], "codeCoverageWarnings": [], "failures": [], "flowCoverage": [ { "elementsNotCovered": [ "recipients_loop", "email_alert" ], "flowId": "3011w00000082zf", "flowName": "CA_AlternateEmailVerification", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "ca_get_receipt_record", "ca_create_new_receipt_record" ], "flowId": "3011w000000PMpk", "flowName": "CA_Auto_Clone_Receipt_Record", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "get_case", "handle_error", "get_record_type", "create_order", "get_account", "return_orderid", "careplan_or_foc", "get_foc" ], "flowId": "3011w000000PJjo", "flowName": "CA_Create_Drug_Order", "flowNamespace": null, "numElements": 8, "numElementsNotCovered": 8, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "recipients_loop", "email_alert" ], "flowId": "3011i000000I3qM", "flowName": "CA_EmailVerification", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "set", "update_standard_birthdate", "record_type_account", "core_update_email_opt_out_to_opted_out", "check_current_birthdate_with_previous", "update_email_opt_out_0_0", "core_update_email_opt_out_to_opted_out_0", "oktoemailtoemailconsen_when_record_is_created", "choose_record_type", "update_email_opt_out", "update_email_opt_out_0", "update_email_opt_out_0_0_0" ], "flowId": "3011w000000PJU5", "flowName": "Core_Account_predefaults", "flowNamespace": null, "numElements": 12, "numElementsNotCovered": 12, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "myrule_1_a1", "mydecision" ], "flowId": "3011w0000007yHK", "flowName": "Core_Individual_Threshold_Email", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "Workflow" }, { "elementsNotCovered": [ "myrule_1_a2", "myrule_1_a1", "mydecision" ], "flowId": "3011w0000008Jz3", "flowName": "Core_Special_Auth_Record_Creation", "flowNamespace": null, "numElements": 3, "numElementsNotCovered": 3, "processType": "Workflow" }, { "elementsNotCovered": [ "myrule_1_a1", "mydecision" ], "flowId": "3011w0000007yHM", "flowName": "Core_Update_Field_Preferred_Channel_on_Service", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "Workflow" }, { "elementsNotCovered": [ "myrule_1_a1", "myrule_3_a1", "mydecision", "mydecision2" ], "flowId": "3011w0000007yHN", "flowName": "Core_Updating_Clinical_Service_Training_Location", "flowNamespace": null, "numElements": 4, "numElementsNotCovered": 4, "processType": "Workflow" }, { "elementsNotCovered": [ "recipients_loop", "email_alert" ], "flowId": "3011i000000I3qO", "flowName": "DE_EmailVerification", "flowNamespace": null, "numElements": 2, "numElementsNotCovered": 2, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "myrule_1_a2", "myrule_1_a1", "mydecision" ], "flowId": "3011w0000007yHO", "flowName": "LeadToPatientConversion", "flowNamespace": null, "numElements": 3, "numElementsNotCovered": 3, "processType": "Workflow" }, { "elementsNotCovered": [ "is_available_for_profile", "get_account_info", "nondrugorderassignment", "nondrug_order", "caseid", "return_orderid", "getrectype", "setcaseid" ], "flowId": "3011w000000PI1q", "flowName": "NonDrugOrder_creation", "flowNamespace": null, "numElements": 8, "numElementsNotCovered": 8, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "country_and_brand_decision", "abbvie_care_nurse_role", "care_coach_role", "pcs_role" ], "flowId": "3011i000000Hsva", "flowName": "OneCRM_CT_Case_Team_Member_Creation", "flowNamespace": null, "numElements": 4, "numElementsNotCovered": 4, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "onecrm_ct_update_order_status" ], "flowId": "3011i000000Hsvb", "flowName": "OneCRM_CT_Update_Order_Satus", "flowNamespace": null, "numElements": 1, "numElementsNotCovered": 1, "processType": "AutoLaunchedFlow" }, { "elementsNotCovered": [ "onecrm_ct_update_order_status" ], "flowId": "3011i000000Hsvd", "flowName": "Update_Order_Status_To_Canceled", "flowNamespace": null, "numElements": 1, "numElementsNotCovered": 1, "processType": "AutoLaunchedFlow" } ], "flowCoverageWarnings": [], "numFailures": 0, "numTestsRun": 1, "successes": [ { "id": "01p3N000000RKF3QAO", "methodName": "controllerSaveCurrentLines", "name": "Core_ScriptFlowTest", "namespace": null, "seeAllData": false, "time": 5575.0 } ], "totalTime": 35459.0 }
in webstorm:
-
repo owner Okay, that's very useful. That isolates the behavior to WebStorm (or more specifically, WebStorm's host JVM process). My guess is that your network requires some type of proxy configuration:
You might compare your configuration to your co-workers' configs to see what's different.
-
reporter we have same “no proxy” config:
-
repo owner Unfortunately without access to the network it's going to be difficult for me to help debug this further. Because this occurs in the base IDE's REST client, it's some issue with that process issuing HTTPS REST requests to that endpoint, particularly since the same request works just fine in an external process. The good news is that you should be able to log a case with JetBrains support on this as a paying customer of WebSphere and able to reproduce it in their standard tooling. That would be my next recommendation as they're going to be much more well-versed in other things to try. I apologize for redirecting you to them, but at this point it seems to be a base IDE/JVM issue.
-
repo owner - changed status to resolved
Issue tracker grooming. If this is still an issue, please feel free to reopen, ideally with a concrete reproduction scenario.
- Log in to comment