Hibernate errors in dotCMS 3.3

Bart Plasmans

unread,

Mar 11, 2016, 9:31:20 AM3/11/16

to dotCMS User Group

Hi,

I have a weird issue with a clustered dotCMS 3.3 on MSSQL.

For a customer we have just copied dotCMS and its database from UAT to Production environment.

On the UAT environment all was working well. We have only adjusted minor things, like the location of shares and the database url.

Somehow we now get the following error, which prevents us from creating an index, it just stops at 0%:

[11/03/16 14:20:49:100 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:20:53:254 GMT] INFO action.ViewCMSMaintenanceAction: Running Contents Index Cache

[11/03/16 14:20:53:267 GMT] INFO action.ViewCMSMaintenanceAction: Running Contentlet Reindex

[11/03/16 14:20:53:270 GMT] INFO business.ESIndexAPI: createIndex : Trying to create index: working_20160311142053 with shards: 0

[11/03/16 14:20:53:457 GMT] INFO cluster.metadata: [1] [working_20160311142053] creating index, cause [api], shards [1]/[0], mappings []

[11/03/16 14:20:53:541 GMT] INFO business.ESIndexAPI: createIndex : Index created: working_20160311142053 with shards: 1

[11/03/16 14:20:53:573 GMT] INFO cluster.metadata: [1] [working_20160311142053] create_mapping [content]

[11/03/16 14:20:53:586 GMT] INFO business.ESIndexAPI: createIndex : Trying to create index: live_20160311142053 with shards: 0

[11/03/16 14:20:53:675 GMT] INFO cluster.metadata: [1] [live_20160311142053] creating index, cause [api], shards [1]/[0], mappings []

[11/03/16 14:20:53:733 GMT] INFO business.ESIndexAPI: createIndex : Index created: live_20160311142053 with shards: 1

[11/03/16 14:20:53:740 GMT] INFO cluster.metadata: [1] [live_20160311142053] create_mapping [content]

[11/03/16 14:20:53:761 GMT] INFO cluster.metadata: [1] updating number_of_replicas to [0] for indices [working_20160311142053]

[11/03/16 14:20:53:769 GMT] INFO cluster.metadata: [1] updating number_of_replicas to [0] for indices [live_20160311142053]

[11/03/16 14:20:54:110 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:20:54:113 GMT] INFO guava.GuavaCache: *** Building Cache : indiciescache, size:8,Concurrency:32

[11/03/16 14:20:59:124 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:03:820 GMT] INFO reindex.ReindexThread: ContentIndexationThread ordered to start processing

[11/03/16 14:21:03:823 GMT] INFO action.ViewCMSMaintenanceAction: processAction : Running Contentlet Reindex

[11/03/16 14:21:04:203 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:04:208 GMT] INFO guava.GuavaCache: *** Building Cache : indiciescache, size:8,Concurrency:32

