Skip to content

fix logMissingProperties (WW-4999) #358

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Jun 3, 2019
Merged

fix logMissingProperties (WW-4999) #358

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
3ac6835
fix logMissingProperties (WW-4999)
yasserzamani May 30, 2019
0999fba
not log user exceptions as missing properties (WW-4999)
yasserzamani May 31, 2019
d4dd338
test not throw exception on top missing property (WW-4999)
yasserzamani Jun 1, 2019
9e01fbd
decouple logMissingProperties from devMode (WW-4999)
yasserzamani Jun 1, 2019
a50af87
test false for logMissingProperties (WW-4999)
yasserzamani Jun 2, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 5 additions & 4 deletions core/src/main/java/com/opensymphony/xwork2/ognl/OgnlValueStack.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -182,7 +182,7 @@ public void setValue(String expr, Object value, boolean throwExceptionOnFailure)

private void trySetValue(String expr, Object value, boolean throwExceptionOnFailure, Map<String, Object> context) throws OgnlException {
context.put(XWorkConverter.CONVERSION_PROPERTY_FULLNAME, expr);
context.put(REPORT_ERRORS_ON_NO_PROP, (throwExceptionOnFailure) ? Boolean.TRUE : Boolean.FALSE);
context.put(REPORT_ERRORS_ON_NO_PROP, throwExceptionOnFailure || logMissingProperties ? Boolean.TRUE : Boolean.FALSE);
ognlUtil.setValue(expr, context, root, value);
}

Expand Down Expand Up @@ -246,7 +246,7 @@ public Object findValue(String expr, boolean throwExceptionOnFailure) {
}

protected void setupExceptionOnFailure(boolean throwExceptionOnFailure) {
if (throwExceptionOnFailure) {
if (throwExceptionOnFailure || logMissingProperties) {
context.put(THROW_EXCEPTION_ON_FAILURE, true);
}
}
Expand Down Expand Up @@ -339,8 +339,9 @@ protected Object handleOgnlException(String expr, boolean throwExceptionOnFailur
}

protected boolean shouldLogMissingPropertyWarning(OgnlException e) {
return (e instanceof NoSuchPropertyException || e instanceof MethodFailedException)
&& devMode && logMissingProperties;
return (e instanceof NoSuchPropertyException ||
(e instanceof MethodFailedException && e.getReason() instanceof NoSuchMethodException))
&& logMissingProperties;
}

private Object tryFindValue(String expr, Class asType) throws OgnlException {
Expand Down
24 changes: 14 additions & 10 deletions core/src/main/java/com/opensymphony/xwork2/ognl/accessor/CompoundRootAccessor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -217,13 +217,14 @@ public Object callMethod(Map context, Object target, String name, Object[] objec
return null;
}

Throwable reason = null;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 fixed

Class[] argTypes = getArgTypes(objects);
for (Object o : root) {
if (o == null) {
continue;
}

Class clazz = o.getClass();
Class[] argTypes = getArgTypes(objects);

MethodCall mc = null;

Expand All @@ -233,24 +234,27 @@ public Object callMethod(Map context, Object target, String name, Object[] objec

if ((argTypes == null) || !invalidMethods.containsKey(mc)) {
try {
Object value = OgnlRuntime.callMethod((OgnlContext) context, o, name, objects);
return OgnlRuntime.callMethod((OgnlContext) context, o, name, objects);
} catch (OgnlException e) {
reason = e.getReason();

if (value != null) {
return value;
if (reason != null && !(reason instanceof NoSuchMethodException)) {
// method has found but thrown an exception
break;
}
} catch (OgnlException e) {
// try the next one
Throwable reason = e.getReason();

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link

@qqu0127 qqu0127 Jun 1, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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);
  }

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

throw new MethodFailedException(o, name, e.getReason());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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) ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

}
// continue and try the next one
}
}
}

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

}

return null;
}

Expand Down
152 changes: 152 additions & 0 deletions core/src/test/java/com/opensymphony/xwork2/ognl/OgnlValueStackTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,9 +34,16 @@

import java.io.*;
import java.math.BigDecimal;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.struts2.StrutsConstants;


Expand Down Expand Up @@ -238,6 +245,95 @@ public void testFailOnMissingProperty() {
}
}

/**
* monitors the resolution of WW-4999
* @since 2.5.21
*/
public void testLogMissingProperties() {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 fixed

testLogMissingProperties(true);
testLogMissingProperties(false);
}

