fix logMissingProperties (WW-4999) #358

yasserzamani · 2019-05-30T12:09:29Z

Moves checking OgnlValueStack.THROW_EXCEPTION_ON_FAILURE outside loop because it shouldn't throw exception on first failure while is trying all root objects.

Returns on first successful call because it's not rational and is confusing user to skip when user method successfully returns null as an actual result.

Fixes WW-4999 via honoring (devMode && logMissingProperties) for OgnlValueStack.THROW_EXCEPTION_ON_FAILURE and REPORT_ERRORS_ON_NO_PROP.

Moves checking OgnlValueStack.THROW_EXCEPTION_ON_FAILURE outside loop because it shouldn't throw exception on first failure while is trying all root objects. Returns on first successful call because it's not rational and is confusing user to skip when user method successfully returns null as an actual result. Fixes WW-4999 via honoring (devMode && logMissingProperties) for OgnlValueStack.THROW_EXCEPTION_ON_FAILURE and REPORT_ERRORS_ON_NO_PROP.

coveralls · 2019-05-30T13:18:49Z

Coverage increased (+0.003%) to 47.029% when pulling a50af87 on yasserzamani:WW-4999 into b0dd7c1 on apache:struts-2-5-x.

qqu0127

Is there a reason we have to set both devMode and logMissingProperties true in order to enable logging? Could we just use logMissingProperties for clarity?

qqu0127 · 2019-05-30T17:26:51Z

core/src/main/java/com/opensymphony/xwork2/ognl/accessor/CompoundRootAccessor.java

        }

