Hello,

I tried to find the same identity many times and every time I get a DB access.



I would expect that the object is cached to avoid the second DB access, but it isn't.
Do I need to configure something or is this normal?

Thanks
Haug

all objects associated with Container(s) will be retrieved from the cache.

If you want hibernate to retrieve Container(s) from the cache, use query.iterate() --> but you must study the impacts (look at sql generated at first hit).

Basically, the cache only works for when loading by object id, i.e. session.load(...) and lazy loading. Hibernate doesn't have some magic HQL -> return objects from the cache logic, instead all HQL queries get translated to SQL and are run against the database.

The trick to making effective use of the cache is to try to structure your application more along the lines of "navigating the object graph" instead of "do queries and then do something with the result". If that doesn't work, you can always try to do your own caching which might work, because you know better the requirements of your app than hibernate does. But that is of course error-prone and time-consuming, so it might be better to just buy a faster DB box. ;-)

You can also use the Query cache, see the "Performance" chapter in the documentation.

huag, be careful with caching. There's a reason why query caching is not turned on by default. What happens when your database changes? How will hibernate know that its cached object is now invalid? Is the chance of getting stale data worth the .023 seconds it takes to perform the query again (assuming you already have a connection)?

You'll need to evaluate your DB and determine how often the data changes and who changes it. Then set your caching accordingly.

This is a common problem with caching in general. Usually, I find the best solution is to turn it off. Database pooling will dramatically improve your overall perfomance.

Chrisjan

Actually, Hibernate notifies the query cache when it updates any data. So if Hibernate is the only client of the DB, the query cache is perfectly safe.

To recapitolate, the find method doesn't notice when a query uses the primary key of a table. It doesn't optimise the access by directly using the cache, it always does a query to the database.

I tried the session.load() method but it doesn't use the cache too. I understand that parsing a query isn't without overhead but the load method could easily look into the cache before doing a database query. Is there a reason why it is not done?

I must have done something wrong, because this would mean that caching is nearly worthless.

How to access an object where I know the primary key without accessing the database?

Regards
Haug

This is not correct. I suggest you read the documentation much more carefully, and take the time to properly understand Hibernate's cache architecture.

Your post isn't very helpful you should at least say which of my
sentences are not correct and which documentation you mean.

What I do is loading the container "10000316" (const) and changing its
Location to something new. I did it 3 times for the same container and
expected at least one cache hit for it.

From what I can read in the following log file:
1. The ehcache is initialised and instantiated.
2. There are exactly 3 queries executed for the container.
3. The object is expecitely invalidated (why?)

The cache has no effect with my configuration!

Is my assumption wrong that a JVM cache caches all objects used
in the same Java VM no matter what session or transaction I use?
Has sombody proved that the so called(1) JVM cache really works?
Any idea why it doesn't work for me?

Thanks
Haug

[code]INFO [org.jboss.deployment.MainDeployer] Starting deployment of package: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.EARDeployer] Init J2EE application: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/cglib-2.0-rc2.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/commons-collections-3.0.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/commons-logging-1.0.3.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/dom4j-1.4.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/ehcache-0.6.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/hibernate2.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/odmg-3.0.jar
INFO [org.jboss.ejb.EjbModule] Deploying WMS/Sorter
INFO [org.jboss.ejb.EjbModule] Deploying WMS/PutAway
INFO [org.jboss.ejb.EjbModule] Deploying WMS/OrderPlanning
INFO [net.sf.hibernate.jmx.HibernateServiceMBean] starting service at JNDI name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.jmx.HibernateServiceMBean] service properties: {hibernate.transaction.manager_lookup_class=net.sf.hibernate.transaction.JBossTransactionManagerLookup, hibernate.dialect=net.sf.hibernate.dialect.Oracle9Dialect, hibernate.use_outer_join=true, hibernate.connection.username=J2EE, hibernate.session_factory_name=java:/WMSPrototype/Hibernate2J2EE, hibernate.connection.datasource=java:/OracleDS, jta.UserTransaction=UserTransaction, hibernate.show_sql=true, hibernate.connection.password=bean, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JTATransactionFactory}
INFO [net.sf.hibernate.cfg.Environment] Hibernate 2.1.2
INFO [net.sf.hibernate.cfg.Environment] hibernate.properties not found
INFO [net.sf.hibernate.cfg.Environment] using CGLIB reflection optimizer
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Container.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath

INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Container -> CONTAINER
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Container usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDCONTAINER, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: items, type: java.util.Set
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: containerNo -> containerNo, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: location -> IDLOCATION, type: com.vanderlande.lsg.entity.Location
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Location.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Location -> LOCATION
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Location usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDLOCATION, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: locationNo -> locationNo, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: containers, type: java.util.Set

INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/PickTask.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.PickTask -> PICKTASK
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.PickTask usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDPICKTASK, type: long
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryLine -> IDDELIVERYLINE, type: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> QUANTITY, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: pickLocation -> IDLOCATION, type: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: status -> status, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: fromContainerItem -> IDCONTAINERITEMFROM, type: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: toContainerItem -> IDCONTAINERITEMTO, type: com.vanderlande.lsg.entity.ContainerItem
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/DeliveryLine.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.DeliveryLine -> DELIVERYLINE
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.DeliveryLine usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDDELIVERYLINE, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: delivery -> IDDELIVERY, type: com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: sku -> IDSKU, type: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: lineNo -> LINENO, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> quantity, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Sku.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Sku -> SKU
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Sku usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDSKU, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: matchCode -> SKUNO, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: shortDescription -> shortDescription, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: longDescription -> longDescription, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Delivery.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Delivery -> DELIVERY
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Delivery usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDDELIVERY, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryLines, type: java.util.List
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: status -> status, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryNo -> deliveryNo, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/ContainerItem.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.ContainerItem -> CONTAINERITEM
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.ContainerItem usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDCONTAINERITEM, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: sku -> IDSKU, type: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: container -> IDCONTAINER, type: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> quantity, type: integer
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.ContainerItem.attributes -> CONTAINERITEMATTRIBUTE
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: attributes, type: java.util.Map
INFO [net.sf.hibernate.cfg.Configuration] processing one-to-many association mappings
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Container.items
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Container.items -> CONTAINERITEM
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDCONTAINER, one-to-many: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Location.containers
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Location.containers -> CONTAINER
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDLOCATION, one-to-many: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Delivery.deliveryLines
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Delivery.deliveryLines -> DELIVERYLINE
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDDELIVERY, index: LINENO, one-to-many: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.ContainerItem.attributes
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDCONTAINERITEM, index: KEY, element: VALUE, type: string
INFO [net.sf.hibernate.cfg.Configuration] processing one-to-one association property references
INFO [net.sf.hibernate.cfg.Configuration] processing foreign key constraints
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Container
INFO [net.sf.hibernate.dialect.Dialect] Using dialect: net.sf.hibernate.dialect.Oracle9Dialect
INFO [net.sf.hibernate.cfg.SettingsFactory] Use outer join fetching: true
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.connection.DatasourceConnectionProvider] Using datasource: java:/OracleDS
INFO [net.sf.hibernate.transaction.TransactionFactoryFactory] Transaction strategy: net.sf.hibernate.transaction.JTATransactionFactory
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiating TransactionManagerLookup: net.sf.hibernate.transaction.JBossTransactionManagerLookup
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiated TransactionManagerLookup
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiating TransactionManagerLookup: net.sf.hibernate.transaction.JBossTransactionManagerLookup
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiated TransactionManagerLookup
INFO [net.sf.hibernate.cfg.SettingsFactory] Use scrollable result sets: true
INFO [net.sf.hibernate.cfg.SettingsFactory] Use JDBC3 getGeneratedKeys(): false
INFO [net.sf.hibernate.cfg.SettingsFactory] Optimize cache for minimal puts: false
INFO [net.sf.hibernate.cfg.SettingsFactory] echoing all SQL to stdout
INFO [net.sf.hibernate.cfg.SettingsFactory] Query language substitutions: {}
INFO [net.sf.hibernate.cfg.SettingsFactory] cache provider: net.sf.ehcache.hibernate.Provider
INFO [net.sf.hibernate.cfg.Configuration] instantiating and configuring caches
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Container
DEBUG [net.sf.ehcache.CacheManager] Creating new CacheManager with default config
DEBUG [net.sf.ehcache.CacheManager] Configuring ehcache from classpath.
DEBUG [net.sf.ehcache.config.Configurator] Configuring ehcache from ehcache.xml found in the classpath: jar:file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar!/ehcache.xml
DEBUG [net.sf.ehcache.config.Configuration$DiskStore] Disk Store Path: D:\TEMP\
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Container. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Container Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Container

DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Location
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Location. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Location Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Location

DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.PickTask
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.PickTask. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.PickTask Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.PickTask
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.DeliveryLine. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.DeliveryLine Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Sku. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Sku Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.ContainerItem. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerItem Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Delivery. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Delivery Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Delivery
INFO [net.sf.hibernate.impl.SessionFactoryImpl] building session factory
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] instantiating session factory with properties: {java.vendor=Sun Microsystems Inc., catalina.base=D:\opt\jboss-3.2.3\server\default, catalina.useNaming=false, os.name=Windows NT, sun.boot.class.path=D:\opt\j2sdk1.4.2\jre\lib\rt.jar;D:\opt\j2sdk1.4.2\jre\lib\i18n.jar;D:\opt\j2sdk1.4.2\jre\lib\sunrsasign.jar;D:\opt\j2sdk1.4.2\jre\lib\jsse.jar;D:\opt\j2sdk1.4.2\jre\lib\jce.jar;D:\opt\j2sdk1.4.2\jre\lib\charsets.jar;D:\opt\j2sdk1.4.2\jre\classes, sun.java2d.fontpath=, java.vm.specification.vendor=Sun Microsystems Inc., java.runtime.version=1.4.2_02-b03, user.name=haug, jboss.bind.address=0.0.0.0, hibernate.session_factory_name=java:/WMSPrototype/Hibernate2J2EE, jboss.home.dir=D:\opt\jboss-3.2.3, user.language=de, java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, sun.boot.library.path=D:\opt\j2sdk1.4.2\jre\bin, jboss.home.url=file:/D:/opt/jboss-3.2.3/, java.version=1.4.2_02, version=2.4.1, user.timezone=Europe/Berlin, jboss.server.home.dir=D:\opt\jboss-3.2.3\server\default, sun.arch.data.model=32, hibernate.use_outer_join=true, java.endorsed.dirs=D:\opt\j2sdk1.4.2\jre\lib\endorsed, jboss.server.home.url=file:/D:/opt/jboss-3.2.3/server/default/, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.cglib.use_reflection_optimizer=true, java.class.version=48.0, jboss.server.config.url=file:/D:/opt/jboss-3.2.3/server/default/conf/, user.country=DE, java.home=D:\opt\j2sdk1.4.2\jre, java.vm.info=mixed mode, jboss.lib.url=file:/D:/opt/jboss-3.2.3/lib/, os.version=4.0, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JTATransactionFactory, hibernate.connection.datasource=java:/OracleDS, path.separator=;, java.vm.version=1.4.2_02-b03, hibernate.connection.password=bean, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, user.variant=, vendor-url=http://xml.apache.org/xalan-j, java.protocol.handler.pkgs=org.jboss.net.protocol, java.awt.printerjob=sun.awt.windows.WPrinterJob, vendor=Apache Software Foundation, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=J2EE, jboss.server.temp.dir=D:\opt\jboss-3.2.3\server\default\tmp, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces, user.home=C:\NTW4\Profiles\Haug, java.rmi.server.RMIClassLoaderSpi=org.jboss.system.JBossRMIClassLoader, java.specification.vendor=Sun Microsystems Inc., org.xml.sax.driver=org.apache.crimson.parser.XMLReaderImpl, java.library.path=D:\opt\j2sdk1.4.2\bin;.;C:\NTW4\System32;C:\NTW4;D:\Perl\bin\;C:\NTW4\SYSTEM32;C:\NTW4;.;D:\oracle\ora92\bin;D:\opt\j2sdk1.4.2\bin;D:\Program Files\IBM\MQSeries\Java\Bin;D:\Program Files\IBM\MQSeries\Java\Lib;d:\usr\bin;D:\opt\apache-ant-1.5.3\bin;D:\opt\jwsdp-1_0\bin;d:\programme\borland\AppServer\bin;"d:\program files\borland\AppServer\bin";D:\PROGRAM FILES\BORLAND\CBUILDER3\BIN;"D:\Programme\GAMBIT\SQL-PC";D:\Program Files\Symantec\pcAnywhere\;D:\PROGRA~1\Tcl\bin;D:\Program Files\Argos\SOUL\bin;d:\Program Files\MQSeries Client\bin;d:\Program Files\MQSeries Client\tools\c\samples\bin;D:\opt\j2sdk1.4.1_01\bin;d:\PROGRA~1\Borland\CBUILD~3\Projects\Bpl;d:\PROGRA~1\Borland\CBUILD~3\Bin;d:\PROGRA~1\Borland\CBUILD~2\Projects\Bpl;D:\Program Files\Adabas\bin;D:\Program Files\Adabas\pgm;D:\Lotus\Notes;D:\Programme\GAMBIT\GamCVS;d:\Program Files\SSH Communications Security\SSH Secure Shell;C:\DOS, java.vendor.url=http://java.sun.com/, program.name=run.bat, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=net.sf.hibernate.dialect.Oracle9Dialect, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=;D:\opt\j2sdk1.4.2\lib\tools.jar;D:\opt\jboss-3.2.3\bin\\run.jar, jbossmx.loader.repository.class=org.jboss.mx.loading.UnifiedLoaderRepository3, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, catalina.home=D:\opt\jboss-3.2.3\server\default, sun.cpu.endian=little, sun.os.patch.level=Service Pack 6, jboss.server.lib.url=file:/D:/opt/jboss-3.2.3/server/default/lib/, java.rmi.server.codebase=http://haug-pc:8083/, java.io.tmpdir=D:\TEMP\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, jboss.server.data.dir=D:\opt\jboss-3.2.3\server\default\data, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=D:\opt\j2sdk1.4.2\jre\lib\ext, user.dir=D:\opt\jboss-3.2.3\bin, line.separator=
, java.vm.name=Java HotSpot(TM) Server VM, jboss.server.base.dir=D:\opt\jboss-3.2.3\server, jboss.server.base.url=file:/D:/opt/jboss-3.2.3/server/, file.encoding=Cp1252, jta.UserTransaction=UserTransaction, hibernate.transaction.manager_lookup_class=net.sf.hibernate.transaction.JBossTransactionManagerLookup, java.specification.version=1.4, jboss.server.name=default, hibernate.show_sql=true}
INFO [net.sf.hibernate.util.ReflectHelper] reflection optimizer disabled for: com.vanderlande.lsg.entity.ContainerItem, BulkBeanException: Property is private (property setAttributes)
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] initializing class SessionFactoryObjectFactory
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] registered: 05131cbcfb77b93e00fb77b949010000 (java:/WMSPrototype/Hibernate2J2EE)
INFO [net.sf.hibernate.impl.SessionFactoryObjectFactory] Factory name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
DEBUG [net.sf.hibernate.util.NamingHelper] binding: java:/WMSPrototype/Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] Returning a Reference to the SessionFactory
DEBUG [net.sf.hibernate.util.NamingHelper] lookup: java:
DEBUG [net.sf.hibernate.util.NamingHelper] Found subcontext: java:
DEBUG [net.sf.hibernate.util.NamingHelper] lookup: WMSPrototype
INFO [net.sf.hibernate.util.NamingHelper] Creating subcontext: WMSPrototype
DEBUG [net.sf.hibernate.util.NamingHelper] binding: Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] Returning a Reference to the SessionFactory
DEBUG [net.sf.hibernate.util.NamingHelper] Bound name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.impl.SessionFactoryObjectFactory] Bound factory to JNDI name: java:/WMSPrototype/Hibernate2J2EE
WARN [net.sf.hibernate.impl.SessionFactoryObjectFactory] InitialContext did not implement EventContext
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] instantiated session factory
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] obtaining JTA TransactionManager
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [org.jboss.ejb.plugins.StatelessSessionInstancePool] Started jboss.j2ee:jndiName=WMS/Sorter,plugin=pool,service=EJB
INFO [org.jboss.ejb.StatelessSessionContainer] Started jboss.j2ee:jndiName=WMS/Sorter,service=EJB
INFO [org.jboss.ejb.plugins.StatefulSessionInstancePool] Started jboss.j2ee:jndiName=WMS/PutAway,plugin=pool,service=EJB
INFO [org.jboss.ejb.plugins.StatefulSessionFilePersistenceManager] Started null
INFO [org.jboss.ejb.StatefulSessionContainer] Started jboss.j2ee:jndiName=WMS/PutAway,service=EJB
INFO [org.jboss.ejb.plugins.StatelessSessionInstancePool] Started jboss.j2ee:jndiName=WMS/OrderPlanning,plugin=pool,service=EJB
INFO [org.jboss.ejb.StatelessSessionContainer] Started jboss.j2ee:jndiName=WMS/OrderPlanning,service=EJB
INFO [org.jboss.ejb.EjbModule] Started jboss.j2ee:module=wmsprototype.jar,service=EjbModule
INFO [org.jboss.ejb.EJBDeployer] Deployed: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/wmsprototype.jar
INFO [org.jboss.deployment.EARDeployer] Started J2EE application: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.MainDeployer] Deployed package: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.scanner.URLDeploymentScanner] Started jboss.deployment:type=DeploymentScanner,flavor=URL
INFO [org.jboss.deployment.MainDeployer] Deployed package: file:/D:/opt/jboss-3.2.3/server/default/conf/jboss-service.xml
INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel) [3.2.3 (build: CVSTag=JBoss_3_2_3 date=200311301445)] Started in 1m:12s:956ms
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: WMSPrototype/Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=05131cbcfb77b93e00fb77b949010000
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-4-1-32-7]
DEBUG [net.sf.hibernate.hql.QueryTranslator] compiling query
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-4-1-32-7' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '68413' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 68413
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 68413
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#68413
DEBUG [net.sf.hibernate.type.StringType] returning '1-4-1-32-7' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 68413
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache mis for 10000316
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Container as container where containerNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [10000316]
DEBUG [net.sf.hibernate.hql.QueryTranslator] compiling query
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#68413], was: [com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-4-1-32-7, containers=uninitialized, id=68413}
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Container as container where containerNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '316' as column: IDCONTAI1_
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_
DEBUG [net.sf.hibernate.type.IntegerType] returning '68566' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#68566]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#68413], was: [com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Container{items=uninitialized, location=Location#68413, containerNo=10000316, id=316}
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-4-1-32-7, containers=uninitialized, id=68413}
DEBUG [net.sf.hibernate.impl.SessionImpl] executing flush
DEBUG [net.sf.hibernate.persister.EntityPersister] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
INFO [STDOUT] Hibernate: update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.persister.EntityPersister] Dehydrating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.type.IntegerType] binding '68413' to parameter: 2
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 3
DEBUG [net.sf.hibernate.impl.BatcherImpl] Adding to batch
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating: 316
DEBUG [net.sf.hibernate.impl.BatcherImpl] Executing batch size: 1
DEBUG [net.sf.hibernate.impl.BatcherImpl] success of batch update unknown: 0
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.impl.SessionImpl] post flush
DEBUG [net.sf.hibernate.impl.SessionImpl] closing session
DEBUG [net.sf.hibernate.impl.SessionImpl] disconnecting session
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction before completion callback
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction after completion callback, status: 3
DEBUG [net.sf.hibernate.impl.SessionImpl] transaction completion
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating (again): 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: Cannot remove entry as key 316 was not found
DEBUG [net.sf.hibernate.impl.SessionImpl] running Session.finalize()
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-3-1-21-23]
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-3-1-21-23' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '62943' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 62943
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 62943
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#62943
DEBUG [net.sf.hibernate.type.StringType] returning '1-3-1-21-23' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 62943
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache hit for 10000316 oid=316 using load
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] attempting to resolve [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache lookup: 316
DEBUG [net.sf.ehcache.hibernate.Plugin] key: 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: MemoryStore miss for 316
DEBUG [net.sf.ehcache.Cache] com.vanderlande.lsg.entity.Container cache - Miss
DEBUG [net.sf.ehcache.hibernate.Plugin] Element for 316 is null
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache miss
DEBUG [net.sf.hibernate.impl.SessionImpl] object not resolved in any cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.persister.EntityPersister] Materializing entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_0_
DEBUG [net.sf.hibernate.type.IntegerType] returning '68413' as column: IDLOCATION0_
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#62943], was: [com.vanderlande.lsg.entity.Location.containers#62943]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Container{items=uninitialized, location=Location#62943, containerNo=10000316, id=316}
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-3-1-21-23, containers=uninitialized, id=62943}
DEBUG [net.sf.hibernate.impl.SessionImpl] executing flush
DEBUG [net.sf.hibernate.persister.EntityPersister] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
INFO [STDOUT] Hibernate: update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.persister.EntityPersister] Dehydrating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.type.IntegerType] binding '62943' to parameter: 2
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 3
DEBUG [net.sf.hibernate.impl.BatcherImpl] Adding to batch
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating: 316
DEBUG [net.sf.hibernate.impl.BatcherImpl] Executing batch size: 1
DEBUG [net.sf.hibernate.impl.BatcherImpl] success of batch update unknown: 0
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.impl.SessionImpl] post flush
DEBUG [net.sf.hibernate.impl.SessionImpl] closing session
DEBUG [net.sf.hibernate.impl.SessionImpl] disconnecting session
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction before completion callback
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction after completion callback, status: 3
DEBUG [net.sf.hibernate.impl.SessionImpl] transaction completion
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating (again): 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: Cannot remove entry as key 316 was not found
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-5-2-15-16]
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-5-2-15-16' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '75780' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 75780
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 75780
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#75780
DEBUG [net.sf.hibernate.type.StringType] returning '1-5-2-15-16' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 75780
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache hit for 10000316 oid=316 using load
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] attempting to resolve [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache lookup: 316
DEBUG [net.sf.ehcache.hibernate.Plugin] key: 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: MemoryStore miss for 316
DEBUG [net.sf.ehcache.Cache] com.vanderlande.lsg.entity.Container cache - Miss
DEBUG [net.sf.ehcache.hibernate.Plugin] Element for 316 is null
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache miss
DEBUG [net.sf.hibernate.impl.SessionImpl] object not resolved in any cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.persister.EntityPersister] Materializing entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_0_
DEBUG [net.sf.hibernate.type.IntegerType] returning '62943' as column: IDLOCATION0_
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#75780], was: [com.vanderlande.lsg.entity.Location.containers#75780]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collectio

