[Geoserver-devel] Detailed Log WFS Deadlock

He Jesse; you got the wrong list ...

I turned on logging in GeoServer to ALL in the hopes of learning more. I have reproduced this problem on GeoServer 1.5.3 and 1.5.2. With both JDK5 and JDK6.
The log is at the end of the message and is a solid stack trace...
- first of all this looks like a fixable shapefile problem
- second the message did not make it back to the screen in uDig

I will look into the service policy on the GeoServer side to make sure we are sending back a well formed error message.

Hi list,

Have you gotten any reports of Geoserver 1.5.3 getting locked on a dataset after a few edits take place? Here's what I'm doing:

1. Add a geoserver layer (say tasmania roads).
2. Edit it a bunch of times (with uDig, any version as far as I can tell)

Eventually it will lock up (not uDig but rendering that layer). I can close the map and try to the the layer with a WMS. That will also never return (until uDig times out). All other layers are fine.

I kill GeoServer and it looks like it is deadlocking on the Shapefile Lock... Sounds like my fault :frowning: or possibly a result of one of Andreas changes and I missed the mistake as well.

I think one of two things are happening:

1. The lock has an internal race condition and should be replaced with a Java 5 Read/Write lock
2. Some object is aquiring the lock (read or write I don't know right now) and forgetting to release it (or throwing an exception so that it doesn't get released).

Here is the LOG from GeoServer 1.5.3, JDK6 set to ALL:

handle: null topp:tasmania_roads 5
ReleaseAll: true
filter: [ tasmania_roads.14 ]
Property - Name: the_geom, Value: MULTILINESTRING ((147.256744 -42.778393, 147.220184 -42.824776, 147.179596 -42.82143, 147.111328 -42.795731, 147.057098 -42.741581, 147.003479 -42.704803, 146.919098
-42.622734, 146.910538 -42.610928, 146.889984 -42.585396, 146.83844 -42.572792, 146.78569 -42.539352, 146.724335 -42.485966, 146.695023 -42.469582, 146.649872 -42.450371, 146.604965 -42.432274, 146.57
8781 -42.408531, 146.539307 -42.364208, 146.525055 -42.30883, 146.558044 -42.275948, 146.576248 -42.23777, 146.4846279686722 -42.2049867477115, 146.47080106940575 -42.15244453049892, 146.4099627126333
-42.12202535211269, 146.334061 -42.138741, 146.270966 -42.165703, 146.23021302216918 -42.15520991035221, 146.20255922363626 -42.149679150645625, 146.16660928554344 -42.199455988004914, 146.167908 -42
.244835, 146.164932 -42.245171, 146.111023 -42.265202, 146.037476 -42.239738, 145.981628 -42.187851, 145.853912 -42.133492, 145.819611 -42.129154, 145.72052 -42.104084, 145.618576 -42.056023, 145.5417
18 -42.027241, 145.486282 -41.983326, 145.452744 -41.926544, 145.494034 -41.896477, 145.591736 -41.860214, 145.64212 -41.838398, 145.669449 -41.830734, 145.680923 -41.795753, 145.682968 -41.743221, 14
5.675156 -41.710377, 145.680115 -41.688908, 145.701065 -41.648228, 145.714798 -41.609509, 145.629196 -41.462051, 145.648895 -41.470337, 145.633423 -41.420902, 145.631866 -41.36528, 145.640854 -41.3015
33, 145.700424 -41.242611, 145.77243 -41.193897, 145.802338 -41.161488, 145.856018 -41.08007))