[11/03/16 14:21:04:238 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:09:247 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:09:257 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:14:264 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

java.sql.SQLException: rollback() should not be called while in auto-commit mode.

[11/03/16 14:21:14:273 GMT] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

The error keeps appearing non stop.

The customer's IT department has checked the reindex tables, but they are all empty.

I have undeployed all custom plugins, so there are no other custom libs active.

Everything else seems to be fine, I have added the complete startup log here.

Can anyone help me??

greetings Bart

dotcms-log.txt.txt

Bart Plasmans

unread,

Mar 14, 2016, 9:25:27 AM3/14/16

to dotCMS User Group

Hi,

can anyone point me in the correct direction?

Still have no clue at why this happens.

Could it be that MSSQL database server is configured wrong, or is it not in the database?

greetings Bart

Will Ezell

unread,

Mar 14, 2016, 9:31:32 AM3/14/16

to dot...@googlegroups.com

A few quick thoughts - is the index directory writable by dotCMS? Also, transaction isolation is set correctly on the MSSQL db? Are the versions of MSSQL the same on UAT and Prod?

--
You received this message because you are subscribed to the Google Groups "dotCMS User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dotcms+un...@googlegroups.com.
To post to this group, send email to dot...@googlegroups.com.
Visit this group at https://groups.google.com/group/dotcms.
For more options, visit https://groups.google.com/d/optout.

--

3059 Grand Avenue

Suite 410-B

Miami FL 33133

Main: 305-900-2001 | Direct: 978.294.9429

wi...@dotcms.com | dotcms.com

Jason Tesser

unread,

Mar 14, 2016, 9:32:38 AM3/14/16

to dot...@googlegroups.com

Just FYI this is the doc for what Will is talking about http://dotcms.com/docs/latest/database-configuration#MSSQLServer

Bart Plasmans

unread,

Mar 15, 2016, 4:06:40 AM3/15/16

to dotCMS User Group

Thank you Will and Jason,

I'm going to check this with the Customers IT department.

Bart

Bart Plasmans

unread,

Mar 15, 2016, 9:22:15 AM3/15/16

to dotCMS User Group

Hi,

the database server is configured exactly the same, inclduding the transaction isolation.

Also the correct rights are set to the complete dotCMS folder, including the index folder.

What else could we check?

greetings Bart

Brent Griffin

unread,

Mar 15, 2016, 9:58:49 AM3/15/16

to dotCMS User Group

Is there anything of interest in the catalina.out log file?

What plugins do you have deployed and what scheduled jobs do you have? Any chance there is environmentally specific logic/config in them?

The only thing in the log file that got my attention were these lines:

[11/03/16 14:17:13:134 GMT] INFO dialect.Dialect: Using dialect: null

[11/03/16 14:17:13:165 GMT] INFO dialect.Dialect: Using dialect: com.dotcms.repackage.net.sf.hibernate.dialect.GenericDialect

Later on it does properly select SQLServerDialect but it seems weird that it initially choses the GenericDialect

Brent Griffin Sr. Java Architect dotCMS

Bart Plasmans

unread,

Mar 18, 2016, 5:56:42 AM3/18/16

to dotCMS User Group

Hi Brent,

we now also see the same error for another customer on a linux device with mysql, the DEV environment was fine, but after setting up the UAT environment we see the same errors.

For the initial reported dotCMS customer we don't have access to their production environment where the error occured, so I have added all plugins, config and logs for this new UAT dotcms for the other customer.

We do have env specific configuration in our custom plugins, but thats only for defining what domain the website is on, and the location of external systems we call.

There are no custom scheduled tasks in dotcms.

I have attached the plugins we use, all zip files are static plugins, the other dynamic ones.

greetings Bart

catalina.out

dotcms.log

Bart Plasmans

unread,

Mar 18, 2016, 6:08:08 AM3/18/16

to dotCMS User Group

Hi Brent,

The files are on my google drive, can you please let me know if you have trouble downloading them?

https://drive.google.com/file/d/0B2tcJYy0Lc1nMEJaVXRaYnhmQ1E/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nT2lra0F3U2w5U1k/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nMWNDcE9vdGY3UUk/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nSXNPWXNIT0tCZnc/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nZl94Q1p4bENzdms/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nV1g1RUdnQm5jR3M/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nTXNSOWtMYkNyUWc/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nVmxld1NtNWxsS00/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nMU1hWGpxZjIxSHM/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nWFhUY2ZiRDhOY2c/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nUTUzZWNTSVMtYnc/view?usp=sharing

https://drive.google.com/file/d/0B2tcJYy0Lc1nTV95WmNEeTZqSHM/view?usp=sharing

greetings Bart

Brent Griffin

unread,

Mar 18, 2016, 8:56:44 AM3/18/16

to dotCMS User Group

Does this problem happen without the plugins? I would suggest that you only deploy the bare minimum plugin that only handles the necessary configuration. This will help diagnose whether the problem is in core dotCMS code or whether it has something to do with the plugins.

Brent Griffin

Sr. Java Architect

dotCMS

Bart Plasmans

unread,

Mar 21, 2016, 4:28:57 AM3/21/16

to dotCMS User Group

Hi Brent,

I have undeployed all plugins except the "com.dotcms.config" which contains the dotCMS configuration settings.(It contains no libs or code).

Still we see the error appear.

I have again attached the dotCMS.log and the catalina.out log.

greetings Bart

catalina.out

dotcms.log

Brent Griffin

unread,

Mar 21, 2016, 8:42:41 AM3/21/16

to dotCMS User Group

Ok, my best guess is that you either do not have the mysql stored procedures in your database or the user you are running as does not have permission to invoke them.

If you dump the database you are having problems with do you have the load_records_to_index stored procedure?

By default mysqldump does not include stored procedures, you have to specifically include the --routines option. http://dotcms.com/docs/latest/database-configuration

Unrelated to your specific problem, I also noticed that you seem to have two default sites. Based on this line in the logfile:

[21/03/16 09:24:23:259 CET] FATAL web.HostWebAPIImpl: More of one host is marked as default!!

Let me know what you find out,

Brent Griffin

Sr. Java Architect

dotCMS

Bart Plasmans

unread,

Mar 21, 2016, 8:58:48 AM3/21/16

to dotCMS User Group

I see the following error occur in the log when i have loglevel to debug:

[21/03/16 13:55:41:916 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:916 CET] DEBUG business.CacheLocator:

[21/03/16 13:55:41:916 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:919 CET] DEBUG filters.CMSFilter: CMS Filter URI = /api/notification/getNewNotificationsCount/

[21/03/16 13:55:41:919 CET] DEBUG web.WebAPILocator:

[21/03/16 13:55:41:919 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:919 CET] DEBUG web.WebAPILocator:

[21/03/16 13:55:41:919 CET] DEBUG business.CacheLocator:

[21/03/16 13:55:41:919 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:919 CET] DEBUG business.CacheLocator:

[21/03/16 13:55:41:919 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:919 CET] DEBUG business.CacheLocator:

[21/03/16 13:55:41:920 CET] DEBUG business.APILocator:

[21/03/16 13:55:41:921 CET] DEBUG web.WebAPILocator:

[21/03/16 13:55:41:923 CET] DEBUG db.DbConnectionFactory: Closing all connections for 234

[21/03/16 13:55:41:923 CET] DEBUG db.DbConnectionFactory: All connections closed for 234

[21/03/16 13:55:44:863 CET] DEBUG db.DbConnectionFactory: Connection opened for thread 35-jdbc/dotCMSPool

[21/03/16 13:55:44:863 CET] DEBUG impl.SessionImpl: opened session

[21/03/16 13:55:44:863 CET] DEBUG db.HibernateUtil: Starting Transaction!

[21/03/16 13:55:44:863 CET] DEBUG db.DotConnect: ------------ DotConnect() --------------------

[21/03/16 13:55:44:863 CET] DEBUG db.DotConnect: setSQL: {call load_records_to_index(?,?,?)}

[21/03/16 13:55:44:863 CET] DEBUG db.DotConnect: db.addParam 0 (String): bf0cc954-68b3-4714-ad50-db764b4009e0

[21/03/16 13:55:44:863 CET] DEBUG db.DotConnect: db.addParam 1 (int): 50

[21/03/16 13:55:44:864 CET] DEBUG db.DotConnect: db.addParam 2 (int): 30

[21/03/16 13:55:44:865 CET] DEBUG db.DotConnect: SQL = com.mysql.jdbc.JDBC4CallableStatement@3e533fcc: CALL load_records_to_index(** NOT SPECIFIED **,** NOT SPECIFIED **,** NOT SPECIFIED **)

[21/03/16 13:55:44:867 CET] DEBUG db.HibernateUtil: sessionCleanupAndRollback

[21/03/16 13:55:44:867 CET] DEBUG impl.SessionImpl: disconnecting session

[21/03/16 13:55:44:868 CET] DEBUG db.DbConnectionFactory: Connection opened for thread 35-jdbc/dotCMSPool

[21/03/16 13:55:44:868 CET] DEBUG impl.SessionImpl: opened session

[21/03/16 13:55:44:868 CET] DEBUG db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Can't call rollback when autocommit=true

at sun.reflect.GeneratedConstructorAccessor95.newInstance(Unknown Source) ~[?:?]

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.7.0_95]

