[#GRAILS-7232] Refine the stack sanitization and improve the output readability of regular traces - Grails JIRA

Details

Type: Improvement
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 1.3.6
Fix Version/s: 2.0-M1
Component/s: None
Labels:
None

Description

I mentioned the idea to alter the output of stack traces on the list, and it was enthusiastically received.

Basically we'd either need to replace the printStackTrace impl or call our own stack dumper method whenever we dump traces. This may be non-trivial, but the gains will be significant.

Key requirements:

Make it trivial for people to see the deepest point of the trace - the point of failure
Hide groovy internals
Make it easier for humans who are not Java gurus to scan
Reduce duplication

Example desired output:

=============== GRAILS EXCEPTION ===================
Cannot get property 'userName' on null object (java.lang.NullPointerException)
doCall method on line 217 in NoticeUtilsService.groovy (NoticeUtilsService$_processResults_closure5_closure7)

Stack trace:

   Line  | Method               
->>  217 | doCall           in NoticeUtilsService.groovy
|        | - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
|    216 | doCall           in      "       "
|    214 | processResults   in      "       "
|    129 | mapFields        in KnownUserService.groovy
|     97 | sendMessage      in NoticeEventsService.groovy
|     58 | noticeEvent      in      "       "
|    199 | doCall           in BoardAreaController.groovy
|    167 | doArchiveRestore in      "       "
|    127 | doCall           in      "       "
^    680 | run              in Thread.java (java.lang)

See your unsanitized stack log for the full Java stack trace if necessary.

The detail is important here:

It needs to calculate column widths for line number and method, and align all text correctly
The arrows and separator are important visual cues
The source file is shown in the stack trace lines, NOT the class name. the package name is included in brackets, no brackets shown at all if code is in the default package
We need to filter out code with no source (Unknown Source)
We need configurable sanitized packages, so users can add stuff to Config - or preferably they can specify the list of package prefixes that are in their app, in Config: grails.stack.packages=['org.myapp']
Class names are in general not shown except in the first couple of lines of preamble.

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Marc Palmer added a comment - 07/Feb/11 10:18 AM

Here's an alternative format, with line number nearer the filename which scans a bit better:

=============== GRAILS EXCEPTION ===================
Cannot get property 'userName' on null object (java.lang.NullPointerException)
doCall method on line 217 in NoticeUtilsService.groovy (NoticeUtilsService$_processResults_closure5_closure7)

Stack trace:
   
    Method           | Line    Source file
-----------------------------------------------------------      
->> doCall           |  217 in NoticeUtilsService.groovy
|   - - - - - - - - -|- - - - - - - - - - - - - - - - - - - 
|   doCall           |  216 in      "       "
|   processResults   |  214 in      "       "
|   mapFields        |  129 in KnownUserService.groovy
|   sendMessage      |   97 in NoticeEventsService.groovy
|   noticeEvent      |   58 in      "       "
|   doCall           |  199 in BoardAreaController.groovy
|   doArchiveRestore |  167 in      "       "
|   doCall           |  127 in      "       "
^   run              |  680 in Thread.java (java.lang)

See your unsanitized stack log for the full Java stack trace if necessary.

Show

Marc Palmer added a comment - 07/Feb/11 10:18 AM Here's an alternative format, with line number nearer the filename which scans a bit better:

=============== GRAILS EXCEPTION ===================
Cannot get property 'userName' on null object (java.lang.NullPointerException)
doCall method on line 217 in NoticeUtilsService.groovy (NoticeUtilsService$_processResults_closure5_closure7)

Stack trace:
   
    Method           | Line    Source file
-----------------------------------------------------------      
->> doCall           |  217 in NoticeUtilsService.groovy
|   - - - - - - - - -|- - - - - - - - - - - - - - - - - - - 
|   doCall           |  216 in      "       "
|   processResults   |  214 in      "       "
|   mapFields        |  129 in KnownUserService.groovy
|   sendMessage      |   97 in NoticeEventsService.groovy
|   noticeEvent      |   58 in      "       "
|   doCall           |  199 in BoardAreaController.groovy
|   doArchiveRestore |  167 in      "       "
|   doCall           |  127 in      "       "
^   run              |  680 in Thread.java (java.lang)

See your unsanitized stack log for the full Java stack trace if necessary.

Hide

Permalink

Marc Palmer added a comment - 07/Feb/11 10:20 AM

The above could also use "@" instead of "in"

Show

Marc Palmer added a comment - 07/Feb/11 10:20 AM The above could also use "@" instead of "in"

Hide

Permalink

Jeff Brown added a comment - 07/Feb/11 1:47 PM

Does the "in" column really add anything to readability?

Show

Jeff Brown added a comment - 07/Feb/11 1:47 PM Does the "in" column really add anything to readability?

Hide

Permalink

Marc Palmer added a comment - 07/Feb/11 2:26 PM

I think in or @ is fine, but I think its important line number is before file name, with a meaningful separator...

Show

Marc Palmer added a comment - 07/Feb/11 2:26 PM I think in or @ is fine, but I think its important line number is before file name, with a meaningful separator...

Hide

Permalink

Marc Palmer added a comment - 07/Feb/11 4:19 PM

My thinking with line-number before source file name, is that often you are working on the file in question, and you really just want to know the line number first.

I accept that not everyone would agree...

Show

Marc Palmer added a comment - 07/Feb/11 4:19 PM My thinking with line-number before source file name, is that often you are working on the file in question, and you really just want to know the line number first. I accept that not everyone would agree...

Hide

Permalink

Charlie added a comment - 10/Feb/11 3:56 AM

Yes, I'd like to have a better view on the traces.
Normally I don't need the whole stack trace, really very, very seldom.
Normally the exception, the file and row number is enough.
If I really need the stack trace then it'd be good to get it easy, or it could be shown like you mentioned at the bottom, but most of the time it's a little bit time consuming to have a look at the whole stack trace and find only the one line I need - like it is now.

I've done 10 years of programming with ColdFusion and there the errors are displayed very easily and maybe this is why I'm so spoiled.
A quick view on it can help maybe to change your mind:
http://www.coldfusionjedi.com/index.cfm/2007/12/5/The-Complete-Guide-to-Adding-Error-Handling-to-Your-ColdFusion-Application

Thanks for the good idea Marc Palmer.

Show

Charlie added a comment - 10/Feb/11 3:56 AM Yes, I'd like to have a better view on the traces. Normally I don't need the whole stack trace, really very, very seldom. Normally the exception, the file and row number is enough. If I really need the stack trace then it'd be good to get it easy, or it could be shown like you mentioned at the bottom, but most of the time it's a little bit time consuming to have a look at the whole stack trace and find only the one line I need - like it is now. I've done 10 years of programming with ColdFusion and there the errors are displayed very easily and maybe this is why I'm so spoiled. A quick view on it can help maybe to change your mind: http://www.coldfusionjedi.com/index.cfm/2007/12/5/The-Complete-Guide-to-Adding-Error-Handling-to-Your-ColdFusion-Application Thanks for the good idea Marc Palmer.

Hide

Permalink

Marc Palmer added a comment - 23/Feb/11 10:24 AM - edited

Here's some Groovy code to do this. Ideally we should impl this in Java and put it into Groovy core, but for now here's what I had time to write. This runs in groovy console:

def prettyStackTrace(Throwable t) {
   def sb = new StringBuilder()
   if (t.message) {
       sb << "${t.message} (${t.getClass().name})\n"
   } else {
       sb << t.getClass().toString() + '\n'
   }
   
   def failurePoint = t.stackTrace[0]

   def failureFile = failurePoint.fileName ?: 'Unknown source'
   sb << "In: ${failurePoint.methodName} method, line ${failurePoint.lineNumber} in $failureFile\n"

   sb << "\nStack trace\n\n"

   def mln = Math.max(4, t.stackTrace.lineNumber.max())
   def lineNumWidth = mln.toString().size()
   def methodNameWidth = t.stackTrace.methodName*.size().max()+1
      
   def lh = "Line".padLeft(lineNumWidth+4)
   sb << "$lh | Method\n"
      
   def last = t.stackTrace.size()
   def prevFn
   def evenRow = false
   t.stackTrace[0..-1].eachWithIndex { te, idx ->
       def fn = te.fileName
       if ((idx == 0) || fn) {
           if (prevFn && (prevFn == fn)) {
               fn = "    ''"
           } else {
               prevFn = fn
           }
           if (!fn) {
               fn = "Unknown source"
           }

           def padChar = (evenRow || idx == 0) ? ' ' : ' .'
           evenRow = evenRow ? false : true

           def mn = te.methodName
           if (mn.size() < methodNameWidth) {
               mn = mn.padRight(methodNameWidth-1, padChar)
           }
           def ln = te.lineNumber.toString().padLeft(lineNumWidth)
           if (idx == 0) {
               sb << "->> $ln | $mn in $fn\n"
               sb << "- "*36
               sb << "\n"
           } else if (idx < last-1) {
               sb << "|   $ln | $mn in $fn\n"
           } else {
               sb << "^   $ln | $mn in $fn\n"
           }
       }
   }
   
   return sb
}

println "================ Grails Exception =================="
println prettyStackTrace(new RuntimeException('This is me blowing up!') )
println "For full Java trace see your unsanitized stacktrace log"

It also adds alternating row ". . . . . " to help the lines scan well with fixed width columns.

Fixed width columns may cause problems with long class names / line wrap, but it reads better for most cases. Taking out the padRight on the filename makes for a very unreadable result.

Example output:

================ Grails Exception ==================
This is me blowing up! (java.lang.RuntimeException)
In: newInstance method, line -1 in Unknown source

Stack trace

   Line | Method
->>  -1 | newInstance                     in Unknown source
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
|    27 | newInstance                     in DelegatingConstructorAccessorImpl.java
|   513 | newInstance . . . . . . . . . . in Constructor.java
|    77 | invoke                          in CachedConstructor.java
|   107 | callConstructor . . . . . . . . in ConstructorSite.java
|    52 | defaultCallConstructor          in CallSiteArray.java
|   192 | callConstructor . . . . . . . . in AbstractCallSite.java
|   200 | callConstructor                 in     ''
|    62 | run . . . . . . . . . . . . . . in stacktraceprint.groovy
|   264 | runScriptOrMainOrTestOrRunnable in GroovyShell.java
|   513 | run . . . . . . . . . . . . . . in     ''
|   170 | run                             in     ''
|   865 | doCall . . . . . . . . . . . .  in Console.groovy
|    25 | invoke                          in DelegatingMethodAccessorImpl.java
|   597 | invoke . . . . . . . . . . . .  in Method.java
|    88 | invoke                          in CachedMethod.java
|   233 | doMethodInvoke . . . . . . . .  in MetaMethod.java
|   273 | invokeMethod                    in ClosureMetaClass.java
|   886 | invokeMethod . . . . . . . . .  in MetaClassImpl.java
|    66 | callCurrent                     in PogoMetaClassSite.java
|   151 | callCurrent . . . . . . . . . . in AbstractCallSite.java
|    -1 | doCall                          in Console.groovy
|    25 | invoke . . . . . . . . . . . .  in DelegatingMethodAccessorImpl.java
|   597 | invoke                          in Method.java
|    88 | invoke . . . . . . . . . . . .  in CachedMethod.java
|   233 | doMethodInvoke                  in MetaMethod.java
|   273 | invokeMethod . . . . . . . . .  in ClosureMetaClass.java
|   886 | invokeMethod                    in MetaClassImpl.java
|   276 | call . . . . . . . . . . . . .  in Closure.java
|   271 | call                            in     ''
|   354 | run . . . . . . . . . . . . . . in     ''
^   680 | run                             in Thread.java

For full Java trace see your unsanitized stacktrace log

Show

Marc Palmer added a comment - 23/Feb/11 10:24 AM - edited Here's some Groovy code to do this. Ideally we should impl this in Java and put it into Groovy core, but for now here's what I had time to write. This runs in groovy console:

def prettyStackTrace(Throwable t) {
   def sb = new StringBuilder()
   if (t.message) {
       sb << "${t.message} (${t.getClass().name})\n"
   } else {
       sb << t.getClass().toString() + '\n'
   }
   
   def failurePoint = t.stackTrace[0]

   def failureFile = failurePoint.fileName ?: 'Unknown source'
   sb << "In: ${failurePoint.methodName} method, line ${failurePoint.lineNumber} in $failureFile\n"

   sb << "\nStack trace\n\n"

   def mln = Math.max(4, t.stackTrace.lineNumber.max())
   def lineNumWidth = mln.toString().size()
   def methodNameWidth = t.stackTrace.methodName*.size().max()+1
      
   def lh = "Line".padLeft(lineNumWidth+4)
   sb << "$lh | Method\n"
      
   def last = t.stackTrace.size()
   def prevFn
   def evenRow = false
   t.stackTrace[0..-1].eachWithIndex { te, idx ->
       def fn = te.fileName
       if ((idx == 0) || fn) {
           if (prevFn && (prevFn == fn)) {
               fn = "    ''"
           } else {
               prevFn = fn
           }
           if (!fn) {
               fn = "Unknown source"
           }

           def padChar = (evenRow || idx == 0) ? ' ' : ' .'
           evenRow = evenRow ? false : true

           def mn = te.methodName
           if (mn.size() < methodNameWidth) {
               mn = mn.padRight(methodNameWidth-1, padChar)
           }
           def ln = te.lineNumber.toString().padLeft(lineNumWidth)
           if (idx == 0) {
               sb << "->> $ln | $mn in $fn\n"
               sb << "- "*36
               sb << "\n"
           } else if (idx < last-1) {
               sb << "|   $ln | $mn in $fn\n"
           } else {
               sb << "^   $ln | $mn in $fn\n"
           }
       }
   }
   
   return sb
}

println "================ Grails Exception =================="
println prettyStackTrace(new RuntimeException('This is me blowing up!') )
println "For full Java trace see your unsanitized stacktrace log"

This adds some more variations (note the demo does not sanitize trace first, deliberately) including handling of "Unknown source" (filename == null) for the point of failure, but skipping any other null source rows (which is something sanitize should be doing actually). It also adds alternating row ". . . . . " to help the lines scan well with fixed width columns. Fixed width columns may cause problems with long class names / line wrap, but it reads better for most cases. Taking out the padRight on the filename makes for a very unreadable result. Example output:

================ Grails Exception ==================
This is me blowing up! (java.lang.RuntimeException)
In: newInstance method, line -1 in Unknown source

Stack trace

   Line | Method
->>  -1 | newInstance                     in Unknown source
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
|    27 | newInstance                     in DelegatingConstructorAccessorImpl.java
|   513 | newInstance . . . . . . . . . . in Constructor.java
|    77 | invoke                          in CachedConstructor.java
|   107 | callConstructor . . . . . . . . in ConstructorSite.java
|    52 | defaultCallConstructor          in CallSiteArray.java
|   192 | callConstructor . . . . . . . . in AbstractCallSite.java
|   200 | callConstructor                 in     ''
|    62 | run . . . . . . . . . . . . . . in stacktraceprint.groovy
|   264 | runScriptOrMainOrTestOrRunnable in GroovyShell.java
|   513 | run . . . . . . . . . . . . . . in     ''
|   170 | run                             in     ''
|   865 | doCall . . . . . . . . . . . .  in Console.groovy
|    25 | invoke                          in DelegatingMethodAccessorImpl.java
|   597 | invoke . . . . . . . . . . . .  in Method.java
|    88 | invoke                          in CachedMethod.java
|   233 | doMethodInvoke . . . . . . . .  in MetaMethod.java
|   273 | invokeMethod                    in ClosureMetaClass.java
|   886 | invokeMethod . . . . . . . . .  in MetaClassImpl.java
|    66 | callCurrent                     in PogoMetaClassSite.java
|   151 | callCurrent . . . . . . . . . . in AbstractCallSite.java
|    -1 | doCall                          in Console.groovy
|    25 | invoke . . . . . . . . . . . .  in DelegatingMethodAccessorImpl.java
|   597 | invoke                          in Method.java
|    88 | invoke . . . . . . . . . . . .  in CachedMethod.java
|   233 | doMethodInvoke                  in MetaMethod.java
|   273 | invokeMethod . . . . . . . . .  in ClosureMetaClass.java
|   886 | invokeMethod                    in MetaClassImpl.java
|   276 | call . . . . . . . . . . . . .  in Closure.java
|   271 | call                            in     ''
|   354 | run . . . . . . . . . . . . . . in     ''
^   680 | run                             in Thread.java

For full Java trace see your unsanitized stacktrace log

Hide

Permalink

J. David Beutel added a comment - 24/Feb/11 10:18 PM

I like the line number column next to the source file column.

Show

J. David Beutel added a comment - 24/Feb/11 10:18 PM I like the line number column next to the source file column.

Hide

Permalink

Peter Ledbrook added a comment - 25/Feb/11 12:50 AM

This feature probably needs some way for IDEs to force output to the old format, since that's the format they are used to processing.

Show

Peter Ledbrook added a comment - 25/Feb/11 12:50 AM This feature probably needs some way for IDEs to force output to the old format, since that's the format they are used to processing.

Hide

Permalink

Graeme Rocher added a comment - 14/Jun/11 3:39 PM

old output can be reactivated with "grails -verbose"

Show

Graeme Rocher added a comment - 14/Jun/11 3:39 PM old output can be reactivated with "grails -verbose"

Hide

Permalink

Richard Feldman added a comment - 26/Jun/11 8:30 PM

The following output is from the current 1.4-SNAPSHOT build, with CommentService intentionally throwing a RuntimeException with message "something broke":

| Server running. Browse to http://localhost:8080/
| Error 2011-06-26 20:16:49,080 ["http-bio-localhost/127.0.0.1-8080"-exec-9] ERROR errors.GrailsExceptionResolver  - Exception occurred when processing request: [POST] /comments - parameters:
body: foo
Stacktrace follows:
    Line | Method
->>   51 | createComment in CommentService.groovy
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
|    443 | doCall        in CommentController.groovy
|   1110 | runWorker . . in ThreadPoolExecutor.java
|    603 | run           in     ''
^    636 | run . . . . . in Thread.java

In the current build the exception reporter seems to replace the deepest point-of-failure message with "Exception occurred when processing request", which is the shallowest part of the trace. Right now -verbose is the only way I can see exception messages that occur at a deeper level than the controller.

Is this the intended behavior?

Show

Richard Feldman added a comment - 26/Jun/11 8:30 PM The following output is from the current 1.4-SNAPSHOT build, with CommentService intentionally throwing a RuntimeException with message "something broke":

| Server running. Browse to http://localhost:8080/
| Error 2011-06-26 20:16:49,080 ["http-bio-localhost/127.0.0.1-8080"-exec-9] ERROR errors.GrailsExceptionResolver  - Exception occurred when processing request: [POST] /comments - parameters:
body: foo
Stacktrace follows:
    Line | Method
->>   51 | createComment in CommentService.groovy
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
|    443 | doCall        in CommentController.groovy
|   1110 | runWorker . . in ThreadPoolExecutor.java
|    603 | run           in     ''
^    636 | run . . . . . in Thread.java

It's definitely nice that it shows me the details of the request - what was posted and so forth. But the first "key requirement" listed in this issue was "Make it trivial for people to see the deepest point of the trace - the point of failure". In the current build the exception reporter seems to replace the deepest point-of-failure message with "Exception occurred when processing request", which is the shallowest part of the trace. Right now -verbose is the only way I can see exception messages that occur at a deeper level than the controller. Is this the intended behavior?

Hide

Permalink

Graeme Rocher added a comment - 27/Jun/11 2:17 AM

Can you attach an example and I'll take a look? It should recursively show nested exceptions

Show

Graeme Rocher added a comment - 27/Jun/11 2:17 AM Can you attach an example and I'll take a look? It should recursively show nested exceptions

People

Assignee:

Graeme Rocher

Reporter:

Marc Palmer

Vote (46)

Watch (21)

Dates

Created:

07/Feb/11 10:07 AM

Updated:

27/Jun/11 2:17 AM

Resolved:

14/Jun/11 3:38 PM