104844 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Preprocess to remember modification as a set of fids
104844 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.NONE
104860 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.ALL
104860 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been opened. Number open: 1
104860 [FINER] org.geotools.data.shapefile.Lock - Start Read Lock:btpool0-4 has 5 locks
104860 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been opened. Number open: 1
104860 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.NONE
104860 [FINER] org.geotools.data.shapefile.Lock - unlock Read:btpool0-4 has 4 locks
104860 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been closed. Number open: 0
104860 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been closed. Number open: 0
104860 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been opened. Number open: 1
104860 [FINER] org.geotools.data.shapefile.Lock - Start Read Lock:btpool0-4 has 5 locks
104875 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been opened. Number open: 1
104875 [FINER] org.geotools.data.shapefile.Lock - unlock Read:btpool0-4 has 4 locks
104875 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been closed. Number open: 0
104875 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been closed. Number open: 0
104875 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Post process update for boundary update and featureValidation
104875 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.NONE
104875 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.ALL
104875 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been opened. Number open: 1
104875 [FINER] org.geotools.data.shapefile.Lock - Start Read Lock:btpool0-4 has 5 locks
104875 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been opened. Number open: 1
104875 [FINEST] org.geotools.filter.FidFilterImpl - condition: Filter.NONE
104891 [FINE] org.vfny.geoserver.global.Data - getting type topp:tasmania_roads
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - FeatureValidation called on tasmania_roads:tasmania_roads
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Required to validate 1 typeRefs
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - within Env[145.452744 : 147.256744, -42.824776 : -41.08007]
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - typeRef tasmania_roads:tasmania_roads requires
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Searching for required typeRef: tasmania_roads:tasmania_roads
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - found required typeRef: tasmania_roads:tasmania_roads (it was already loaded)
104891 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Total of 1 featureSource marshalled for testing
104907 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - Runing integrity tests using validation processor
104907 [FINE] org.geotools.validation.ValidationProcessor - No tests defined by integrityLookup - validation not needed
104907 [FINER] org.vfny.geoserver.wfs.responses.TransactionResponse - All validation tests passed
104907 [FINER] org.vfny.geoserver.servlets.AbstractService - execution succeed
104907 [FINEST] org.vfny.geoserver.servlets.AbstractService - getting strategy output
104907 [FINER] org.vfny.geoserver.servlets.AbstractService - strategy output is: java.io.BufferedOutputStream
104907 [FINE] org.vfny.geoserver.servlets.AbstractService - mime type is: text/xml; charset=UTF-8
104907 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been opened. Number open: 1
104907 [FINER] org.geotools.data.shapefile.Lock - Start Read Lock:btpool0-4 has 6 locks
104907 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been opened. Number open: 1
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - SHP Channel in ShapefileWriter has been opened. Number open: 1
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - SHX Channel in ShapefileWriter has been opened. Number open: 1
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Writer has been opened. Number open: 1
104922 [FINER] org.geotools.data.shapefile.Lock - unlock Read:btpool0-4 has 5 locks
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - Shapefile Reader has been closed. Number open: 0
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Reader has been closed. Number open: 0
104922 [FINEST] org.geotools.data.shapefile.StreamLogging - SHP Channel in ShapefileWriter has been closed. Number open: 0
104938 [FINEST] org.geotools.data.shapefile.StreamLogging - SHX Channel in ShapefileWriter has been closed. Number open: 0
104938 [FINEST] org.geotools.data.shapefile.StreamLogging - Dbase File Writer has been closed. Number open: 0
104938 [FINER] org.geotools.data.shapefile.Lock - btpool0-4 is getting write lock:1
104938 [FINER] org.geotools.data.shapefile.Lock - unlock write:btpool0-4
104938 [INFO] org.vfny.geoserver.servlets.AbstractService - Stream abruptly closed by client, response aborted
104938 [FINE] org.vfny.geoserver.servlets.AbstractService - Error writing out Unable to delete original file: file:/C:/Program Files/GeoServer 1.5.3/data_dir/data/taz_shapes/tasmania_roads.shp
java.io.IOException: Unable to delete original file: file:/C:/Program Files/GeoServer 1.5.3/data_dir/data/taz_shapes/tasmania_roads.shp
        at org.geotools.data.shapefile.ShapefileDataStore.copyAndDelete(ShapefileDataStore.java:1215)
        at org.geotools.data.shapefile.ShapefileDataStore$Writer.clean(ShapefileDataStore.java:1488)
        at org.geotools.data.shapefile.ShapefileDataStore$Writer.close(ShapefileDataStore.java:1554)
        at org.geotools.data.TransactionStateDiff.applyDiff(TransactionStateDiff.java:252)
        at org.geotools.data.TransactionStateDiff.commit(TransactionStateDiff.java:139)
        at org.geotools.data.DefaultTransaction.commit(DefaultTransaction.java:181)
        at org.vfny.geoserver.wfs.responses.TransactionResponse.writeTo(TransactionResponse.java:818)
        at org.vfny.geoserver.servlets.AbstractService.doService(AbstractService.java:592)
        at org.vfny.geoserver.servlets.AbstractService.doPost(AbstractService.java:447)
        at org.geoserver.request.Dispatcher.post(Dispatcher.java:301)
        at org.geoserver.request.Dispatcher.dispatch(Dispatcher.java:181)
        at org.geoserver.request.Dispatcher.handleRequestInternal(Dispatcher.java:52)
        at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:139)
        at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:44)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:684)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:625)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:392)
        at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:357)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:445)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1050)
        at org.vfny.geoserver.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:103)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1041)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:354)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:226)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:627)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:149)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:123)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:141)
        at org.mortbay.jetty.Server.handle(Server.java:269)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:430)
        at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:701)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:617)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:193)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:339)
        at org.mortbay.jetty.nio.HttpChannelEndPoint.run(HttpChannelEndPoint.java:270)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)