Your post isn't very helpful you should at least say which of my
sentences are not correct and which documentation you mean.

What I do is loading the container "10000316" (const) and changing its
Location to something new. I did it 3 times for the same container and
expected at least one cache hit for it.

From what I can read in the following log file:
1. The ehcache is initialised and instantiated.
2. There are exactly 3 queries executed for the container.
3. The object is expecitely invalidated (why?)

The cache has no effect with my configuration!

Is my assumption wrong that a JVM cache caches all objects used
in the same Java VM no matter what session or transaction I use?
Has sombody proved that the so called(1) JVM cache really works?
Any idea why it doesn't work for me?

Thanks
Haug

[code]INFO [org.jboss.deployment.MainDeployer] Starting deployment of package: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.EARDeployer] Init J2EE application: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/cglib-2.0-rc2.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/commons-collections-3.0.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/commons-logging-1.0.3.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/dom4j-1.4.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/ehcache-0.6.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/hibernate2.jar
INFO [org.jboss.deployment.SARDeployer] nested deployment: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar-contents/odmg-3.0.jar
INFO [org.jboss.ejb.EjbModule] Deploying WMS/Sorter
INFO [org.jboss.ejb.EjbModule] Deploying WMS/PutAway
INFO [org.jboss.ejb.EjbModule] Deploying WMS/OrderPlanning
INFO [net.sf.hibernate.jmx.HibernateServiceMBean] starting service at JNDI name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.jmx.HibernateServiceMBean] service properties: {hibernate.transaction.manager_lookup_class=net.sf.hibernate.transaction.JBossTransactionManagerLookup, hibernate.dialect=net.sf.hibernate.dialect.Oracle9Dialect, hibernate.use_outer_join=true, hibernate.connection.username=J2EE, hibernate.session_factory_name=java:/WMSPrototype/Hibernate2J2EE, hibernate.connection.datasource=java:/OracleDS, jta.UserTransaction=UserTransaction, hibernate.show_sql=true, hibernate.connection.password=bean, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JTATransactionFactory}
INFO [net.sf.hibernate.cfg.Environment] Hibernate 2.1.2
INFO [net.sf.hibernate.cfg.Environment] hibernate.properties not found
INFO [net.sf.hibernate.cfg.Environment] using CGLIB reflection optimizer
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Container.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath

INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Container -> CONTAINER
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Container usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDCONTAINER, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: items, type: java.util.Set
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: containerNo -> containerNo, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: location -> IDLOCATION, type: com.vanderlande.lsg.entity.Location
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Location.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Location -> LOCATION
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Location usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDLOCATION, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: locationNo -> locationNo, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: containers, type: java.util.Set

INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/PickTask.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.PickTask -> PICKTASK
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.PickTask usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDPICKTASK, type: long
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryLine -> IDDELIVERYLINE, type: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> QUANTITY, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: pickLocation -> IDLOCATION, type: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: status -> status, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: fromContainerItem -> IDCONTAINERITEMFROM, type: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: toContainerItem -> IDCONTAINERITEMTO, type: com.vanderlande.lsg.entity.ContainerItem
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/DeliveryLine.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.DeliveryLine -> DELIVERYLINE
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.DeliveryLine usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDDELIVERYLINE, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: delivery -> IDDELIVERY, type: com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: sku -> IDSKU, type: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: lineNo -> LINENO, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> quantity, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Sku.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Sku -> SKU
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Sku usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDSKU, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: matchCode -> SKUNO, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: shortDescription -> shortDescription, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: longDescription -> longDescription, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/Delivery.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.Delivery -> DELIVERY
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.Delivery usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDDELIVERY, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryLines, type: java.util.List
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: status -> status, type: string
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: deliveryNo -> deliveryNo, type: string
INFO [net.sf.hibernate.cfg.Configuration] Mapping resource: com/vanderlande/lsg/entity/ContainerItem.hbm.xml
DEBUG [net.sf.hibernate.util.DTDEntityResolver] trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
DEBUG [net.sf.hibernate.util.DTDEntityResolver] found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
INFO [net.sf.hibernate.cfg.Binder] Mapping class: com.vanderlande.lsg.entity.ContainerItem -> CONTAINERITEM
DEBUG [net.sf.hibernate.cache.CacheFactory] cache for: com.vanderlande.lsg.entity.ContainerItem usage strategy: nonstrict-read-write
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: id -> IDCONTAINERITEM, type: integer
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: sku -> IDSKU, type: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: container -> IDCONTAINER, type: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: quantity -> quantity, type: integer
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.ContainerItem.attributes -> CONTAINERITEMATTRIBUTE
DEBUG [net.sf.hibernate.cfg.Binder] Mapped property: attributes, type: java.util.Map
INFO [net.sf.hibernate.cfg.Configuration] processing one-to-many association mappings
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Container.items
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Container.items -> CONTAINERITEM
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDCONTAINER, one-to-many: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Location.containers
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Location.containers -> CONTAINER
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDLOCATION, one-to-many: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.Delivery.deliveryLines
INFO [net.sf.hibernate.cfg.Binder] Mapping collection: com.vanderlande.lsg.entity.Delivery.deliveryLines -> DELIVERYLINE
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDDELIVERY, index: LINENO, one-to-many: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Binder] Second pass for collection: com.vanderlande.lsg.entity.ContainerItem.attributes
DEBUG [net.sf.hibernate.cfg.Binder] Mapped collection key: IDCONTAINERITEM, index: KEY, element: VALUE, type: string
INFO [net.sf.hibernate.cfg.Configuration] processing one-to-one association property references
INFO [net.sf.hibernate.cfg.Configuration] processing foreign key constraints
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] resolving reference to class: com.vanderlande.lsg.entity.Container
INFO [net.sf.hibernate.dialect.Dialect] Using dialect: net.sf.hibernate.dialect.Oracle9Dialect
INFO [net.sf.hibernate.cfg.SettingsFactory] Use outer join fetching: true
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.connection.DatasourceConnectionProvider] Using datasource: java:/OracleDS
INFO [net.sf.hibernate.transaction.TransactionFactoryFactory] Transaction strategy: net.sf.hibernate.transaction.JTATransactionFactory
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiating TransactionManagerLookup: net.sf.hibernate.transaction.JBossTransactionManagerLookup
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiated TransactionManagerLookup
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiating TransactionManagerLookup: net.sf.hibernate.transaction.JBossTransactionManagerLookup
INFO [net.sf.hibernate.transaction.TransactionManagerLookupFactory] instantiated TransactionManagerLookup
INFO [net.sf.hibernate.cfg.SettingsFactory] Use scrollable result sets: true
INFO [net.sf.hibernate.cfg.SettingsFactory] Use JDBC3 getGeneratedKeys(): false
INFO [net.sf.hibernate.cfg.SettingsFactory] Optimize cache for minimal puts: false
INFO [net.sf.hibernate.cfg.SettingsFactory] echoing all SQL to stdout
INFO [net.sf.hibernate.cfg.SettingsFactory] Query language substitutions: {}
INFO [net.sf.hibernate.cfg.SettingsFactory] cache provider: net.sf.ehcache.hibernate.Provider
INFO [net.sf.hibernate.cfg.Configuration] instantiating and configuring caches
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Container
DEBUG [net.sf.ehcache.CacheManager] Creating new CacheManager with default config
DEBUG [net.sf.ehcache.CacheManager] Configuring ehcache from classpath.
DEBUG [net.sf.ehcache.config.Configurator] Configuring ehcache from ehcache.xml found in the classpath: jar:file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/hibernate.sar!/ehcache.xml
DEBUG [net.sf.ehcache.config.Configuration$DiskStore] Disk Store Path: D:\TEMP\
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Container. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Container Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Container

DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Location
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Location. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Location Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Location

DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.PickTask
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.PickTask. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.PickTask Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.PickTask
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.DeliveryLine. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.DeliveryLine Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.DeliveryLine
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Sku. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Sku Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Sku
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.ContainerItem. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerItem Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.ContainerItem
DEBUG [net.sf.hibernate.cfg.Configuration] instantiating cache com.vanderlande.lsg.entity.Delivery
DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
WARN [net.sf.ehcache.hibernate.Plugin] Could not find configuration for com.vanderlande.lsg.entity.Delivery. Configuring using the defaultCache settings.
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.Delivery Cache: Using SpoolingLinkedHashMap implementation
DEBUG [net.sf.ehcache.store.MemoryStore] initialized MemoryStore for com.vanderlande.lsg.entity.Delivery
INFO [net.sf.hibernate.impl.SessionFactoryImpl] building session factory
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] instantiating session factory with properties: {java.vendor=Sun Microsystems Inc., catalina.base=D:\opt\jboss-3.2.3\server\default, catalina.useNaming=false, os.name=Windows NT, sun.boot.class.path=D:\opt\j2sdk1.4.2\jre\lib\rt.jar;D:\opt\j2sdk1.4.2\jre\lib\i18n.jar;D:\opt\j2sdk1.4.2\jre\lib\sunrsasign.jar;D:\opt\j2sdk1.4.2\jre\lib\jsse.jar;D:\opt\j2sdk1.4.2\jre\lib\jce.jar;D:\opt\j2sdk1.4.2\jre\lib\charsets.jar;D:\opt\j2sdk1.4.2\jre\classes, sun.java2d.fontpath=, java.vm.specification.vendor=Sun Microsystems Inc., java.runtime.version=1.4.2_02-b03, user.name=haug, jboss.bind.address=0.0.0.0, hibernate.session_factory_name=java:/WMSPrototype/Hibernate2J2EE, jboss.home.dir=D:\opt\jboss-3.2.3, user.language=de, java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, sun.boot.library.path=D:\opt\j2sdk1.4.2\jre\bin, jboss.home.url=file:/D:/opt/jboss-3.2.3/, java.version=1.4.2_02, version=2.4.1, user.timezone=Europe/Berlin, jboss.server.home.dir=D:\opt\jboss-3.2.3\server\default, sun.arch.data.model=32, hibernate.use_outer_join=true, java.endorsed.dirs=D:\opt\j2sdk1.4.2\jre\lib\endorsed, jboss.server.home.url=file:/D:/opt/jboss-3.2.3/server/default/, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.cglib.use_reflection_optimizer=true, java.class.version=48.0, jboss.server.config.url=file:/D:/opt/jboss-3.2.3/server/default/conf/, user.country=DE, java.home=D:\opt\j2sdk1.4.2\jre, java.vm.info=mixed mode, jboss.lib.url=file:/D:/opt/jboss-3.2.3/lib/, os.version=4.0, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JTATransactionFactory, hibernate.connection.datasource=java:/OracleDS, path.separator=;, java.vm.version=1.4.2_02-b03, hibernate.connection.password=bean, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, user.variant=, vendor-url=http://xml.apache.org/xalan-j, java.protocol.handler.pkgs=org.jboss.net.protocol, java.awt.printerjob=sun.awt.windows.WPrinterJob, vendor=Apache Software Foundation, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=J2EE, jboss.server.temp.dir=D:\opt\jboss-3.2.3\server\default\tmp, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces, user.home=C:\NTW4\Profiles\Haug, java.rmi.server.RMIClassLoaderSpi=org.jboss.system.JBossRMIClassLoader, java.specification.vendor=Sun Microsystems Inc., org.xml.sax.driver=org.apache.crimson.parser.XMLReaderImpl, java.library.path=D:\opt\j2sdk1.4.2\bin;.;C:\NTW4\System32;C:\NTW4;D:\Perl\bin\;C:\NTW4\SYSTEM32;C:\NTW4;.;D:\oracle\ora92\bin;D:\opt\j2sdk1.4.2\bin;D:\Program Files\IBM\MQSeries\Java\Bin;D:\Program Files\IBM\MQSeries\Java\Lib;d:\usr\bin;D:\opt\apache-ant-1.5.3\bin;D:\opt\jwsdp-1_0\bin;d:\programme\borland\AppServer\bin;"d:\program files\borland\AppServer\bin";D:\PROGRAM FILES\BORLAND\CBUILDER3\BIN;"D:\Programme\GAMBIT\SQL-PC";D:\Program Files\Symantec\pcAnywhere\;D:\PROGRA~1\Tcl\bin;D:\Program Files\Argos\SOUL\bin;d:\Program Files\MQSeries Client\bin;d:\Program Files\MQSeries Client\tools\c\samples\bin;D:\opt\j2sdk1.4.1_01\bin;d:\PROGRA~1\Borland\CBUILD~3\Projects\Bpl;d:\PROGRA~1\Borland\CBUILD~3\Bin;d:\PROGRA~1\Borland\CBUILD~2\Projects\Bpl;D:\Program Files\Adabas\bin;D:\Program Files\Adabas\pgm;D:\Lotus\Notes;D:\Programme\GAMBIT\GamCVS;d:\Program Files\SSH Communications Security\SSH Secure Shell;C:\DOS, java.vendor.url=http://java.sun.com/, program.name=run.bat, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=net.sf.hibernate.dialect.Oracle9Dialect, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=;D:\opt\j2sdk1.4.2\lib\tools.jar;D:\opt\jboss-3.2.3\bin\\run.jar, jbossmx.loader.repository.class=org.jboss.mx.loading.UnifiedLoaderRepository3, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, catalina.home=D:\opt\jboss-3.2.3\server\default, sun.cpu.endian=little, sun.os.patch.level=Service Pack 6, jboss.server.lib.url=file:/D:/opt/jboss-3.2.3/server/default/lib/, java.rmi.server.codebase=http://haug-pc:8083/, java.io.tmpdir=D:\TEMP\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, jboss.server.data.dir=D:\opt\jboss-3.2.3\server\default\data, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=D:\opt\j2sdk1.4.2\jre\lib\ext, user.dir=D:\opt\jboss-3.2.3\bin, line.separator=
, java.vm.name=Java HotSpot(TM) Server VM, jboss.server.base.dir=D:\opt\jboss-3.2.3\server, jboss.server.base.url=file:/D:/opt/jboss-3.2.3/server/, file.encoding=Cp1252, jta.UserTransaction=UserTransaction, hibernate.transaction.manager_lookup_class=net.sf.hibernate.transaction.JBossTransactionManagerLookup, java.specification.version=1.4, jboss.server.name=default, hibernate.show_sql=true}
INFO [net.sf.hibernate.util.ReflectHelper] reflection optimizer disabled for: com.vanderlande.lsg.entity.ContainerItem, BulkBeanException: Property is private (property setAttributes)
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] initializing class SessionFactoryObjectFactory
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] registered: 05131cbcfb77b93e00fb77b949010000 (java:/WMSPrototype/Hibernate2J2EE)
INFO [net.sf.hibernate.impl.SessionFactoryObjectFactory] Factory name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
DEBUG [net.sf.hibernate.util.NamingHelper] binding: java:/WMSPrototype/Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] Returning a Reference to the SessionFactory
DEBUG [net.sf.hibernate.util.NamingHelper] lookup: java:
DEBUG [net.sf.hibernate.util.NamingHelper] Found subcontext: java:
DEBUG [net.sf.hibernate.util.NamingHelper] lookup: WMSPrototype
INFO [net.sf.hibernate.util.NamingHelper] Creating subcontext: WMSPrototype
DEBUG [net.sf.hibernate.util.NamingHelper] binding: Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] Returning a Reference to the SessionFactory
DEBUG [net.sf.hibernate.util.NamingHelper] Bound name: java:/WMSPrototype/Hibernate2J2EE
INFO [net.sf.hibernate.impl.SessionFactoryObjectFactory] Bound factory to JNDI name: java:/WMSPrototype/Hibernate2J2EE
WARN [net.sf.hibernate.impl.SessionFactoryObjectFactory] InitialContext did not implement EventContext
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] instantiated session factory
DEBUG [net.sf.hibernate.impl.SessionFactoryImpl] obtaining JTA TransactionManager
INFO [net.sf.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
INFO [org.jboss.ejb.plugins.StatelessSessionInstancePool] Started jboss.j2ee:jndiName=WMS/Sorter,plugin=pool,service=EJB
INFO [org.jboss.ejb.StatelessSessionContainer] Started jboss.j2ee:jndiName=WMS/Sorter,service=EJB
INFO [org.jboss.ejb.plugins.StatefulSessionInstancePool] Started jboss.j2ee:jndiName=WMS/PutAway,plugin=pool,service=EJB
INFO [org.jboss.ejb.plugins.StatefulSessionFilePersistenceManager] Started null
INFO [org.jboss.ejb.StatefulSessionContainer] Started jboss.j2ee:jndiName=WMS/PutAway,service=EJB
INFO [org.jboss.ejb.plugins.StatelessSessionInstancePool] Started jboss.j2ee:jndiName=WMS/OrderPlanning,plugin=pool,service=EJB
INFO [org.jboss.ejb.StatelessSessionContainer] Started jboss.j2ee:jndiName=WMS/OrderPlanning,service=EJB
INFO [org.jboss.ejb.EjbModule] Started jboss.j2ee:module=wmsprototype.jar,service=EjbModule
INFO [org.jboss.ejb.EJBDeployer] Deployed: file:/D:/opt/jboss-3.2.3/server/default/tmp/deploy/tmp53867WMSPrototype4jboss.ear-contents/wmsprototype.jar
INFO [org.jboss.deployment.EARDeployer] Started J2EE application: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.MainDeployer] Deployed package: file:/D:/opt/jboss-3.2.3/server/default/deploy/WMSPrototype4jboss.ear
INFO [org.jboss.deployment.scanner.URLDeploymentScanner] Started jboss.deployment:type=DeploymentScanner,flavor=URL
INFO [org.jboss.deployment.MainDeployer] Deployed package: file:/D:/opt/jboss-3.2.3/server/default/conf/jboss-service.xml
INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel) [3.2.3 (build: CVSTag=JBoss_3_2_3 date=200311301445)] Started in 1m:12s:956ms
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] JNDI lookup: WMSPrototype/Hibernate2J2EE
DEBUG [net.sf.hibernate.impl.SessionFactoryObjectFactory] lookup: uid=05131cbcfb77b93e00fb77b949010000
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-4-1-32-7]
DEBUG [net.sf.hibernate.hql.QueryTranslator] compiling query
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-4-1-32-7' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '68413' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 68413
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 68413
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#68413
DEBUG [net.sf.hibernate.type.StringType] returning '1-4-1-32-7' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 68413
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache mis for 10000316
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Container as container where containerNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [10000316]
DEBUG [net.sf.hibernate.hql.QueryTranslator] compiling query
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#68413], was: [com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-4-1-32-7, containers=uninitialized, id=68413}
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Container as container where containerNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_, container0_.containerNo as containe2_, container0_.IDLOCATION as IDLOCATION from CONTAINER container0_ where (containerNo=? )

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '316' as column: IDCONTAI1_
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_
DEBUG [net.sf.hibernate.type.IntegerType] returning '68566' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#68566]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#68413], was: [com.vanderlande.lsg.entity.Location.containers#68413]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Container{items=uninitialized, location=Location#68413, containerNo=10000316, id=316}
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-4-1-32-7, containers=uninitialized, id=68413}
DEBUG [net.sf.hibernate.impl.SessionImpl] executing flush
DEBUG [net.sf.hibernate.persister.EntityPersister] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
INFO [STDOUT] Hibernate: update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.persister.EntityPersister] Dehydrating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.type.IntegerType] binding '68413' to parameter: 2
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 3
DEBUG [net.sf.hibernate.impl.BatcherImpl] Adding to batch
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating: 316
DEBUG [net.sf.hibernate.impl.BatcherImpl] Executing batch size: 1
DEBUG [net.sf.hibernate.impl.BatcherImpl] success of batch update unknown: 0
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.impl.SessionImpl] post flush
DEBUG [net.sf.hibernate.impl.SessionImpl] closing session
DEBUG [net.sf.hibernate.impl.SessionImpl] disconnecting session
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction before completion callback
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction after completion callback, status: 3
DEBUG [net.sf.hibernate.impl.SessionImpl] transaction completion
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating (again): 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: Cannot remove entry as key 316 was not found
DEBUG [net.sf.hibernate.impl.SessionImpl] running Session.finalize()
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-3-1-21-23]
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-3-1-21-23' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '62943' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 62943
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 62943
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#62943
DEBUG [net.sf.hibernate.type.StringType] returning '1-3-1-21-23' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 62943
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache hit for 10000316 oid=316 using load
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] attempting to resolve [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache lookup: 316
DEBUG [net.sf.ehcache.hibernate.Plugin] key: 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: MemoryStore miss for 316
DEBUG [net.sf.ehcache.Cache] com.vanderlande.lsg.entity.Container cache - Miss
DEBUG [net.sf.ehcache.hibernate.Plugin] Element for 316 is null
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache miss
DEBUG [net.sf.hibernate.impl.SessionImpl] object not resolved in any cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.persister.EntityPersister] Materializing entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_0_
DEBUG [net.sf.hibernate.type.IntegerType] returning '68413' as column: IDLOCATION0_
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#68413]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#62943], was: [com.vanderlande.lsg.entity.Location.containers#62943]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
DEBUG [net.sf.hibernate.impl.Printer] listing entities:
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Container{items=uninitialized, location=Location#62943, containerNo=10000316, id=316}
DEBUG [net.sf.hibernate.impl.Printer] com.vanderlande.lsg.entity.Location{locationNo=1-3-1-21-23, containers=uninitialized, id=62943}
DEBUG [net.sf.hibernate.impl.SessionImpl] executing flush
DEBUG [net.sf.hibernate.persister.EntityPersister] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
INFO [STDOUT] Hibernate: update CONTAINER set containerNo=?, IDLOCATION=? where IDCONTAINER=?
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.persister.EntityPersister] Dehydrating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.type.StringType] binding '10000316' to parameter: 1
DEBUG [net.sf.hibernate.type.IntegerType] binding '62943' to parameter: 2
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 3
DEBUG [net.sf.hibernate.impl.BatcherImpl] Adding to batch
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating: 316
DEBUG [net.sf.hibernate.impl.BatcherImpl] Executing batch size: 1
DEBUG [net.sf.hibernate.impl.BatcherImpl] success of batch update unknown: 0
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.impl.SessionImpl] post flush
DEBUG [net.sf.hibernate.impl.SessionImpl] closing session
DEBUG [net.sf.hibernate.impl.SessionImpl] disconnecting session
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction before completion callback
DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction after completion callback, status: 3
DEBUG [net.sf.hibernate.impl.SessionImpl] transaction completion
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Invalidating (again): 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: Cannot remove entry as key 316 was not found
DEBUG [net.sf.hibernate.impl.SessionImpl] opened session
DEBUG [net.sf.hibernate.impl.SessionImpl] find: from Location as location where locationNo=?
DEBUG [net.sf.hibernate.engine.QueryParameters] parameters: [1-5-2-15-16]
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Scheduling collection removes/(re)creates/updates
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Dont need to execute flush
DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: from com.vanderlande.lsg.entity.Location as location where locationNo=?
DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
INFO [STDOUT] Hibernate: select location0_.IDLOCATION as IDLOCATION, location0_.locationNo as locationNo from LOCATION location0_ where (locationNo=? )
DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.StringType] binding '1-5-2-15-16' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.type.IntegerType] returning '75780' as column: IDLOCATION
DEBUG [net.sf.hibernate.loader.Loader] result row: 75780
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 75780
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Location#75780
DEBUG [net.sf.hibernate.type.StringType] returning '1-5-2-15-16' as column: locationNo
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Location.containers#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 75780
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Location#75780]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
INFO [STDOUT] cache hit for 10000316 oid=316 using load
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] attempting to resolve [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache lookup: 316
DEBUG [net.sf.ehcache.hibernate.Plugin] key: 316
DEBUG [net.sf.ehcache.store.MemoryStore] com.vanderlande.lsg.entity.ContainerCache: MemoryStore miss for 316
DEBUG [net.sf.ehcache.Cache] com.vanderlande.lsg.entity.Container cache - Miss
DEBUG [net.sf.ehcache.hibernate.Plugin] Element for 316 is null
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Cache miss
DEBUG [net.sf.hibernate.impl.SessionImpl] object not resolved in any cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.persister.EntityPersister] Materializing entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.SQL] select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

INFO [STDOUT] Hibernate: select container0_.IDCONTAINER as IDCONTAI1_0_, container0_.containerNo as containe2_0_, container0_.IDLOCATION as IDLOCATION0_ from CONTAINER container0_ where container0_.IDCONTAINER=?

DEBUG [net.sf.hibernate.impl.BatcherImpl] preparing statement
DEBUG [net.sf.hibernate.type.IntegerType] binding '316' to parameter: 1
DEBUG [net.sf.hibernate.loader.Loader] processing result set
DEBUG [net.sf.hibernate.loader.Loader] result row: 316
DEBUG [net.sf.hibernate.loader.Loader] Initializing object from ResultSet: 316
DEBUG [net.sf.hibernate.loader.Loader] Hydrating entity: com.vanderlande.lsg.entity.Container#316
DEBUG [net.sf.hibernate.type.StringType] returning '10000316' as column: containe2_0_
DEBUG [net.sf.hibernate.type.IntegerType] returning '62943' as column: IDLOCATION0_
DEBUG [net.sf.hibernate.loader.Loader] done processing result set (1 rows)
DEBUG [net.sf.hibernate.impl.BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG [net.sf.hibernate.impl.BatcherImpl] closing statement
DEBUG [net.sf.hibernate.loader.Loader] total objects hydrated: 1
DEBUG [net.sf.hibernate.impl.SessionImpl] resolving associations for [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] creating collection wrapper:[com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] loading [com.vanderlande.lsg.entity.Location#62943]
DEBUG [net.sf.hibernate.impl.SessionImpl] adding entity to second-level cache [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.cache.ReadWriteCache] Caching: 316
DEBUG [net.sf.hibernate.impl.SessionImpl] done materializing entity [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] initializing non-lazy collections
DEBUG [net.sf.hibernate.impl.SessionImpl] flushing session
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Location.containers
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Location
DEBUG [net.sf.hibernate.engine.Cascades] processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.engine.Cascades] cascading to collection: com.vanderlande.lsg.entity.Container.items
DEBUG [net.sf.hibernate.engine.Cascades] done processing cascades for: com.vanderlande.lsg.entity.Container
DEBUG [net.sf.hibernate.impl.SessionImpl] Flushing entities and processing referenced collections
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Location.containers#75780], was: [com.vanderlande.lsg.entity.Location.containers#75780]
DEBUG [net.sf.hibernate.persister.AbstractEntityPersister] com.vanderlande.lsg.entity.Container.location is dirty
DEBUG [net.sf.hibernate.impl.SessionImpl] Updating entity: [com.vanderlande.lsg.entity.Container#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Collection found: [com.vanderlande.lsg.entity.Container.items#316], was: [com.vanderlande.lsg.entity.Container.items#316]
DEBUG [net.sf.hibernate.impl.SessionImpl] Processing unreferenced collectio

Hibernate of course uses the first and second level cache if you load() an object, if not, you haven't turned on caching properly. Please cut your log traces to a minimum, no one will read it otherwise.