Logs from async tests not available in Log Viewer

[Fernando Machado]

Sometimes I need to run tests asynchronously, otherwise tests that should pass will fail. But every time I set the option to "Always run unit tests asynchronously" the logs are not generated.

[Scott Wells]

Fernando, I fixed this very recently. Can you verify that you're on the latest build?

[Fernando Machado]

Hey Scott. Here's the version I'm running: 1.7.9.7-idea14

[Scott Wells]

Thanks for verifying. Do you mind going into Developer Console (Illuminated Cloud>Show Developer Console) and seeing what is configured under Debug>Change Log Levels? I just want to make sure that IC's trace flag and log level are there (it uses the same one as Developer Console).

[Fernando Machado]

Sure. Here you go:

[Scott Wells]

Thanks again. Do you mind deleting all of those and then trying again from IC. I've seen some problems with the correct trace flag/logging level being used from outside tools and have been discussing that with Salesforce.

For what it's worth, the fix I put in recently was required because of a very slight difference in the clocks between the database where the active date/time range of the trace flag is stored and the application server on which the actual logging occurs. I accommodated for that by setting the start date of IC's flag as a bit earlier to accommodate for such as slight drift. In all cases times are in GTM so there shouldn't be a timezone issue.

Anyway, perhaps more than you wanted to know, but I'm curious to know if the problem you're seeing is caused by other trace flags.

[Fernando Machado]

Thanks Scott. I deleted everything and ran the unit test from IC. But it is still not generating any logs. Here's the debug level that got generated:

And here's the trace flag:

[Scott Wells]

Okay, please add logging for the following classes using Help>Debug Log Settings, reproduce the issue, and send me your idea.log:

#com.illuminatedcloud.intellij.unittest.ApexUnitTestRunProcessHandler
#com.illuminatedcloud.client.ApexLogUtil

[Fernando Machado]

Here's the log Scott.

[Scott Wells]

Fernando, it looks like it's successfully getting a method-level log back from the server:

2017-08-06 09:17:49,058 [ 630811]  DEBUG - .ApexUnitTestRunProcessHandler - Querying Apex logs for tests. 
2017-08-06 09:17:52,637 [ 634390]  DEBUG - .ApexUnitTestRunProcessHandler -   1 logs found. 
2017-08-06 09:17:52,637 [ 634390]  DEBUG - .ApexUnitTestRunProcessHandler - No class-level log found. 
2017-08-06 09:17:52,637 [ 634390]  DEBUG - .ApexUnitTestRunProcessHandler - Processing results for test method trac_QuoteLineItemStampFieldsTest.testFieldMirroringFieldNotInCustomSetting. 
2017-08-06 09:17:52,637 [ 634390]  DEBUG - .ApexUnitTestRunProcessHandler -   Method-level log found. 

Just to verify, you're not seeing anything at all when you look at the console window for that test method's execution?

[Fernando Machado]

It shows everything on the console window. However it does not show anything on the Log Viewer (unless it is set to run synchronously), which allow us to show only debug statements, start the debugger, etc.

[Scott Wells]

Ah, perhaps I've been misunderstanding. I've been thinking that no log is ever produced at all, but if I understand you correctly now, the log is shown properly in the unit test output window but cannot be be found in the Log Viewer tool window. Is that correct? Just want to make sure I'm debugging the right thing.

[Fernando Machado]

Yep, that's it!

[Scott Wells]

Gotcha. I've updated the issue summary to reflect the actual problem to ensure that I'm debugging the right thing. Thanks for clarifying!

[Scott Wells]

Interesting. Evidently querying for ApexLog.LogLength via the Tooling API can cause log entries to drop out of the result set. Never would've guessed that, but that's the issue. I guess I'll just issue multiple queries for the Log Viewer tool window to ensure I get all of the logs and lengths for those where it's available. This should be fixed in tomorrow's build.

[Fernando Machado]

Cool, thank you Scott.

[Scott Wells]

No, thank you! There's no way I would've stumbled into this one without a concrete use case that demonstrates it!

[Scott Wells]

Okay, I have to revise my assessment of what's going on here. Turns out the issue is that IC is deleting the logs from async test execution after displaying them in the test results. It has to do that in cases where the test results don't include explicit log IDs and IC has to "attach" the latest log to the test result. However, that's very much the exception to the rule, so I've made it only delete the logs when that happens and leave them when it's behaving properly. This should give you the desired behavior. Again, it'll be included in tomorrow's build.

[Scott Wells]

Delivered in 1.7.9.8.