groovy

When accessing a property on a null object inside of a closure, the line number is not always reported in the stack trace.

Details

  • Type: Improvement Improvement
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 1.5.6
  • Fix Version/s: 1.5.8
  • Component/s: Compiler
  • Labels:
    None
  • Number of attachments :
    1

Description

If we have a simple script such as follows:

package example

def t = { someVariable.property = 1 }

t()

When we run this, it will report a NPE and in the stack trace line 5 the call to t() will show up, but up the stack it will only show the file name on calls inside the closure with no line number. This is even worse when the call originates from java so that you could not even have a clue as to where in the groovy script the NPE took place.

Activity

Hide
blackdrag blackdrag added a comment -

someVariable needs to be defined before it can be used and it has to have the value null if it should cause the NPE. But fact is that the doCall methods shown in the stack trace do not have line numbers in any version

Show
blackdrag blackdrag added a comment - someVariable needs to be defined before it can be used and it has to have the value null if it should cause the NPE. But fact is that the doCall methods shown in the stack trace do not have line numbers in any version
Hide
Lewis Gass added a comment -

For a script that variable does not have to be declared since it is a script and relies on script bindings.

But in relation to the point are you saying that it is impossible to report the line numbers? The point of the example is to talk about a solution since just about every other exception will report line numbers, but this will not, and if a line number cannot be reported then is there anyway to report at least the name of the variable (in this case "someVariable") in the exception somehow propogated down to the InvokerHelper which eventually gets called so that at least one can have an idea of where in the script the problem arises from?

Show
Lewis Gass added a comment - For a script that variable does not have to be declared since it is a script and relies on script bindings. But in relation to the point are you saying that it is impossible to report the line numbers? The point of the example is to talk about a solution since just about every other exception will report line numbers, but this will not, and if a line number cannot be reported then is there anyway to report at least the name of the variable (in this case "someVariable") in the exception somehow propogated down to the InvokerHelper which eventually gets called so that at least one can have an idea of where in the script the problem arises from?
Hide
blackdrag blackdrag added a comment -

A script variable is in the binding, and true it does not have to be declared, but with the standard binding you need to assign a value to the variable first, or else you get a MissingPropertyException. If you don't get that Exception, then you use either a different binding or you already assigned a vale to that variable.

I did not say it is impossible to report the line numbers, I only confirmed that they are not there.. meaning I can reproduce the issue. I added that comment to remember myself that it is a valid issue and that all versions of groovy seem to have the problem. I am positive that a line number can be reported even by the NPE. I am sure it is just a small fix... finding the reason is the real task in fixing this issue.

What we cannot do is reporting the variable name in case of the NPE. In case of the MissingPropertyException the name will be reported.

Show
blackdrag blackdrag added a comment - A script variable is in the binding, and true it does not have to be declared, but with the standard binding you need to assign a value to the variable first, or else you get a MissingPropertyException. If you don't get that Exception, then you use either a different binding or you already assigned a vale to that variable. I did not say it is impossible to report the line numbers, I only confirmed that they are not there.. meaning I can reproduce the issue. I added that comment to remember myself that it is a valid issue and that all versions of groovy seem to have the problem. I am positive that a line number can be reported even by the NPE. I am sure it is just a small fix... finding the reason is the real task in fixing this issue. What we cannot do is reporting the variable name in case of the NPE. In case of the MissingPropertyException the name will be reported.
Hide
blackdrag blackdrag added a comment -

looks like I have to correct myself... there are two doCall methods and the second one contains a line number in 1.6 and 1.7. In 1.5 doCall has no line number.

Show
blackdrag blackdrag added a comment - looks like I have to correct myself... there are two doCall methods and the second one contains a line number in 1.6 and 1.7. In 1.5 doCall has no line number.
Hide
blackdrag blackdrag added a comment -

another addition... the line information is there in 1.5, if the closure contains a newline.

Show
blackdrag blackdrag added a comment - another addition... the line information is there in 1.5, if the closure contains a newline.
Hide
Lewis Gass added a comment -

Makes sense, thanks for taking the time to clarify. So does this mean that there may be a fix in the 1.5 branch? 1.5.8 as implied above?

