Sign Up ›

Browse by Topic
ShowAll Questionssorted byDate Posted
+ Start a Discussion
BodhiDharmaBodhiDharma 

New Debug Logs Don't Log Method Names or Save Filter Settings

I am in the middle of debugging an Apex/Visualforce application, and the maintenance that just occurred this evening (1/22/10) just completely changed the behavior of the debug logs.  Two problems with this new behavior:

 

- My filter settings don't seem to be saving.  For instance, when I change my filter settings to "FINEST" in Apex Code and Save, those changes do not show up when I go to filter settings again.

 

-MOST IMPORTANT: the log line does not show the method name. Here is an example of the new format:

 

23:35:20.832|CODE_UNIT_FINISHED
23:35:20.833|CODE_UNIT_STARTED|[EXTERNAL]VForcePage
23:35:20.840|USER_DEBUG|[157,4]|DEBUG|***s.Id b4: a4yQ000000000DAIAY
23:35:20.840|DML_BEGIN|[159,3]|Op:Upsert|Type:BP_Stage_Rule__c|Rows:1

 

Notice - no method name in any of the debug lines.

 

I went to the Help and Training to find out if I am doing something wrong. It says the event identifier will log "any additional information logged with that event, such as the method name or the line and character number where the code was executed."  But they give an example pretty much like the one I copied and pasted in here -- no method name.

 

If anyone has any insight on how to get the method name to show or how to get the old debug log format to show, please be so kind as to respond.  If this is not possible, then salesforce just got 10 times harder to debug in my book.

 

Thanks for any help!

Message Edited by BodhiDharma on 01-23-2010 12:04 AM
tmatthiesentmatthiesen
This is a known bug and has been resolved in the next patch.  I'm checking the exact timing of the patch.  Will respond today with the exact timing.
SteveFromTLSteveFromTL

I'm not getting any debug output either in the Force.com IDE or the System Log window. All I get is 'Anonymous execution was successful.' in the results panel. Works fine in my Prod and Dev instances. 

 

Same issue?

tmatthiesentmatthiesen
The IDE issue is a separate bug.  I believe the IDE team is investigating this.  The patch on wednesday night will include the fix for the method names as well as the filter setting bug.
MarkL.ax269MarkL.ax269
Looks like nothing happened Wednesday night, at least on tapp0. The debug log is so much harder to use now, please get it back to the old format!
tmatthiesentmatthiesen
Did you set the apex debug level to finest?
MarkL.ax269MarkL.ax269
Yes I did, and what I get looks like raw debug information, very hard to use. The old format was much better organized and informative. Here's a snippet. What happened?

13:47:02.861|SOQL_EXECUTE_BEGIN|[176,27]|Aggregations:0|select Id from Account where Area_ID__c like :this.searchAcct
13:47:02.955|SOQL_EXECUTE_END|[176,27]|Rows:1|Duration:94
13:47:03.538|SOQL_EXECUTE_END|[140,26]|Rows:12|Duration:691
13:47:03.541|USER_DEBUG|[230,13]|DEBUG|config variable: Variable__c:{Category__c=Product Default, Product_Setup__c=01t60000001oyaHAAQ, Priority__c=3, Default__c=false, Name=V643822, FieldID__c=CT3, Field_Value_Reference__c=Value__c, Variable_Master__c=a0Q6000000070bTEAQ, Id=a0RT0000000Xo9yMAC, Type__c=Text, Max_Length__c=80}
tmatthiesentmatthiesen

Looking at the below log there should be a method entry event which shows the corresponding source.

The below items are straightforward, no?  I think you omitted the first SOQL_EXECUTE_BEGIN [140,26]

 

Can you log a case and add the case# to this post.  I basically need repro steps and support login access.  This is my #1 priority.  

 

Changing the log format was a very difficult choice and we are aware there will be some pains with the new format.  Our goal is to guarantee that no fidelity was lost with the new format.  If there was a loss in fidelity, then it's a serious bug.  

 

The benefits of the new format combined with the filtering will allow developers to view entire executions without dealing with log truncation.

 

Additionally, this format paves the way for the exciting "debugging" enhancements we are planning for later this year.
MarkL.ax269MarkL.ax269
I didn't include everything, just a snip from the middle. You're telling me this format is correct? I must have missed the announcement of the change. It's incredibly hard to read, I can't believe this was supposed to be an improvement. It looks like raw pipe-delimited data that in the old log, was parsed into something legible. From the looks of it, I'd be better off importing it into a spreadsheet and trying to build my own reader, and that is a huge loss in productivity. There also used to be very useful summary information at the bottom if I was trying to determine where I needed performance improvements and so on, which is just gone. Here's a more complete snippet, still only a tiny fraction of a sizeable log file.

