Logs Not Generated When Running Tests

[Anthony Sanchez]

The run window used to provide log information when running tests. It seems they no longer do.

[Anthony Sanchez]

It looks like this may be intermittent? I actually get logs when tests pass.

[Anthony Sanchez]

I think this may be user error. I didn't have my log levels set appropriately :/

I'll mark this as resolved Scott.

[Anthony Sanchez]

User error.

[Greg Beams]

I'm not seeing any logs for passing tests and just the failing assertion for failing tests. This is when running tests with the 'Full Debugging' preset selected under the Run/Debug Configurations.

[Scott Wells]

Greg, I see that Anthony resolved this issue which may not be the same as the one you're seeing. Would you mind logging a distinct issue with details on exactly what you're doing when it happens?

[Matt Addy]

I've run into this issue as well, which I think may be a regression after fixing #312. I can get you more information, but I believe this happens when you have a trace flag set for the user before running the tests. Removing all trace flags for the user, then re-running the tests fixes it.

[Scott Wells]

Moving this back to open as others are encountering it as well. I agree with Matt that it's a regression from the change to be more conservative about which trace logs are managed by IC. While there's a workaround, it's definitely impacting more and more people, so I'll see if I can turn around a fix in short order.

[Anthony Sanchez]

Thank Scott, I was also about to reopen this as I noticed the issue would only resolve itself if the trace flag was set outside of IC e.g. running tests in Dev Console.

[Scott Wells]

Prospective fix delivered in 1.7.1.9. I was never able to reproduce the issue, but I think I can see how it might have happened. Please reopen with detailed steps to reproduce if the problem still exists.

[Stefan Abramiuk]

Hi @RoseSilverSoftware I have same issue. It looks like IDE is not registering (or doing it wrog) User Trace Flags. When I open Developer Console (just open) then it works fine.

[Scott Wells]

Stefan, were you using 1.7.1.9 when this happened? If so my prospective fix didn't address the problem.

[Stefan Abramiuk]

Hi Scott, yes I'm using 1.7.1.9 version.

[Scott Wells]

Thanks for confirming, Stefan. I think I may roll back to the previous behavior that I tried to address in #312 while I come up with a better solution overall.

[Scott Wells]

Back to open.

[Scott Wells]

For those of you experiencing this issue, I have a few questions before I revert to the previous behavior in hopes that I can get enough info to solve the real problem here in short order. I've been unsuccessful in reproducing this behavior, but obviously it's happening to enough people that it's something that needs to be addressed. I'd really appreciate it if you could tell me the state of your TraceFlags and DebugLevels in your org when the problem is occurring so that I can try to reproduce and/or characterize the issue enough to produce a deterministic fix. First let me describe in detail what exactly I'm now trying to do so that we can look at what's actually happening and figure out why it's not working out as intended.

First I'm creating or updating a Tooling API DebugLevel with the requested log levels with DeveloperName and MasterLabel set to "IlluminatedCloud". I first query whether a row already exists with that developer name and, if not, I create one; if so, I update the existing one.

Once that's in place, I query any existing trace flags where TracedEntityId = <current-user-id>, LogType = "USER_DEBUG", and DebugLevel.MasterLabel = "IlluminatedCloud". If such a trace flag already exists, I delete it. This is because I'm limited in how I can adjust the expiration date, so it makes more sense to start from scratch. I then create a new Tooling API TraceFlag with the requested logging levels and the following field values:

• DebugLevelId = <debug-level-id-from-first-step>
• TracedEntityId = <current-user-id>
• LogType = USER_DEBUG
• StartDate = <now>
• ExpirationDate = <two-hours-from-now>

I'd be very interested to know exactly what TraceFlags and DebugLevels exist in your orgs when logs are failing to return. I'd also like to know if idea.log contains any failures in this area, in particular anything like the following:

• "Failed to create/update debug level"
• "Failed to delete old trace flag"
• "Failed to create trace flag"

Anything you can provide to help diagnose this is greatly appreciated!

[Anthony Sanchez]

Scott, I took a quick look at this just now while I had a spare moment. I'm seeing this line multiple times in my idea.log

2016-05-31 09:55:04,940 [1659034]   WARN - inatedcloud.client.ApexLogUtil - Failed to create trace flag 