private void testLogMissingProperties(boolean logMissingProperties) {
OgnlValueStack vs = createValueStack();
vs.setLogMissingProperties("" + logMissingProperties);

Dog dog = new Dog();
vs.push(dog);

TestAppender testAppender = new TestAppender();
Logger logger = (Logger) LogManager.getLogger(OgnlValueStack.class);
logger.addAppender(testAppender);
testAppender.start();

try {
vs.setValue("missingProp1", "missingProp1Value", false);
vs.findValue("missingProp2", false);
vs.findValue("missingProp3", Integer.class, false);

if (logMissingProperties) {
assertEquals(3, testAppender.logEvents.size());
assertEquals("Error setting value [missingProp1Value] with expression [missingProp1]",
testAppender.logEvents.get(0).getMessage().getFormattedMessage());
assertEquals("Could not find property [missingProp2]!",
testAppender.logEvents.get(1).getMessage().getFormattedMessage());
assertEquals("Could not find property [missingProp3]!",
testAppender.logEvents.get(2).getMessage().getFormattedMessage());
} else {
assertEquals(0, testAppender.logEvents.size());
}
} finally {
testAppender.stop();
logger.removeAppender(testAppender);
}
}

/**
* tests the correctness of distinguishing between user exception and NoSuchMethodException
* @since 2.5.21
*/
public void testNotLogUserExceptionsAsMissingProperties() {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And @since 2.5.21 here ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 fixed

OgnlValueStack vs = createValueStack();
vs.setLogMissingProperties("true");

Dog dog = new Dog();
vs.push(dog);

TestAppender testAppender = new TestAppender();
Logger logger = (Logger) LogManager.getLogger(OgnlValueStack.class);
logger.addAppender(testAppender);
testAppender.start();

try {
vs.setValue("exception", "exceptionValue", false);
vs.findValue("exception", false);
vs.findValue("exception", String.class, false);
vs.findValue("getException()", false);
vs.findValue("getException()", String.class, false);
vs.findValue("bite", false);
vs.findValue("bite", void.class, false);
vs.findValue("getBite()", false);
vs.findValue("getBite()", void.class, false);

vs.setLogMissingProperties("false");

vs.setValue("exception", "exceptionValue", false);
vs.findValue("exception", false);
vs.findValue("exception", String.class, false);
vs.findValue("getException()", false);
vs.findValue("getException()", String.class, false);
vs.findValue("bite", false);
vs.findValue("bite", void.class, false);
vs.findValue("getBite()", false);
vs.findValue("getBite()", void.class, false);

assertEquals(0, testAppender.logEvents.size());
} finally {
testAppender.stop();
logger.removeAppender(testAppender);
}
}

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 fixed

public void testFailOnMissingMethod() {
OgnlValueStack vs = createValueStack();

Expand Down Expand Up @@ -879,6 +975,49 @@ public void testStatics() {
assertNull(vs.findValue("@com.nothing.here.Nothing@BLAH"));
}

/**
* Fails on 2.5.20 and earlier - tested on 2.5 (5/5/2016) and failed
* @since 2.5.21
*/
public void testNotThrowExceptionOnTopMissingProperty() {
OgnlValueStack vs = createValueStack();

Dog dog = new Dog();
dog.setName("Rover");
vs.push(dog);

Cat cat = new Cat();
vs.push(cat);

vs.setValue("age", 12, true);

assertEquals(12, vs.findValue("age", true));
assertEquals(12, vs.findValue("age", Integer.class, true));
assertEquals(12, vs.findValue("getAge()", true));
assertEquals(12, vs.findValue("getAge()", Integer.class, true));
}

/**
* Fails on 2.5.20 and earlier - tested on 2.5 (5/5/2016) and failed
* @since 2.5.21
*/
public void testNotSkipUserReturnedNullValues() {
OgnlValueStack vs = createValueStack();

Dog dog = new Dog();
dog.setName("Rover");
vs.push(dog);

Cat cat = new Cat();
vs.push(cat);

// should not skip returned null values from cat.name
assertNull(vs.findValue("name", true));
assertNull(vs.findValue("name", String.class, true));
assertNull(vs.findValue("getName()", true));
assertNull(vs.findValue("getName()", String.class, true));
}

public void testTop() {
OgnlValueStack vs = createValueStack();

Expand Down Expand Up @@ -1293,6 +1432,19 @@ public void setDisplayName(String displayName) {
this.displayName = displayName;
}
}

class TestAppender extends AbstractAppender {
List<LogEvent> logEvents = new ArrayList<>();

TestAppender() {
super("TestAppender", null, null, false, null);
}

@Override
public void append(LogEvent logEvent) {
logEvents.add(logEvent);
}
}
}

enum MyNumbers {
Expand Down