jackrabbit-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Patrick Haggood <codezi...@email.com>
Subject Re: OverlappingFileLockException using DerbyPersistenceManager
Date Mon, 19 Feb 2007 23:52:42 GMT
On Mon, 2007-02-19 at 17:28 +0100, Stefan Guggisberg wrote:
> ok, i guess we can rule derby out.
> 
> it seems like the same process/jvm tries to acquire a file lock
> on the repository .lock file.
> 
> you should see a related warning in your jackrabbit log file.
> 

Haven't tried your recommendation, but i got a jackrabbit log (finally -
log4j.properties + Netbeans = nightmare):

What's interesting is the "existing lock" message:
18:32:07,627 [main] WARN core.RepositoryImpl             - Existing lock
file
at /home/pbh/projects/lab/javadev/nbprojects/UnityJSR170/repository/.lock deteteced. Repository
was not shut down properly. 

Before each test, I delete the repository directory and the log.  I do
not understand how it's finding this existing lock each time.  

******* jackrabbit.log

18:32:07,598 [main] DEBUGcore.TransientRepository        - Initializing
transient repository 
18:32:07,618 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/repository 
18:32:07,619 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/version 
18:32:07,626 [main] INFO core.RepositoryImpl             - Starting
repository... 
18:32:07,627 [main] WARN core.RepositoryImpl             - Existing lock
file
at /home/pbh/projects/lab/javadev/nbprojects/UnityJSR170/repository/.lock deteteced. Repository
was not shut down properly. 
18:32:07,643 [main] DEBUGcore.ItemManager                - created item
cafebabe-cafe-babe-cafe-babecafebabe 
18:32:07,643 [main] DEBUGcore.ItemManager                - caching item
cafebabe-cafe-babe-cafe-babecafebabe 
18:32:07,645 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:32:07,645 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}unstructured' is already contained. 
18:32:07,646 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:32:07,647 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}unstructured' is already contained. 
18:32:07,647 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{internal}root' is already contained. 
18:32:07,651 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac 
18:32:07,651 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac 
18:32:07,657 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}primaryType 
18:32:07,658 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}primaryType 
18:32:07,660 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:32:07,660 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:32:07,661 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}uuid 
18:32:07,662 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{http://www.jcp.org/jcr/1.0}uuid 
18:32:07,680 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{}name 
18:32:07,680 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{}name 
18:32:07,681 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{}type 
18:32:07,682 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{}type 
18:32:07,692 [main] DEBUGcore.ItemManager                - created item
84a3399f-c77a-425c-b679-4427cd509fac/{}xmldata 
18:32:07,692 [main] DEBUGcore.ItemManager                - caching item
84a3399f-c77a-425c-b679-4427cd509fac/{}xmldata 
18:32:07,836 [main] DEBUGstate.SharedItemStateManager    - persisting
change log {#addedStates=7, #modifiedStates=1, #deletedStates=0,
#modifiedRefs=0} took 117ms 
18:32:07,837 [main] DEBUGtion.ObservationManagerFactory  - notifying 3
synchronous listeners. 
18:32:07,842 [main] DEBUGcore.SearchManager              - onEvent:
indexing started 
18:32:07,847 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 4 ->  
18:32:07,849 [main] DEBUGcore.SearchManager              - onEvent:
indexing finished in 6 ms. 
18:32:07,850 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
got EventStateCollection 
18:32:07,857 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery to 1 consumers started... 
18:32:07,858 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery finished. 
18:32:10,118 [Timer-1] DEBUGlucene.MultiIndex               - Flushing
index after being idle for 3014 ms. 
18:32:10,122 [Timer-1] DEBUGlucene.AbstractIndex            - closing
IndexReader. 
18:32:10,123 [Timer-1] DEBUGlucene.AbstractIndex            - committing
IndexWriter. 
18:32:10,124 [Timer-1] DEBUGlucene.AbstractIndex            - merging
segments _0 (1 docs) into _1 (1 docs) 
18:32:10,126 [Timer-1] DEBUGlucene.IndexMerger              - index
added: name=_1, numDocs=1 
18:32:10,127 [Timer-1] DEBUGlucene.MultiIndex               - Committed
in-memory index in 8ms. 


> try the following:
> 
>             Repository rep1 = new TransientRepository();
>             Session s1 = rep1.login(new SimpleCredentials("johndoe",
> "".toCharArray()));
>             Repository rep2 = new TransientRepository();
>             Session s2 = rep2.login(new SimpleCredentials("johndoe",
> "".toCharArray()));
> 
> the last call should trigger an exception (which is legitimate and correct).
> 
> however, the OverlappingFileLockException is probably only thrown on linux.
> at least i couldn't reproduce it on a windows box.
> 
> the lock file should prevent multiple repository instantiation with
> identical parameters.
> and that's probably your issue...

But I'm not re-opening a new session, I only have one session for the
entire run.

This must be some artifact of junit; I'm doing the following in a simple
test class and it works w/ no locking problem:

public static void main(String[] args) throws Exception {        
        System.out.println("Connecting..");
        DBConn myDB = new DBConn();
        String userid = myDB.getSutil().putUnityUser(new
UnityUser("pbh","secret","Patrick Haggood"));
        String otheruserid = myDB.getSutil().putUnityUser(new
UnityUser("ash","secret","Andrea Haggood"));
        System.out.println("User stored at " + userid);
        UnityUser usr = myDB.getSutil().getUnityUserByID(userid);
        System.out.println("User retrieved: " + usr.getUsername());
        myDB.shutdown();
    }

As you can see from below, there are no locking issues from this simple
test:

*************** 

18:44:09,558 [main] DEBUGcore.TransientRepository        - Initializing
transient repository 
18:44:09,561 [main] INFO core.TransientRepository        - Creating
repository home directory repository 
18:44:09,882 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/repository 
18:44:09,883 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/version 
18:44:10,025 [main] INFO core.RepositoryImpl             - Starting
repository... 
18:44:10,305 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:44:10,306 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:44:10,306 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}hierarchyNode' is already contained. 
18:44:10,320 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/mix/1.0}referenceable' is already contained. 
18:44:10,338 [main] INFO nodetype.NodeTypeRegistry       - no custom
node type definitions found 
18:44:14,369 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/version/blobs 
18:44:14,394 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:44:14,452 [main] INFO core.RepositoryImpl             - initializing
workspace 'default'... 
18:44:14,453 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/workspaces/default 
18:44:17,053 [main] INFO local.LocalFileSystem           -
LocalFileSystem initialized at path repository/workspaces/default/blobs 
18:44:17,055 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:44:17,055 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}unstructured' is already contained. 
18:44:17,071 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{http://www.jcp.org/jcr/nt/1.0}base' is already contained. 
18:44:17,071 [main] DEBUGnodetype.EffectiveNodeType      - node type
'{internal}nodeTypes' is already contained. 
18:44:17,092 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=1 
18:44:17,094 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=2 
18:44:17,099 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=3 
18:44:17,101 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=4 
18:44:17,103 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=5 
18:44:17,105 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=6 
18:44:17,106 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=7 
18:44:17,108 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=8 
18:44:17,110 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=9 
18:44:17,111 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=10 
18:44:17,113 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=11 
18:44:17,114 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=12 
18:44:17,116 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=13 
18:44:17,118 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=14 
18:44:17,121 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=15 
18:44:17,123 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=16 
18:44:17,125 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=17 
18:44:17,126 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=18 
18:44:17,128 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=19 
18:44:17,130 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=20 
18:44:17,132 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=21 
18:44:17,133 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=22 
18:44:17,135 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=23 
18:44:17,136 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=24 
18:44:17,138 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=25 
18:44:17,139 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=26 
18:44:17,154 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=27 
18:44:17,156 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=28 
18:44:17,157 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=29 
18:44:17,158 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=30 
18:44:17,160 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=31 
18:44:17,162 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=32 
18:44:17,163 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=33 
18:44:17,165 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=34 
18:44:17,167 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=35 
18:44:17,180 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=36 
18:44:17,182 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=37 
18:44:17,183 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=38 
18:44:17,184 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=39 
18:44:17,186 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=40 
18:44:17,187 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=41 
18:44:17,188 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=42 
18:44:17,190 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=43 
18:44:17,191 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=44 
18:44:17,193 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=45 
18:44:17,195 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=46 
18:44:17,196 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=47 
18:44:17,198 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=48 
18:44:17,199 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=49 
18:44:17,200 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=50 
18:44:17,215 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=51 
18:44:17,217 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=52 
18:44:17,219 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=53 
18:44:17,220 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=54 
18:44:17,222 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=55 
18:44:17,223 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=56 
18:44:17,225 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=57 
18:44:17,226 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=58 
18:44:17,231 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=59 
18:44:17,233 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=60 
18:44:17,235 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=61 
18:44:17,237 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=62 
18:44:17,239 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=63 
18:44:17,240 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=64 
18:44:17,241 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=65 
18:44:17,242 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=66 
18:44:17,244 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=67 
18:44:17,246 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=68 
18:44:17,247 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=69 
18:44:17,249 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=70 
18:44:17,250 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=71 
18:44:17,252 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=72 
18:44:17,253 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=73 
18:44:17,255 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=74 
18:44:17,257 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=75 
18:44:17,258 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=76 
18:44:17,260 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=77 
18:44:17,262 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=78 
18:44:17,263 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=79 
18:44:17,264 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=80 
18:44:17,266 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=81 
18:44:17,267 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=82 
18:44:17,269 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=83 
18:44:17,271 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=84 
18:44:17,273 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=85 
18:44:17,274 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=86 
18:44:17,275 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=87 
18:44:17,277 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=88 
18:44:17,278 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=89 
18:44:17,280 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=90 
18:44:17,282 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=91 
18:44:17,283 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=92 
18:44:17,285 [main] DEBUGvirtual.AbstractVISProvider     - item added to
cache. size=93 
18:44:17,302 [main] INFO core.RepositoryImpl             - workspace
'default' initialized 
18:44:17,419 [main] DEBUGcore.ItemManager                - created item
cafebabe-cafe-babe-cafe-babecafebabe 
18:44:17,419 [main] DEBUGcore.ItemManager                - caching item
cafebabe-cafe-babe-cafe-babecafebabe 
18:44:17,426 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-babe-cafe-babecafebabe 
18:44:17,427 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-babe-cafe-babecafebabe 
18:44:17,435 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,436 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,438 [main] DEBUGstate.NodeState                 - listener
already registered:
org.apache.jackrabbit.core.CachingHierarchyManager@4b6c06dd 
18:44:17,439 [main] DEBUGcore.ItemManager                - created item
deadbeef-face-babe-cafe-babecafebabe 
18:44:17,439 [main] DEBUGcore.ItemManager                - caching item
deadbeef-face-babe-cafe-babecafebabe 
18:44:17,439 [main] DEBUGcore.ItemManager                - created item
deadbeef-face-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,439 [main] DEBUGcore.ItemManager                - caching item
deadbeef-face-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,440 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-cafe-cafe-babecafebabe 
18:44:17,440 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-cafe-cafe-babecafebabe 
18:44:17,440 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-cafe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,441 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-cafe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,642 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-cafe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,642 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-cafe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,643 [main] DEBUGcore.ItemManager                - created item
deadbeef-face-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,643 [main] DEBUGcore.ItemManager                - caching item
deadbeef-face-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,643 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-cafe-cafe-babecafebabe 
18:44:17,643 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-cafe-cafe-babecafebabe 
18:44:17,644 [main] DEBUGcore.ItemManager                - created item
deadbeef-face-babe-cafe-babecafebabe 
18:44:17,644 [main] DEBUGcore.ItemManager                - caching item
deadbeef-face-babe-cafe-babecafebabe 
18:44:17,644 [main] DEBUGcore.ItemManager                - created item
deadbeef-cafe-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,644 [main] DEBUGcore.ItemManager                - caching item
deadbeef-cafe-babe-cafe-babecafebabe/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:17,689 [main] DEBUGstate.SharedItemStateManager    - persisting
change log {#addedStates=6, #modifiedStates=1, #deletedStates=0,
#modifiedRefs=0} took 15ms 
18:44:17,690 [main] DEBUGtion.ObservationManagerFactory  - notifying 0
synchronous listeners. 
18:44:17,690 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
got EventStateCollection 
18:44:17,691 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery to 0 consumers started... 
18:44:17,691 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery finished. 
18:44:17,843 [main] DEBUGlucene.Recovery                 - RedoLog is
empty, no recovery needed. 
18:44:17,855 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 0 -> http://www.jcp.org/jcr/1.0 
18:44:17,857 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 1 -> internal 
18:44:17,862 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 2 -> http://www.jcp.org/jcr/nt/1.0 
18:44:18,284 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 3 -> http://www.jcp.org/jcr/mix/1.0 
18:44:20,475 [main] INFO lucene.SearchIndex              - Index
initialized: repository/repository/index 
18:44:20,479 [main] DEBUGlucene.Recovery                 - RedoLog is
empty, no recovery needed. 
18:44:20,480 [main] INFO lucene.SearchIndex              - Index
initialized: repository/workspaces/default/index 
18:44:20,480 [main] INFO core.RepositoryImpl             - Repository
started 
18:44:20,480 [main] INFO core.TransientRepository        - Transient
repository initialized 
18:44:20,480 [main] DEBUGcore.TransientRepository        - Opening a new
session 
18:44:20,505 [main] INFO core.TransientRepository        - Session
opened 
18:44:20,506 [main] DEBUGcore.ItemManager                - created item
cafebabe-cafe-babe-cafe-babecafebabe 
18:44:20,506 [main] DEBUGcore.ItemManager                - caching item
cafebabe-cafe-babe-cafe-babecafebabe 
18:44:20,507 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc 
18:44:20,507 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc 
18:44:20,507 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:20,507 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:20,509 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:44:20,509 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:44:20,509 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}uuid 
18:44:20,509 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{http://www.jcp.org/jcr/1.0}uuid 
18:44:20,536 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{}name 
18:44:20,537 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{}name 
18:44:20,537 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{}type 
18:44:20,537 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{}type 
18:44:20,538 [main] DEBUGcore.ItemManager                - created item
4cf20632-3438-4c31-b099-f378df92f8cc/{}xmldata 
18:44:20,538 [main] DEBUGcore.ItemManager                - caching item
4cf20632-3438-4c31-b099-f378df92f8cc/{}xmldata 
18:44:20,548 [main] DEBUGstate.SharedItemStateManager    - persisting
change log {#addedStates=7, #modifiedStates=1, #deletedStates=0,
#modifiedRefs=0} took 8ms 
18:44:20,549 [main] DEBUGtion.ObservationManagerFactory  - notifying 3
synchronous listeners. 
18:44:20,553 [main] DEBUGcore.SearchManager              - onEvent:
indexing started 
18:44:20,557 [main] DEBUGlucene.NamespaceMappings        - adding new
namespace mapping: 4 ->  
18:44:20,558 [main] DEBUGcore.SearchManager              - onEvent:
indexing finished in 5 ms. 
18:44:20,558 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
got EventStateCollection 
18:44:20,558 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery to 1 consumers started... 
18:44:20,558 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery finished. 
18:44:20,559 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b 
18:44:20,559 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b 
18:44:20,560 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:20,560 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}primaryType 
18:44:20,561 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:44:20,561 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}mixinTypes 
18:44:20,561 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}uuid 
18:44:20,561 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{http://www.jcp.org/jcr/1.0}uuid 
18:44:20,562 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}name 
18:44:20,562 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}name 
18:44:20,562 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}type 
18:44:20,562 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}type 
18:44:20,562 [main] DEBUGcore.ItemManager                - created item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}xmldata 
18:44:20,562 [main] DEBUGcore.ItemManager                - caching item
9f9dda69-3fea-48b3-a8aa-c8ab606b0c4b/{}xmldata 
18:44:20,610 [main] DEBUGstate.SharedItemStateManager    - persisting
change log {#addedStates=7, #modifiedStates=1, #deletedStates=0,
#modifiedRefs=0} took 46ms 
18:44:20,611 [main] DEBUGtion.ObservationManagerFactory  - notifying 3
synchronous listeners. 
18:44:20,612 [main] DEBUGcore.SearchManager              - onEvent:
indexing started 
18:44:20,612 [main] DEBUGcore.SearchManager              - onEvent:
indexing finished in 0 ms. 
18:44:20,613 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
got EventStateCollection 
18:44:20,613 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery to 1 consumers started... 
18:44:20,613 [ObservationManager] DEBUGtion.ObservationManagerFactory  -
event delivery finished. 
18:44:20,641 [main] DEBUGcore.ItemManager                - invalidated
item cafebabe-cafe-babe-cafe-babecafebabe 
18:44:20,641 [main] DEBUGcore.ItemManager                - removing item
cafebabe-cafe-babe-cafe-babecafebabe from cache 
18:44:20,642 [main] INFO core.TransientRepository        - Session
closed 
18:44:20,642 [main] DEBUGcore.TransientRepository        - Shutting down
transient repository 
18:44:20,642 [main] INFO core.RepositoryImpl             - Shutting down
repository... 
18:44:20,642 [main] INFO core.RepositoryImpl             - shutting down
workspace 'default'... 
18:44:20,642 [main] INFO tion.ObservationManagerFactory  - Notification
of EventListeners stopped. 
18:44:20,642 [main] DEBUGlucene.IndexMerger              - dispose
IndexMerger 
18:44:20,643 [IndexMerger] INFO lucene.IndexMerger              -
IndexMerger terminated 
18:44:20,645 [main] DEBUGlucene.IndexMerger              - quit sent 
18:44:20,645 [main] DEBUGlucene.IndexMerger              - IndexMerger
thread stopped 
18:44:20,645 [main] DEBUGlucene.IndexMerger              - merge queue
size: 0 
18:44:20,663 [main] DEBUGlucene.AbstractIndex            - committing
IndexWriter. 
18:44:20,698 [main] DEBUGlucene.AbstractIndex            - merging
segments _0 (1 docs) _1 (1 docs) _2 (1 docs) into _3 (3 docs) 
18:44:20,732 [main] DEBUGlucene.IndexMerger              - index added:
name=_0, numDocs=3 
18:44:20,732 [main] DEBUGlucene.MultiIndex               - Committed
in-memory index in 87ms. 
18:44:20,733 [main] INFO lucene.SearchIndex              - Index closed:
repository/workspaces/default/index 
18:44:20,735 [main] DEBUGcore.ItemManager                - invalidated
item cafebabe-cafe-babe-cafe-babecafebabe 
18:44:20,735 [main] DEBUGcore.ItemManager                - removing item
cafebabe-cafe-babe-cafe-babecafebabe from cache 
18:44:20,750 [main] DEBUGrvation.ObservationManagerImpl  - removing
EventListener: org.apache.jackrabbit.core.SearchManager@5fa721e2 
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl  - removing
EventListener: org.apache.jackrabbit.core.lock.LockManagerImpl@4a6b2ab7 
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl  - removing
EventListener: org.apache.jackrabbit.core.SearchManager@5bab2ddb 
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl  - removing
EventListener: org.apache.jackrabbit.core.RepositoryImpl@11742dfe 
18:44:21,011 [main] INFO db.DerbyPersistenceManager      - Database
'repository/workspaces/default/db' shutdown. 
18:44:21,013 [main] INFO core.RepositoryImpl             - workspace
'default' has been shutdown 
18:44:21,013 [main] DEBUGlucene.IndexMerger              - dispose
IndexMerger 
18:44:21,013 [IndexMerger] INFO lucene.IndexMerger              -
IndexMerger terminated 
18:44:21,014 [main] DEBUGlucene.IndexMerger              - quit sent 
18:44:21,014 [main] DEBUGlucene.IndexMerger              - IndexMerger
thread stopped 
18:44:21,014 [main] DEBUGlucene.IndexMerger              - merge queue
size: 0 
18:44:21,035 [main] DEBUGlucene.AbstractIndex            - committing
IndexWriter. 
18:44:21,140 [main] DEBUGlucene.AbstractIndex            - merging
segments _0 (1 docs) _1 (1 docs) _2 (1 docs) _3 (1 docs) _4 (1 docs) _5
(1 docs) _6 (1 docs) _7 (1 docs) _8 (1 docs) _9 (1 docs) _a (1 docs) _b
(1 docs) _c (1 docs) _d (1 docs) _e (1 docs) _f (1 docs) _g (1 docs) _h
(1 docs) _i (1 docs) _j (1 docs) _k (1 docs) _l (1 docs) _m (1 docs) _n
(1 docs) _o (1 docs) _p (1 docs) _q (1 docs) _r (1 docs) _s (1 docs) _t
(1 docs) _u (1 docs) _v (1 docs) _w (1 docs) _x (1 docs) _y (1 docs) _z
(1 docs) _10 (1 docs) _11 (1 docs) _12 (1 docs) _13 (1 docs) _14 (1
docs) _15 (1 docs) _16 (1 docs) _17 (1 docs) _18 (1 docs) _19 (1 docs)
_1a (1 docs) _1b (1 docs) _1c (1 docs) _1d (1 docs) _1e (1 docs) _1f (1
docs) _1g (1 docs) _1h (1 docs) _1i (1 docs) _1j (1 docs) _1k (1 docs)
_1l (1 docs) _1m (1 docs) _1n (1 docs) _1o (1 docs) _1p (1 docs) _1q (1
docs) _1r (1 docs) _1s (1 docs) _1t (1 docs) _1u (1 docs) _1v (1 docs)
_1w (1 docs) _1x (1 docs) _1y (1 docs) _1z (1 docs) _20 (1 docs) _21 (1
docs) _22 (1 docs) _23 (1 docs) _24 (1 docs) _25 (1 docs) _26 (1 docs)
_27 (1 docs) _28 (1 docs) _29 (1 docs) _2a (1 docs) _2b (1 docs) _2c (1
docs) _2d (1 docs) _2e (1 docs) _2f (1 docs) _2g (1 docs) _2h (1 docs)
_2i (1 docs) _2j (1 docs) _2k (1 docs) _2l (1 docs) _2m (1 docs) _2n (1
docs) into _2o (96 docs) 
18:44:21,149 [main] DEBUGlucene.IndexMerger              - index added:
name=_0, numDocs=96 
18:44:21,149 [main] DEBUGlucene.MultiIndex               - Committed
in-memory index in 135ms. 
18:44:21,150 [main] INFO lucene.SearchIndex              - Index closed:
repository/repository/index 
18:44:21,380 [main] INFO db.DerbyPersistenceManager      - Database
'repository/version/db' shutdown. 
18:44:21,381 [main] INFO core.RepositoryImpl             - Repository
has been shutdown 
18:44:21,382 [main] INFO core.TransientRepository        - Transient
repository shut down 


If this is an issue with JUnit, then I'll just have to be handicapped
for a while w/o unit testing (nnnnoooooooooooooo!) until I figure out
what's going on.



Mime
View raw message