Nearly every query is rolled back before commit. Any thoughts?

[Brian Baillargeon]

I've got some spooky Halloween stuff going on in my local sakai instance
that's baffling my co-workers and I, hopefully someone on this list can
be of assistance:

I noticed certain data wasn't persisting in my mysql database, yet
nothing was logged in catalina.out. So I began troubleshooting and I
checked mysql-query.log, and the appropriate 'insert' statements were
there, but each one was immediately followed by 'ROLLBACK'. I noticed
these ROLLBACK statements were occurring on the vast majority of the
queries in my DB (even after select queries).

So while troubleshooting, I took the following steps which yielded the
same result (for the purpose of this email, I replaced the database
name, user, pw, and machine name with a festive jack-o-lantern: 🎃). Steps:

-pulled down latest source code from master

-renamed ~/.m2/repository to eliminate the possibility of bad dependencies

-dropped my database, recreated it, granted privileges to user
'🎃'@'localhost' to eliminate possibility of corrupt data

-backed up and deleted tomcat, replaced it with a fresh instance from
apache-tomcat-7.0.34.tar.gz to eliminate possibility of duplicate jars, etc.

-in $CATALIA_HOME/conf/catalina.properties: set
org.apache.catalina.startup.ContextConfig.jarsToSkip=*.jar (as
recommended by Steve Swinsburg for quicker startups)

-copied default.sakai.propertiers to
$CATALINA_HOME/sakai/sakai.properties, and set the following properties:
test...@org.sakaiproject.email.api.EmailService=true
auto.ddl=true
user...@javax.sql.BaseDataSource=🎃
pass...@javax.sql.BaseDataSource=🎃
ven...@org.sakaiproject.db.api.SqlService=mysql
driverC...@javax.sql.BaseDataSource=<I've taken all these steps
using both com.mysql.jdbc.Driver and org.mariadb.jdbc.Driver with the
same result>
hibernate.dialect=org.hibernate.dialect.MySQL5InnoDBDialect
u...@javax.sql.BaseDataSource=jdbc:mysql://127.0.0.1:3306/🎃?useUnicode=true&characterEncoding=UTF-8
validat...@javax.sql.BaseDataSource=select 1 from DUAL
defaultTransacti...@javax.sql.BaseDataSource=TRANSACTION_READ_COMMITTED

