Dump SQL queries from Hibernate in OpenUnderWriter

Question

I have just downloaded openunderwriter insurance solution with source code and set it up to open in and run from Eclipse. The project is uses Liferay framework and it also uses Hibernate for data persistence in MySQL database. I want to somehow enable debugging of SQL queries that are sent to MySQL server from Hibernate whenever I perform a CRUD operation in the application.

I have found many similar questions on SO and elsewhere like this, this and this to mention a few. I tried to follow them but could not get the queries to be printed on console. One problem is that there are more than 15 log4j.properties files in the project. I have updated all of them with the relevant properties but to no avail so far. I am new to Hibernate and don't know a thing about Liferay framework. How can I enable the SQL debugging in openunderwriter?

Edit: I have setup openunderwriter by cloning it from bitbucket repository and following the setup instructions to open it in Eclipse. It uses Ant builds. I can successfully start/stop/build it using Ant commands from Eclipse and use the application from browser. I could not find [OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1 directory in the repository. However, I did find

[OpenUnderWriterHome]\system\target\liferay-portal-6.2-ce-ga6\

directory. And I made changes to the log4j.properties file in the following directory assuming that *g1 and '*g6` indicates the version difference

D:\OpenUnderWriter\OpenUnderWriterRepo\system\target\liferay-portal-6.2-ce-ga6\jboss-7.1.1\standalone\deployments\ROOT.war\WEB-INF\classes

The contents of log4j.properties file in above directory are as follows log4j.rootLogger=INFO, CONSOLE

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.EnhancedPatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d{ABSOLUTE} %-5p [%c{1}:%L] %m%n
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type=trace
log4j.logger.org.hibernate.jdbc=DEBUG
log4j.logger.org.hibernate.transaction=DEBUG

But when I go to the logs files in D:\OpenUnderWriter\OpenUnderWriterRepo\system\target\liferay-portal-6.2-ce-ga6\logs, there are no sql queries and no parameter values. However, Eclipse console does show the sql queries but it shows them with ? marks instead of parameter values. And even the showing of queries is due to show_sql=true property set in HibernateConfiguration.xml file. If I remove this property and rebuild the code, the queries stop showing in console as well. Is there something wrong I am doing?

Edit 2:
I have two HibernateConfiguration.xml files. The first one is at D:\OpenUnderWriter\OpenUnderWriterRepo\system\target\test\integration-test.jar\com\ail\core\persistence\hibernate and the second one is at D:\OpenUnderWriter\OpenUnderWriterRepo\system\modules\com\ail\core.jar\com\ail\core\persistence\hibernate. The contents of the both files respectively are as under

<?xml version='1.0' encoding='utf-8'?> 
<!DOCTYPE hibernate-configuration PUBLIC 
    "-//Hibernate/Hibernate Configuration DTD 3.0//EN" 
    "http://www.hibernate.org/dtd/hibernate-configuration-3.0.dtd"> 

<hibernate-configuration>

    <session-factory>

        <property name="org.hibernate.envers.track_entities_changed_in_revision">true</property>
        <property name="org.hibernate.envers.audit_table_suffix">_</property>

        <!-- Database connection settings --> 
        <property name="connection.driver_class">com.mysql.jdbc.Driver</property> 
        <property name="connection.url">jdbc:mysql://@dbhost@:3306/@dbname.openunderwriter@</property> 
        <property name="connection.username">@dbusername@</property> 
        <property name="connection.password">@dbpassword@</property> 
        <property name="connection.pool_size">1</property> 

        <!-- Enable Hibernate's automatic session context management --> 
        <property name="current_session_context_class">thread</property> 

        <!-- SQL dialect --> 
        <property name="dialect">org.hibernate.dialect.MySQLDialect</property> 

        <property name="hibernate.bytecode.use_reflection_optimizer">true</property>
        <property name="hibernate.show_sql">true</property>
        <property name="hibernate.format_sql">true</property>
        <property name="use_sql_comments">true</property>
        <property name="hibernate.hbm2ddl.auto">create</property>

        <!-- Mappings for all classes come from one place -->
        <mapping class="com.ail.core.Attribute" />
        <mapping class="com.ail.core.ForeignSystemReference" />
        <mapping class="com.ail.core.Note" />
        <mapping class="com.ail.core.Reference" />
        <mapping class="com.ail.core.PageVisit" />
        <mapping class="com.ail.core.Type" />
        <mapping class="com.ail.core.Version" />
        <mapping class="com.ail.core.audit.envers.Revision" /> 
        <mapping class="com.ail.core.document.Document" /> 
        <mapping class="com.ail.core.document.DocumentContent" /> 
        <mapping class="com.ail.core.document.DocumentPlaceholder" /> 
        <mapping class="com.ail.core.document.DocumentRequest" /> 
        <mapping class="com.ail.core.key.UniqueKey" /> 
        <mapping class="com.ail.core.logging.ServiceRequestRecord" />
        <mapping class="com.ail.core.product.ProductChangeEvent" />
        <mapping class="com.ail.core.product.ProductUpgradeLog" />
        <mapping class="com.ail.financial.CurrencyAmount" />
        <mapping class="com.ail.financial.DirectDebit" />
        <mapping class="com.ail.financial.Eway" />
        <mapping class="com.ail.financial.IWinPay" />
        <mapping class="com.ail.financial.MoneyProvision" />
        <mapping class="com.ail.financial.Orange" />
        <mapping class="com.ail.financial.PaymentCard" />
        <mapping class="com.ail.financial.PaymentHoliday" /> 
        <mapping class="com.ail.financial.PaymentMethod" />
        <mapping class="com.ail.financial.PaymentRecord" />
        <mapping class="com.ail.financial.PaymentSchedule" />
        <mapping class="com.ail.financial.PayPal" />
        <mapping class="com.ail.financial.SagePay" />
        <mapping class="com.ail.financial.Stripe" />
        <mapping class="com.ail.financial.ledger.Account" />
        <mapping class="com.ail.financial.ledger.AccountingPeriod" />
        <mapping class="com.ail.financial.ledger.Balance" />
        <mapping class="com.ail.financial.ledger.Journal" />
        <mapping class="com.ail.financial.ledger.JournalLine" />
        <mapping class="com.ail.financial.ledger.Ledger" />
        <mapping class="com.ail.insurance.claim.Claim" /> 
        <mapping class="com.ail.insurance.claim.ClaimRecovery" /> 
        <mapping class="com.ail.insurance.claim.ClaimSection" /> 
        <mapping class="com.ail.insurance.policy.AssessmentSheet" /> 
        <mapping class="com.ail.insurance.policy.Asset" /> 
        <mapping class="com.ail.insurance.policy.Broker" /> 
        <mapping class="com.ail.insurance.policy.Clause" /> 
        <mapping class="com.ail.insurance.policy.CommercialProposer" /> 
        <mapping class="com.ail.insurance.policy.Coverage" /> 
        <mapping class="com.ail.insurance.policy.PersonalProposer" /> 
        <mapping class="com.ail.insurance.policy.Policy" /> 
        <mapping class="com.ail.insurance.policy.Section" /> 
        <mapping class="com.ail.party.Address" /> 
        <mapping class="com.ail.party.ContactSystem" /> 
        <mapping class="com.ail.party.EmailAddress" /> 
        <mapping class="com.ail.party.Party" /> 
        <mapping class="com.ail.party.PartyRelationship" /> 
        <mapping class="com.ail.party.PartyRole" /> 
        <mapping class="com.ail.party.Person" /> 
        <mapping class="com.ail.party.PhoneNumber" /> 
        <mapping class="com.ail.party.Organisation" />
        <mapping class="com.ail.util.DateOfBirth" /> 

    </session-factory>

</hibernate-configuration> 

and the second HibernateConfiguration.xml is

    <?xml version='1.0' encoding='utf-8'?> 
    <!DOCTYPE hibernate-configuration PUBLIC 
        "-//Hibernate/Hibernate Configuration DTD 3.0//EN" 
        "http://www.hibernate.org/dtd/hibernate-configuration-3.0.dtd">

    <hibernate-configuration>

        <session-factory>

            <property name="org.hibernate.envers.track_entities_changed_in_revision">true</property>
            <property name="org.hibernate.envers.audit_table_suffix">_</property>

            <!-- Enable Hibernate's automatic session context management -->
            <property name="current_session_context_class">jta</property>
            <property name="hibernate.current_session_context_class">jta</property>

            <property name="jta.UserTransaction">java:jboss/UserTransaction</property>

            <property name="hibernate.connection.datasource">java:/PersistenceDS</property>

            <property name="hibernate.transaction.factory_class">org.hibernate.transaction.CMTTransactionFactory</property>

            <property name="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.JBossTransactionManagerLookup</property>

            <property 

name="hibernate.transaction.transaction.jta.platform">org.hibernate.service.jta.platform.internal.JBossAppServerJtaPlatform</property>

        <property name="dialect">org.hibernate.dialect.MySQLDialect</property>

        <property name="hibernate.bytecode.use_reflection_optimizer">true</property>
        <property name="hibernate.connection.isolation">2</property> <!-- read committed -->
        <property name="hibernate.generate_statistics">false</property>
        <property name="hibernate.show_sql">true</property>
        <property name="hibernate.format_sql">true</property>
        <property name="use_sql_comments">true</property>
        <property name="hibernate.hbm2ddl.auto">validate</property>

        <mapping class="com.ail.core.ForeignSystemReference" />
        <mapping class="com.ail.core.Note" />
        <mapping class="com.ail.core.Reference" />
        <mapping class="com.ail.core.Type" />
        <mapping class="com.ail.core.audit.envers.Revision" /> 
        <mapping class="com.ail.core.document.Document" /> 
        <mapping class="com.ail.core.document.DocumentContent" /> 
        <mapping class="com.ail.core.document.DocumentPlaceholder" /> 
        <mapping class="com.ail.core.document.DocumentRequest" /> 
        <mapping class="com.ail.core.key.UniqueKey" /> 
        <mapping class="com.ail.core.logging.ServiceRequestRecord" />
        <mapping class="com.ail.core.product.ProductChangeEvent" />
        <mapping class="com.ail.core.product.ProductUpgradeLog" />
        <mapping class="com.ail.financial.CurrencyAmount" />
        <mapping class="com.ail.financial.DirectDebit" />
        <mapping class="com.ail.financial.Eway" />
        <mapping class="com.ail.financial.IWinPay" />
        <mapping class="com.ail.financial.MoneyProvision" />
        <mapping class="com.ail.financial.Orange" />
        <mapping class="com.ail.financial.PaymentCard" />
        <mapping class="com.ail.financial.PaymentHoliday" /> 
        <mapping class="com.ail.financial.PaymentMethod" />
        <mapping class="com.ail.financial.PaymentRecord" />
        <mapping class="com.ail.financial.PaymentSchedule" />
        <mapping class="com.ail.financial.PayPal" />
        <mapping class="com.ail.financial.SagePay" />
        <mapping class="com.ail.financial.Stripe" />
        <mapping class="com.ail.financial.ledger.Account" />
        <mapping class="com.ail.financial.ledger.AccountingPeriod" />
        <mapping class="com.ail.financial.ledger.Balance" />
        <mapping class="com.ail.financial.ledger.Journal" />
        <mapping class="com.ail.financial.ledger.JournalLine" />
        <mapping class="com.ail.financial.ledger.Ledger" />
        <mapping class="com.ail.insurance.claim.Claim" /> 
        <mapping class="com.ail.insurance.claim.ClaimRecovery" /> 
        <mapping class="com.ail.insurance.claim.ClaimSection" /> 
        <mapping class="com.ail.insurance.policy.AssessmentSheet" /> 
        <mapping class="com.ail.insurance.policy.Asset" /> 
        <mapping class="com.ail.insurance.policy.Broker" /> 
        <mapping class="com.ail.insurance.policy.Clause" /> 
        <mapping class="com.ail.insurance.policy.CommercialProposer" /> 
        <mapping class="com.ail.insurance.policy.Coverage" /> 
        <mapping class="com.ail.insurance.policy.PersonalProposer" /> 
        <mapping class="com.ail.insurance.policy.Policy" /> 
        <mapping class="com.ail.insurance.policy.Section" /> 
        <mapping class="com.ail.party.Address" /> 
        <mapping class="com.ail.party.ContactSystem" /> 
        <mapping class="com.ail.party.EmailAddress" /> 
        <mapping class="com.ail.party.PartyRelationship" /> 
        <mapping class="com.ail.party.PartyRole" /> 
        <mapping class="com.ail.party.Party" /> 
        <mapping class="com.ail.party.Person" /> 
        <mapping class="com.ail.party.PhoneNumber" /> 
        <mapping class="com.ail.party.Organisation" />
        <mapping class="com.ail.util.DateOfBirth" /> 
    </session-factory>

</hibernate-configuration> 

Also in D:\OpenUnderWriter\OpenUnderWriterRepo\system\target\liferay-portal-6.2-ce-ga6 directory, I don't have portal.properties file. The only props files I have in it are portal-ext.properties and portal-setup-wizard.properties. The contents of portal-ext.properties are as follows

index.on.startup=true
javascript.fast.load=false
jdbc.default.driverClassName=com.mysql.jdbc.Driver
jdbc.default.password=password
jdbc.default.url=jdbc:mysql://localhost/OU_trunk_trunk_Liferay?useUnicode=true&characterEncoding=UTF-8&useFastDateParsing=false
jdbc.default.username=openquote
layout.user.private.layouts.auto.create=false
layout.user.private.layouts.enabled=false
layout.user.public.layouts.auto.create=false
layout.user.public.layouts.enabled=false
theme.portlet.decorate.default=false
velocity.engine.restricted.classes=
velocity.engine.restricted.variables=
web.server.https.port=8443
users.screen.name.allow.numeric=true
company.default.home.url=/web/ou/welcome

and contents of portal-setup-wizard.properties are as follows

admin.email.from.name=Adam OpenUnderwriter
liferay.home=../..
admin.email.from.address=adam@openunderwriter.org
setup.wizard.enabled=false

Answer 1

Liferay Basics

tl;dr summary at the bottom of this post

Liferay is an open source Java-based portal platform. Liferay is a portal with a robust user account management system (roles, groups, permissions, etc), content management capabilities, extensible document store, and most importantly an excellent SDK for developing custom applications and extending the Liferay portal itself.

It appears that Open Underwriter uses Liferay 6.2 as it's underline portal. Essentially Open Underwrites application simply extends the Liferay portal to fit a particular business domain, but the underline structure is just an extension of the portal, not really a completely separate product. Liferay supports most major application servers / servlet containers, and it appears that Open Underwriter uses JBoss as it's application server.

Liferay comes default with dozens of different applications. Liferay calls these applications plugins (and I will refer to them as such from now on). Liferay 6.2 and below uses JSR-286 portlets (regular portlets and service builder portlets), hooks (and adaptive hooks), extensions, and layout templates to build applications and extend the platform. Liferay 7.0 and DXP (the Enterprise release of 7.0) uses OSGi modules based on Apache Felix to build and extend the portal.

You can find these plugins at the following location

[OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1/jboss-7.1.1/standalone/deployments

Liferay Configuration

Changing the configuration of the Liferay portal (such as to log queries a specific type of way) is NOT done by modifing those files directly (unless its your own plugin you build).

Liferay has extension points used to configure and extend the portal and related technologies. At a high level, you are either extending or changing configurations for one of the following four components

1. The portal itself (and the dependencies used by the portal)
2. The individual plugins (modules, portlets, hooks, extensions, adapters, etc) also know as the applications that reside in the portal
3. The database
4. The application server

Liferay's ORM (ServiceBuilder and Hibernate)

Liferay's Object Relational Mapping component is called Service Builder which itself is just a JPA implementation using Hibernate and EclipseLink.

Each plugin (that interacts with the database) has a file called service.xml which defines the ORM (the objects and their associated CRUD queries) and can be found at the following location

[OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1/jboss-7.1.1/standalone/deployments/{portlet-name}/WEB-INF/service.xml

Additionally you can see the generated SQL, tables, and indexes in the following location.

[OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1/jboss-7.1.1/standalone/deployments/{portlet-name}/WEB-INF/sql/

You will see four or five files in that directory. These are NOT a SQL log, but rather it is the generated SQL from the service.xml file associated with that plugin. You cannot modified these files directly as they will be overwritten during the build process for that plugin.

Runtime SQL

To log the hibernate queries correctly you should modify the following file

[OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1/portal-ext.properties

You should append the following property to the bottom

hibernate.show_sql=true

If that file already exists, simply change the value from false to true (it defaults as false).

Save the file and restart the server. The query will now output in the Liferay log file in the following form:

insert into table1 (column1, column2) values (?, ?)

The question marks will NOT be replace with the actual value of the query, and this is because of how hibernate prepares the queries (which is a technical term that means something specific in the case of Java / SQL).

If you want to see the values of these queries you will need to modify the following file:

[OPEN_UNDERWRITER_HOME]/liferay-portal-6.2.0-ce-ga1/jboss-7.1.1/standalone/deployments/ROOT/WEB-INF/classes/log4j.properties

By adding these properties (or modifying the values if they already exist)

log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type=trace

You may also want to append these properties as well

log4j.logger.org.hibernate.jdbc=DEBUG
log4j.logger.org.hibernate.transaction=DEBUG

And if you are troubleshooting a performance issue you might want to also add the following to trace the hibernate sessions

log4j.logger.org.hibernate.impl.SessionImpl=TRACE

portal.properties is the properties file that contains the portal's configuration. You never directly modify this and instead you modify portal-ext.properties. However, you may (or may not) notice four other properties files in the same directory

1. portal-bundle.properties
2. portal-ext.properties
3. portal-setup-wizard.properties
4. portal-ide.properties

All of these files override portal.properties and they are listed in order of preference. In other words if I have a property in portal-bundle.properties set to true, and the same property in portal-ide.properties set to false, that property will be false. You will not likely see those files created though.

Viewing the log

You may have noticed there are several different */log directories underneath the platforms home directory. After you start the server for the first time you should see a log folder here

[OPEN_UNDERWRITE_HOME]/liferay-portal-6.2.0-ce-ga1/logs

Those are the log files you are mostly interested in. The log folder underneath the JBoss directory is the app servers log file. It may contain useful information, but won't contain the queries you are looking for.

Final thoughts

I don't exactly know why you want to see the hibernate queries but I assume it's for performance reasons. Firstly, do not turn this on in production. It's going to slow down your machine. Secondly, you might want to consider turning on your MySQL query log instead.

To do so find your my.cnf file and add the following

general_log_file = /var/logs/mysql.log
general_log = 1

Furthermore after you begin logging and find the queries of interest you should look at their execution plan (link in references below).

References and Additional Thoughts

You can find an exhaustive list of properties used to override portal.properties here (note - never modify portal.properties itself, modify portal-ext.properties)

https://docs.liferay.com/portal/6.2/propertiesdoc/portal.properties.html

If you think the performance issue is database related I the properties you care about are between the following two subsections

1. https://docs.liferay.com/portal/6.2/propertiesdoc/portal.properties.html#Model%20Hints
2. https://docs.liferay.com/portal/6.2/propertiesdoc/portal.properties.html#SQL%20Data

MySQL query execution plan

https://dev.mysql.com/doc/refman/5.7/en/execution-plan-information.html

Finally, in the future when you are researching technical issues related to Open Underwriter I highly suggest you do look up things specific to the technologies used in the Liferay platform. Those technologies are implemented in a very particular way, and I suggest you instead focus your searches on Liferay (with hibernate as a minor search criteria). If you can't follow the information I posted above or if you need additional assistance please respond and we can discuss.

Also, I'm not sure what your role is in implementing this solution, but New Relic APM monitoring has really help us manage our enterprise Liferay platform in production. If your issue is performance look through my post history, I believe I wrote a very thorough post on some best practices for configuring your production environment (although every deployment is different)