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:
[EMAIL PROTECTED]
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: [EMAIL PROTECTED]
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl - removing
EventListener: [EMAIL PROTECTED]
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl - removing
EventListener: [EMAIL PROTECTED]
18:44:20,751 [main] DEBUGrvation.ObservationManagerImpl - removing
EventListener: [EMAIL PROTECTED]
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.