And then I built with:
>mvn8cld
(that's my alias for:
'JAVA_HOME=/usr/lib/jvm/java-8-oracle MAVEN_OPTS="-Xms512m -Xmx1024m
-XX:MaxMetaspaceSize=512m -Djava.util.Arrays.useLegacyMergeSort=true"
mvn -T 4 -Dmaven.test.skip=true clean install sakai:deploy')
>startup.sh

It started up successfully, there were no stack traces during startup,
but the rollbacks persisted in mysql-query.log without any output to
catalina.out.

An excerpt of one such rollback from mysql-query.log:
77 Execute insert into dash_config (property_name,
property_value) values ('PROP_LOOP_TIMER_ENABLED_🎃', 0)
77 Query SHOW WARNINGS
77 Query rollback

^ "SHOW WARNINGS" only occurs when using the mysql driver; doesn't occur
using mariadb driver

If I enter mysql with
>mysql --version
mysql Ver 14.14 Distrib 5.5.46, for debian-linux-gnu (i686) using
readline 6.3
>mysql -u 🎃 -p
mysql>use 🎃
mysql>insert into dash_config (property_name, property_value) values
('PROP_LOOP_TIMER_ENABLED_🎃', 0);
mysql>commit;
It makes it into the database, but it will be the only row in that table.

Now, some things are successfully getting inserted. For instance, I can
use the New Account tool and create a user, and an entry will be added
to sakai_user, sakai_user_id_map, etc. My best guess is that the
successes are raw sql, and rollbacks are occurring whenever a hibernate
session is closed (instead of a commit perhaps). But I haven't confirmed
this, it's just a guess.

My co-workers are not experiencing any of these issues, yet I can't
think of anything that I've missed in that process that would allow for
these issues to persist exclusively on my machine. The sakai src, the
maven repo, the db, tomcat, sakai.properties - it's all fresh. Anyone
have any suggestions?

It's very spooky, Happy Halloween! 🎃

[Matthew Jones]

Hi Brian,

There was this issue that came up recently with the message bundle where hikaricp would perform an automatic rollback for colsed connections with auto-commit set to false. This one really bugged me too if it's the same thing! 

Any background thread in Runnable using Spring's Hibernate Template would have the problem where it would get rolled back because we don't have auto-commit set to true. We're also still using the "not recommended" HibernateDaoSupport all over the place.

Earle fixed Message Bundle in https://jira.sakaiproject.org/browse/KNL-1386 where I was noticing the bug but we believed there were probably more places that this would come up. I wouldn't be suprised if dashboard it another case of this. If you turn on the debug logging of com.zakker (hikaricp) I think you could see it was rolling back the transactions. Yeah, these will probably be a bunch of blockers we'll really have to fix.

You could switch to dbcp and see if you still see the issue there. I think you just create a 

sakai/sakai-configuration.xml    with the following contents

<?xml version="1.0" encoding="UTF-8"?>

<beans xmlns="http://www.springframework.org/schema/beans"

    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

    xsi:schemaLocation="http://www.springframework.org/schema/beans

    http://www.springframework.org/schema/beans/spring-beans-2.0.xsd">

    <!-- Shared DataSource for all pooled database connections -->

        <bean id="javax.sql.BaseDataSource" parent="javax.sql.dbcp.BaseDataSource"></bean>

</beans>




--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.
To post to this group, send email to saka...@apereo.org.
Visit this group at http://groups.google.com/a/apereo.org/group/sakai-dev/.

[Brian Baillargeon]

Creating the suggested sakai-configuration.xml in $CATALINA_HOME/sakai
did the trick! Thanks Matt!

For what it's worth, nothing was logged by adding DEBUG.com.zaxxer to my
log.config properties.

I'm working in the context of Forums, and the issue that brought this to
my attention was within a class I added that extends
HibernateDaoSupport. I'll keep it in mind that this is not a recommended
approach and will seek alternatives going forward.

Thanks again!

On 15-10-31 12:47 AM, Matthew Jones wrote:
> Hi Brian,
>
> There was this issue that came up recently with the message bundle where
> hikaricp would perform an automatic rollback for colsed connections with
> auto-commit set to false. This one really bugged me too if it's the same
> thing!
>
> Any background thread in Runnable using Spring's Hibernate Template
> would have the problem where it would get rolled back because we don't
> have auto-commit set to true. We're also still using the "not
> recommended" HibernateDaoSupport all over the place.
>
> Earle fixed Message Bundle
> in https://jira.sakaiproject.org/browse/KNL-1386 where I was noticing
> the bug but we believed there were probably more places that this would
> come up. I wouldn't be suprised if dashboard it another case of this. If
> you turn on the debug logging of com.zakker (hikaricp) I think you could
> see it was rolling back the transactions. Yeah, these will probably be a
> bunch of blockers we'll really have to fix.
>
> You could switch to dbcp and see if you still see the issue there. I
> think you just create a
>
> sakai/sakai-configuration.xml with the following contents
>
> |<?||xml| |version||=||"1.0"| |encoding||=||"UTF-8"||?>|
> |<||beans| |xmlns||=||"http://www.springframework.org/schema/beans"

> <http://www.springframework.org/schema/beans>|
> | ||xmlns:xsi||=||"http://www.w3.org/2001/XMLSchema-instance"

> <http://127.0.0.1:3306/>🎃?useUnicode=true&characterEncoding=UTF-8

> <mailto:sakai-dev%2Bunsu...@apereo.org>.

> To post to this group, send email to saka...@apereo.org

> <mailto:saka...@apereo.org>.

[Matthew Jones]

Yeah, I forgot how I saw it. It was basically that dbcp didn't enforce the dirty state transaction as well as hikaricp is. And some of these out of session background thread queries didn't have enough session established.

If you look at the pattern on that ticket Earle made you should be able to get your code to work. If you find other places where commits aren't being "committed" and should be, file it as a bug. I think hikaricp is worth leaving as the default, but it's nice to be able to confirm this issue.

[Matthew Jones]

In com.zakker.hikari.proxy.ConnectionProxy this is the error I was seeing with debug on. (It said "Performing rollback on") 

if (isCommitStateDirty && !delegate.getAutoCommit()) {

  LOGGER.debug("{} Performing rollback on {} due to dirty commit state.", parentPool, delegate);

  delegate.rollback();

}

This debug line was added in hikaricp 2.3.10. Hmm, I don't have master updated to that I just had that updated locally in an uncommitted change. ;) Should get that committed.

diff --git a/kernel/pom.xml b/kernel/pom.xml

index e1c82f1..caea6df 100644

--- a/kernel/pom.xml

+++ b/kernel/pom.xml

@@ -132,7 +132,7 @@

       <dependency>

         <groupId>com.zaxxer</groupId>

         <artifactId>HikariCP</artifactId>

-        <version>2.3.7</version>

+        <version>2.3.12</version>

         <scope>compile</scope>

       </dependency>

       <!--