13:46:41.067|VF_APEX_CALL|j_id29|{!beginSearch}|PageReference: none
13:46:41.085|CODE_UNIT_STARTED|[EXTERNAL]VForcePage
13:46:41.085|CODE_UNIT_STARTED|[EXTERNAL]orders
13:46:41.085|SOQL_EXECUTE_BEGIN|[270,42]|Aggregations:0|select Id, Area_ID__c, Full_Product_Code__c, Quantity, Order_Line_Item__c, Order_Status__c, Opportunity.AccountId from OpportunityLineItem where Area_ID__c like :this.searchAcct and PricebookEntry.ProductCode = :this.inputProd and Order_Status__c in ('Signed','Confirmed','Production') order by Area_ID__c, Order_Line_Item__c
13:46:41.588|SOQL_EXECUTE_END|[270,42]|Rows:2|Duration:503
13:46:41.589|SOQL_EXECUTE_BEGIN|[121,26]|Aggregations:0|select Id, Name, Type__c, FieldID__c, Field_Value_Reference__c, Max_Length__c, Order_Line_Item__c, Value__c, Default__c, Category__c, Priority__c, Address_Name__c, Primary_Address_Line__c, Secondary_Address_Line__c, City__c, State__c, Zip_Postal_Code__c, Country__c, County__c, Product__c, Product_Setup__c, Variable_Master__c, Variable_Master__r.Name, Variable_Master__r.Class__c, Variable_Master__r.Type__c, SigFormalName__c from Variable__c where Product_Setup__c = :this.pid order by Variable_Master__r.Name, Priority__c desc
13:46:41.599|SOQL_EXECUTE_BEGIN|[165,11]|Aggregations:0|select Id from Product2 where ProductCode = :this.inputProd limit 1
13:46:41.606|SOQL_EXECUTE_END|[165,11]|Rows:1|Duration:7
13:46:41.917|SOQL_EXECUTE_END|[121,26]|Rows:33|Duration:328
tmatthiesentmatthiesen
The log should include the profiling information at the bottom - similar to before.  If it's not there, please log a case and add the case# to the post.  Can you also respond directly to me, I'd like to see if we could schedule time to walk through this.
MarkL.ax269MarkL.ax269
Yes I'll log a case, and thanks for the help. PM coming up.
MarkL.ax269MarkL.ax269
Case 03266183 Debug log new format is missing profile/summary information.
BodhiDharmaBodhiDharma

I am still experiencing the following problems:

 

- Filter Settings are not being saved in Monitoring > Debug Logs.  You must put the settings in an open System Log window and keep that window open for the settings to persist in  Monitoring > Debug Logs.

 

- When an exception is thrown by a page, no debug log is captured.

BodhiDharmaBodhiDharma

On last post I reported:

- When an exception is thrown by a page, no debug log is captured. 

 

This seems to be working now.   The other problem of filter settings not being saved still persists. Thanks.

BodhiDharmaBodhiDharma
Another thing: The Setup > Monitoring > Debug Logs page takes an extremely long time to load and sometimes times out.  The other Setup pages load fine.  I am trying to access this from the Salesforce internal network in San Mateo so there are no network issues.  This behavior started after you did the Wednesday patch.
BARJRDBARJRD
I'm having the same problem --- when I change the debug filter settings, then save --- nothing happens. 
BARJRDBARJRD
Also, whenever I try to delete a log file, I receive a URL No Longer Exists error.
tmatthiesentmatthiesen

Thank you all for your patience.  We've unfortunately found a number of bugs with the new system/debug logs, namely:

1) delete logs redirects the user to the login screen and logs them out

2) filter settings are not persisting

3) Issues with IE and formatting (seems fine with firefox or safari)

4) VF requests are not including profile details 

 

I think we've resolved all of these in the latest patch.  We are reviewing our UI ftest framework to figure out why these issues were not caught during our QA process.

 

I will respond to this thread later today with all the known issues and corresponding patch timings.  
bikerdan76bikerdan76
Any update on this?  Also, how soon can we expect to see the fixes?
BodhiDharmaBodhiDharma

One thing I've noticed about the debug log format is even though you specify the method names, you don't always preface them with the class name.  For example, look at the last line in the log below.  

 

 13:20:18.540|METHOD_ENTRY|[50,4]|TeamSellingActionBuilder.createRuleAction(TeamSellingActionBean)

13:20:18.540|METHOD_ENTRY|[171,5]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[171,5]|getBpAction()13:20:18.541|METHOD_ENTRY|[171,55]|TeamSellingActionBean.getParentRuleBean()13:20:18.541|METHOD_EXIT|[171,55]|getParentRuleBean()13:20:18.541|METHOD_ENTRY|[171,92]|TeamSellingRuleBean.getBpRule()13:20:18.541|METHOD_EXIT|[171,92]|getBpRule()13:20:18.541|METHOD_ENTRY|[172,4]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[172,4]|getBpAction()13:20:18.541|METHOD_ENTRY|[172,61]|TeamSellingActionBean.getBpProcessorControl()13:20:18.541|METHOD_EXIT|[172,61]|getBpProcessorControl()13:20:18.541|METHOD_ENTRY|[173,7]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[173,7]|getBpAction()13:20:18.541|METHOD_ENTRY|[176,5]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[176,5]|getBpAction()13:20:18.541|METHOD_ENTRY|[177,5]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[177,5]|getBpAction()13:20:18.541|METHOD_ENTRY|[177,74]|TeamSellingActionBean.getBpAction()13:20:18.541|METHOD_EXIT|[177,74]|getBpAction()13:20:18.541|METHOD_EXIT|[50,4]|createRuleAction(TeamSellingActionBean)13:20:18.541|METHOD_ENTRY|[51,4]|LIST:TeamSellingActionBean.add(TeamSellingActionBean)13:20:18.541|METHOD_EXIT|[51,4]|add(ANY)13:20:18.541|METHOD_EXIT|[72,4]|createNewBean(TeamSellingBean)

 

createNewBean is a method in TeamSellingActionBuilder which is most recently mentioned in the first line of this snippet.  This is a huge inconvenience when debugging a complex application.  It is hard to have to scroll up the log to decipher what class a method call belongs to.  In this example, had I not known with some digging that createNewBean was in TeamSellingActionBuilder, what class would I know to go to line 72 of?

 

Can you guys please bring back the old format that prefaces every method call with the class name?  The debugging experience is hard enough in Salesforce without a step through debugger and this is making it more difficult.

 

Thanks! 
LaurentDelcLaurentDelc

Hi everyone,

 

So? Any response for Salesforce about this huge inconvenience? Indeed debugging without seeing the class name is burden.

 

Cheers,

 

Laurent