Inconsistent logging output!

Question

I am trying to log some values for general testing and I am getting some really strange behaviour. Some of the logs are just not printing. This is what is happening:

1. I am pressing a button that runs a query, make some calculations and displays the results in a table
2. When the button action method runs, I am writing messages to the console using System.debug
3. Confusingly, some of the messages are just not showing when run. For example, I get the last print of the method, but not the first one (on the first line of the method). How can the last line print, but not the first??? There is no login before the first line that would mean that it would not be run. If the last line runs, then so must the first line...

I have been able to find the method (makeCalculations) that causes the "problem". If i remove this method, then the logs seem to print out as expected. But the trouble is, I was kinda wanting to make those calculations. If I go into more detail, I can get about half of the method (makeCalculations) commented out and the console logs are still fine. But if I add just one additional System.debug line to that method, then the logs become screwey again.

I think I can assert that it is not that the System.debug is not being called, because setting variables which are shown on the page above and below the line and they output as expected.

I have also tried downloading the raw log file in case there was some limit on the browser (which I think i have reached before, but when I did, I was alerted to this fact). The only real thing I can think of is:

1. There is a limit to the number of logs you are allowed to output and to be really mean they decided to just randomly delete some log messages, but not all.
2. I have too mush sql - I don't think so - only three
3. The code is running for too long - maybe, but the calculations are only iterating over a small collection and the calculations are not anything special (there are a lot of them though)

Any ideas? This is driving me crazy.

---

update

Added the code to a gist as requested. The names have been changed to protect the innocent. Apologies for the length. The code comes in through doSearch. The method 'makeCalculations' gets called on an inner class, which in tern instantiates a different inner class. The second class is where the calculations are done.

Update 2

I have tried changing the logging levels (as discussed in the comments below), with no apparent change. Any further ideas appreciated.

Update 3

After a bit more pain with this. I have found that the most reliable way to get logging is by throwing exceptions as suggested below. A little less destructive, but not always as reliable is to add an ApexPages memssage (ApexPages.addMessage(new ApexPages.Message(ApexPages.severity.ERROR, 'Search did not validate....'));)

Answer 1

This seems to happen whenever the log is very long. Salesforce seems to skip your Logging statements to put more of their own into the file.

The only (ugly) workaround I found for those case to throw a custom exception that shows my debug output. That always reveals a result.

Answer 2

I have had this issue recently where the Apex class I am attempting to debug performed a lot of calculations/script statements. The platform will truncate the debug logs and you would see something along the lines of ******** Max debug log size reached********.

What worked for me was to a combination of the methods mentioned above (I notice you have tried changing the logging levels)

1. Upping the logging level in your debug statement i.e System.debug(Logginglevel.ERROR , ::::::: My Debug :::::::::::::)

2. Setting up my debug logs with filtering with the filters below through the salesforce UI

   • Database : NONE
   • Workflow : NONE
   • Validation : NONE
   • Callouts : NONE
   • Apex Code : ERROR
   • Apex Profiling : NONE
   • Visualforce : NONE

For more detailed info check out this awesome blog post http://forceguru.blogspot.co.uk/2011/04/system-debug.html

Answer 3

I think what you are trying to do is a classic developer problem. We tried to find the line of code which causes the problem and think if salesforce logs would atleast say something to us to know where the problem is. So to solve this, you need to follow the method of guess and elimination.

1. comment out all methods where you think the problem is not there.

2. Make the system filter to none so that you dont want loops to be printed.

3. if this is a vfpage, use apex messages to print on the screen.

4. Use developer console to view the log and see if if shows the values.

Once you know, the value of the variables, then you can easily fix the line of code. Doing this 3 times would help you to come to the problematic code area. Sorry for being too theory oriented but this might help..