Log Viewer - log retrieving not always working

[Clio K]

I have an issue with the log viewer not retrieving logs at times.

I can force it to start working by opening the Developer's Console. This work around is not ideal as the Developer's Console log monitoring times out after awhile (typically at a time when I just spent a lot of time to recreate a manual test / debug condition and didn't notice).

I have not been able to find a simple reproducible case.

Any ideas what is happening?

Any ideas on how I can gather some more details to assist with troubleshooting?

[Scott Wells]

Clio, can you verify that you're on the latest build? There were some fixes added semi-recently (last few months) to address some problems keeping the trace flags current and pulling logs for some specific operations. If you are on the latest build and this happens, please add the following under Help>Debug Log Settings and send me your idea.log (Help>Show Log in Explorer/Finder/Files) when this happens so that I can see what's going on:

#com.illuminatedcloud.client.ApexLogUtil

[Clio K]

on version - 1.8.0.4

added the debug flag as above...

clicked on log refresh button...no logs shown...

got the following (doesn't look very helpful)

2017-10-05 14:56:27,799 [194135128] INFO - lij.diagnostic.DebugLogManager - Set DEBUG for the following categories: #com.illuminatedcloud.client.ApexLogUtil 2017-10-05 14:57:27,979 [194195308] INFO - ide.actions.ShowFilePathAction - Exit code 1 2017-10-05 14:59:22,732 [194310061] INFO - ide.actions.ShowFilePathAction - Exit code 1

[Clio K]

I also tried a restart of the IDE, still no log entries appear as a result of clicking the log refresh button..

[Scott Wells]

Yeah, I wouldn't expect an IDE restart to help. Clio, can you see what all trace flags exist in your org via the Developer Console and remove any you aren't actively using. The order of precedence for trace flags in Salesforce is a bit weird and I'm concerned that perhaps the one being managed by IC is being "starved out" or something. Honestly there's just not much to this...it runs a SOQL query to list the header-level information about the logs in the org, then when you open one it runs a REST request to pull the log body for display. It's not something that would generally be affected by outside caches or anything...at least not in the IDE. Let's make sure we're working against a clean environment from a trace flag perspective and then see if it's reproducible. If so, I might have you run some queries against the org while it's happening to see if we can corner it.

[Clio K]

The mystery deepens...

With no changes, the next morning logs are now retrievable, including ones that would not show the day before.

I checked the debug trace flags in the DC. My user was listed several times in the "user tracing for all users" but all showed expired. I deleted all entries from this section. I now have just a single entry in "general trace settings for you". I'll let you know if the issue comes back and there are any changes in these settings.

[Scott Wells]

Yeah, that's definitely strange. The next time it happens please let me know ASAP and maybe we'll jump on a screenshare to see if we can pin it down while it's happening.

[Kevin Vizcarra]

@RoseSilverSoftware I also have this issue with scratch orgs and Illuminated Cloud version 2.0.0.6. Adding #com.illuminatedcloud.client.ApexLogUtil to the Debug Log Settings doesn't show any new debug entries when opening or refreshing the Log Viewer. My current workaround is to open and close the Developer Console to initiate logging. Ideally, I wouldn't need to do this and instead logging would be started when the Log Viewer is open.

[Scott Wells]

Thanks for letting me know, Kevin. We can get an entirely other level of debug logging going that should she more insight if this is reproducible for you. You can add the following to Debug Log Settings:

#com.illuminatedcloud.client.ForceComApiClient
#com.illuminatedcloud.client.ForceComApiClient!trace

and then restart the IDE. This is going to produce VERY verbose log files because every SOAP interaction with the server is going to be logged. I would recommend that you do this when you first see the problem happen, enable logging, reproduce the problem, send logs to me, and then disable logging. Hopefully that will shed some light on what's happening.

[Scott Wells]

Kevin sent a log earlier showing detailed SOAP interactions when the problem is happening and then after opening Developer Console and trying again when the problem goes away. It was very useful in showing me the behavior as it occurs, but unfortunately it didn't yield any concrete insights into the underlying issue. Basically I see SOQL queries for the TraceFlags which are identical before and after, the queries for the actual ApexLog rows which are empty before and include rows after, and while the problem is occurring I also see a query for the DebugLevel which looks as expected.

Here's what I think I'm going to need to be able to continue to debug this issue...when the problem is occurring, please drop to the sfdx CLI and execute the following two commands, capturing their output:

sfdx force:data:soql:query -u <usernameOrAlias> -t -q 'SELECT ApexCode, ApexProfiling, Callout, CreatedById, CreatedDate, Database, DeveloperName, Id, IsDeleted, Language, LastModifiedById, LastModifiedDate, MasterLabel, System, Validation, Visualforce, Wave, Workflow FROM DebugLevel' --json
sfdx force:data:soql:query -u <usernameOrAlias> -t -q 'SELECT ApexCode, ApexProfiling, Callout, CreatedById, CreatedDate, Database, DebugLevelId, ExpirationDate, Id, IsDeleted, LastModifiedById, LastModifiedDate, LogType, StartDate, System, TracedEntityId, Validation, Visualforce, Wave, Workflow FROM TraceFlag' --json

Then open Developer Console, verify that it's resolved the issue and you see logs, and then repeat the two commands above, also capturing their output. That should show me what the DebugLevel and TraceFlag rows look like when managed by IC compared to what they look like when managed by Developer Console. Once I can see the differences (if there are any), I can update IC to emulate Developer Console in terms of how it configures these two rows. This is critical because Developer Console is hard-coded by Salesforce to have absolute highest priority when it comes to logging, hence why IC tries to configure things in an identical fashion. There must be something it's not quite doing, and hopefully this will expose that difference...

Thanks for the help debugging this!

[Scott Wells]

Kevin was able to provide the output of the requested queries. I think it contains the answer to the problem. While the issue was happening, the TraceFlag had an expiration date in the past which evidently opening Developer Console corrected. I'll take a look at when the TraceFlag is being updated by IC and make sure that it's always kept current just as the DebugLog is. Hopefully I'll have a final fix for this in the next-next build (the next build is already ready to go). Thanks for all the diagnostic info!

[Scott Wells]

Issue tracker grooming. If this is still an issue, please feel free to reopen, ideally with a concrete reproduction scenario.