[Exist-open] concurrency issue - xmldb:add-user or xmldb:delete-user

[Xma M. <mon...@gm...>]

eXist team,

i am working with an eXist 1.4.1 instance and am running into a seeming
concurrency issue with the xmldb:add-user and xmldb:delete-user XQuery
functions.

we see the following scenario:

   - if the system is not busy, adding or removing users works without
   issue.  we have written ANT scripts to do this via URL and they do it a
   lot, without issue.
   - if the system is busy, adding and removing users generally works, but
   if you do it enough (script it) you can hit an error condition.  it seems
   like a concurrency problem as it is not consistent (sometimes 20 adds will
   work, sometimes only 1 or 2 before failure.  deletes seem to much more
   consistently fail).  when the error condition is hit, the eXist database
   seems to come to a deadlock and it cannot be roused by any means (XML-RPC,
   eclipse, Java client, HTTP, etc).


here are the debug logs from a successful add user and a failed add user:

== Logs from a Successful Add-user ==
  -> the highlighted or *** lines below never appear in the failed case,
nor does the entire second SYNC operation. T failed case goes into
storeXMLInternal and the GrammarPool functions and never comes out.
==========================
2012-03-27 13:24:30,589 ["http-bio-8080"-exec-2] DEBUG
(XMLSecurityManager.java [getUser]:257) - user WORKING_USER_ADD not found
2012-03-27 13:24:30,589 ["http-bio-8080"-exec-2] INFO
(XMLDBCreateUser.java [eval]:91) - Attempting to create user
WORKING_USER_ADD
2012-03-27 13:24:30,589 ["http-bio-8080"-exec-2] DEBUG
(XMLSecurityManager.java [save]:350) - storing acl file
2012-03-27 13:24:30,589 ["http-bio-8080"-exec-2] DEBUG (NGramIndex.java
[sync]:86) - SYNC NGRAM
2012-03-27 13:24:30,589 ["http-bio-8080"-exec-2] INFO  (NativeBroker.java
[sync]:3236) - Memory: 203,328K total; 1,040,512K max; 167,920K free
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
dom.dbx INDEX Buffers occupation : 69% (99 out of 144) Cache efficiency :
100%
 ["http-bio-8080"-exec-2] INFO  (DOMFile.java [printStatistics]:1434) -
dom.dbx DATA Buffers occupation : 100% (255 out of 256) Cache efficiency :
99%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
collections.dbx INDEX Buffers occupation : 11% (7 out of 64) Cache
efficiency : 100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
collections.dbx DATA Buffers occupation : 20% (13 out of 64) Cache
efficiency : 89%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
elements.dbx INDEX Buffers occupation : 30% (19 out of 64) Cache efficiency
: 100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
elements.dbx DATA Buffers occupation : 99% (154 out of 156) Cache
efficiency : 100%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
values.dbx INDEX Buffers occupation : 11% (7 out of 64) Cache efficiency :
100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
values.dbx DATA Buffers occupation : 12% (8 out of 64) Cache efficiency :
100%
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[checkPermissions]:1352) - Found old doc 1
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[validateXMLResourceInternal]:1223) - Scanning document /db/system/users.xml
 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[validateXMLResourceInternal]:1228) - removing old document users.xml
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] INFO  (NativeBroker.java
[removeXMLResource]:2246) - Removing document users.xml (1) ...
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (NativeBroker.java
[removeXMLResource]:2253) - removeDocument() - removing dom
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (NativeBroker.java
[removeResourceMetadata]:2360) - Removing resource metadata for 1
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[validateXMLResourceInternal]:1249) - removed old document users.xml
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[storeXMLInternal]:1041) - storing document 1 ...
 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 13:24:30,605 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
*** 2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[storeXMLInternal]:1055) - document stored.
*** 2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG (Collection.java
[storeXMLInternal]:1061) - users.xml changed
*** 2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG
(XMLSecurityManager.java [attach]:142) - loading acl
*** 2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG (BrokerPool.java
[reloadSecurityManager]:1399) - Security manager reloaded
2012-03-27 13:24:30,620 ["http-bio-8080"-exec-2] DEBUG (NGramIndex.java
[sync]:86) - SYNC NGRAM
2012-03-27 13:24:30,636 ["http-bio-8080"-exec-2] INFO  (NativeBroker.java
[sync]:3236) - Memory: 203,328K total; 1,040,512K max; 174,633K free
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
dom.dbx INDEX Buffers occupation : 69% (99 out of 144) Cache efficiency :
100%
 ["http-bio-8080"-exec-2] INFO  (DOMFile.java [printStatistics]:1434) -