Show
Lewis Gass added a comment - Makes sense, thanks for taking the time to clarify. So does this mean that there may be a fix in the 1.5 branch? 1.5.8 as implied above?
Hide
Roshan Dawrani added a comment -

Hi,
I looked into this issue and a few things I want to add:

The issue seems to be related to a line number check (createEntry = lineNumber!=line) that is happening in AsmClassGenerator -> onLineNumber(), which writes the ASM label/line number in the bytecode. These line numbers are used in the exception stack trace, as far as I understand.

When the code is written as

var = null
def t = {
    var.property = 1 } // ie, with an extra line inside the closure
t()

, the line numbers get written by ASM in the following sequence and since ASM label/line info is being written for "var.property = 1", exception trace is able to show this info.

ExpressionStatement     (var = null)       - Line 1
ExpressionStatement     (t = {})           - Line 2
MethodCallExpression    (t())              - Line 3
BlockStatement          ({...})            - Line 2
BinaryExpression        (var.property = 1) - Line 3

But when the code is written as:

var = null
def t = { var.property = 1 } // ie, block statement and var.property = 1 expression on the same line
t()

, then labels are written as

ExpressionStatement     (var = null)       - Line 1
ExpressionStatement     (t = {})           - Line 2
MethodCallExpression    (t())              - Line 3
BlockStatement          ({...})            - Line 2

And now when ACG processes "var.property = 1", it sees the line number as 2, and because of the line check it does not write the line information and hence, we don't see the line number for "var.property = 1" when it results in NPE.

A few small questions:

1) Is there any issue in writing multiple ASM labels/line numbers multiple times for the same source file line?

2) Is there any use of writing line numbers in bytecode for BlockStatement? Do they serve any purpose? [I have no familiarity with ASM or bytecode specification, so this question.]

Thanks,
Roshan

Show
Roshan Dawrani added a comment - Hi, I looked into this issue and a few things I want to add: The issue seems to be related to a line number check (createEntry = lineNumber!=line) that is happening in AsmClassGenerator -> onLineNumber(), which writes the ASM label/line number in the bytecode. These line numbers are used in the exception stack trace, as far as I understand. When the code is written as
var = null
def t = {
    var.property = 1 } // ie, with an extra line inside the closure
t()
, the line numbers get written by ASM in the following sequence and since ASM label/line info is being written for "var.property = 1", exception trace is able to show this info.
ExpressionStatement     (var = null)       - Line 1
ExpressionStatement     (t = {})           - Line 2
MethodCallExpression    (t())              - Line 3
BlockStatement          ({...})            - Line 2
BinaryExpression        (var.property = 1) - Line 3
But when the code is written as:
var = null
def t = { var.property = 1 } // ie, block statement and var.property = 1 expression on the same line
t()
, then labels are written as
ExpressionStatement     (var = null)       - Line 1
ExpressionStatement     (t = {})           - Line 2
MethodCallExpression    (t())              - Line 3
BlockStatement          ({...})            - Line 2
And now when ACG processes "var.property = 1", it sees the line number as 2, and because of the line check it does not write the line information and hence, we don't see the line number for "var.property = 1" when it results in NPE. A few small questions: 1) Is there any issue in writing multiple ASM labels/line numbers multiple times for the same source file line? 2) Is there any use of writing line numbers in bytecode for BlockStatement? Do they serve any purpose? [I have no familiarity with ASM or bytecode specification, so this question.] Thanks, Roshan
Hide
blackdrag blackdrag added a comment -

this is a 1.5.8 issue only, because it is not reproducable in 1.6/1.7

I remember I added a few line numbers in 1.6, seems like I did not backport that change... that was before the last beta I think. So comparing ACG 1.5.x and 1.6.x might help finding the missing onLineNumber calls that fixed the issue.

As to answer your questions:

(1) many line number labels seem to slow down the class for some reason I don't know. I had that impression
(2) the 1.6 class generator does visit line numbers for block statements. Usually that does not hurt. I am not sure I can say that your analysis is completely right. It might be true, what you say about the line numbers, but aren't we resetting that information when we process the closure as a InnerClassNode?

