You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@jackrabbit.apache.org by "Thomas Mueller (JIRA)" <ji...@apache.org> on 2011/05/05 16:31:03 UTC
[jira] [Created] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Improve logging of Session.save() to trace back root cause of externally modified nodes
---------------------------------------------------------------------------------------
Key: JCR-2961
URL: https://issues.apache.org/jira/browse/JCR-2961
Project: Jackrabbit Content Repository
Issue Type: New Feature
Reporter: Thomas Mueller
Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Thomas Mueller updated JCR-2961:
--------------------------------
Priority: Minor (was: Major)
Fix Version/s: 2.3.0
Assignee: Thomas Mueller
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13030647#comment-13030647 ]
Thomas Mueller commented on JCR-2961:
-------------------------------------
Most likely you don't see the NPE because it is ignored (now) when using the default log settings. To see it in stdout, use src/test/resource/lockback-test.xml:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
</layout>
</appender>
<appender name="file" class="ch.qos.logback.core.FileAppender">
<file>target/jcr.log</file>
<encoder>
<pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg%n</pattern>
</encoder>
</appender>
<appender name="sift" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<Key>testclass</Key>
<DefaultValue>junit</DefaultValue>
</discriminator>
<sift>
<appender name="FILE-${testname}" class="ch.qos.logback.core.FileAppender">
<File>target/surefire-reports/${testclass}.log</File>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg%n</Pattern>
</layout>
</appender>
</sift>
</appender>
<logger name="org.apache.jackrabbit.test" level="DEBUG"/>
<root level="INFO">
<appender-ref ref="file"/>
<appender-ref ref="sift"/>
</root>
<logger name="org.apache.jackrabbit.core.session.SessionSaveOperation" level="DEBUG">
<appender-ref ref="STDOUT"/>
</logger>
</configuration>
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Stefan Guggisberg (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13029987#comment-13029987 ]
Stefan Guggisberg commented on JCR-2961:
----------------------------------------
i am unable to reproduce the NPE with the provided test case on current trunk.
any idea why i am not getting those?
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13029346#comment-13029346 ]
Thomas Mueller commented on JCR-2961:
-------------------------------------
To enable logging each session.save call, configure the logger (logback) as follows (logs to stdout):
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
</layout>
</appender>
<logger
name="org.apache.jackrabbit.core.session.SessionSaveOperation"
level="DEBUG">
<appender-ref ref="STDOUT"/>
</logger>
If the system property "org.jackrabbit.logWithStackTrace" is set to "true", then a stack trace is logged as well (this slows down performance).
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Stefan Guggisberg (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13030756#comment-13030756 ]
Stefan Guggisberg commented on JCR-2961:
----------------------------------------
thanks, i could now reproduce the NPE.
i filed JCR-2967.
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13029756#comment-13029756 ]
Thomas Mueller commented on JCR-2961:
-------------------------------------
The path is already included in the exception message in some cases:
Exception in thread "main" javax.jcr.InvalidItemStateException: property /test/x/y: the property cannot be saved because it has been modified externally.
at org.apache.jackrabbit.core.PropertyImpl.makePersistent(PropertyImpl.java:155)
at org.apache.jackrabbit.core.ItemSaveOperation.persistTransientItems(ItemSaveOperation.java:835)
at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:243)
at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
at org.apache.jackrabbit.core.ItemImpl.perform(ItemImpl.java:91)
at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:329)
at org.apache.jackrabbit.core.session.SessionSaveOperation.perform(SessionSaveOperation.java:57)
at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:360)
at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:800)
But not in all cases. This message looks like a bug:
Exception in thread "main" javax.jcr.InvalidItemStateException: Item cannot be saved because it has been deleted externally: item.save()
at org.apache.jackrabbit.core.ItemSaveOperation.getTransientStates(ItemSaveOperation.java:322)
at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:98)
at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
at org.apache.jackrabbit.core.ItemImpl.perform(ItemImpl.java:91)
at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:329)
at org.apache.jackrabbit.core.session.SessionSaveOperation.perform(SessionSaveOperation.java:64)
at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:360)
at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:800)
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Thomas Mueller resolved JCR-2961.
---------------------------------
Resolution: Fixed
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Marcel Reutegger (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13029415#comment-13029415 ]
Marcel Reutegger commented on JCR-2961:
---------------------------------------
Would it be possible to put the path of the item into the exception message instead of the UUID? I think that would be even more helpful.
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (JCR-2961) Improve logging of Session.save() to
trace back root cause of externally modified nodes
Posted by "Thomas Mueller (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/JCR-2961?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13029758#comment-13029758 ]
Thomas Mueller commented on JCR-2961:
-------------------------------------
It seems the more I test, the more problems I find. In some cases, SessionItemStateManager.getIdOfRootTransientNodeState throws a NullPointerException.
I guess that means the change for JCR-2425 isn't working:
java.lang.NullPointerException: null
at org.apache.jackrabbit.core.cache.ConcurrentCache.getSegment(ConcurrentCache.java:96) ~[classes/:na]
at org.apache.jackrabbit.core.cache.ConcurrentCache.get(ConcurrentCache.java:122) ~[classes/:na]
at org.apache.jackrabbit.core.state.MLRUItemStateCache.retrieve(MLRUItemStateCache.java:69) ~[classes/:na]
at org.apache.jackrabbit.core.state.ItemStateReferenceCache.retrieve(ItemStateReferenceCache.java:139) ~[classes/:na]
at org.apache.jackrabbit.core.state.LocalItemStateManager.getItemState(LocalItemStateManager.java:169) ~[classes/:na]
at org.apache.jackrabbit.core.state.XAItemStateManager.getItemState(XAItemStateManager.java:260) ~[classes/:na]
at org.apache.jackrabbit.core.state.SessionItemStateManager.getItemState(SessionItemStateManager.java:162) ~[classes/:na]
at org.apache.jackrabbit.core.state.SessionItemStateManager.getIdOfRootTransientNodeState(SessionItemStateManager.java:520) ~[classes/:na]
at org.apache.jackrabbit.core.session.SessionSaveOperation.perform(SessionSaveOperation.java:51) ~[classes/:na]
at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200) [classes/:na]
at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:360) [classes/:na]
at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:800) [classes/:na]
at org.apache.jackrabbit.api.Test.main(Test.java:39) [test-classes/:na]
Test case:
Repository repository = new TransientRepository();
Session session = repository.login(
new SimpleCredentials("admin", "admin".toCharArray()));
Session session2 = repository.login(
new SimpleCredentials("admin", "admin".toCharArray()));
boolean setProperty = false;
try {
if (session.getRootNode().hasNode("test")) {
session.getRootNode().getNode("test").remove();
}
Node test = session.getRootNode().addNode("test");
session.save();
Node x = test.addNode("x");
x.setProperty("y", 1);
session.save();
Node x2 = session2.getRootNode().getNode("test").getNode("x");
if (setProperty) {
x2.setProperty("y", 2);
x.setProperty("y", 3);
} else {
x2.remove();
x.addNode("b");
}
session2.save();
session.save();
} finally {
session.logout();
session2.logout();
}
> Improve logging of Session.save() to trace back root cause of externally modified nodes
> ---------------------------------------------------------------------------------------
>
> Key: JCR-2961
> URL: https://issues.apache.org/jira/browse/JCR-2961
> Project: Jackrabbit Content Repository
> Issue Type: New Feature
> Reporter: Thomas Mueller
> Assignee: Thomas Mueller
> Priority: Minor
> Fix For: 2.3.0
>
>
> Currently it's very difficult to find the root cause of error like: javax.jcr.InvalidItemStateException: <UUID> has been modified externally.
> To better trace back such issues, it would be nice to add DEBUG logging for the Session.save() call.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira