You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@wicket.apache.org by "Vincent (JIRA)" <ji...@apache.org> on 2010/03/24 14:54:27 UTC
[jira] Issue Comment Edited: (WICKET-2796) Error reporting on
locked page maps, revisited
[ https://issues.apache.org/jira/browse/WICKET-2796?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12849186#action_12849186 ]
Vincent edited comment on WICKET-2796 at 3/24/10 1:54 PM:
----------------------------------------------------------
Ok, did a proof of concept. See the attached unittest, which fails, but does print two stacktraces we can compare :)
Original stacktrace:
org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-2,5,main], giving up trying to get the page for path: form
Begin of stack trace of Thread[Thread-2,5,main]
java.lang.Thread.sleep(Native Method)
java.lang.Thread.sleep(Thread.java:850)
org.apache.wicket.SessionTest$1.run(SessionTest.java:16)
java.lang.Thread.run(Thread.java:735)
End of stack trace of Thread[Thread-2,5,main]
at org.apache.wicket.SessionTest.test(SessionTest.java:46)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:599)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:46)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
Patched stacktrace.
org.apache.wicket.WicketRuntimeException: org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-3,5,main], giving up trying to get the page for path: form
at org.apache.wicket.SessionTest.test2(SessionTest.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:599)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:46)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
Caused by: org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-3,5,main], giving up trying to get the page for path: form
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:850)
at org.apache.wicket.SessionTest$2.run(SessionTest.java:56)
at java.lang.Thread.run(Thread.java:735)
I like the patched stacktrace. It's more readable than the first imho. Also, I can choose to log the message only on error when I catch this message in the RequestCycle, and the complete trace on debug, if debug logging is enabled.
What do you think? The change is pretty simple, see the differences between the actual tests (quite a code cleanup as well! ;-). And maybe a different message is wanted here.
was (Author: vin):
Ok, did a proof of concept. See the attached unittest, which fails, but does print two stacktraces we can compare :)
Original stacktrace:
org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-2,5,main], giving up trying to get the page for path: form
Begin of stack trace of Thread[Thread-2,5,main]
java.lang.Thread.sleep(Native Method)
java.lang.Thread.sleep(Thread.java:850)
org.apache.wicket.SessionTest$1.run(SessionTest.java:16)
java.lang.Thread.run(Thread.java:735)
End of stack trace of Thread[Thread-2,5,main]
at org.apache.wicket.SessionTest.test(SessionTest.java:46)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:599)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:46)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
Patched stacktrace.
org.apache.wicket.WicketRuntimeException: org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-3,5,main], giving up trying to get the page for path: form
at org.apache.wicket.SessionTest.test2(SessionTest.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:599)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:46)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
Caused by: org.apache.wicket.WicketRuntimeException: After 1 second the Pagemap null is still locked by: Thread[Thread-3,5,main], giving up trying to get the page for path: form
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:850)
at org.apache.wicket.SessionTest$2.run(SessionTest.java:56)
at java.lang.Thread.run(Thread.java:735)
I like the patched stacktrace. It's more readable that the first imho. What do you think?
> Error reporting on locked page maps, revisited
> ----------------------------------------------
>
> Key: WICKET-2796
> URL: https://issues.apache.org/jira/browse/WICKET-2796
> Project: Wicket
> Issue Type: Improvement
> Components: wicket
> Affects Versions: 1.4.6
> Reporter: Vincent
> Priority: Minor
> Attachments: SessionTest.java
>
>
> I'm creating this issue as suggested by Igor in the comments of the following issue: WICKET-433.
> The change done for WICKET-433 results in a quite large error message that has the potential to flood log files when running under heavy load. The error message includes a full stack of the thread that is currently locking the page map. Usually, an exception is raised that includes a message and a cause so the catcher can decide to log the complete stack or not. In this case, I'd suggest the same: create an exception, set the stack trace of the thread locking the page map on it, and throw a WicketRuntimeException with a message and a cause. Something like:
> {code}
> StackTraceElement[] stackTrace = t.getStackTrace();
> WicketRuntimeException cause = new WicketRuntimeException("Thread is locking page map.");
> cause.setStackTrace(stackTrace);
> throw new WicketRuntimeException("After " + timeout + " the Pagemap " +
> pageMapName + " is still locked by: " + t +
> ", giving up trying to get the page for path: " + path,
> cause);
> {code}
> This issue was raised by one of the administrators on my project that was trying to break the application by doing a manual load and stress test (read: disabling javascript and submitting requests like a maniac). Since our application integrates with a web service that can take up quite some time, up to 5 seconds, a queue starts to build up because Wicket allows only one request per user to be executed because the page map is locked. While this is a great design decision in my opinion (low impact for other users), after a minute threads that are still waiting will start to abort. As quite a queue had been built up at this point and each waiting thread throws an exception with a quite verbose message (the blocking thread's stack), quite some lines will be written to the log at this time - probably on error level.
> Johan comments:
> {quote}
> how can a malicious user lock pages/pagemaps so create those kind of errors?
> These errors are more or less programming/web application errors that you need to fix
> {quote}
> Of course, you are right. This is a serious error that should never occur in a properly tuned production environment. In production, the webservice should respond much quicker and is viable for client-side caching, which we will address in future iterations.
> Our administrator's concern is that IF a user manages to build up a queue long enough to trigger this error (whatever the cause), he will face a 'log storm' that makes him effectively blind. This is the reason that stack traces on error level are not allowed in our production environment. Of course, this will only be a serious problem under very very heavy load.
> Well enough with the theoretical mumbo-jumbo, do you like the idea? Shall I cook up a proof of concept? And if successful, build a patch for this?
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.