Closed henning-gerhardt closed 8 months ago
henning-gerhardt
commented
8 years ago I think it has nothing to do with search form as this error appear on different sites - more a problem inside batch exporting or how batch exporting influence database connection. Maybe useful to switch to ExportWithoutHibernate class instead of Export class?
matthias-ronge
commented
8 years ago Cause is simple, solving it isn’t:
You have a race condition in your application. [… The session is] close()ed between the query and the commit. […] You need to understand the lifecycle of your Sessions, and ensure that this never happens.
Do you use the c3p0.properties cheat as stated in #296 ?
henning-gerhardt
commented
8 years ago Yes, on my develop system I used this statements in c3p0.properties file but only with c3p0.unreturnedConnectionTimeout with value 800 instead of 32768. The defined stacktrace c3p0.debugUnreturnedConnectionStackTraces=true was never be shown or logged in any log file.
matthias-ronge
commented
8 years ago It seems that the problem originates from HibernateUtilOld.getSession(), l. 136. It does not create a new session if the thread already has (a closed) one. This should probably be corrected to s == null || !s.isOpen().
By the way, keeping the Hibernate session in a ThreadLocal seems to me to contradict to also keeping the Hibernate session in the Faces session of each user. If a new thread is created to process a HTTP request from one user (due to decision of the framework, because of increasing load), the user will get a new Hibernate session. If a thread from the therad pool is reused to process the HTTP request, the user will get the Hibernate session from just someone, both users now share the same Hibernate session. Is this what we want?
matthias-ronge
commented
8 years ago If the application’s design shares sessions between users the session must never be closed. Opening a new session would not fix it as also the beans in the user’s Faces session are interconnected to their originating session. Solution must be not to share the session between the worker thread for newspaper export and the (your) user session.
henning-gerhardt
commented
8 years ago It makes for me no sense to hold hibernate session on two places nor should users share same hibernate session.
Edit: My comment was for @matthias-ronge https://github.com/goobi/goobi-production/issues/431#issuecomment-180245587
henning-gerhardt
commented
8 years ago @matthias-ronge : What did you think is a good or best solution to solve this problem?
matthias-ronge
commented
8 years ago There are various problems with this:
I do only see one clean solution:
Each HTTP request must open and close its own Hibernate session. Every bean from the user session must be re-attached to the new Hibernate session before it is reused. (This would also fix the problem of objects showing a state that is no longer true.) There are steps towards this in de.sub.goobi.persistence.HibernateSessionConversationFilter and HibernateSessionConversationFilterWithoutTransaction, but they are currently dead code.
This feels like a very major rewrite. If this is done, updating to the latest Hibernate version should happen at the same time.
henning-gerhardt
commented
8 years ago I see in your solution a possible performance problem / issue as synchronizing takes a lot of time and made responses to the user slower.
Do you know how other java web applications solve this kind of probem / issue? I think Spring / Seam and other frameworks must have an solution for this and maybe this "proved" solution can be adopted to our code.
matthias-ronge
commented
8 years ago Each HTTP request must open and close its own Hibernate session.
Spring comes with OpenSessionInViewFilter which does this.
BTW, this also fixes objects showing in an outdated state that can sometimes be encountered here, because reconnecting the object updates them from the database.
henning-gerhardt
commented
8 years ago Some more discussion and analyzing of this bug happen in pull request #432 .
matthias-ronge
commented
8 years ago The “clean solution” is even more complex as I thought. Here is a discussion on SO which references a German and an English version of a recommendable article that sheds some light on the complex and problematic relationship between multi-threaded (web) applications and Hibernate. I supect that this bug and #296 have the same cause.
henning-gerhardt
commented
8 years ago @matthias-ronge : thank you for this interesting lecture. It is more complicate as I thought.
A work around for a more stable / solid search form are opened as pull request #439.
matthias-ronge
commented
8 years ago A related discussion in the Hibernate Forum
matthias-ronge
commented
8 years ago This article proposes a design which seems to solve it. They do not rely on unreliable magic code but make transactions explicit in their program.
henning-gerhardt
commented
8 years ago @matthias-ronge : nice and informative article! Reworking current state to hopeful better implementation is a major task.
But I had covered a new problem in batch form: "You can't operate on a closed Connection!!! "
java.lang.NullPointerException
at com.mchange.v2.c3p0.impl.NewProxyConnection.getAutoCommit(NewProxyConnection.java:985)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.isAutoCommit(LogicalConnectionImpl.java:392)
at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.afterNonTransactionalQuery(TransactionCoordinatorImpl.java:195)
at org.hibernate.internal.SessionImpl.afterOperation(SessionImpl.java:598)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1630)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:374)
at org.goobi.production.flow.statistics.hibernate.UserDefinedFilter.createIDListFromCriteria(UserDefinedFilter.java:218)
at org.goobi.production.flow.statistics.hibernate.UserDefinedFilter.createCriteriaFromFilterString(UserDefinedFilter.java:202)
at org.goobi.production.flow.statistics.hibernate.UserDefinedFilter.getCriteria(UserDefinedFilter.java:103)
at de.sub.goobi.forms.BatchForm.filterProcesses(BatchForm.java:136)
at de.sub.goobi.forms.BatchForm.FilterAlleStart(BatchForm.java:217)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.myfaces.el.MethodBindingImpl.invoke(MethodBindingImpl.java:132)
at org.apache.myfaces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:61)
at javax.faces.component.UICommand.broadcast(UICommand.java:109)
at org.ajax4jsf.component.AjaxViewRoot.processEvents(AjaxViewRoot.java:184)
at org.ajax4jsf.component.AjaxViewRoot.broadcastEvents(AjaxViewRoot.java:162)
at org.ajax4jsf.component.AjaxViewRoot.processApplication(AjaxViewRoot.java:350)
at org.apache.myfaces.lifecycle.InvokeApplicationExecutor.execute(InvokeApplicationExecutor.java:32)
at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:95)
at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:70)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:139)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:141)
at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:281)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at de.sub.goobi.helper.servletfilter.SessionCounterFilter.doFilter(SessionCounterFilter.java:74)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at de.sub.goobi.helper.servletfilter.HibernateSessionFilter2.doFilter(HibernateSessionFilter2.java:75)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at de.sub.goobi.helper.servletfilter.SecurityCheckFilter.doFilter(SecurityCheckFilter.java:77)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at de.sub.goobi.helper.servletfilter.RequestControlFilter.doFilter(RequestControlFilter.java:147)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:341)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:225)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:200)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:579)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)I exported multiple newspaper batches including a multiple year newspaper batch export (134 processes), looked into the files. A few minutes later, I want to export an other newspaper batch and I got above error message and stack trace.
matthias-ronge
commented
8 years ago at org.goobi.production.flow.statistics.hibernate.UserDefinedFilter.createIDListFromCriteria(UserDefinedFilter.java:218)is the same kind of iteration on criteria.list() that you could fix in SearchForm. May you try to apply the same fix there?
henning-gerhardt
commented
8 years ago I can try it. But what should we do if this error occur an other part of code? Fixing there too? It could be a never ending story.
henning-gerhardt
commented
8 years ago While testing changes for I got an other exception (partial stack trace attached)
...
at de.sub.goobi.helper.PaginatingCriteria.list(PaginatingCriteria.java:357)
at de.sub.goobi.forms.BatchForm.filterProcesses(BatchForm.java:144)
at de.sub.goobi.forms.BatchForm.FilterAlleStart(BatchForm.java:217)
...It is again a list() call to Criteria object.
matthias-ronge
commented
8 years ago I am about to create a bigger newspaper batch in hope that I can then reproduce the problems. Currently it hides from me.
henning-gerhardt
commented
8 years ago Just for info: Fro testing I use 9 batches with 5 to 26 processes and one big batch with 134 processes.
matthias-ronge
commented
8 years ago Rethinking the consequences of the first article I linked to above got me onto one idea which might solve it. Would you check this one out? https://github.com/matthias-ronge/goobi-production/tree/pass-id-to-worker-thread (Diff)
To put it short, instead of using the batch object, its ID will be passed to the run() function which then acts on its own thread and there should load its own, clean version from the database.
At least it didn’t break my existing exports.
henning-gerhardt
commented
8 years ago I tried your code change and there is no difference for search form after exporting a newspaper batch. Goobi logs following message
WARN 2016-02-11 11:05:30,739 (SearchForm.java:<init>:142)
Catched RuntimeException. Hibernate session maybe corrupted - recreating new hibernate session!I have now tryied with a larger batch, but still no problems appear.
henning-gerhardt
commented
8 years ago That is bad :( I can reproduce this kind of errors on every our created newspaper batches. Even if I created new batches from existing newspaper processes.
matthias-ronge
commented
8 years ago I created a branch which adds a lot of logging for hibernate session access and closing (diff). Along with these settings it is quite useable:
# standard-out-Appender
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%m%n
# no duplicate log messages
log4j.additivity.org.hibernate=false
# Goobi allgemein
log4j.rootLogger=ERROR, stdout
log4j.logger.de.sub.goobi=DEBUG
log4j.logger.org.goobi=DEBUG
log4j.logger.ugh=ERRORIt reveals that my newspaper batch export does not at all request any session. This makes it quite clear why there is no interference when I do export. Also all requests from me were performed by the same thread. :(
Perhaps you can try it and find something surprising?
henning-gerhardt
commented
8 years ago I tried your changes and send you a log file.
matthias-ronge
commented
8 years ago I think that I’ve found the corresponding Hibernate bug report. Two excerpts:
Gavin King:
This would have to be a c3p0 problem, not a HB problem, I assume.
Konrad Steinmuller:
I think I have managed to fix it though.
There were two things I did.
- Upgrading the postgres driver to the latest version seemed to help the problem.
- Then after that upgrading the C3P0 jar to the latest version then stopped the problem completely.
Perhaps the latter will do the trick?
henning-gerhardt
commented
8 years ago I did the following in a new branch
and now I got following messages in Goobi Log
WARN 2016-02-18 10:41:59,133 (SqlExceptionHelper.java:logExceptions:144)
SQL Error: 0, SQLState: null
ERROR 2016-02-18 10:41:59,134 (SqlExceptionHelper.java:logExceptions:146)
You can't operate on a closed ResultSet!!!
WARN 2016-02-18 10:41:59,136 (SqlExceptionHelper.java:logExceptions:144)
SQL Error: 0, SQLState: null
ERROR 2016-02-18 10:41:59,137 (SqlExceptionHelper.java:logExceptions:146)
You can't operate on a closed Connection!!!
WARN 2016-02-18 10:41:59,137 (SearchForm.java:<init>:160)
Catched RuntimeException. Hibernate session maybe corrupted - recreating new hibernate session!and a related stack trace:
org.hibernate.exception.GenericJDBCException: could not inspect JDBC autocommit mode
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.isAutoCommit(LogicalConnectionImpl.java:311)
at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.afterNonTransactionalQuery(TransactionCoordinatorImpl.java:200)
at org.hibernate.internal.SessionImpl.afterOperation(SessionImpl.java:477)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1631)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:374)
at de.sub.goobi.forms.SearchForm.<init>(SearchForm.java:153)(for this output I added some printStackTrace() calls into the catch blocks)
henning-gerhardt
commented
8 years ago If I changed auto commit mode of C3P0 to true, the stack trace changed to following output
org.hibernate.exception.GenericJDBCException: could not execute query
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)
at org.hibernate.loader.Loader.doList(Loader.java:2553)
at org.hibernate.loader.Loader.doList(Loader.java:2536)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2366)
at org.hibernate.loader.Loader.list(Loader.java:2361)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:124)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1623)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:374)
at de.sub.goobi.forms.SearchForm.<init>(SearchForm.java:138)with corresponding log messages:
WARN 2016-02-18 10:59:33,048 (SqlExceptionHelper.java:logExceptions:144)
SQL Error: 0, SQLState: null
ERROR 2016-02-18 10:59:33,048 (SqlExceptionHelper.java:logExceptions:146)
You can't operate on a closed ResultSet!!!
WARN 2016-02-18 10:59:33,050 (SearchForm.java:<init>:143)
Catched RuntimeException. Hibernate session maybe corrupted - recreating new hibernate session!Googleing GenericJDBCException: could not inspect JDBC autocommit mode returns me to an article which suggests to set validationQuery to “something that returns at least one row”:
select version();
henning-gerhardt
commented
8 years ago I tried that but with no luck.
I resetted yesterday my develop database and did not changed MySQL engine from MyISAM to InnoDB nor I changed collation from latin1_swedish_ci to utf8mb4_unicode_ci and the error disappear.
I will test some combinations of used MySQL engines and collations.
henning-gerhardt
commented
8 years ago I did some basic tests:
| latin1_swedish_ci | utf8_general_ci | utf8_unicode_ci | utf8mb4_general_ci | utf8mb4_unicode_ci | |
|---|---|---|---|---|---|
| MyISAM | OK | OK | GOOD | GOOD | ERROR |
| InnoDB | OK | OK | GOOD | ERROR | ERROR |
Meaning of
It's look like that collation utf8mb4_general_ci or utf8mb4_unicode_ci are problematic in certain usage scenarios.
matthias-ronge
commented
8 years ago Does this also fix #445?
henning-gerhardt
commented
8 years ago Issue #445 is independent of used database engine and used collation.
matthias-ronge
commented
8 years ago Do you know if the erroneous …_cis came into the database automatically (created our init sql scripts or Hibernate)? Could it come from a MySQL preferences setting?
henning-gerhardt
commented
8 years ago Why is ..._ci erroneous? Most character sets are case-insensitive (..._ci) instead of case-sensitive (..._cs) and a few binary collations (..._bin).
I use both: created database and tables by init sql scripts and by hibernate. Hibernate used the database server default values (MySQL 5.6 with InnoDB engine and utf8mb4_unicode_ci collation) or what you define in your hibernate.cfg.xml as to used dialect f.e. org.hibernate.dialect.MySQLDialect. In my init sql scripts I could vary engine and collation.
The provided schema sql is defining latin1 as charset / collation which is expanded to latin1_swedish_ci on table creation.
After exporting one or a few newspaper batches and switch to my task or searching for a volume an error message for a closed connection appear:
You can't operate on a closed Connection!!!
and following stack trace (for searching for a volume):
Stack trace leads to line 121 in SearchForm class.
You must reload the site to work again.
Same message "You can't operate on a closed Connection!!!" logged in Goobi log while working in batch form (f.e. after exporting a batch, switching back to batches and exporting an other batch).