at java.lang.reflect.Constructor.newInstance(Constructor.java:526) ~[?:1.7.0_95]

at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:898) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:887) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:862) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4617) ~[mysql-connector-java-5.1.37-bin.jar:5.1.37]

at org.apache.tomcat.dbcp.dbcp2.DelegatingConnection.rollback(DelegatingConnection.java:491) ~[tomcat-dbcp.jar:8.0.30]

at com.dotmarketing.db.HibernateUtil.sessionCleanupAndRollback(HibernateUtil.java:804) [dotcms_3.3_1bbd913.jar:?]

at com.dotmarketing.db.HibernateUtil.rollbackTransaction(HibernateUtil.java:769) [dotcms_3.3_1bbd913.jar:?]

at com.dotmarketing.common.reindex.ReindexThread.fillRemoteQ(ReindexThread.java:637) [dotcms_3.3_1bbd913.jar:?]

at com.dotmarketing.common.reindex.ReindexThread.fillRemoteQ(ReindexThread.java:627) [dotcms_3.3_1bbd913.jar:?]

at com.dotmarketing.common.reindex.ReindexThread.run(ReindexThread.java:213) [dotcms_3.3_1bbd913.jar:?]

[21/03/16 13:55:44:871 CET] ERROR db.HibernateUtil: ---------- DotHibernate: error on rollbackTransaction ---------------

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Can't call rollback when autocommit=true

[21/03/16 13:55:44:871 CET] DEBUG db.DbConnectionFactory: Closing all connections for 35

[21/03/16 13:55:44:875 CET] DEBUG db.DbConnectionFactory: All connections closed for 35

[21/03/16 13:55:44:875 CET] DEBUG impl.SessionImpl: disconnecting session

[21/03/16 13:55:44:876 CET] DEBUG db.DbConnectionFactory: Connection opened for thread 35-jdbc/dotCMSPool

[21/03/16 13:55:44:876 CET] DEBUG business.APILocator:

[21/03/16 13:55:44:876 CET] DEBUG db.DbConnectionFactory: Closing all connections for 35

[21/03/16 13:55:44:876 CET] DEBUG db.DbConnectionFactory: All connections closed for 35

Bart Plasmans

unread,

Mar 21, 2016, 9:00:04 AM3/21/16

to dotCMS User Group

Hi Brent,

also cleaned up the hosts this morning, that error is gone now.

Brent Griffin

unread,

Mar 21, 2016, 9:09:13 AM3/21/16

to dotCMS User Group

i believe this confirms my earlier diagnosis - there is a problem with the stored procedures. Probably missing from the backup.

Brent Griffin

Sr. Java Architect

dotCMS

Bart Plasmans

unread,

Mar 21, 2016, 9:14:44 AM3/21/16

to dotCMS User Group

Hi Brent,

it was indeed the missing stored procedures.

The dotCMS is now working again after restoring them.

Thank you very much for your time!

greetings Bart

Reply all

Reply to author

Forward