No error/exception in log on insert yet no row inserted to db

[steve jones]

Hibernate version:3.2
DB used:hsqldb v1.8

Hi,

I've got a problem when trying to insert a record into my database. The insert itself seems to work fine (no warnings/errors) in the console logs when I run the below code, and I can even see where hibernate has generated my new Track_ID number (for index column in db).
However when I check the actual db once the insert has allegedly been flushed and committed the new row does not appear there???

If I manually insert a row to the db and then use hibernate to select it out of db, it all works fine and i get the object returned.

Below is initial stuff that I hope will let someone solve my problem, if there 's something else somebody wants to see, let me know and I'll add to the post.

Any help on this one greatly appreciated as it's driving me up the wall!!!

Java code (simple main method containing the following) to do the actual insert (called from an ant task running under eclipse) :-

public static void main(String args[]) throws Exception {
  Configuration config = new Configuration();
 
  config.addClass(Track.class);
 
  SessionFactory sessionFactory = config.buildSessionFactory();
 
  Session session = sessionFactory.openSession();
  Transaction tx = null;
  try {
    // Create some data and persist it
    tx = session.beginTransaction();
 
    Track track = new Track("Russian Trance",
                            "vol2/album610/track02.mp3",
                            Time.valueOf("00:03:30"), new Date(),
                            (short)7);
 
    System.out.println("**************\nTrack in memory is :     +track.toString()+"\n**************");
 
    session.save(track);
    tx.commit();
    System.out.println("***********COMMITED *************");
  
  } catch (Exception e) {
    if (tx != null) {
      e.printStackTrace();
      // Something went wrong; discard all partial changes
      tx.rollback();
      System.out.println("***********ROLLBACK *************");
      System.out.println("EXCEPTION :-");
      e.printStackTrace();
    }
    throw e;
  
  } finally {
    session.close();
  }
 
  sessionFactory.close();
 
}

The log output that comes out of running above (anything with "*****" are my system.out debug statements, see code above. the reason it generates track id 101 is because I manually inserted a record id of 100 to make sure that code was generating correct id's) :-

 
Buildfile: D:\Dev\Java\EclipseProjects\Hibernate\build.xml
prepare:
compile:
ctest:
[java] 01:28:40,440 INFO Environment:514 - Hibernate 3.2.5
[java] 01:28:40,448 INFO Environment:532 - loaded properties from resource hibernate.properties: {hibernate.connection.username=sa, hibernate.connection.password=****, hibernate.dialect=org.hibernate.dialect.HSQLDialect, hibernate.connection.url=jdbc:hsqldb:file  :D  ata/music, hibernate.bytecode.use_reflection_optimizer=false, hibernate.connection.driver_class=org.hsqldb.jdbcDriver}
[java] 01:28:40,450 INFO Environment:681 - Bytecode provider name : cglib
[java] 01:28:40,455 INFO Environment:598 - using JDK 1.4 java.sql.Timestamp handling
[java] 01:28:40,538 INFO Configuration:585 - Reading mappings from resource: com/oreilly/hh/Track.hbm.xml
[java] 01:28:40,539 INFO Configuration:530 - Reading mappings from resource: com/oreilly/hh/Track.hbm.xml
[java] 01:28:40,780 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
[java] 01:28:40,780 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
[java] 01:28:40,783 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
[java] 01:28:40,933 INFO HbmBinder:300 - Mapping class: com.oreilly.hh.Track -> TRACK
[java] 01:28:40,941 DEBUG HbmBinder:1270 - Mapped property: id -> TRACK_ID
[java] 01:28:40,951 DEBUG HbmBinder:1270 - Mapped property: title -> title
[java] 01:28:40,952 DEBUG HbmBinder:1270 - Mapped property: filePath -> filePath
[java] 01:28:40,952 DEBUG HbmBinder:1270 - Mapped property: playTime -> playTime
[java] 01:28:40,953 DEBUG HbmBinder:1270 - Mapped property: added -> added
[java] 01:28:40,954 DEBUG HbmBinder:1270 - Mapped property: volume -> volume
[java] 01:28:40,955 DEBUG Configuration:1285 - Preparing to build session factory with filters : {}
[java] 01:28:40,955 DEBUG Configuration:1120 - processing extends queue
[java] 01:28:40,956 DEBUG Configuration:1124 - processing collection mappings
[java] 01:28:40,956 DEBUG Configuration:1135 - processing native query and ResultSetMapping mappings
[java] 01:28:40,956 DEBUG Configuration:1143 - processing association property references
[java] 01:28:40,956 DEBUG Configuration:1165 - processing foreign key constraints
[java] 01:28:41,038 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
[java] 01:28:41,039 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 20
[java] 01:28:41,039 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
[java] 01:28:41,048 INFO DriverManagerConnectionProvider:80 - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:file  :D  ata/music
[java] 01:28:41,049 INFO DriverManagerConnectionProvider:83 - connection properties: {user=sa, password=}
[java] 01:28:41,049 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
[java] 01:28:41,049 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
[java] 01:28:41,387 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:hsqldb:file  :D  ata/music, Isolation Level: 0
[java] 01:28:41,415 INFO SettingsFactory:89 - RDBMS: HSQL Database Engine, version: 1.8.0
[java] 01:28:41,415 INFO SettingsFactory:90 - JDBC driver: HSQL Database Engine Driver, version: 1.8.0
[java] 01:28:41,416 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
[java] 01:28:41,444 INFO Dialect:152 - Using dialect: org.hibernate.dialect.HSQLDialect
[java] 01:28:41,451 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
[java] 01:28:41,454 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
[java] 01:28:41,454 INFO SettingsFactory:143 - Automatic flush during beforeCompletion(): disabled
[java] 01:28:41,454 INFO SettingsFactory:147 - Automatic session close at end of transaction: disabled
[java] 01:28:41,454 INFO SettingsFactory:154 - JDBC batch size: 15
[java] 01:28:41,457 INFO SettingsFactory:157 - JDBC batch updates for versioned data: disabled
[java] 01:28:41,459 INFO SettingsFactory:162 - Scrollable result sets: enabled
[java] 01:28:41,461 DEBUG SettingsFactory:166 - Wrap result sets: disabled
[java] 01:28:41,462 INFO SettingsFactory:170 - JDBC3 getGeneratedKeys(): disabled
[java] 01:28:41,462 INFO SettingsFactory:178 - Connection release mode: auto
[java] 01:28:41,464 INFO SettingsFactory:205 - Default batch fetch size: 1
[java] 01:28:41,464 INFO SettingsFactory:209 - Generate SQL with comments: disabled
[java] 01:28:41,464 INFO SettingsFactory:213 - Order SQL updates by primary key: disabled
[java] 01:28:41,464 INFO SettingsFactory:217 - Order SQL inserts for batching: disabled
[java] 01:28:41,465 INFO SettingsFactory:386 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
[java] 01:28:41,467 INFO ASTQueryTranslatorFactory:24 - Using ASTQueryTranslatorFactory
[java] 01:28:41,468 INFO SettingsFactory:225 - Query language substitutions: {}
[java] 01:28:41,468 INFO SettingsFactory:230 - JPA-QL strict compliance: disabled
[java] 01:28:41,468 INFO SettingsFactory:235 - Second-level cache: enabled
[java] 01:28:41,468 INFO SettingsFactory:239 - Query cache: disabled
[java] 01:28:41,469 INFO SettingsFactory:373 - Cache provider: org.hibernate.cache.NoCacheProvider
[java] 01:28:41,469 INFO SettingsFactory:254 - Optimize cache for minimal puts: disabled
[java] 01:28:41,469 INFO SettingsFactory:263 - Structured second-level cache entries: disabled
[java] 01:28:41,471 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
[java] 01:28:41,476 INFO SettingsFactory:290 - Statistics: disabled
[java] 01:28:41,476 INFO SettingsFactory:294 - Deleted entity synthetic identifier rollback: disabled
[java] 01:28:41,476 INFO SettingsFactory:309 - Default entity-mode: pojo
[java] 01:28:41,477 INFO SettingsFactory:313 - Named query checking : enabled
[java] 01:28:41,559 INFO SessionFactoryImpl:161 - building session factory
[java] 01:28:41,560 DEBUG SessionFactoryImpl:173 - Session factory constructed with filter configurations : {}
[java] 01:28:41,560 DEBUG SessionFactoryImpl:177 - instantiating session factory with properties: {java.runtime.name=Java(TM) SE Runtime Environment, hibernate.connection.password=, sun.boot.library.path=C:\Sun\SDK\jdk\jre\bin, java.vm.version=1.6.0_02-b05, hibernate.connection.username=sa, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=GB, sun.java.launcher=SUN_STANDARD, sun.os.patch.level=, java.vm.specification.name=Java Virtual Machine Specification, user.dir=D:\Dev\Java\EclipseProjects\Hibernate, java.runtime.version=1.6.0_02-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Sun\SDK\jdk\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\Users\steve\AppData\Local\Temp\, line.separator=
[java] , java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows Vista, sun.jnu.encoding=Cp1252, java.library.path=C:\Sun\SDK\jdk\jre\bin;.;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Sun\SDK\jdk\bin\..\jre\bin\client;C:\Sun\SDK\jdk\bin\..\jre\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Program Files\Common Files\Roxio Shared\DLLShared\;C:\Program Files\Common Files\Roxio Shared\DLLShared\;C:\Program Files\Common Files\Roxio Shared\9.0\DLLShared\;C:\Sun\SDK\jdk\bin;C:\apache-tomcat-6.0.14\lib;C:\Program Files\QuickTime\QTSystem\;C:\Sun\SDK\bin;C:\Program Files\Java\bin;C:\Sun\SDK\bin, java.specification.name=Java Platform API Specification, java.class.version=50.0, sun.management.compiler=HotSpot Client Compiler, os.version=6.0, user.home=C:\Users\steve, user.timezone=Pacific/Guadalcanal, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.6, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, user.name=steve, java.class.path=D:\Dev\Java\EclipseProjects\Hibernate\classes;D:\Dev\Java\EclipseProjects\Hibernate\lib\ant-1.6.5.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\ant-antlr.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\ant-junit-1.6.5.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\ant-launcher.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\antlr-2.7.6.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\asm-attrs.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\asm.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib    \bsh-2.0b1.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\bsh-core-2.0b4.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\cglib-2.1.3.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\commons-collections-2.1.1.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\commons-logging-1.0.4.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\dom4j-1.6.1.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\ehcache-1.2.3.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\freemarker.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\hibernate    -tools.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\hibernate3.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\hsqldb.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\jta.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\jtidy-r8-20060801.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\log4j-1.2.11.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\xerces-2.6.2.jar;D:\Dev\Java\EclipseProjects\Hibernate\lib\xml-apis.jar;D:\Hibernate\hibernate-3.2\lib\ant-1.6.5.jar;D:\Hibernate\hibernate-3.2\lib\ant-antlr-1.6.5.    jar;D:\Hibernate\hibernate-3.2\lib\ant-junit-1.6.5.jar;D:\Hibernate\hibernate-3.2\lib\ant-launcher-1.6.5.jar;D:\Hibernate\hibernate-3.2\lib\ant-swing-1.6.5.jar;D:\Hibernate\hibernate-3.2\lib\antlr-2.7.6.jar;D:\Hibernate\hibernate-3.2\lib\asm-attrs.jar;D:\Hibernate\hibernate-3.2\lib\asm.jar;D:\Hibernate\hibernate-3.2\lib\c3p0-0.9.1.jar;D:\Hibernate\hibernate-3.2\lib\cglib-2.1.3.jar;D:\Hibernate\hibernate-3.2\lib\checkstyle-all.jar;D:\Hibernate\hibernate-3.2\lib\cleanimports.jar;D:\Hibernate\hiber    nate-3.2\lib\commons-collections-2.1.1.jar;D:\Hibernate\hibernate-3.2\lib\commons-logging-1.0.4.jar;D:\Hibernate\hibernate-3.2\lib\concurrent-1.3.2.jar;D:\Hibernate\hibernate-3.2\lib\connector.jar;D:\Hibernate\hibernate-3.2\lib\dom4j-1.6.1.jar;D:\Hibernate\hibernate-3.2\lib\ehcache-1.2.3.jar;D:\Hibernate\hibernate-3.2\lib\jaas.jar;D:\Hibernate\hibernate-3.2\lib\jacc-1_0-fr.jar;D:\Hibernate\hibernate-3.2\lib\javassist.jar;D:\Hibernate\hibernate-3.2\lib\jaxen-1.1-beta-7.jar;D:\Hibernate\hibernate-    3.2\lib\jboss-cache.jar;D:\Hibernate\hibernate-3.2\lib\jboss-common.jar;D:\Hibernate\hibernate-3.2\lib\jboss-jmx.jar;D:\Hibernate\hibernate-3.2\lib\jboss-system.jar;D:\Hibernate\hibernate-3.2\lib\jdbc2_0-stdext.jar;D:\Hibernate\hibernate-3.2\lib\jgroups-2.2.8.jar;D:\Hibernate\hibernate-3.2\lib\jta.jar;D:\Hibernate\hibernate-3.2\lib\junit-3.8.1.jar;D:\Hibernate\hibernate-3.2\lib\log4j-1.2.11.jar;D:\Hibernate\hibernate-3.2\lib\oscache-2.1.jar;D:\Hibernate\hibernate-3.2\lib\proxool-0.8.3.jar;D:\Hib    ernate\hibernate-3.2\lib\swarmcache-1.0rc2.jar;D:\Hibernate\hibernate-3.2\lib\syndiag2.jar;D:\Hibernate\hibernate-3.2\lib\versioncheck.jar;D:\Hibernate\hibernate-3.2\lib\xerces-2.6.2.jar;D:\Hibernate\hibernate-3.2\lib\xml-apis.jar, hibernate.bytecode.use_reflection_optimizer=false, java.vm.specification.version=1.0, sun.arch.data.model=32, java.home=C:\Sun\SDK\jdk\jre, hibernate.connection.url=jdbc:hsqldb:file  :D  ata/music, hibernate.dialect=org.hibernate.dialect.HSQLDialect, java.specification.vendor=Sun Microsystems Inc., user.language=en, awt.toolkit=sun.awt.windows.WToolkit, java.vm.info=mixed mode, java.version=1.6.0_02, java.ext.dirs=C:\Sun\SDK\jdk\jre\lib\ext;C:\Windows\Sun\Java\lib\ext, sun.boot.class.path=C:\Sun\SDK\jdk\jre\lib\resources.jar;C:\Sun\SDK\jdk\jre\lib\rt.jar;C:\Sun\SDK\jdk\jre\lib\sunrsasign.jar;C:\Sun\SDK\jdk\jre\lib\jsse.jar;C:\Sun\SDK\jdk\jre\lib\jce.jar;C:\Sun\SDK\jdk\jre\lib\charsets.jar;C:\Sun\SDK\jdk\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.cpu.endian=little, sun.io.unicode.encoding=UnicodeLittle, sun.desktop=windows, sun.cpu.isalist=}
[java] 01:28:41,863 DEBUG AbstractEntityPersister:2738 - Static SQL for entity: com.oreilly.hh.Track
[java] 01:28:41,863 DEBUG AbstractEntityPersister:2743 - Version select: select TRACK_ID from TRACK where TRACK_ID =?
[java] 01:28:41,864 DEBUG AbstractEntityPersister:2746 - Snapshot select: select track_.TRACK_ID, track_.title as title0_, track_.filePath as filePath0_, track_.playTime as playTime0_, track_.added as added0_, track_.volume as volume0_ from TRACK track_ where track_.TRACK_ID=?
[java] 01:28:41,864 DEBUG AbstractEntityPersister:2749 - Insert 0: insert into TRACK (title, filePath, playTime, added, volume, TRACK_ID) values (?, ?, ?, ?, ?, ?)
[java] 01:28:41,864 DEBUG AbstractEntityPersister:2750 - Update 0: update TRACK set title=?, filePath=?, playTime=?, added=?, volume=? where TRACK_ID=?
[java] 01:28:41,867 DEBUG AbstractEntityPersister:2751 - Delete 0: delete from TRACK where TRACK_ID=?
[java] 01:28:41,867 DEBUG AbstractEntityPersister:2755 - Identity insert: insert into TRACK (TRACK_ID, title, filePath, playTime, added, volume) values (null, ?, ?, ?, ?, ?)
[java] 01:28:41,894 DEBUG EntityLoader:79 - Static select for entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,895 DEBUG EntityLoader:79 - Static select for entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,896 DEBUG EntityLoader:79 - Static select for entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,897 DEBUG EntityLoader:79 - Static select for entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,898 DEBUG EntityLoader:79 - Static select for entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,908 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,909 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity com.oreilly.hh.Track: select track0_.TRACK_ID as TRACK1_0_0_, track0_.title as title0_0_, track0_.filePath as filePath0_0_, track0_.playTime as playTime0_0_, track0_.added as added0_0_, track0_.volume as volume0_0_ from TRACK track0_ where track0_.TRACK_ID=?
[java] 01:28:41,918 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
[java] 01:28:41,922 DEBUG SessionFactoryObjectFactory:76 - registered: 4028801818b7fe070118b7fe09380000 (unnamed)
[java] 01:28:41,922 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
[java] 01:28:41,924 DEBUG SessionFactoryImpl:308 - instantiated session factory
[java] 01:28:41,924 DEBUG SessionFactoryImpl:392 - Checking 0 named HQL queries
[java] 01:28:41,924 DEBUG SessionFactoryImpl:412 - Checking 0 named SQL queries
[java] 01:28:41,978 DEBUG SessionImpl:220 - opened session at timestamp: 12056777219
[java] 01:28:41,982 DEBUG JDBCTransaction:54 - begin
[java] 01:28:41,982 DEBUG ConnectionManager:421 - opening JDBC connection
[java] 01:28:41,982 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
[java] 01:28:41,982 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
[java] 01:28:41,983 DEBUG JDBCTransaction:59 - current autocommit status: false
[java] 01:28:41,983 DEBUG JDBCContext:210 - after transaction begin
[java] **************
[java] Track in memory is : id:0; title:Russian Trance; path:vol2/album610/track02.mp3; volume7
[java] **************
[java] 01:28:41,991 DEBUG DefaultSaveOrUpdateEventListener:158 - saving transient instance
[java] 01:28:41,993 DEBUG AbstractSaveEventListener:153 - saving [com.oreilly.hh.Track#<null>]
[java] 01:28:41,993 DEBUG AbstractSaveEventListener:244 - executing insertions
[java] 01:28:42,011 DEBUG AbstractSaveEventListener:297 - executing identity-insert immediately
[java] 01:28:42,013 DEBUG AbstractEntityPersister:2144 - Inserting entity: com.oreilly.hh.Track (native id)
[java] 01:28:42,015 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[java] 01:28:42,016 DEBUG SQL:401 - insert into TRACK (TRACK_ID, title, filePath, playTime, added, volume) values (null, ?, ?, ?, ?, ?)
[java] 01:28:42,017 DEBUG AbstractBatcher:484 - preparing statement
[java] 01:28:42,024 DEBUG AbstractEntityPersister:1992 - Dehydrating entity: [com.oreilly.hh.Track#<null>]
[java] 01:28:42,030 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 01:28:42,032 DEBUG AbstractBatcher:533 - closing statement
[java] 01:28:42,033 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[java] 01:28:42,034 DEBUG SQL:401 - call identity()
[java] 01:28:42,034 DEBUG AbstractBatcher:484 - preparing statement
[java] 01:28:42,034 DEBUG IdentifierGeneratorFactory:37 - Natively generated identity: 101
[java] 01:28:42,035 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 01:28:42,035 DEBUG AbstractBatcher:533 - closing statement
[java] 01:28:42,039 DEBUG JDBCTransaction:103 - commit
[java] 01:28:42,040 DEBUG SessionImpl:337 - automatically flushing session
[java] 01:28:42,040 DEBUG AbstractFlushingEventListener:58 - flushing session
[java] 01:28:42,041 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
[java] 01:28:42,042 DEBUG AbstractFlushingEventListener:154 - dirty checking collections
[java] 01:28:42,042 DEBUG AbstractFlushingEventListener:171 - Flushing entities and processing referenced collections
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:210 - Processing unreferenced collections
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:224 - Scheduling collection removes/(re)creates/updates
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[java] 01:28:42,049 DEBUG Printer:83 - listing entities:
[java] 01:28:42,050 DEBUG Printer:90 - com.oreilly.hh.Track{id=101, title=Russian Trance, playTime=00:03:30, added=17 March 2008, filePath=vol2/album610/track02.mp3, volume=7}
[java] 01:28:42,050 DEBUG AbstractFlushingEventListener:290 - executing flush
[java] 01:28:42,052 DEBUG ConnectionManager:469 - registering flush begin
[java] 01:28:42,052 DEBUG ConnectionManager:478 - registering flush end
[java] 01:28:42,052 DEBUG AbstractFlushingEventListener:321 - post flush
[java] 01:28:42,052 DEBUG JDBCContext:201 - before transaction completion
[java] 01:28:42,052 DEBUG SessionImpl:393 - before transaction completion
[java] 01:28:42,053 DEBUG JDBCTransaction:116 - committed JDBC Connection
[java] 01:28:42,053 DEBUG JDBCContext:215 - after transaction completion
[java] 01:28:42,053 DEBUG ConnectionManager:404 - aggressively releasing JDBC connection
[java] 01:28:42,053 DEBUG ConnectionManager:441 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 01:28:42,055 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
[java] 01:28:42,055 DEBUG SessionImpl:422 - after transaction completion
[java] ***********COMMITED *************
[java] 01:28:42,055 DEBUG SessionImpl:273 - closing session
[java] 01:28:42,055 DEBUG ConnectionManager:375 - connection already null in cleanup : no action
[java] 01:28:42,058 INFO SessionFactoryImpl:769 - closing
[java] 01:28:42,058 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:hsqldb:file  :D  ata/music
BUILD SUCCESSFUL
Total time: 2 seconds

My hibernate.properties file (located at root of src directory and copied over to output src dir when ant does the prepare task for the project) :-

 
hibernate.dialect=org.hibernate.dialect.HSQLDialect
hibernate.connection.driver_class=org.hsqldb.jdbcDriver
hibernate.connection.url=jdbc:hsqldb:file:Data/music
hibernate.connection.username=sa
hibernate.connection.password=

[ March 17, 2008: Message edited by: steve jones ]

[ March 17, 2008: Message edited by: steve jones ]
[ March 17, 2008: Message edited by: steve jones ]

[Paul Sturrock]

"sleep er"

Please check your private messages for a message from me.

[steve jones]

Hi Paul,
Name has been changed in line with naming policy.

Any chance you could take a stab at the problem I'm posting about?

[Mark Spritzler]

"Steve"

Can you edit your post and add code tags to your code, and put some carriage returns in the log stuff, it is impossible to read it.

Also can you post your mapping and config file.

Thanks

Mark

[Mark Spritzler]

Um, where is your Connection Pool? Hibernate requires a Connection Pool, either using a third party Connection Pool like C3PO, which comes with Hibenate, or a Datasource through a container like an App Server.

Mark

[steve jones]

Hi Mark,
Thanks for replying. I've added the code tags and a bit of indenting to the code itself, hope it's readable now.

Mapping, java object and config files given below. I don't think it's anything to do with connection pooling as the other tests which pull data out of the database seem to work fine (see below points for bit more info). I'm only using it in the simplest way ie. 1 ant target launching just one main thread which is exactly as you see in the code above.

I've also looked at a number of websites/books and they all seem to run a similar example in almost exactly the same kind of configuration with no mention of specifying connection pools anywhere (but I did notice they tended to use an xml config file whereas I'm using the hibernate.properties file (shown at bottom of original post), but it should do same thing as far as I'm aware?).

Here's a couple more things I've tried since posting :-

* used the wasCommitted() method of the session to check what it reports and getting 'true' value back which would indicate the inserts have been committed but again checking the db later shows no row inserted.

* Manually added a row to db for testing. If i use hibernate to load the manually inputted row it successfully pulls it back and I get the expected Track object

* Tried changing the flush method on the session to ALWAYS via calling

session.setFlushMode(FlushMode.ALWAYS);

but as with everything else it makes no difference.

Could it be something to do with some setting for HSQL that I haven't setup correctly?

Here's my Track.hbm.xml file :-

<?xml version="1.0"?>
 <!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
          "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd"> 
 
<hibernate-mapping>
 
  <class name="com.oreilly.hh.Track" table="TRACK">
    <meta attribute="class-description">
      Represents a single playable track in the music database.
      @author Jim Elliott (with help from Hibernate)
    </meta>
 
    <id name="id" type="int" column="TRACK_ID">
      <meta attribute="scope-set">protected</meta>
      <generator class="native"/>
    </id>
 
    <property name="title" type="string" not-null="true"/>
 
    <property name="filePath" type="string" not-null="true"/>
 
    <property name="playTime" type="time">
      <meta attribute="field-description">Playing time</meta>
    </property>
 
    <property name="added" type="date">
      <meta attribute="field-description">When the track was created</meta>
    </property>
 
    <property name="volume" type="short" not-null="true">
      <meta attribute="field-description">How loud to play the track</meta>
    </property>
 
  </class>
</hibernate-mapping>

Here's my Track.java class :-

package com.oreilly.hh;
// Generated 17-Mar-2008 15:06:47 by Hibernate Tools 3.2.0.CR1
 

import java.util.Date;
 
public class Track  implements java.io.Serializable {
 

     private int id;
     private String title;
     private String filePath;
     /**
      * Playing time
     */
     private Date playTime;
     /**
      * When the track was created
     */
     private Date added;
     /**
      * How loud to play the track
     */
     private short volume;
 
    public Track() {
    }
 

    public Track(String title, String filePath, short volume) {
        this.title = title;
        this.filePath = filePath;
        this.volume = volume;
    }
    public Track(String title, String filePath, Date playTime, Date added, short volume) {
       this.title = title;
       this.filePath = filePath;
       this.playTime = playTime;
       this.added = added;
       this.volume = volume;
    }
   
    public int getId() {
        return this.id;
    }
    
    protected void setId(int id) {
        this.id = id;
    }
    public String getTitle() {
        return this.title;
    }
    
    public void setTitle(String title) {
        this.title = title;
    }
    public String getFilePath() {
        return this.filePath;
    }
    
    public void setFilePath(String filePath) {
        this.filePath = filePath;
    }
    /**       
     *      * Playing time
     */
    public Date getPlayTime() {
        return this.playTime;
    }
    
    public void setPlayTime(Date playTime) {
        this.playTime = playTime;
    }
    /**       
     *      * When the track was created
     */
    public Date getAdded() {
        return this.added;
    }
    
    public void setAdded(Date added) {
        this.added = added;
    }
    /**       
     *      * How loud to play the track
     */
    public short getVolume() {
        return this.volume;
    }
    
    public void setVolume(short volume) {
        this.volume = volume;
    }
}

Here's the ddl that's in the music.script file of the HSQL data directory :-

CREATE SCHEMA PUBLIC AUTHORIZATION DBA
CREATE MEMORY TABLE TRACK(TRACK_ID INTEGER GENERATED BY DEFAULT AS IDENTITY(START WITH 0) NOT NULL PRIMARY KEY,TITLE VARCHAR(255) NOT NULL,FILEPATH VARCHAR(255) NOT NULL,PLAYTIME TIME,ADDED DATE,VOLUME SMALLINT)
ALTER TABLE TRACK ALTER COLUMN TRACK_ID RESTART WITH 101
CREATE USER SA PASSWORD ""
GRANT DBA TO SA
SET WRITE_DELAY 20
SET SCHEMA PUBLIC
INSERT INTO TRACK VALUES(100,'STODGE','PEE/PAH','00:00:02',NULL,7)

where the 'STODGE' track above is the one I manually added to the db.

Much appreciation for peoples help.

[Jaikiran Pai]

I have no experience with HSQLDB but could you try adding this following qualifier(ON COMMIT PRESERVE ROWS) while creating the table:

CREATE MEMORY TABLE TRACK(TRACK_ID INTEGER GENERATED BY DEFAULT AS IDENTITY(START WITH 0) NOT NULL PRIMARY KEY,TITLE VARCHAR(255) NOT NULL,FILEPATH VARCHAR(255) NOT NULL,PLAYTIME TIME,ADDED DATE,VOLUME SMALLINT) [B]ON COMMIT PRESERVE ROWS[/B]

[steve jones]

Hi Jaikiran,
Thanks for the suggestion, I dropped the table and recreated it with the ddl you gave. Again the logs were almost identical to the one I've posted (ie. it told me it had committed the stuff successfully) but again checking after the process had ran I have an empty table!!!

Anything else you/someone might suggest? For a bit more info. on what I'm trying to do, this is basically the first part of chapter 3 of the book "Hibernate , A developers notebook" by James Elliott, but updated code/config bits for hibernate 3 (Note I've followed most of the details of updating as given by the following site : http://www.epischel.de/wordpress/?p=24 )

Maybe I should just give up with HSQL and write it off as not very good (blatant flame to hsql devotees so they maybe inspired to help me out and point out where it's me and not hsql that's a write off ). Can anyone recommend a good free rdbms that's simple to install and use? I tried setting up postgresql earlier but eventually gave up as stuffing around with all the configuration was proving just as much of a headache as this problem.

[Jaikiran Pai]

Originally posted by steve jones:
Can anyone recommend a good free rdbms that's simple to install and use? I tried setting up postgresql earlier but eventually gave up as stuffing around with all the configuration was proving just as much of a headache as this problem.

For simple application like this, i personally use MySQL which is simple to install and use.

[Mark Spritzler]

When posting any logs or console displays, please please add carriage returns, so that we can read the thread. You can always go back and edit your posts to add them.

Mark

[steve jones]

Hi guys,
Mark : Not sure what browser you're viewing this thread with but I've viewed it with both firefox and internet explorer and the log entry has carriage returns and appears totally readable when I look at it in either (but just to help I'll re-post the bits that I think matter below).

Jaikiran : Good idea but as far as I know mysql isn't free so unfortunately doesn't solve my problem.

Log highlights, this is taken from the part following it successfully setting up a connection to the db and now its trying to create the session factory :-

[java] 01:28:41,918 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
[java] 01:28:41,922 DEBUG SessionFactoryObjectFactory:76 - registered: 4028801818b7fe070118b7fe09380000 (unnamed)
[java] 01:28:41,922 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
[java] 01:28:41,924 DEBUG SessionFactoryImpl:308 - instantiated session factory
[java] 01:28:41,924 DEBUG SessionFactoryImpl:392 - Checking 0 named HQL queries
[java] 01:28:41,924 DEBUG SessionFactoryImpl:412 - Checking 0 named SQL queries
[java] 01:28:41,978 DEBUG SessionImpl:220 - opened session at timestamp: 12056777219
[java] 01:28:41,982 DEBUG JDBCTransaction:54 - begin
[java] 01:28:41,982 DEBUG ConnectionManager:421 - opening JDBC connection
[java] 01:28:41,982 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
[java] 01:28:41,982 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
[java] 01:28:41,983 DEBUG JDBCTransaction:59 - current autocommit status: false
[java] 01:28:41,983 DEBUG JDBCContext:210 - after transaction begin
 
[java] **************
[java] Track in memory is : id:0; title:Russian Trance; path:vol2/album610/track02.mp3; volume7
[java] **************
 
[java] 01:28:41,991 DEBUG DefaultSaveOrUpdateEventListener:158 - saving transient instance
[java] 01:28:41,993 DEBUG AbstractSaveEventListener:153 - saving [com.oreilly.hh.Track#<null>]
[java] 01:28:41,993 DEBUG AbstractSaveEventListener:244 - executing insertions
[java] 01:28:42,011 DEBUG AbstractSaveEventListener:297 - executing identity-insert immediately
[java] 01:28:42,013 DEBUG AbstractEntityPersister:2144 - Inserting entity: com.oreilly.hh.Track (native id)
[java] 01:28:42,015 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
 
[java] 01:28:42,016 DEBUG SQL:401 - insert into TRACK (TRACK_ID, title, filePath, playTime, added, volume) values (null, ?, ?, ?, ?, ?)
[java] 01:28:42,017 DEBUG AbstractBatcher:484 - preparing statement
[java] 01:28:42,024 DEBUG AbstractEntityPersister:1992 - Dehydrating entity: [com.oreilly.hh.Track#<null>]
[java] 01:28:42,030 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 01:28:42,032 DEBUG AbstractBatcher:533 - closing statement
 
[java] 01:28:42,033 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[java] 01:28:42,034 DEBUG SQL:401 - call identity()
[java] 01:28:42,034 DEBUG AbstractBatcher:484 - preparing statement
[java] 01:28:42,034 DEBUG IdentifierGeneratorFactory:37 - Natively generated identity: 101
[java] 01:28:42,035 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[java] 01:28:42,035 DEBUG AbstractBatcher:533 - closing statement
 
[java] 01:28:42,039 DEBUG JDBCTransaction:103 - commit
 
[java] 01:28:42,040 DEBUG SessionImpl:337 - automatically flushing session
[java] 01:28:42,040 DEBUG AbstractFlushingEventListener:58 - flushing session
[java] 01:28:42,041 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
[java] 01:28:42,042 DEBUG AbstractFlushingEventListener:154 - dirty checking collections
[java] 01:28:42,042 DEBUG AbstractFlushingEventListener:171 - Flushing entities and processing referenced collections
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:210 - Processing unreferenced collections
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:224 - Scheduling collection removes/(re)creates/updates[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
[java] 01:28:42,047 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
 
[java] 01:28:42,049 DEBUG Printer:83 - listing entities:
[java] 01:28:42,050 DEBUG Printer:90 - com.oreilly.hh.Track{id=101, title=Russian Trance, playTime=00:03:30, added=17 March 2008, filePath=vol2/album610/track02.mp3, volume=7}
 
[java] 01:28:42,050 DEBUG AbstractFlushingEventListener:290 - executing flush
[java] 01:28:42,052 DEBUG ConnectionManager:469 - registering flush begin
[java] 01:28:42,052 DEBUG ConnectionManager:478 - registering flush end
[java] 01:28:42,052 DEBUG AbstractFlushingEventListener:321 - post flush
[java] 01:28:42,052 DEBUG JDBCContext:201 - before transaction completion
[java] 01:28:42,052 DEBUG SessionImpl:393 - before transaction completion
[java] 01:28:42,053 DEBUG JDBCTransaction:116 - committed JDBC Connection
[java] 01:28:42,053 DEBUG JDBCContext:215 - after transaction completion
[java] 01:28:42,053 DEBUG ConnectionManager:404 - aggressively releasing JDBC connection
[java] 01:28:42,053 DEBUG ConnectionManager:441 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[java] 01:28:42,055 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
[java] 01:28:42,055 DEBUG SessionImpl:422 - after transaction completion
 
[java] ***********COMMITED *************
 
[java] 01:28:42,055 DEBUG SessionImpl:273 - closing session
[java] 01:28:42,055 DEBUG ConnectionManager:375 - connection already null in cleanup : no action
[java] 01:28:42,058 INFO SessionFactoryImpl:769 - closing
[java] 01:28:42,058 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:hsqldb:file   :mrgreen:   ata/musicBUILD SUCCESSFULTotal time: 2 seconds

[Mark Spritzler]

I am using FF 2.0.0.12 and I have to scroll quite a bit to the right to get to any text in the posts.

Sorry, I am not being much help, but I just can't read the posts.

Mark

[steve jones]

hmmmmmmmmmmmmmmmmm............. I appear to have solved the problem, but how I solved it doesn't make much sense!!

While trying to view the logs from the database while the transaction was in progress I threw in a Thread.sleep(20*1000) just after the tx.commit() statement and for some reason this caused the transaction to be permanently committed to the db!

I've played around with the delay I need to use and for some reason it has to be no less than 19 seconds or the transaction doesn't seem to get committed.

So now my question has changed to :-
Anybody have any idea why this delay seems to work???

Thanks again for any replies

[Mark Spritzler]

Steve, that is odd, but now that you have that temp solution, can you post it in a new thread so that this whole no carriage return can't read the thread thing isn't an issue.

Thanks

Mark

[Jaikiran Pai]

Steve,

Mark is right. Even i am having problem reading this thread (i'm using Firefox 2.0.0). If you could edit your post to delete a couple of lines before and after (including) the following statement in the log

01:28:41,560 DEBUG SessionFactoryImpl:177......

that would be great.

Coming back to what you mention about HSQLDB behaviour, i hadn't heard about such a thing before. But after you mentioned the 20 second delay, i read the HSQLDB docs and found the WRITE_DELAY property of the server (which i think in your case is set to true). Try setting it to FALSE and see if it helps. Read through that doc to understand what that property is meant for.

[steve jones]

Hi Jakiran/Mark,
Looks like Jakiran found the solution! It was indeed the default setting of the WRITE_DELAY setting of HSQL db that was causing the problem, it's set at 20 seconds. Turning the WRITE_DELAY function off in the db sorted the problem.

Because I'm running the db in a mode which means its only ever up when I run my application code, the db was never alive for more than 20 seconds thus the committed additions were never committed to file.

Thanks for all your help and apologies for the awkward formatting of the thread.