Also, in my Org the only debug I have showing up under my user is this one:

[Scott Wells]

Thanks, Anthony. That at least confirms the root cause...basically the requested trace flag isn't being created. Unfortunately it's not providing much in the way of details. When I print that message I'm also trying to print the error details from the save result, but evidently the API isn't giving me back anything useful or it would be included.

Do you mind showing me your trace flag configuration from the Developer Console? You should be able to get more info than in the Setup menu. Let me know if you're not sure how to get to it. Thanks again!

[Anthony Sanchez]

Sure thing Scott. I wasn't sure exactly how to get the trace flag config from the DevConsole though. I just pulled the settings through a query:

Let me know if this works. If not, I can get the config if you can point me in the right direction.

[Scott Wells]

Okay, I'm 99% sure that the reason for this is the following:

https://releasenotes.docs.salesforce.com/en-us/summer15/release-notes/rn_apex_debug_logs.htm

in particular the fact that "trace flags set in the Developer Console override all other logging logic". When I made the change in issue #312 to be a good citizen and not delete the Developer Console's trace flag, I basically made my own trace flag a second-class citizen. Because the Developer Console automatically creates its own trace flag when it's opened, mine is going to be trumped.

I've been looking at a few options for addressing this:

1. Return to co-opting the Developer Console's trace flag which definitely sets the log levels properly, but creates ambiguity around who "owns" that trace flag.
2. Add a DebuggingHeader to calls, but unfortunately not all of the API calls that I make support this header, notably the Tooling API's runTestsAsynchronous REST resource which I use for unit testing.
3. Add a class/trigger (vs. user) trace flag for the entry point of a process (typically a unit test), but this won't work well when running tests for multiple classes.
4. Add a full configuration UI for log levels and trace flags instead of trying to route everything through one log level/trace flag pair for Illuminated Cloud.

The second and third options aren't general enough solutions, so I'm pretty much discarding those. The fourth option is probably the best one because it affords the most flexibility, but I really hate that I can't just set the logging levels for IC's processes without requiring the user to think that hard about things. I think for the moment I'm going to return to the original behavior as in the first option, trying to see if I can be a better citizen and not delete things I don't actually own. I'm also going to ping the kind folks at Salesforce who are in charge of these particular features and see if I'm missing something. It just seems odd that things work the way they do today.

[Scott Wells]

Okay, I went with option 1, but I no longer delete trace flags or log levels...I just update them. In particular, I now use the exact same ones that are created/managed by the Developer Console. Hopefully this puts this class of issues to rest.

[Scott Wells]

Delivered in 1.7.2.6.

[Scott Wells]

Unfortunately this still doesn't seem to be fixed. Now some users are seeing the following sometimes:

2016-06-29 10:58:15,875 [ 236582]   WARN - inatedcloud.client.ApexLogUtil - Failed to create trace flag
FIELD_INTEGRITY_EXCEPTION - Trace flags can be active for up to 24 hours. Set ExpirationDate to be less than 24 hours from StartDate, or, if StartDate is null, less than 24 hours from now.: Expiration Date; fields = ExpirationDate 

[Scott Wells]

Yet another round of work on this including:

• Consistently specifying the trace flag start date in addition to the expiration date to avoid the "Set ExpirationDate to be less than 24 hours..." issue.
• For anonymous Apex execution, changed the way that logs are retrieved to use the API's DebuggingHeader/DebuggingInfo SOAP header mechanism. This required a change to the Apex API vs. the Tooling API for anonymous Apex execution because the Tooling API doesn't seem to respect that header even though it's documented to do so (I've contacted Salesforce about this). Anyway, a nice side-effect of this is MUCH faster anonymous Apex execution because 3-4 API calls are now collapsed into a single call.
• Also for anonymous Apex execution, trace flags/debug levels are now managed in the same manner as in the Log Viewer tool window. This is because DebuggingHeader doesn't supersede the Developer Console's trace flag/debug level for that request.

Perhaps some other small fixes that aren't occurring to me right now. I'm really hoping that this set of changes really-truly-for-sure puts this issue to rest, at least within the confines of how trace flags/debug levels work in Salesforce currently.

[Scott Wells]

Taking a chance and resolving this one again for what I hope to be a final fix delivered in 1.7.2.7.