+        if (context.containsKey(OgnlValueStack.THROW_EXCEPTION_ON_FAILURE)) {
+            throw new MethodFailedException(target, name, reason);


Seems like previously this MethodFailedException is thrown when the method is found but failed on execution. Now we are mixing up both cases "no such method" and "method failed" by throwing this exception outside the loop. Is this the expected behavior?
Also, shall we consider break the loop at the point we threw MethodFailedException?

No, previously it was mixed up both cases also so it is same as previous in this behavior. The only difference for it is: Now it is outside of the loop. Being inside of the loop is a bug. I discovered it in #357 - For example OgnlValueStack.findValue(expr: "someProp", throwExceptionOnFailure: true) always fail when top of stack doesn't have someProp property while it must check also other objects in stack and fail if none of them had this property.

Also, shall we consider break the loop at the point we threw MethodFailedException?

I think no. AFAIK it must try on all of objects in stack.

Looks ok to me, it makes sense to keep the mixed up behavior.
Regarding the exception previously at line 248, doesn't that break the loop already? I don't think that would be an issue even throwExceptionOnFailure is set true. Because that is only thrown when the property is found, but an exception is thrown in application code (that's why reason != null).
Do you propose to search down the stack anyway even we've already "hit"?
The only use case I can think of: we have more than one "hit" on stack, while first one throws runtime exception and second one execute smoothly and return -- yes, in this case we don't want to break the loop.
I'm not super familiar with the coding style and design pattern of ognl, is that really what we want?
Hiding exceptions doesn't look quite right to me...

Now, it doesn't break the loop but previously it did, and I thought it was an issue when throwExceptionOnFailure is set true because of casual failed tests #357 - for example it accidentally uncovered that XWorkConverter.getConversionErrorMessage seems fails when user set throwExceptionOnFailure to true, I think. right?

I just found all usages of OgnlValueStack.THROW_EXCEPTION_ON_FAILURE and found all of them outside loop except here. Thanks for heads up for reason != null, it makes sense! But now I'm surprised if reason != null is a good decision to distinguish between property not found and user app exception then why #357 tests fail?! (see prev para) In #357 everything is same as before except throwExceptionOnFailure which is hard-coded to true.

yasserzamani · 2019-05-30T20:16:33Z

Is there a reason we have to set both devMode and logMissingProperties true in order to enable logging? Could we just use logMissingProperties for clarity?

@apache/struts-committers, I agree with @qqu0127 , any objection?

JCgH4164838Gh792C124B5

My "vote" would be too keep devMode and logMissingProperties "linked" so that logMissingProperties is only effective in devMode (reasoning given within the review).

JCgH4164838Gh792C124B5 · 2019-05-31T01:24:55Z

core/src/main/java/com/opensymphony/xwork2/ognl/accessor/CompoundRootAccessor.java

-                    if (!context.containsKey(OgnlValueStack.THROW_EXCEPTION_ON_FAILURE) && (mc != null) && (reason != null) && (reason.getClass() == NoSuchMethodException.class)) {
+                    if ((mc != null) && (reason != null) && (reason.getClass() == NoSuchMethodException.class)) {
                        invalidMethods.put(mc, Boolean.TRUE);
-                    } else if (reason != null) {


Is it certain that dropping the "if (reason != null)" check as part of the decision whether to throw the exception or not won't cause an issue ?

It looks like the old code would "skip" throwing an Exception in that case, no matter what THROW_EXCEPTION_ON_FAILURE is set to ?

As @qqu0127 mentioned, it seems reason != null tries to distinguish between property not found and user app exception but actually it doesn't work. As far as I could see and debug, OGNL always fill it here

https://github.com/jkuhnert/ognl/blob/b6e58c4db776beb20e20d5792227d1da7b4355e0/src/main/java/ognl/OgnlRuntime.java#L1529

in both NoSuchMethodException (i.e. property not found) and InvocationTargetException (i.e. user app exception).

I realized that this is an old issue, please see this test :

struts/core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

Line 958 in d4dd338

* Fails on 2.5.20 and earlier - tested on 2.5 (5/5/2016) and failed

Oh, you are right. reason != null itself is not a complete check. Actually, I fixed this in my workplace integrated with our logging system internally, based on 2.5.17. And it classifies the exceptions correctly. FYI, we modified ValueStack. (we also changed CompoundRootAccessor, but differently, so not sure if it works here). Just for reference, not super important.

@Override public Object handleOgnlException(String expr, boolean throwExceptionOnFailure, OgnlException e) { Object ret = findInContext(expr); if (ret != null) { return ret; } String errMsg = null; if (shouldLogWarning()) { if (e.getCause() == null || e.getCause() instanceof NoSuchMethodException) { errMsg = String.format("Could not evaluate expression [%s]", expr); } else { // exception in invoked method errMsg = String.format("Caught an exception in evaluating expression [%s]", expr); } logStackTrace(errMsg, e); } if (throwExceptionOnFailure) { throw new XWorkException(e, errMsg); } return null; }

And

@Override protected Object handleOtherException(String expr, boolean throwExceptionOnFailure, Exception e) { if (shouldLogWarning()) { if (e.getCause() == null) { logStackTrace(String.format("Could not evaluate expression [%s]", expr), e); } else { logStackTrace(String.format("Caught an exception in evaluating expression [%s]", expr), e); } } if (throwExceptionOnFailure) { throw new XWorkException(e); } return findInContext(expr); }

I'm still not sure if we should remove elseif (reason != null). In my view it changes the flow too much (validity and performance), and it's irrelevant to the issue.

We should because with that following test fails. I tested and even Struts 2.5 (5/5/2016) with no change also fails on this test:

struts/core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

Line 982 in a50af87

public void testNotThrowExceptionOnTopMissingProperty() {

but this is and was a wrong behavior.

JCgH4164838Gh792C124B5 · 2019-05-31T01:32:40Z

core/src/main/java/com/opensymphony/xwork2/ognl/accessor/CompoundRootAccessor.java

+                    if ((mc != null) && (reason != null) && (reason.getClass() == NoSuchMethodException.class)) {
                        invalidMethods.put(mc, Boolean.TRUE);
-                    } else if (reason != null) {
-                        throw new MethodFailedException(o, name, e.getReason());


Was the old logic intentionally limiting the loop to 1 iteration (unless the exception reason was null ) ?
Previously it would seem things would only succeed if the method was defined on the object at the top of the stack.

Will "walking the whole valuestack" potentially introduce a different issue (unexpectedly) ?

Was the old logic intentionally limiting the loop to 1 iteration (unless the exception reason was null ) ?
Previously it would seem things would only succeed if the method was defined on the object at the top of the stack.

In case of throwExceptionOnFailure=true, Yes, but it is a wrong behavior. Please see my test at

struts/core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

Line 958 in d4dd338

* Fails on 2.5.20 and earlier - tested on 2.5 (5/5/2016) and failed

which fails on Struts 2.5 (5/5/2016) on L#975.

Will "walking the whole valuestack" potentially introduce a different issue (unexpectedly) ?

No, it is already current behavior in case of throwExceptionOnFailure=false.

JCgH4164838Gh792C124B5 · 2019-05-31T01:55:15Z

core/src/main/java/com/opensymphony/xwork2/ognl/OgnlValueStack.java


    protected void setupExceptionOnFailure(boolean throwExceptionOnFailure) {
-        if (throwExceptionOnFailure) {
+        if (throwExceptionOnFailure || (devMode && logMissingProperties)) {


I think this is the main reason why devMode and logMissingProperties should continue to be "linked" (at least in 2.5.x). Most users probably only want to check for missing properties in devMode (development) anyway.

If logMissingProperties becomes a "standalone flag", it could turn on THROW_EXCEPTION_ON_FAILURE in a production configuration - and that could have greater repercussions than intended. Maybe it could be decoupled in 2.6 in a "safe way" ?

throwExceptionOnFailure || logMissingProperties also works even better. As far as I can see in codes, Struts will check them separately later to check throw any exception and log any message.

JCgH4164838Gh792C124B5 · 2019-05-31T02:21:52Z

core/src/main/java/com/opensymphony/xwork2/ognl/accessor/CompoundRootAccessor.java

            return null;
        }

+        Throwable reason = null;


(Oops ... forgot to include this comment in the review).

Assuming the loop logic will continue to process more than 1 iteration, I suggest a small optimization:

Move Line 227: Class[] argTypes = getArgTypes(objects); -- to Line 219/220 (outside of the loop).
Should be safe as the argument types don't change across the loop iterations.

lukaszlenart · 2019-05-31T07:26:53Z

Would you mind adding a test case where an existing property throws a runtime exception? Such case should not be reported as missing property. Basically something has changed in struts <-> ognl flow and ognl.NoSuchPropertyException isn't thrown/handled any more. I was trying to figure out what was wrong but failed :(

Also reaks loop on user method exceptions - but continue to next objects in stack on NoSuchMethodException.

yasserzamani · 2019-05-31T13:43:13Z

Hi all,

Thanks all for comments! I tried to fix all of them in a new commit above. The only weakness is when user method body itself throws NoSuchMethodException which cannot be fixed nicely without changing ognl itself.

@lukaszlenart , I realized these issues are old. I checked out Struts 2.5 (5/5/2016) and tested it against two issues. 1. devMode=true&&logMissingProperties=true doesn't work their either. 2. throwExceptionOnFailure=true causes failure on XWorkConverter.getConversionErrorMessage.

@qqu0127 , I think in this new commit I was able to address your concerns. Could you check please? and thanks a tone for heads up!

@JCgH4164838Gh792C124B5 , I'm working on your concerns :)

instead continue to next objects in stack Also tests not skip returned null values by user method

yasserzamani · 2019-06-01T08:26:53Z

I tested and finally found it more clear and nice in both test and production codes to decouple logMissingProperties from devMode so did it.

JCgH4164838Gh792C124B5 · 2019-06-01T15:40:28Z

core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

        }
    }

+    public void testLogMissingProperties() {


Since testNotThrowExceptionOnTopMissingProperty() added @since 2.5.21, do you want the same annotation here ?

JCgH4164838Gh792C124B5 · 2019-06-01T15:41:01Z

core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

+        }
+    }
+
+    public void testNotLogUserExceptionsAsMissingProperties() {


And @since 2.5.21 here ?

JCgH4164838Gh792C124B5 · 2019-06-01T15:44:48Z

core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java

+            logger.removeAppender(testAppender);
+        }
+    }
+


@yasserzamani , do you think adding equivalent tests testLogMissingPropertiesFalse() and testNotLogUserExceptionsAsMissingPropertiesFalse() would be a good idea ?

They could set vs.setLogMissingProperties("false"); and then confirm that nothing was logged. Might be a good additional check ?

As it stands the changes LGTM, but I think those two additional tests might be useful to catch a future change that accidentally causes the opposite behaviour (i.e. something gets logged when logMissingProperties is false, but should not).

Hello @yasserzamani . Thanks for responding to the feedback and your excellent work on this PR. 👍 .
Thanks to @qqu0127 for opening the Jira issue and reviewing the PR's changes too.

qqu0127

Great work. Thanks!

JCgH4164838Gh792C124B5

Good work. 👍

lukaszlenart · 2019-06-03T06:25:29Z

LGTM 👍

lukaszlenart · 2019-06-03T06:25:59Z

@yasserzamani do you plan cherry-pick those changes into 2.6?

yasserzamani · 2019-06-03T08:29:10Z

Thanks for thanks and 👍s :)

@lukaszlenart , cherry picked into 2.6 and travis is green :)

lukaszlenart · 2019-06-03T08:35:37Z

💯

qqu0127 reviewed May 30, 2019

View reviewed changes

JCgH4164838Gh792C124B5 suggested changes May 31, 2019

View reviewed changes

JCgH4164838Gh792C124B5 reviewed May 31, 2019

View reviewed changes

not log user exceptions as missing properties (WW-4999)

0999fba

Also reaks loop on user method exceptions - but continue to next objects in stack on NoSuchMethodException.

yasserzamani added the Work in Progress label May 31, 2019

yasserzamani added 2 commits June 1, 2019 09:37

test not throw exception on top missing property (WW-4999)

d4dd338

instead continue to next objects in stack Also tests not skip returned null values by user method

decouple logMissingProperties from devMode (WW-4999)

9e01fbd

yasserzamani added Ready For Merge and removed Work in Progress labels Jun 1, 2019

JCgH4164838Gh792C124B5 reviewed Jun 1, 2019

View reviewed changes

test false for logMissingProperties (WW-4999)

a50af87

qqu0127 approved these changes Jun 2, 2019

View reviewed changes

JCgH4164838Gh792C124B5 approved these changes Jun 2, 2019

View reviewed changes

lukaszlenart merged commit 651eac2 into apache:struts-2-5-x Jun 3, 2019

yasserzamani deleted the WW-4999 branch June 3, 2019 07:29

fix logMissingProperties (WW-4999) #358

fix logMissingProperties (WW-4999) #358

Uh oh!

Conversation

yasserzamani commented May 30, 2019

Uh oh!

coveralls commented May 30, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

qqu0127 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

yasserzamani commented May 30, 2019

Uh oh!

JCgH4164838Gh792C124B5 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

qqu0127 Jun 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lukaszlenart commented May 31, 2019

Uh oh!

yasserzamani commented May 31, 2019

Uh oh!

yasserzamani commented Jun 1, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

qqu0127 left a comment

Choose a reason for hiding this comment

Uh oh!

JCgH4164838Gh792C124B5 left a comment

Choose a reason for hiding this comment

Uh oh!

lukaszlenart commented Jun 3, 2019

Uh oh!

lukaszlenart commented Jun 3, 2019

Uh oh!

yasserzamani commented Jun 3, 2019

coveralls commented May 30, 2019 •

edited

Loading

qqu0127 Jun 1, 2019 •

edited

Loading