ORM - Logging and Debugging

edit

ORM - Logging and Debugging

When something goes wrong with ORM, the first step is to see what Hibernate is actually doing.

The Lucee 5.6 Hibernate Extension added native logging integration that pipes Hibernate's internal logging through Lucee's log system.

Logging Settings

All logging settings go in this.ormSettings in your ORM - Configuration. They all default to false:

this.ormSettings = {
	logSQL: true,
	logParams: true,
	formatSQL: true,
	logCache: true,
	logVerbose: true
};
Setting What it logs Minimum log level
logSQL SQL statements generated by Hibernate DEBUG
logParams Parameter bindings — the actual values bound to ? placeholders. (new in 5.6) TRACE
formatSQL Pretty-prints SQL with indentation and line breaks. (new in 5.6)
logCache L2 cache and query cache activity — hits, misses, puts, evictions. (new in 5.6) DEBUG
logVerbose Hibernate internals — session lifecycle, entity loading, dirty checking, schema tools. Produces a LOT of output. (new in 5.6) TRACE/DEBUG

The "Hibernate log level" column shows the minimum orm log level needed for each setting to produce output. For example, setting logSQL: true with the log at DEBUG will show SQL, but logParams: true needs TRACE.

Where Logs Go

ORM logs write to the Lucee orm log. If no orm log is defined (neither at server level nor via this.logs in Application.cfc), no ORM logging occurs at all — even with ormSettings flags enabled.

The location depends on your Lucee configuration:

  • Default: {lucee-server}/logs/orm.log or {lucee-web}/logs/orm.log
  • Lucee Admin: Configure log appenders and levels under Settings > Logging
  • Console output: Set the environment variable LUCEE_LOGGING_FORCE_APPENDER=console to redirect to stdout (useful for development and CI)

Log Levels

There are two kinds of ORM log messages:

  • Extension messages (lifecycle, warnings, mapping issues) — these always log, subject only to the orm log level. No ormSettings flags needed.
  • Hibernate-internal messages (SQL, params, cache, verbose) — these require both the relevant ormSettings flag and a low enough log level. When logSQL: false, Hibernate never even formats the SQL string.

The minimum log level you need depends on what you're after:

  • DEBUG — gets you logSQL and logCache output, plus extension lifecycle messages
  • TRACE — gets you everything, including logParams and logVerbose

Setting the Log Level (Lucee 7.0+)

Use this.logs in Application.cfc to configure the orm log per-application:

this.logs = {
	"orm": {
		"appender": "console",
		"level": "trace"
	}
};

This is the recommended approach — it only affects your application, not other apps on the same server.

Setting the Log Level (Lucee 6.2 / server-wide)

Use configImport to set the server-level orm log. This affects all applications on the server:

function onApplicationStart() {
	configImport( type: "server", data: {
		loggers: {
			orm: {
				level: "TRACE",
				appender: "console"
			}
		}
	});
}

Settings are read at ORM init

The ormSettings flags are read once when ORM initialises (application startup or ormReload()). Changing logSQL in your Application.cfc and reloading the page won't take effect — you need to call ormReload() or restart the application.

Extension Lifecycle Logging

The Hibernate extension logs its own lifecycle messages at DEBUG level, independent of the ormSettings flags.

These appear whenever the orm log level is DEBUG or lower:

ORM initializing for application [myApp], dbcreate [update]
ORM initialized [12] entities for application [myApp], OrmLoggingSettings[logSQL=true, logParams=false, logCache=false, formatSQL=false, logVerbose=false]

On ormReload(), you'll also see:

ormReload() for application [myApp]

The extension also logs warnings at WARN level for issues it encounters during mapping and schema operations — skipped CFCs, type mismatches, schema export problems.

Inspecting Generated Mappings

savemapping

Set savemapping: true to write the generated .hbm.xml mapping files to disk alongside your entity CFCs:

this.ormSettings = {
	savemapping: true
};

This creates files like User.cfc.hbm.xml next to your User.cfc. Inspect these to see exactly what Hibernate thinks your entities look like — column types, relationships, cascade settings, etc.

Dev only. Files are written on every application startup.

Reading Mapping Files

When something maps unexpectedly (wrong column type, missing relationship, incorrect cascade), check the generated .hbm.xml:

<property name="price" type="big_decimal">
    <column name="price" precision="12" scale="4"/>
</property>

If the mapping doesn't match your intent, adjust the property attributes in your CFC and check again.

Debugging Techniques

Check the SQL First

When data isn't saving, loading, or updating correctly, enable logSQL and logParams to see the actual SQL:

this.ormSettings = {
	logSQL: true,
	logParams: true,
	formatSQL: true
};

Look for:

  • Missing INSERT/UPDATE statements (entity wasn't dirty, or flush didn't happen)
  • Wrong column values (mapping issue)
  • Unexpected WHERE clauses (filter or discriminator issue)
  • Duplicate SQL (missing inverse="true" on a bidirectional relationship)

Session Diagnostics

The native Hibernate session exposes useful state:

sess = ORMGetSession();
// Are there pending changes?
if ( sess.isDirty() ) {
	systemOutput( "Session has unflushed changes", true );
}
// How many entities are cached in this session?
stats = sess.getStatistics();
systemOutput( "Entities: #stats.getEntityCount()#", true );
systemOutput( "Collections: #stats.getCollectionCount()#", true );

Get an Entity's PK Dynamically

When writing generic utility code:

pk = ORMGetSession().getIdentifier( entity );

Inspect Entity Metadata

Get Hibernate's metadata for any entity — property names, types, identifier info:

meta = ORMGetSessionFactory().getClassMetadata( "User" );
systemOutput( "Properties: #arrayToList( meta.getPropertyNames() )#", true );
systemOutput( "ID property: #meta.getIdentifierPropertyName()#", true );

Check the Active Dialect

Verify which SQL dialect Hibernate is using:

dialect = ORMGetSessionFactory().getDialect();
systemOutput( "Dialect: #dialect.getClass().getName()#", true );

Using Log Markers

Write a marker to the orm log before an operation, then search the log file for everything after the marker:

marker = createUUID();
cflog( text: marker, log: "orm" );
// ... your ORM operations here ...
// later, read the log and find your section

This is useful when the log contains output from many requests and you need to isolate one.

Common Debugging Scenarios

"Why isn't my entity saving?"

  1. Enable logSQL: true — is an INSERT being generated?
  2. Check flushAtRequestEnd — if false, are you calling ormFlush() or using a transaction?
  3. Check ORMGetSession().isDirty() — does Hibernate think anything changed?
  4. Check ORMGetSession().contains( entity ) — is the entity persistent?

"Why am I getting extra UPDATE statements?"

  1. Enable logSQL: true and count the statements
  2. Check for missing inverse="true" on bidirectional relationships — see ORM - Relationships
  3. Check for entities loaded and modified unintentionally (dirty checking)

"Why is this query slow?"

  1. Enable logSQL: true, logParams: true — check the generated SQL
  2. Look for N+1 patterns — the same SELECT repeated with different IDs
  3. Enable logCache: true if using L2 cache — check hit/miss ratios
  4. Consider batchsize, fetch="join", or HQL JOIN FETCH — see ORM - Relationships

What's Next?

See also