Logging SQL queries in Grouper
Applies to: current supported releases. The custom p6spy jar ships as p6spy-3.6.0.jar.
Access required: this is a server-side, sysadmin task, not a Grouper privilege. You need filesystem (or container) access to the Grouper webapp to add the jar and config file, edit grouper.hibernate.properties, and restart the process.
This technique is meant to be temporary, for troubleshooting only. Do not leave it on in production — logging every query is a significant performance hindrance.
Overview
A custom p6spy jar is the best way to log the SQL queries Grouper runs against its database. p6spy is a JDBC proxy driver: once registered, every statement (and optionally each result set) is written to a log file. Grouper ships a customized build of the jar — the stock p6spy jar from the p6spy project will not work with Grouper.
Note that the logged SQL is not the exact statement sent to the database: for prepared statements, the bind parameters are substituted into the query text for readability.
Example: a failing loader query
This example shows the query and its results from a loader job, captured from the GTE container against MySQL. The query deliberately ends in a NULL subject_id so it fails, so you can see both the SQL and the resulting error in the log.
SELECT
subject_id,
the_order
FROM
(
SELECT
m.subject_id AS subject_id, 1 AS the_order
FROM
grouper_members m
WHERE
m.subject_id LIKE 'ab%'
UNION
SELECT
NULL AS subject_id, 2 AS the_order
FROM
grouper_members) AS the_subquery
ORDER BY
2Here is the resulting log message (this message was improved in v2.5.36+):
java.lang.RuntimeException: Result has a null subject_id, please correct the query (maybe just filter where subject_id is not null)Enable p6spy logging
1. Get the custom p6spy jar
Add the Grouper-customized p6spy jar to the webapp's WEB-INF/lib directory. Modern Grouper builds use p6spy-3.6.0.jar.
VERIFY: Modern Grouper (v4+) appears to bundle the custom p6spy-3.6.0.jar on the classpath already, so this download step may be unnecessary on a current install — confirm with the sponsor whether the jar ships in the webapp. The command below fetches the older custom jar from the GROUPER_2_3_BRANCH for installs that do not include it.
[student@ip-172-31-14-57 ~]$ docker exec -it -u tomcat 401.2.1 bash
[tomcat@b9f6012bfa3b WEB-INF]$ cd lib
[tomcat@b9f6012bfa3b lib]$ pwd
/opt/grouper/grouperWebapp/WEB-INF/lib
[tomcat@b9f6012bfa3b lib]$ wget https://github.com/Internet2/grouper/raw/GROUPER_2_3_BRANCH/grouper/lib/grouper/p6spy.jar2. Create the spy.properties config file
Place a spy.properties file on the classpath (WEB-INF/classes). You can start from the shipped example:
[tomcat@b9f6012bfa3b lib]$ cd ..
[tomcat@b9f6012bfa3b WEB-INF]$ cd classes
[tomcat@b9f6012bfa3b classes]$ wget https://github.com/Internet2/grouper/raw/GROUPER_2_3_BRANCH/grouper/conf/spy.example.properties
[tomcat@b9f6012bfa3b classes]$ mv spy.example.properties spy.properties
[tomcat@b9f6012bfa3b classes]$ vi spy.propertiesSet the real underlying driver and the log path. Set executionthreshold (in milliseconds) if you only want to log long-running queries, and confirm excludecategories is what you want.
# e.g. mysql: com.mysql.cj.jdbc.Driver
# e.g. p6spy (log sql): com.p6spy.engine.spy.P6SpyDriver
# for p6spy, put the underlying driver in spy.properties
# e.g. oracle: oracle.jdbc.driver.OracleDriver
# e.g. hsqldb: org.hsqldb.jdbcDriver
# e.g. postgres: org.postgresql.Driver
# e.g. SQL Server: com.microsoft.sqlserver.jdbc.SQLServerDriver
realdriver=com.mysql.cj.jdbc.Driver
logfile=/opt/grouper/logs/grouper/grouperSpy.log
excludecategories=info,debug,resultset,batch,result,commit,rollback
# queries longer then 10 seconds
executionthreshold=100003. Register the p6spy driver
In grouper.hibernate.properties, set the connection driver class to the p6spy driver (the real database driver stays in spy.properties, from step 2):
# com.p6spy.engine.spy.P6SpyDriver
# for p6spy, put the underlying driver in spy.properties
# e.g. oracle: oracle.jdbc.driver.OracleDriver
# e.g. hsqldb: org.hsqldb.jdbcDriver
# e.g. postgres: org.postgresql.Driver
# e.g. mssql: com.microsoft.sqlserver.jdbc.SQLServerDriver
hibernate.connection.driver_class = com.p6spy.engine.spy.P6SpyDriver4. Restart Grouper
Bounce Tomcat (or rebuild and run the container) so the new driver and config take effect.
[tomcat@b9f6012bfa3b bin]$ ps -ef | grep tomcat | grep java | grep -v grep
tomcat 86 1 2 Oct16 ? 00:31:51 /usr/lib/jvm/java-1.8.0-amazon-corretto/bin/java -Dnop -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -javaagent:/opt/tomee/lib/openejb-javaagent.jar -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apache.catalina.security.SecurityListener.UMASK=0027 -Xmx1500m -XX:+UseG1GC -XX:+UseStringDeduplication -Dlog4j.configurationFile=/opt/tomee/conf/log4j2.xml -DENV=training -DUSERTOKEN=gte-401.2.1 -Dfile.encoding=UTF-8 -Dignore.endorsed.dirs= -classpath /opt/tomee/bin/*:/opt/tomee/bin/bootstrap.jar:/opt/tomee/bin/tomcat-juli.jar -Dcatalina.base=/opt/tomee -Dcatalina.home=/opt/tomee -Djava.io.tmpdir=/opt/tomee/temp org.apache.catalina.startup.Bootstrap start
[tomcat@b9f6012bfa3b bin]$ kill -KILL 86
[tomcat@b9f6012bfa3b bin]$ ps -ef | grep tomcat | grep java | grep -v grep
tomcat 666 1 99 18:38 ? 00:00:02 /usr/lib/jvm/java-1.8.0-amazon-corretto/bin/java -Dnop -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -javaagent:/opt/tomee/lib/openejb-javaagent.jar -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apache.catalina.security.SecurityListener.UMASK=0027 -Xmx1500m -XX:+UseG1GC -XX:+UseStringDeduplication -Dlog4j.configurationFile=/opt/tomee/conf/log4j2.xml -DENV=training -DUSERTOKEN=gte-401.2.1 -Dfile.encoding=UTF-8 -Dignore.endorsed.dirs= -classpath /opt/tomee/bin/*:/opt/tomee/bin/bootstrap.jar:/opt/tomee/bin/tomcat-juli.jar -Dcatalina.base=/opt/tomee -Dcatalina.home=/opt/tomee -Djava.io.tmpdir=/opt/tomee/temp org.apache.catalina.startup.Bootstrap start
[tomcat@b9f6012bfa3b bin]$ 5. Read the log
Open the log file you set as logfile (here /opt/grouper/logs/grouper/grouperSpy.log) and search for the query you are looking for. Each entry shows the elapsed time, the calling stack, and the SQL: