[
https://issues.apache.org/jira/browse/WOOKIE-145?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12888584#action_12888584
]
Randy Watler commented on WOOKIE-145:
-------------------------------------
Further analysis shows that this JPA exception is not a failure in the
persistence implementation, but rather an error caused by multiple
threads/requests from the widget attempting to set the same property
concurrently. In this case, the JPA exception is correct since one thread has
attempted to add a property that another thread has already added.
Here are significant requests coming from the widget/client:
...
127.0.0.1 - java [14/Jul/2010:16:09:59 -0600] "POST
/wookie/dwr/call/plaincall/WidgetImpl.setPreferenceForKey.dwr HTTP/1.1" 200 123
"http://localhost:8080/wookie/wservices/www.getwookie.org/widgets/wiki/index.html?idkey=tm43FPm3e3N0IkGNQO8EBExrBus.eq.&proxy=http://localhost:8080/wookie/proxy&st=testuser%3Atestuser%3Ahttp%253A%252F%252Fwww.getwookie.org%252Fwidgets%252Fwiki%3Awookie%3A%252Fwookie%252Fwservices%252Fwww.getwookie.org%252Fwidgets%252Fwiki%252Findex.html%3A0%3Atm43FPm3e3N0IkGNQO8EBExrBus.eq.?idkey=.sl.hA.sl.hm9TjfXysB7.sl.fr9U.sl.vgF.sl.3U.eq.&proxy=http://localhost:8080/wookie/proxy";
"Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.15) Gecko/2009102704
Fedora/3.0.15-1.fc10 Firefox/3.0.15"
127.0.0.1 - java [14/Jul/2010:16:09:59 -0600] "POST
/wookie/dwr/call/plaincall/WidgetImpl.setPreferenceForKey.dwr HTTP/1.1" 500
1242
"http://localhost:8080/wookie/wservices/www.getwookie.org/widgets/wiki/index.html?idkey=tm43FPm3e3N0IkGNQO8EBExrBus.eq.&proxy=http://localhost:8080/wookie/proxy&st=testuser%3Atestuser%3Ahttp%253A%252F%252Fwww.getwookie.org%252Fwidgets%252Fwiki%3Awookie%3A%252Fwookie%252Fwservices%252Fwww.getwookie.org%252Fwidgets%252Fwiki%252Findex.html%3A0%3Atm43FPm3e3N0IkGNQO8EBExrBus.eq.?idkey=.sl.hA.sl.hm9TjfXysB7.sl.fr9U.sl.vgF.sl.3U.eq.&proxy=http://localhost:8080/wookie/proxy";
"Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.15) Gecko/2009102704
Fedora/3.0.15-1.fc10 Firefox/3.0.15"
...
127.0.0.1 - java [14/Jul/2010:16:09:59 -0600] "POST
/wookie/dwr/call/plaincall/WidgetImpl.setPreferenceForKey.dwr HTTP/1.1" 200 123
"http://localhost:8080/wookie/wservices/www.getwookie.org/widgets/wiki/index.html?idkey=UzUDJkiTfQ.sl..pl.BGfcQL8MVAEONSQ.eq.&proxy=http://localhost:8080/wookie/proxy&st=testuser2%3Atestuser2%3Ahttp%253A%252F%252Fwww.getwookie.org%252Fwidgets%252Fwiki%3Awookie%3A%252Fwookie%252Fwservices%252Fwww.getwookie.org%252Fwidgets%252Fwiki%252Findex.html%3A0%3AUzUDJkiTfQ.sl..pl.BGfcQL8MVAEONSQ.eq.?idkey=.sl.hA.sl.hm9TjfXysB7.sl.fr9U.sl.vgF.sl.3U.eq.&proxy=http://localhost:8080/wookie/proxy";
"Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.15) Gecko/2009102704
Fedora/3.0.15-1.fc10 Firefox/3.0.15"
127.0.0.1 - java [14/Jul/2010:16:09:59 -0600] "POST
/wookie/dwr/call/plaincall/WidgetImpl.setPreferenceForKey.dwr HTTP/1.1" 200 123
"http://localhost:8080/wookie/wservices/www.getwookie.org/widgets/wiki/index.html?idkey=UzUDJkiTfQ.sl..pl.BGfcQL8MVAEONSQ.eq.&proxy=http://localhost:8080/wookie/proxy&st=testuser2%3Atestuser2%3Ahttp%253A%252F%252Fwww.getwookie.org%252Fwidgets%252Fwiki%3Awookie%3A%252Fwookie%252Fwservices%252Fwww.getwookie.org%252Fwidgets%252Fwiki%252Findex.html%3A0%3AUzUDJkiTfQ.sl..pl.BGfcQL8MVAEONSQ.eq.?idkey=.sl.hA.sl.hm9TjfXysB7.sl.fr9U.sl.vgF.sl.3U.eq.&proxy=http://localhost:8080/wookie/proxy";
"Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.15) Gecko/2009102704
Fedora/3.0.15-1.fc10 Firefox/3.0.15"
...
In this case, only the first widget instance preference operation catches the
error, (signified by the 500 status return code). This error does not seem to
occur as frequently when an embedded database like Derby is used. A centralized
database like MySQL increases the chance of transaction overlap with this
widget.
The question is now whether or not this should be considered expected behavior
or if these kinds of errors need to be handled more gracefully within the
widget server somehow?
> JPA error when Widget sets preference values
> ---------------------------------------------
>
> Key: WOOKIE-145
> URL: https://issues.apache.org/jira/browse/WOOKIE-145
> Project: Wookie
> Issue Type: Bug
> Components: Server
> Reporter: Scott Wilson
> Priority: Blocker
> Fix For: 0.8.1
>
>
> The JPA/JCR branch has a problem in the implementation of Preferences, where
> setting a preference within a widget causes a 500 error.
> To reproduce, run Wookie and open a demo widget for WookieWiki or any other
> widget using preferences.
> Here is the stack trace:
> [java] <openjpa-2.0.0-r422266:935683 fatal store error>
> org.apache.openjpa.persistence.RollbackException: The transaction has been
> rolled back. See the nested exceptions for details on the errors that
> occurred.
> [java] FailedObject:
> org.apache.wookie.beans.jpa.impl.preferencei...@27da9eda
> [java] at
> org.apache.openjpa.persistence.EntityManagerImpl.commit(EntityManagerImpl.java:583)
> [java] at
> org.apache.wookie.beans.jpa.JPAPersistenceManager.commit(JPAPersistenceManager.java:361)
> [java] at
> org.apache.wookie.server.MainFilter.doFilter(MainFilter.java:45)
> [java] at
> org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1089)
> [java] at
> org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:365)
> [java] at
> org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
> [java] at
> org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
> [java] at
> org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712)
> [java] at
> org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
> [java] at
> org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
> [java] at org.mortbay.jetty.Server.handle(Server.java:285)
> [java] at
> org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:502)
> [java] at
> org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:835)
> [java] at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:641)
> [java] at
> org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:202)
> [java] at
> org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:378)
> [java] at
> org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:226)
> [java] at
> org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
> [java] Caused by: <openjpa-2.0.0-r422266:935683 fatal store error>
> org.apache.openjpa.persistence.EntityExistsException: The transaction has
> been rolled back. See the nested exceptions for details on the errors that
> occurred.
> [java] FailedObject:
> org.apache.wookie.beans.jpa.impl.preferencei...@27da9eda
> [java] at
> org.apache.openjpa.kernel.BrokerImpl.newFlushException(BrokerImpl.java:2302)
> [java] at
> org.apache.openjpa.kernel.BrokerImpl.flush(BrokerImpl.java:2139)
> [java] at
> org.apache.openjpa.kernel.BrokerImpl.flushSafe(BrokerImpl.java:2037)
> [java] at
> org.apache.openjpa.kernel.BrokerImpl.beforeCompletion(BrokerImpl.java:1955)
> [java] at
> org.apache.openjpa.kernel.LocalManagedRuntime.commit(LocalManagedRuntime.java:81)
> [java] at
> org.apache.openjpa.kernel.BrokerImpl.commit(BrokerImpl.java:1479)
> [java] at
> org.apache.openjpa.kernel.DelegatingBroker.commit(DelegatingBroker.java:925)
> [java] at
> org.apache.openjpa.persistence.EntityManagerImpl.commit(EntityManagerImpl.java:559)
> [java] ... 17 more
> [java] Caused by: <openjpa-2.0.0-r422266:935683 fatal store error>
> org.apache.openjpa.persistence.EntityExistsException: The statement was
> aborted because it would have caused a duplicate key value in a unique or
> primary key constraint or unique index identified by 'UNPREFERENCE1' defined
> on 'PREFERENCE'. {prepstmnt 1145321369 INSERT INTO JAVA.Preference (ID,
> JPA_VERSION, WIDGET_INSTANCE_ID, DKEY, DVALUE, READONLY) VALUES (?, ?, ?, ?,
> ?, ?) [params=(int) 782, (int) 1, (int) 720, (String) currentPage, (Reader)
> java.io.stringrea...@6c07125, (String) ]} [code=20000, state=23505]
> [java] FailedObject:
> org.apache.wookie.beans.jpa.impl.preferencei...@27da9eda
> [java] at
> org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:4812)
> [java] at
> org.apache.openjpa.jdbc.sql.DBDictionary.newStoreException(DBDictionary.java:4787)
> [java] at
> org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:136)
> [java] at
> org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:78)
> [java] at
> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushAndUpdate(PreparedStatementManagerImpl.java:143)
> [java] at
> org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushAndUpdate(BatchingPreparedStatementManagerImpl.java:81)
> [java] at
> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushInternal(PreparedStatementManagerImpl.java:99)
> [java] at
> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flush(PreparedStatementManagerImpl.java:87)
> [java] at
> org.apache.openjpa.jdbc.kernel.ConstraintUpdateManager.flush(ConstraintUpdateManager.java:550)
> [java] at
> org.apache.openjpa.jdbc.kernel.ConstraintUpdateManager.flush(ConstraintUpdateManager.java:106)
> [java] at
> org.apache.openjpa.jdbc.kernel.BatchingConstraintUpdateManager.flush(BatchingConstraintUpdateManager.java:59)
> [java] at
> org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:103)
> [java] at
> org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:76)
> [java] at
> org.apache.openjpa.jdbc.kernel.JDBCStoreManager.flush(JDBCStoreManager.java:751)
> [java] at
> org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:131)
> [java] at
> org.apache.openjpa.datacache.DataCacheStoreManager.flush(DataCacheStoreManager.java:540)
> [java] at
> org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:131)
> [java] ... 24 more
> [java] Caused by: org.apache.openjpa.lib.jdbc.ReportingSQLException: The
> statement was aborted because it would have caused a duplicate key value in a
> unique or primary key constraint or unique index identified by
> 'UNPREFERENCE1' defined on 'PREFERENCE'. {prepstmnt 1145321369 INSERT INTO
> JAVA.Preference (ID, JPA_VERSION, WIDGET_INSTANCE_ID, DKEY, DVALUE, READONLY)
> VALUES (?, ?, ?, ?, ?, ?) [params=(int) 782, (int) 1, (int) 720, (String)
> currentPage, (Reader) java.io.stringrea...@6c07125, (String) ]} [code=20000,
> state=23505]
> [java] at
> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:257)
> [java] at
> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:233)
> [java] at
> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$1000(LoggingConnectionDecorator.java:70)
> [java] at
> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeUpdate(LoggingConnectionDecorator.java:1079)
> [java] at
> org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:285)
> [java] at
> org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.java:1722)
> [java] at
> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.executeUpdate(PreparedStatementManagerImpl.java:267)
> [java] at
> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushAndUpdate(PreparedStatementManagerImpl.java:118)
> [java] ... 36 more
> [java] 12:01:32,738 ERROR log:? -
> /wookie/dwr/call/plaincall/WidgetImpl.setPreferenceForKey.dwr
> [java] java.lang.RuntimeException
> [java] at
> org.apache.wookie.server.MainFilter.doFilter(MainFilter.java:50)
> [java] at
> org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1089)
> [java] at
> org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:365)
> [java] at
> org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
> [java] at
> org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
> [java] at
> org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712)
> [java] at
> org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
> [java] at
> org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
> [java] at org.mortbay.jetty.Server.handle(Server.java:285)
> [java] at
> org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:502)
> [java] at
> org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:835)
> [java] at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:641)
> [java] at
> org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:202)
> [java] at
> org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:378)
> [java] at
> org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:226)
> [java] at
> org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
