1. Scott Wells Avatar Scott Wells
  2. Illuminated Cloud
  3. IlluminatedCloud
  4. Issues

Intermittent: Unit Test Logs Not Showing in Run Tab

Issue #1271 resolved
Jason Clark created an issue

This is the same as closed issue #995, except it is intermittent. Sometimes (at least a couple of times a day), when I run a unit test which fails, the log is missing, and I only get the assertion failure output. See attached screenshot. Simply re-running the test generally produces the logs as expected.

IntelliJ IDEA 2018.3.5 (Community Edition) Build #IC-183.5912.21, built on February 26, 2019 JRE: 1.8.0_152-release-1343-b28 x86_64 JVM: OpenJDK 64-Bit Server VM by JetBrains s.r.o macOS 10.14.2

Comments (20)

  2. Jason Clark

    @Scott Wells So it looks like I reported this ages ago and never followed up, probably because the intermittent issue became less common. However, it has recently started occurring more regularly, so I’ve added the logging config requested above (note- the link is now https://www.illuminatedcloud.com/support/debug-logging, with a hyphen).

    Seems like it usually happens when a test fails; I see the failure info but no log (see original screenshot). Sometimes it happens when the test passes and the log panel is completely blank. That’s what just happened, so I grabbed the log lines. After starting to write up this comment, I went back and reran the test and this time it worked.

    I’ve appended the lines from my idea.log below for both runs. You can see that I kicked off the first (failling) test run on line 2, with no log activity for 7 minutes prior. On line 75, the logs shows it queried for the apex log by id (Querying logs with log IDs { '07LP000000gxA7MMAU' }) and on line 76 it didn’t find it; I queried that log in Developer Console and it was there. On line 85 the second run kicks off.

    If I get a test failure I’ll return with that log. Otherwise, let me know if I can provide any other info. If you’d like the full log let me know if I can email it; I’ve checked that the log tail below doesn’t need to be sanitized, but I would worry about my 6MB log file potentially containing client information.

    Also - I’m now running on Webstorm 2022.1.1, build #WS-221.5591.52; and I’m running IC2 version 2.2.2.1.

    idea.log tail:

    2022-05-25 14:20:38,082 [133849264]   INFO - #c.i.i.b.ForceComMetadataApiDeployer - Deployment status = SUCCEEDED
2022-05-25 14:27:33,961 [134265143]   INFO - #c.i.u.IlluminatedCloudExceptionUtil - Executing unit tests for run configuration 'JiraIntegration_Test.test_JiraIntegration_noCloudId'.
2022-05-25 14:27:33,961 [134265143]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Running tests for [ treasure: { JiraIntegration_Test } ].
2022-05-25 14:27:33,961 [134265143]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Configured: Setting test class/method map to:
{
  "JiraIntegration_Test": [
    "test_JiraIntegration_noCloudId"
  ]
}
2022-05-25 14:27:33,971 [134265153]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Starting test run.
2022-05-25 14:27:33,973 [134265155]   INFO - #c.i.i.s.a.IlluminatedCloudConnectionConfig - Retrieving org list from Salesforce CLI.
2022-05-25 14:27:34,013 [134265195]   INFO - #c.i.i.s.a.IlluminatedCloudConnectionConfig - Retrieving org list information from Salesforce CLI.
2022-05-25 14:27:34,017 [134265199]   FINE - #c.i.u.VariableLengthPollingInterval - /Users/jclark/.nvm/versions/node/v17.2.0/bin/sfdx force:org:list --skipconnectionstatus --json: Using polling interval 1000 ms for polling iteration 1.
2022-05-25 14:27:35,020 [134266202]   FINE - #c.i.u.VariableLengthPollingInterval - /Users/jclark/.nvm/versions/node/v17.2.0/bin/sfdx force:org:list --skipconnectionstatus --json: Using polling interval 1000 ms for polling iteration 2.
2022-05-25 14:27:36,021 [134267203]   FINE - #c.i.u.VariableLengthPollingInterval - /Users/jclark/.nvm/versions/node/v17.2.0/bin/sfdx force:org:list --skipconnectionstatus --json: Using polling interval 1000 ms for polling iteration 3.
2022-05-25 14:27:37,025 [134268207]   FINE - #c.i.u.VariableLengthPollingInterval - /Users/jclark/.nvm/versions/node/v17.2.0/bin/sfdx force:org:list --skipconnectionstatus --json: Using polling interval 1000 ms for polling iteration 4.
2022-05-25 14:27:38,025 [134269207]   FINE - #c.i.u.VariableLengthPollingInterval - /Users/jclark/.nvm/versions/node/v17.2.0/bin/sfdx force:org:list --skipconnectionstatus --json: Using polling interval 1000 ms for polling iteration 5.
2022-05-25 14:27:39,035 [134270217]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding class declaration for JiraIntegration_Test.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding test methods in JiraIntegration_Test.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration is a test method.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noSettings is a test method.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId is a test method.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId_cannotRetrieve is a test method.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueJSON is a test method.
2022-05-25 14:27:39,052 [134270234]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueCreateMetadata is a test method.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_createIssue is a test method.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found the following test methods for JiraIntegration_Test: { JiraIntegration_Test.test_JiraIntegration(), JiraIntegration_Test.test_JiraIntegration_noSettings(), JiraIntegration_Test.test_JiraIntegration_noCloudId(), JiraIntegration_Test.test_JiraIntegration_noCloudId_cannotRetrieve(), JiraIntegration_Test.test_getIssueJSON(), JiraIntegration_Test.test_getIssueCreateMetadata(), JiraIntegration_Test.test_createIssue() }.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Filtering by the configured test methods based on simple class name JiraIntegration_Test: { test_JiraIntegration_noCloudId }.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noSettings is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId is a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId_cannotRetrieve is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueJSON is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueCreateMetadata is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_createIssue is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:27:39,053 [134270235]   INFO - #c.i.c.ForceComApiClient - Logging into Salesforce DX as jason.clark@axiacpqtd.com.2022full.
2022-05-25 14:27:39,053 [134270235]   INFO - #c.i.c.ForceComApiClient - Retrieving org details from Salesforce CLI.
2022-05-25 14:27:39,053 [134270235]   INFO - o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {urn:partner.soap.sforce.com}PartnerService from class com.sforce.soap.partner.PartnerApi
2022-05-25 14:27:39,059 [134270241]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Creating a trace flag.
2022-05-25 14:27:39,059 [134270241]   INFO - o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {http://soap.sforce.com/2006/04/metadata}MetadataService from class com.sforce.soap.metadata.MetadataApi
2022-05-25 14:27:39,066 [134270248]   INFO - o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {http://soap.sforce.com/2006/08/apex}ApexService from class com.sforce.soap.apex.ApexApi
2022-05-25 14:27:39,070 [134270252]   INFO - o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {urn:tooling.soap.sforce.com}ToolingService from class com.sforce.soap.tooling.ToolingApi
2022-05-25 14:27:40,247 [134271429]   INFO - #c.i.i.u.ApexUnitTestRunProcessHandler - Running unit tests asynchronously.
2022-05-25 14:27:40,247 [134271429]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Queueing the test run skipping coverage.
2022-05-25 14:27:40,249 [134271431]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Posting the following to runTestsAsynchronous:
2022-05-25 14:27:40,249 [134271431]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   {"tests":[{"className":"JiraIntegration_Test","testMethods":["test_JiraIntegration_noCloudId"]}],"skipCodeCoverage":true}
2022-05-25 14:27:53,342 [134284524]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Async Apex job ID = 707P000001otbIn.
2022-05-25 14:27:53,342 [134284524]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Polling status until job completion.
2022-05-25 14:27:53,342 [134284524]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:27:53,557 [134284739]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:27:53,557 [134284739]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status QUEUED.
2022-05-25 14:27:53,558 [134284740]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:27:53,558 [134284740]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.JiraIntegration_Test.test_JiraIntegration_noCloudId: Using polling interval 1000 ms for polling iteration 1.
2022-05-25 14:27:54,563 [134285745]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:27:54,663 [134285845]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:27:54,663 [134285845]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status PROCESSING.
2022-05-25 14:27:54,663 [134285845]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:27:54,663 [134285845]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.JiraIntegration_Test.test_JiraIntegration_noCloudId: Using polling interval 1000 ms for polling iteration 2.
2022-05-25 14:27:55,667 [134286849]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:27:55,861 [134287043]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:27:55,861 [134287043]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status PROCESSING.
2022-05-25 14:27:55,862 [134287044]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:27:55,862 [134287044]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.JiraIntegration_Test.test_JiraIntegration_noCloudId: Using polling interval 1000 ms for polling iteration 3.
2022-05-25 14:27:56,868 [134288050]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:27:57,189 [134288371]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:27:57,189 [134288371]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status PROCESSING.
2022-05-25 14:27:57,190 [134288372]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:27:57,190 [134288372]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.JiraIntegration_Test.test_JiraIntegration_noCloudId: Using polling interval 1000 ms for polling iteration 4.
2022-05-25 14:27:58,201 [134289383]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:27:58,266 [134289448]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:27:58,267 [134289449]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status COMPLETED.
2022-05-25 14:27:58,268 [134289450]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying test results for JiraIntegration_Test.
2022-05-25 14:27:58,360 [134289542]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   1 test results returned.
2022-05-25 14:27:58,360 [134289542]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying Apex logs for tests.
2022-05-25 14:27:58,361 [134289543]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07LP000000gxA7MMAU' }.
2022-05-25 14:27:58,409 [134289591]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler - No Apex logs found for the test run.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0 logs found.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - No class-level log found.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Processing results for test method JiraIntegration_Test.test_JiraIntegration_noCloudId.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Test JiraIntegration_Test.test_JiraIntegration_noCloudId finished with outcome PASS.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Finishing the test.
2022-05-25 14:27:58,415 [134289597]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Setting class to completed after 0 ms and finishing the test suite.
2022-05-25 14:27:58,416 [134289598]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - All tests complete.
2022-05-25 14:27:58,416 [134289598]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finishing test run.
2022-05-25 14:36:17,771 [134788953]   INFO - #c.i.u.IlluminatedCloudExceptionUtil - Executing unit tests for run configuration 'JiraIntegration_Test.test_JiraIntegration_noCloudId'.
2022-05-25 14:36:17,771 [134788953]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Running tests for [ treasure: { JiraIntegration_Test } ].
2022-05-25 14:36:17,771 [134788953]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Configured: Setting test class/method map to:
{
  "JiraIntegration_Test": [
    "test_JiraIntegration_noCloudId"
  ]
}
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Starting test run.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding class declaration for JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding test methods in JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noSettings is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId_cannotRetrieve is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueJSON is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueCreateMetadata is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_createIssue is a test method.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found the following test methods for JiraIntegration_Test: { JiraIntegration_Test.test_JiraIntegration(), JiraIntegration_Test.test_JiraIntegration_noSettings(), JiraIntegration_Test.test_JiraIntegration_noCloudId(), JiraIntegration_Test.test_JiraIntegration_noCloudId_cannotRetrieve(), JiraIntegration_Test.test_getIssueJSON(), JiraIntegration_Test.test_getIssueCreateMetadata(), JiraIntegration_Test.test_createIssue() }.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Filtering by the configured test methods based on simple class name JiraIntegration_Test: { test_JiraIntegration_noCloudId }.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noSettings is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId is a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_JiraIntegration_noCloudId_cannotRetrieve is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueJSON is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_getIssueCreateMetadata is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   test_createIssue is not a configured test method in test class JiraIntegration_Test.
2022-05-25 14:36:17,816 [134788998]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Creating a trace flag.
2022-05-25 14:36:18,813 [134789995]   INFO - #c.i.i.u.ApexUnitTestRunProcessHandler - Running unit tests asynchronously.
2022-05-25 14:36:18,813 [134789995]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Queueing the test run skipping coverage.
2022-05-25 14:36:18,814 [134789996]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Posting the following to runTestsAsynchronous:
2022-05-25 14:36:18,814 [134789996]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   {"tests":[{"className":"JiraIntegration_Test","testMethods":["test_JiraIntegration_noCloudId"]}],"skipCodeCoverage":true}
2022-05-25 14:36:19,296 [134790478]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Async Apex job ID = 707P000001otd3J.
2022-05-25 14:36:19,297 [134790479]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Polling status until job completion.
2022-05-25 14:36:19,297 [134790479]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:36:19,371 [134790553]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:36:19,371 [134790553]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status QUEUED.
2022-05-25 14:36:19,371 [134790553]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:36:19,371 [134790553]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.JiraIntegration_Test.test_JiraIntegration_noCloudId: Using polling interval 1000 ms for polling iteration 1.
2022-05-25 14:36:20,376 [134791558]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:36:20,426 [134791608]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:36:20,427 [134791609]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class JiraIntegration_Test with status COMPLETED.
2022-05-25 14:36:20,427 [134791609]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying test results for JiraIntegration_Test.
2022-05-25 14:36:20,465 [134791647]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   1 test results returned.
2022-05-25 14:36:20,465 [134791647]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying Apex logs for tests.
2022-05-25 14:36:20,465 [134791647]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07LP000000gxA7lMAE' }.
2022-05-25 14:36:20,538 [134791720]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Found 1 logs.
2022-05-25 14:36:20,538 [134791720]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Retrieving the body for log ID 07LP000000gxA7lMAE.
2022-05-25 14:36:20,667 [134791849]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding logs for test methods { test_JiraIntegration_noCloudId }.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Finding a log for test method JiraIntegration_Test.test_JiraIntegration_noCloudId.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found a log for test method JiraIntegration_Test.test_JiraIntegration_noCloudId.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   1 logs found.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - No class-level log found.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Processing results for test method JiraIntegration_Test.test_JiraIntegration_noCloudId.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Method-level log found.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Test JiraIntegration_Test.test_JiraIntegration_noCloudId finished with outcome PASS.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Finishing the test.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Setting class to completed after 0 ms and finishing the test suite.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - All tests complete.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finishing test run.

    ‌

  3. Scott Wells repo owner

    Hi, Jason. Thanks for the log. It certainly looks like it should be writing out the method-level log based on:

    2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Processing results for test method JiraIntegration_Test.test_JiraIntegration_noCloudId.
2022-05-25 14:36:20,668 [134791850]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Method-level log found.

    That corresponds to something that should write the following into the test output window:

    Apex log for <TestClassName>.<testMethodName>
=============================================
<methodLeveLog>

    It specifically should write that to the output window for the node for that specific method, and that should in turn be aggregated into the ancestor nodes. Do you not see anything like that if you click up and down the test results tree from the method-specific node up to the test results root node?

  4. Scott Wells repo owner

    To be more specific, here's what I see:

    Issue_1271.png

    for the following log (extract) which is for all intents and purposes the same as what you posted:

    2022-05-25 14:16:05,021 [6985172]   INFO - #c.i.u.IlluminatedCloudExceptionUtil - Executing unit tests for run configuration 'ShoppingListMobileViewControllerTest.testConstructorExistingObject'.
2022-05-25 14:16:05,021 [6985172]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Running tests for [ df17-with-manifest: { ShoppingListMobileViewControllerTest } ].
2022-05-25 14:16:05,021 [6985172]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Configured: Setting test class/method map to:
{
  "ShoppingListMobileViewControllerTest": [
    "testConstructorExistingObject"
  ]
}
2022-05-25 14:16:05,273 [6985424]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Starting test run.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding class declaration for ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding test methods in ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testConstructorNewObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testConstructorExistingObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testDeleteShoppingList is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testAddItemNewObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testAddItemExistingObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testRemoveItem is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testSaveNewObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testSaveExistingObject is a test method.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found the following test methods for ShoppingListMobileViewControllerTest: { ShoppingListMobileViewControllerTest.testConstructorNewObject(), ShoppingListMobileViewControllerTest.testConstructorExistingObject(), ShoppingListMobileViewControllerTest.testDeleteShoppingList(), ShoppingListMobileViewControllerTest.testAddItemNewObject(), ShoppingListMobileViewControllerTest.testAddItemExistingObject(), ShoppingListMobileViewControllerTest.testRemoveItem(), ShoppingListMobileViewControllerTest.testSaveNewObject(), ShoppingListMobileViewControllerTest.testSaveExistingObject() }.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Filtering by the configured test methods based on simple class name ShoppingListMobileViewControllerTest: { testConstructorExistingObject }.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testConstructorNewObject is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testConstructorExistingObject is a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testDeleteShoppingList is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testAddItemNewObject is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testAddItemExistingObject is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testRemoveItem is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testSaveNewObject is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   testSaveExistingObject is not a configured test method in test class ShoppingListMobileViewControllerTest.
2022-05-25 14:16:05,289 [6985440]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Creating a trace flag.
2022-05-25 14:16:06,296 [6986447]   INFO - #c.i.i.u.ApexUnitTestRunProcessHandler - Running unit tests asynchronously.
2022-05-25 14:16:06,296 [6986447]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Queueing the test run skipping coverage.
2022-05-25 14:16:06,296 [6986447]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Posting the following to runTestsAsynchronous:
2022-05-25 14:16:06,296 [6986447]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   {"tests":[{"className":"ShoppingListMobileViewControllerTest","testMethods":["testConstructorExistingObject"]}],"skipCodeCoverage":true}
2022-05-25 14:16:06,704 [6986855]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Async Apex job ID = 7072E0000HqKEpM.
2022-05-25 14:16:06,704 [6986855]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Polling status until job completion.
2022-05-25 14:16:06,704 [6986855]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:16:07,037 [6987188]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:16:07,037 [6987188]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class ShoppingListMobileViewControllerTest with status QUEUED.
2022-05-25 14:16:07,037 [6987188]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:16:07,037 [6987188]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.ShoppingListMobileViewControllerTest.testConstructorExistingObject: Using polling interval 1000 ms for polling iteration 1.
2022-05-25 14:16:08,046 [6988197]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:16:08,130 [6988281]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:16:08,130 [6988281]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class ShoppingListMobileViewControllerTest with status PROCESSING.
2022-05-25 14:16:08,130 [6988281]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0/1 tests complete.
2022-05-25 14:16:08,130 [6988281]   FINE - #c.i.u.VariableLengthPollingInterval - ApexUnitTestRunProcessHandler.ShoppingListMobileViewControllerTest.testConstructorExistingObject: Using polling interval 1000 ms for polling iteration 2.
2022-05-25 14:16:09,136 [6989287]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Polling status with 0 completed tests.
2022-05-25 14:16:10,050 [6990201]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Status returned for 1 test queue items.
2022-05-25 14:16:10,050 [6990201]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Found class ShoppingListMobileViewControllerTest with status COMPLETED.
2022-05-25 14:16:10,050 [6990201]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying test results for ShoppingListMobileViewControllerTest.
2022-05-25 14:16:10,145 [6990296]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   1 test results returned.
2022-05-25 14:16:10,145 [6990296]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying Apex logs for tests.
2022-05-25 14:16:10,145 [6990296]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2E00005xGuhxUAC' }.
2022-05-25 14:16:10,240 [6990391]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Found 1 logs.
2022-05-25 14:16:10,240 [6990391]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Retrieving the body for log ID 07L2E00005xGuhxUAC.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finding logs for test methods { testConstructorExistingObject }.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Finding a log for test method ShoppingListMobileViewControllerTest.testConstructorExistingObject.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found a log for test method ShoppingListMobileViewControllerTest.testConstructorExistingObject.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   1 logs found.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - No class-level log found.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Processing results for test method ShoppingListMobileViewControllerTest.testConstructorExistingObject.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Method-level log found.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Test ShoppingListMobileViewControllerTest.testConstructorExistingObject finished with outcome PASS.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -     Finishing the test.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Setting class to completed after 0 ms and finishing the test suite.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - All tests complete.
2022-05-25 14:16:10,545 [6990696]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Finishing test run.

    So I guess now we need to figure out what's different between these two environments...

  5. Jason Clark

    Scott - Please note my log shows two test runs - starting at Line 2 is a run that didn’t show a log:

    2022-05-25 14:27:33,961 [134265143]   INFO - #c.i.u.IlluminatedCloudExceptionUtil - Executing unit tests for run configuration 'JiraIntegration_Test.test_JiraIntegration_noCloudId'.

    and starting at line 85 is the second run that DID fetch the log:

    2022-05-25 14:36:17,771 [134788953]   INFO - #c.i.u.IlluminatedCloudExceptionUtil - Executing unit tests for run configuration 'JiraIntegration_Test.test_JiraIntegration_noCloudId'.

    All the lines in the first run are timestamped at 14:27, and the second run at 14:36. I think you caught the successful run and missed the bad one.

    In particular, these lines from the first run show it unable to fetch the log:

    2022-05-25 14:27:58,360 [134289542]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying Apex logs for tests.
2022-05-25 14:27:58,361 [134289543]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07LP000000gxA7MMAU' }.
2022-05-25 14:27:58,409 [134289591]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler - No Apex logs found for the test run.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0 logs found.
2022-05-25 14:27:58,410 [134289592]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - No class-level log found.

    Although I can query for that log by ID just fine.

  6. Scott Wells repo owner

    Hah! My mistake. That's actually more telling. As you point out, the one without logs...er...has no logs. To be more specific, the API result of an asynchronous test run is effectively a list of ApexTestResult objects queried via the Tooling API as:

    SELECT MethodName, Outcome, Message, StackTrace, TestTimestamp, SystemModstamp, ApexLogId
FROM ApexTestResult
WHERE QueueItemId = '<testQueueItemId>'

    Each entry should include a value for ApexLogId, and in fact I can see in your log that the test queue item did in fact include one:

    2022-05-25 14:27:58,361 [134289543]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07LP000000gxA7MMAU' }.

    That is then used to query the actual ApexLog objects, again using the Tooling API, as:

    SELECT Id, Application, DurationMilliseconds, Location, LogLength, Operation, Request, StartTime, Status
FROM ApexLog
WHERE Id IN (<commaDelimitedTestLogIds>)

    It appears that that query is returning an empty result set for a log ID returned by the previous query. That looks like a problem in the Salesforce API to me, but you should be able to confirm this the next time this issue occurs by running the following SOQL queries from IC2 with the Use Tooling API option enabled:

    SELECT MethodName, Outcome, Message, StackTrace, TestTimestamp, SystemModstamp, ApexLogId
FROM ApexTestResult
ORDER BY TestTimestamp DESC
LIMIT 1

    followed by the following query (also with Use Tooling API enabled) using the value for ApexLogId from the row returned above:

    SELECT Id, Application, DurationMilliseconds, Location, LogLength, Operation, Request, StartTime, Status
FROM ApexLog
WHERE Id IN ('<apexLogIdFromAbove>')

    If you get a row back from that query, something else must be going wrong in IC2. If you don't, something is going wrong in Salesforce regarding the test execution logs.

    Please let me know what you find.

  7. Scott Wells repo owner

    I noticed that you said "Although I can query for that log by ID just fine". What query are you running? And which API are you using to run that query (Partner vs. Tooling)? I wonder if there's perhaps a slight lag before that row is available or something. That's never been the case in the past, but if there is now (which might explain the worsening behavior for you), I can certainly add a short retry loop for the second query to see if that resolves the problem.

  8. Jason Clark

    I just hit the developer console and ran Select Id from ApexLog where Id = '07LP000000gxA7MMAU' to confirm it was there, but generally when I see this issue I can always go find the log in Dev Console or other Apex Log Viewer; your idea of a slight lag makes sense, since by the time I could go look for it by other means that lag would have passed.

  9. Scott Wells repo owner

    Here's a build that includes up to 5 attempts with a 250 ms pause before each new attempt so we can see if that is in fact what's happening. Let me know if you're not sure how to install it, but I think you've done this before.

    Let's see what happens, but if this doesn't resolve the issue, my next question will be are you that that query in dev console via the tooling API or the partner API? Also, any particular reason you're running the query from dev console since IC2 supports SOQL queries via both APIs now?

  10. Jason Clark

    install it

    I think so, I just did “install from disk” and after a restart I’m running 2.2.1, build 20220525152957 which looks like a today-build.

    Let's see what happens

    So I ran the test class I’ve been working on about 10 times in a row, and getting the test log back each time. I’ve also been checking the idea log, where I finally saw this:

    2022-05-25 16:54:48,031 [ 257822]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Adding setup method FulfillmentExceptionHandler_Test.setup.
2022-05-25 16:54:48,032 [ 257823]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L53000003slhbEAA' }.
2022-05-25 16:54:48,075 [ 257866]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Found 0 logs for 1 log IDs.
2022-05-25 16:54:48,076 [ 257867]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler - Found less logs than queried log IDs. Waiting a short time and trying to query missing logs again.
2022-05-25 16:54:48,329 [ 258120]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L53000003slhbEAA' }.
2022-05-25 16:54:48,374 [ 258165]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Found 1 logs for 1 log IDs.
2022-05-25 16:54:48,375 [ 258166]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Found 1 logs.
2022-05-25 16:54:48,375 [ 258166]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Retrieving the body for log ID 07L53000003slhbEAA.

    I’d call that an unqualified success, thank you for the rapid turnaround!

    my next question will be are you that that query in dev console via the tooling API or the partner API?

    I was just using the Dev Console default, without Tooling API checked. I guess that uses Partner API?

    any particular reason you're running the query from dev console since IC2 supports SOQL queries via both APIs now?

    Because I’m old and set in my ways lol. In truth, I run queries in from IC2 and from Dev Console, depending on what else I’m doing at the moment. In this case, I think because I had the debug log open in the bottom of my WS window, I just CMD-Tabbed to the browser to run the query, vs. swapping tabs in at the bottom of the WS window. Probably because I don’t know keyboard shortcuts for jumping between the Run and SOQL Query tabs. Maybe I should learn those!

    ‌

    At any rate, I’d call this a win. Anything I need to do to resume getting IC2 updates vs having the local build installed? Thanks again.

  11. Scott Wells repo owner

    No need to do anything special to get back onto official builds. Since you've helped confirm that the suspected delay was in fact the issue, I'll work this into tomorrow's build. Once I post it, you'll be prompted to update which will put you back on official.

    Yes, by default Dev Console uses the partner API (as does IC2). The reason I asked specifically about APIs is that I have seen some behavioral differences between the Tooling API and the corresponding Partner/Metadata API, so if this suspicion didn't bear fruit, I'd have started wondering if perhaps I should just be running those two queries via the Partner API instead. Sounds like that's not the case, though. I'll just massage this retry logic a bit to make it release-ready.

    Thanks for helping to confirm it, and for providing all of the diagnostic info that helped to corner it. Nothing like another weird one...

  13. Jason Clark

    @Scott Wells I’m on 2.2.2.2 now, and it just reoccurred. First off - I was on a mobile connection, not sure if that would affect the outcome. Fortunately, I hadn’t changed my idea logging yet, so I have log lines:

    ‌

    2022-05-26 21:03:40,079 [31574070]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying test results for RenewalOpportunityRollupService_Test.
2022-05-26 21:03:40,359 [31574350]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   4 test results returned.
2022-05-26 21:03:40,359 [31574350]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying Apex logs for tests.
2022-05-26 21:03:40,360 [31574351]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Adding setup method RenewalOpportunityRollupService_Test.setup.
2022-05-26 21:03:40,360 [31574351]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2200000CqAEAEA3' }.
2022-05-26 21:03:40,532 [31574523]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found 0 logs for 1 log IDs.
2022-05-26 21:03:40,533 [31574524]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found less logs than queried log IDs. Waiting a short time and trying to query missing logs again.
2022-05-26 21:03:40,788 [31574779]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2200000CqAEAEA3' }.
2022-05-26 21:03:41,033 [31575024]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found 0 logs for 1 log IDs.
2022-05-26 21:03:41,033 [31575024]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found less logs than queried log IDs. Waiting a short time and trying to query missing logs again.
2022-05-26 21:03:41,287 [31575278]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2200000CqAEAEA3' }.
2022-05-26 21:03:41,511 [31575502]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found 0 logs for 1 log IDs.
2022-05-26 21:03:41,512 [31575503]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found less logs than queried log IDs. Waiting a short time and trying to query missing logs again.
2022-05-26 21:03:41,767 [31575758]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2200000CqAEAEA3' }.
2022-05-26 21:03:41,921 [31575912]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found 0 logs for 1 log IDs.
2022-05-26 21:03:41,921 [31575912]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found less logs than queried log IDs. Waiting a short time and trying to query missing logs again.
2022-05-26 21:03:42,172 [31576163]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler - Querying logs with log IDs { '07L2200000CqAEAEA3' }.
2022-05-26 21:03:42,404 [31576395]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   Found 0 logs for 1 log IDs.
2022-05-26 21:03:42,405 [31576396]   WARN - #c.i.i.u.ApexUnitTestRunProcessHandler - No Apex logs found for the test run.
2022-05-26 21:03:42,405 [31576396]   FINE - #c.i.i.u.ApexUnitTestRunProcessHandler -   0 logs found.

    Would it be possible in this case to display a message in the test results window that logs couldn’t be retrieved, with a link to try again? That way you don’t add any more polling, but the user can still retry if needed.

  14. Scott Wells repo owner

    Not entirely surprising. It's all heuristic-based right now with a somewhat arbitrarily chosen 5x250ms retries, so if the log isn't there within 1.25 secs, it's going to miss. I think it probably makes the most sense to leave the interval the same and crank up the retry count. I can provide a build of 2.2.2.2 with that change in place. I'd prefer not to expose this as configurable given that it seems quite rare, so let's see if we can tune it to the point where it addresses the issue for you as close to 100% of the time as possible. I'll get you a build tomorrow sometime or Monday at the latest (tomorrow is my kids' last day of school).

  15. Jason Clark

    Thanks! Enjoy the day off! I’m out of office next week myself so I’m not likely to be using IC2, but I’ll look for a build when I’m back on 6/6.

  16. Scott Wells repo owner

    Jason, this week's build will include a small change to what was provided previously. I've made the log query retry params configurable via system properties:

    • ic2.log.query.max.attempts - defaults to 10; previously 5
    • ic2.log.query.pause.duration - defaults to 250 ms; same as before

    So hopefully things will just work with the larger number of attempts, but if they don't, you can use Help > Edit Custom VM Options... to set these properties as follows:

    -Dic2.log.query.max.attempts=20
-Dic2.log.query.pause.duration=500

    You likely only need to increase the first value as you tune this. I'll be curious to hear what value(s) work consistently for you.

  17. Scott Wells repo owner

    Jason, the changes described above were delivered in 2.2.2.3. I'll be interested to hear your findings after updating.

  18. Jason Clark

    @Scott Wells Of course, since the update I haven’t seen this issue at all. I’m guessing your tweaks to retry count and timing cover the 99% case, and I just got unlucky with a very slow POD on the day I originally tested. I’ll keep this page bookmarked and update you should I ever need to adjust the params, but for now my problem appears to be solved. Thanks again for your help.

  19. Scott Wells repo owner

    That's great to hear, Jason. Hopefully the additional tuning helped, but of course if you do see this behavior again the future, just reach out and we'll figure out the improved tuning params.

  21. Log in to comment
Assignee
–
Type
bug
Priority
minor
Status
resolved
Component
Apex Unit Testing
Version
2.0.5.6
Votes
0
Watchers
1
Jira: the preferred issue tracker for Bitbucket. Join the team!