dom.dbx DATA Buffers occupation : 100% (255 out of 256) Cache efficiency :
99%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
collections.dbx INDEX Buffers occupation : 11% (7 out of 64) Cache
efficiency : 100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
collections.dbx DATA Buffers occupation : 20% (13 out of 64) Cache
efficiency : 89%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
elements.dbx INDEX Buffers occupation : 30% (19 out of 64) Cache efficiency
: 100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
elements.dbx DATA Buffers occupation : 99% (154 out of 156) Cache
efficiency : 100%
 ["http-bio-8080"-exec-2] INFO  (BTree.java [printStatistics]:2378) -
values.dbx INDEX Buffers occupation : 11% (7 out of 64) Cache efficiency :
100%
 ["http-bio-8080"-exec-2] INFO  (BFile.java [printStatistics]:427) -
values.dbx DATA Buffers occupation : 12% (8 out of 64) Cache efficiency :
100%


== Logs from a Failed Add-user ==
   -> after the *** lines, the entire database is frozen and unresponsive
until restart, at which you may have DB corruption.
==========================
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] DEBUG
(XMLSecurityManager.java [getUser]:257) - user bcm107 not found
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] INFO  (XMLDBCreateUser.java
[eval]:91) - Attempting to create user bcm107
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] DEBUG
(XMLSecurityManager.java [save]:350) - storing acl file
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] DEBUG (NGramIndex.java
[sync]:86) - SYNC NGRAM
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] INFO  (NativeBroker.java
[sync]:3236) - Memory: 593,984K total; 1,013,632K max; 282,979K free
2012-03-27 15:50:10,606 [http-bio-8080-exec-30] INFO  (BTree.java
[printStatistics]:2378) - dom.dbx INDEX Buffers occupation : 100% (64 out
of 64) Cache efficiency : 100%
2012-03-27 15:50:10,622 [http-bio-8080-exec-27] DEBUG (XQueryContext.java
[compileModule]:2333) - Loading module from lib/util.xql
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (DOMFile.java
[printStatistics]:1434) - dom.dbx DATA Buffers occupation : 100% (255 out
of 256) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BTree.java
[printStatistics]:2378) - collections.dbx INDEX Buffers occupation : 9% (6
out of 64) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BFile.java
[printStatistics]:427) - collections.dbx DATA Buffers occupation : 16% (10
out of 64) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BTree.java
[printStatistics]:2378) - elements.dbx INDEX Buffers occupation : 17% (11
out of 64) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BFile.java
[printStatistics]:427) - elements.dbx DATA Buffers occupation : 99% (99 out
of 100) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BTree.java
[printStatistics]:2378) - values.dbx INDEX Buffers occupation : 12% (8 out
of 64) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (BFile.java
[printStatistics]:427) - values.dbx DATA Buffers occupation : 11% (7 out of
64) Cache efficiency : 100%
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (Collection.java
[checkPermissions]:1352) - Found old doc 1
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (Collection.java
[validateXMLResourceInternal]:1223) - Scanning document
/db/system/users.xml
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (Collection.java
[validateXMLResourceInternal]:1228) - removing old document users.xml
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] INFO  (NativeBroker.java
[removeXMLResource]:2246) - Removing document users.xml (1) ...
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (NativeBroker.java
[removeXMLResource]:2253) - removeDocument() - removing dom
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (NativeBroker.java
[removeResourceMetadata]:2360) - Removing resource metadata for 1
2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (Collection.java
[validateXMLResourceInternal]:1249) - removed old document users.xml
*** 2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (Collection.java
[storeXMLInternal]:1041) - storing document 1 ...
*** 2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:81) - Retrieve initial grammarset (
http://www.w3.org/TR/REC-xml).
*** 2012-03-27 15:50:10,653 [http-bio-8080-exec-30] DEBUG (GrammarPool.java
[retrieveInitialGrammarSet]:85) - Found 0 grammars.
2012-03-27 15:50:10,684 [http-bio-8080-exec-22] DEBUG (XQueryContext.java
[importModule]:2212) - Module http://xyenterprise.com/xquery/lcutil already
present.
. . .
the hems and haws a bit as it finishes some outgoing responses, but
basically is deadlocked right here.  it cannot be roused by any means
(XML-RPC, eclipse, Java client, HTTP, etc).

has anyone hit this before?  i have been working with it all day and can
reproduce it very readily.  i have tried it a few different ways now and
its consistently system load + add or delete uses which triggers the
problem.

please help!
xmonkey