Show
blackdrag blackdrag added a comment - this is a 1.5.8 issue only, because it is not reproducable in 1.6/1.7 I remember I added a few line numbers in 1.6, seems like I did not backport that change... that was before the last beta I think. So comparing ACG 1.5.x and 1.6.x might help finding the missing onLineNumber calls that fixed the issue. As to answer your questions: (1) many line number labels seem to slow down the class for some reason I don't know. I had that impression (2) the 1.6 class generator does visit line numbers for block statements. Usually that does not hurt. I am not sure I can say that your analysis is completely right. It might be true, what you say about the line numbers, but aren't we resetting that information when we process the closure as a InnerClassNode?
Hide
Roshan Dawrani added a comment -

I compared ACG 1.5.8 and 1.6-RC-1 and found no difference in calls to onLineNumber(). Both have the exact same number of calls from the same methods.

Actually the "createEntry = lineNumber!=line" check that is creating the problem for 1.5.8 is present only in this version. In versions 1.6-RC-1 and 1.7-beta-1, the check is not there and whenever called, onLineNumber() simply writes the line number information.

Also I didn't notice any difference in processing of closure as an InnerClassNode between 1.5.8 and 1.6 (assuming you were pointing to ACG -> createClosureClass when you mentioned processing of closure)

I had tried removing that "createEntry = lineNumber!=line" check to see if it was fixing the issue reported here but I couldn't be sure of any side effects that change might have. Because it is related to line numbers and test cases might not be covering testing of those sufficiently.

Do you think there will be any side effects of letting the line numbers be written in 1.5.8 as they do in 1.6 and 1.7 - without the comparison mentioned above? Anything else in ACG of 1.6 that is complementing the removal of line number comparison?

Show
Roshan Dawrani added a comment - I compared ACG 1.5.8 and 1.6-RC-1 and found no difference in calls to onLineNumber(). Both have the exact same number of calls from the same methods. Actually the "createEntry = lineNumber!=line" check that is creating the problem for 1.5.8 is present only in this version. In versions 1.6-RC-1 and 1.7-beta-1, the check is not there and whenever called, onLineNumber() simply writes the line number information. Also I didn't notice any difference in processing of closure as an InnerClassNode between 1.5.8 and 1.6 (assuming you were pointing to ACG -> createClosureClass when you mentioned processing of closure) I had tried removing that "createEntry = lineNumber!=line" check to see if it was fixing the issue reported here but I couldn't be sure of any side effects that change might have. Because it is related to line numbers and test cases might not be covering testing of those sufficiently. Do you think there will be any side effects of letting the line numbers be written in 1.5.8 as they do in 1.6 and 1.7 - without the comparison mentioned above? Anything else in ACG of 1.6 that is complementing the removal of line number comparison?
Hide
blackdrag blackdrag added a comment -

I think the removal of "createEntry = lineNumber!=line" was by accident... but I also think that it is safe to remove that if it fixes the issue reported here

Show
blackdrag blackdrag added a comment - I think the removal of "createEntry = lineNumber!=line" was by accident... but I also think that it is safe to remove that if it fixes the issue reported here
Hide
Roshan Dawrani added a comment -

Attaching the patch the fixes the line number problem reported in this bug on 1.5.8.

I have modified AsmClassGenerator->onLineNumber() to remove the line number comparison. Now the writing of line numbers is in sync with the way it is done in 1.6-RC-1 and 1.7-beta-1.

If line number check is put back some time for performance reasons or something else, then 1.5.x can also be taken up along-with 1.6 and 1.7. In the meanwhile, the patch will help in having the line number behavior in 1.5.8 be consistent with 1.6/1.7.

rgds,
Roshan

Show
Roshan Dawrani added a comment - Attaching the patch the fixes the line number problem reported in this bug on 1.5.8. I have modified AsmClassGenerator->onLineNumber() to remove the line number comparison. Now the writing of line numbers is in sync with the way it is done in 1.6-RC-1 and 1.7-beta-1. If line number check is put back some time for performance reasons or something else, then 1.5.x can also be taken up along-with 1.6 and 1.7. In the meanwhile, the patch will help in having the line number behavior in 1.5.8 be consistent with 1.6/1.7. rgds, Roshan
Hide
blackdrag blackdrag added a comment -

patch applied

Show
blackdrag blackdrag added a comment - patch applied

People

Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: