Hi Hui,
Thanks for your reply.
Connecting through ip does not seem to make a difference.
Increasing the log level indeed yields a lot more info (mostly sql database and serialization logging) but this does not really help me to trace the actual problem with auto-connect.
Our core implementation of the IGetConnectorInfoHandler interface looks like this:
response.setName("XXX");
response.setDescription("YYY");
response.setBrand("ZZZ");
response.setIcon(IconCreator.createDiskIcon());
Our core implementation of the IConnectHandler interface looks like this:
String username = request.getUserName();
String password = request.getUserPassword();
URI uri = request.getUri();
String uuid = "http://" + uri.getAuthority() + uri.getPath();
_factory.connect(uuid, username, password);
response.setCapabilities(getCapabilities());
response.setUuid(uuid);
response.setStateChecker(new StateChecker());
In the connect method, we connect to our web services using Axis2.
Please let me know if anything looks wrong here or if you happen to have any other tips to debug the issue.
Below is the trace logging obtained when autoconnect fails.
2011/10/10 08:47:11,908 [AutoMounter] DEBUG SessionImpl - opened session at timestamp: 5399466933895168
2011/10/10 08:47:11,909 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server)
2011/10/10 08:47:11,910 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,910 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server)
2011/10/10 08:47:11,910 [AutoMounter] DEBUG HQLQueryPlan - find: from Server
2011/10/10 08:47:11,911 [AutoMounter] DEBUG QueryParameters - named parameters: {}
2011/10/10 08:47:11,913 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,913 [AutoMounter] DEBUG ConnectionManager - opening JDBC connection
2011/10/10 08:47:11,913 [AutoMounter] DEBUG DriverManagerConnectionProvider - total checked-out connections: 0
2011/10/10 08:47:11,913 [AutoMounter] DEBUG DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
2011/10/10 08:47:11,913 [AutoMounter] DEBUG SQL - select server0_.id as id2_, server0_.generation as generation2_, server0_.name as name2_, server0_.version as version2_, server0_.url as url2_, server0_.userInputUrl as userInpu6_2_, server0_.guid as guid2_, server0_.local as local2_, server0_.autoMounted as autoMoun9_2_, server0_.enableOfflineEditing as enableO10_2_, server0_.isOfflineEditing as isOffli11_2_, server0_.transitionState as transit12_2_ from Server server0_
2011/10/10 08:47:11,913 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,914 [AutoMounter] DEBUG AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011/10/10 08:47:11,914 [AutoMounter] DEBUG Loader - processing result set
2011/10/10 08:47:11,914 [AutoMounter] DEBUG Loader - result set row: 0
2011/10/10 08:47:11,914 [AutoMounter] DEBUG IntegerType - returning '2003' as column: id2_
2011/10/10 08:47:11,915 [AutoMounter] DEBUG Loader - result row: EntityKey[com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,916 [AutoMounter] DEBUG Loader - Initializing object from ResultSet: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,918 [AutoMounter] DEBUG AbstractEntityPersister - Hydrating entity: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,918 [AutoMounter] DEBUG IntegerType - returning '3' as column: generation2_
2011/10/10 08:47:11,918 [AutoMounter] DEBUG StringType - returning 'ADAMDB' as column: name2_
2011/10/10 08:47:11,918 [AutoMounter] DEBUG StringType - returning '4.6' as column: version2_
2011/10/10 08:47:11,919 [AutoMounter] DEBUG SerializationHelper - Starting deserialization of object
2011/10/10 08:47:11,920 [AutoMounter] DEBUG SerializationHelper - Attempting to locate class [java.net.URI]
2011/10/10 08:47:11,920 [AutoMounter] DEBUG SerializationHelper - Class resolved through context class loader
2011/10/10 08:47:11,923 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,924 [AutoMounter] DEBUG SerializableType - returning '2c6d8085f3f2808ceae1f6e1aeeee5f4aed5d2c92c81f8aec31ec92b838081cc8086f3f4f2e9eee7f48092cc eae1f6e1afece1eee7afd3f4f2e9eee7bbf8f0f480a0e1e4e1edbaafafb1b0aeb0aeb0aeb1b9b1bab8b0afc3d3 c3efeeeee5e3f4eff2f8' as column: url2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG StringType - returning '10.0.0.191:80/CSConnector' as column: userInpu6_2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG StringType - returning 'http://10.0.0.191:80/CSConnector' as column: guid2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG BooleanType - returning 'false' as column: local2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG BooleanType - returning 'true' as column: autoMoun9_2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG BooleanType - returning 'false' as column: enableO10_2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG BooleanType - returning 'false' as column: isOffli11_2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG StringType - returning '' as column: transit12_2_
2011/10/10 08:47:11,924 [AutoMounter] DEBUG TwoPhaseLoad - Version: 3
2011/10/10 08:47:11,924 [AutoMounter] DEBUG Loader - done processing result set (1 rows)
2011/10/10 08:47:11,925 [AutoMounter] DEBUG AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011/10/10 08:47:11,925 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,925 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,925 [AutoMounter] DEBUG Loader - total objects hydrated: 1
2011/10/10 08:47:11,925 [AutoMounter] DEBUG TwoPhaseLoad - resolving associations for [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,927 [AutoMounter] DEBUG LoadContexts - creating collection wrapper:[com.adobe.drive.data.internal.model.Server.mountpoints#2003]
2011/10/10 08:47:11,930 [AutoMounter] DEBUG TwoPhaseLoad - adding entity to second-level cache: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,930 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,931 [AutoMounter] DEBUG EhCache - key: com.adobe.drive.data.internal.model.Server#2003
2011/10/10 08:47:11,931 [AutoMounter] DEBUG MemoryStore - com.adobe.drive.data.internal.model.ServerCache: com.adobe.drive.data.internal.model.ServerMemoryStore miss for com.adobe.drive.data.internal.model.Server#2003
2011/10/10 08:47:11,931 [AutoMounter] DEBUG Cache - com.adobe.drive.data.internal.model.Server cache - Miss
2011/10/10 08:47:11,931 [AutoMounter] DEBUG EhCache - Element for com.adobe.drive.data.internal.model.Server#2003 is null
2011/10/10 08:47:11,933 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,933 [AutoMounter] DEBUG SerializationHelper - Starting deserialization of object
2011/10/10 08:47:11,933 [AutoMounter] DEBUG SerializationHelper - Attempting to locate class [java.net.URI]
2011/10/10 08:47:11,933 [AutoMounter] DEBUG SerializationHelper - Class resolved through context class loader
2011/10/10 08:47:11,933 [AutoMounter] DEBUG TwoPhaseLoad - done materializing entity [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,933 [AutoMounter] DEBUG StatefulPersistenceContext - initializing non-lazy collections
2011/10/10 08:47:11,933 [AutoMounter] DEBUG JDBCContext - after autocommit
2011/10/10 08:47:11,933 [AutoMounter] DEBUG ConnectionManager - aggressively releasing JDBC connection
2011/10/10 08:47:11,933 [AutoMounter] DEBUG ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011/10/10 08:47:11,933 [AutoMounter] DEBUG DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2011/10/10 08:47:11,933 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,942 [AutoMounter] DEBUG SessionImpl - closing session
2011/10/10 08:47:11,943 [AutoMounter] DEBUG ConnectionManager - connection already null in cleanup : no action
2011/10/10 08:47:11,944 [AutoMounter] DEBUG SessionImpl - opened session at timestamp: 5399466934042624
2011/10/10 08:47:11,944 [AutoMounter] DEBUG SessionImpl - opened session at timestamp: 5399466934042625
2011/10/10 08:47:11,946 [AutoMounter] DEBUG JDBCTransaction - begin
2011/10/10 08:47:11,946 [AutoMounter] DEBUG ConnectionManager - opening JDBC connection
2011/10/10 08:47:11,946 [AutoMounter] DEBUG DriverManagerConnectionProvider - total checked-out connections: 0
2011/10/10 08:47:11,946 [AutoMounter] DEBUG DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
2011/10/10 08:47:11,946 [AutoMounter] DEBUG JDBCTransaction - current autocommit status: false
2011/10/10 08:47:11,946 [AutoMounter] DEBUG JDBCContext - after transaction begin
2011/10/10 08:47:11,946 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server where guid = :guid)
2011/10/10 08:47:11,946 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,946 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server where guid = :guid)
2011/10/10 08:47:11,946 [AutoMounter] DEBUG HQLQueryPlan - find: from Server where guid = :guid
2011/10/10 08:47:11,946 [AutoMounter] DEBUG QueryParameters - named parameters: {guid=http://10.0.0.191:80/CSConnector}
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SQL - select server0_.id as id2_, server0_.generation as generation2_, server0_.name as name2_, server0_.version as version2_, server0_.url as url2_, server0_.userInputUrl as userInpu6_2_, server0_.guid as guid2_, server0_.local as local2_, server0_.autoMounted as autoMoun9_2_, server0_.enableOfflineEditing as enableO10_2_, server0_.isOfflineEditing as isOffli11_2_, server0_.transitionState as transit12_2_ from Server server0_ where server0_.guid=?
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - binding 'http://10.0.0.191:80/CSConnector' to parameter: 1
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - processing result set
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - result set row: 0
2011/10/10 08:47:11,947 [AutoMounter] DEBUG IntegerType - returning '2003' as column: id2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - result row: EntityKey[com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - Initializing object from ResultSet: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractEntityPersister - Hydrating entity: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG IntegerType - returning '3' as column: generation2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - returning 'ADAMDB' as column: name2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - returning '4.6' as column: version2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Starting deserialization of object
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Attempting to locate class [java.net.URI]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Class resolved through context class loader
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializableType - returning '2c6d8085f3f2808ceae1f6e1aeeee5f4aed5d2c92c81f8aec31ec92b838081cc8086f3f4f2e9eee7f48092cc eae1f6e1afece1eee7afd3f4f2e9eee7bbf8f0f480a0e1e4e1edbaafafb1b0aeb0aeb0aeb1b9b1bab8b0afc3d3 c3efeeeee5e3f4eff2f8' as column: url2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - returning '10.0.0.191:80/CSConnector' as column: userInpu6_2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - returning 'http://10.0.0.191:80/CSConnector' as column: guid2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG BooleanType - returning 'false' as column: local2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG BooleanType - returning 'true' as column: autoMoun9_2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG BooleanType - returning 'false' as column: enableO10_2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG BooleanType - returning 'false' as column: isOffli11_2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StringType - returning '' as column: transit12_2_
2011/10/10 08:47:11,947 [AutoMounter] DEBUG TwoPhaseLoad - Version: 3
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - done processing result set (1 rows)
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,947 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,947 [AutoMounter] DEBUG Loader - total objects hydrated: 1
2011/10/10 08:47:11,947 [AutoMounter] DEBUG TwoPhaseLoad - resolving associations for [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG LoadContexts - creating collection wrapper:[com.adobe.drive.data.internal.model.Server.mountpoints#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG TwoPhaseLoad - adding entity to second-level cache: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG EhCache - key: com.adobe.drive.data.internal.model.Server#2003
2011/10/10 08:47:11,947 [AutoMounter] DEBUG MemoryStore - com.adobe.drive.data.internal.model.ServerCache: com.adobe.drive.data.internal.model.ServerMemoryStore hit for com.adobe.drive.data.internal.model.Server#2003
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Starting serialization of object [adam://10.0.0.191:80/CSConnector]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Starting deserialization of object
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Attempting to locate class [java.net.URI]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SerializationHelper - Class resolved through context class loader
2011/10/10 08:47:11,947 [AutoMounter] DEBUG TwoPhaseLoad - done materializing entity [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,947 [AutoMounter] DEBUG StatefulPersistenceContext - initializing non-lazy collections
2011/10/10 08:47:11,947 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,948 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server where guid = :guid)
2011/10/10 08:47:11,948 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,948 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (from Server where guid = :guid)
2011/10/10 08:47:11,949 [AutoMounter] DEBUG Cascade - processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,949 [AutoMounter] DEBUG Cascade - cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,949 [AutoMounter] DEBUG Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,949 [AutoMounter] DEBUG Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,952 [AutoMounter] DEBUG Collections - Collection found: [com.adobe.drive.data.internal.model.Server.mountpoints#2003], was: [com.adobe.drive.data.internal.model.Server.mountpoints#2003] (uninitialized)
2011/10/10 08:47:11,952 [AutoMounter] DEBUG DefaultAutoFlushEventListener - Dont need to execute flush
2011/10/10 08:47:11,952 [AutoMounter] DEBUG HQLQueryPlan - find: from Server where guid = :guid
2011/10/10 08:47:11,952 [AutoMounter] DEBUG QueryParameters - named parameters: {guid=http://10.0.0.191:80/CSConnector}
2011/10/10 08:47:11,952 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,952 [AutoMounter] DEBUG SQL - select server0_.id as id2_, server0_.generation as generation2_, server0_.name as name2_, server0_.version as version2_, server0_.url as url2_, server0_.userInputUrl as userInpu6_2_, server0_.guid as guid2_, server0_.local as local2_, server0_.autoMounted as autoMoun9_2_, server0_.enableOfflineEditing as enableO10_2_, server0_.isOfflineEditing as isOffli11_2_, server0_.transitionState as transit12_2_ from Server server0_ where server0_.guid=?
2011/10/10 08:47:11,952 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,952 [AutoMounter] DEBUG StringType - binding 'http://10.0.0.191:80/CSConnector' to parameter: 1
2011/10/10 08:47:11,952 [AutoMounter] DEBUG AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011/10/10 08:47:11,952 [AutoMounter] DEBUG Loader - processing result set
2011/10/10 08:47:11,952 [AutoMounter] DEBUG Loader - result set row: 0
2011/10/10 08:47:11,952 [AutoMounter] DEBUG IntegerType - returning '2003' as column: id2_
2011/10/10 08:47:11,952 [AutoMounter] DEBUG Loader - result row: EntityKey[com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - done processing result set (1 rows)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - total objects hydrated: 0
2011/10/10 08:47:11,953 [AutoMounter] DEBUG StatefulPersistenceContext - initializing non-lazy collections
2011/10/10 08:47:11,953 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,953 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (
from MountPoint where server.guid = :serverGuid and username = :username
)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,953 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (
from MountPoint where server.guid = :serverGuid and username = :username
)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Cascade - processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Cascade - cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Collections - Collection found: [com.adobe.drive.data.internal.model.Server.mountpoints#2003], was: [com.adobe.drive.data.internal.model.Server.mountpoints#2003] (uninitialized)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG DefaultAutoFlushEventListener - Dont need to execute flush
2011/10/10 08:47:11,953 [AutoMounter] DEBUG HQLQueryPlan - find:
from MountPoint where server.guid = :serverGuid and username = :username
2011/10/10 08:47:11,953 [AutoMounter] DEBUG QueryParameters - named parameters: {username=administrator, serverGuid=http://10.0.0.191:80/CSConnector}
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG SQL - select mountpoint0_.id as id9_, mountpoint0_.generation as generation9_, mountpoint0_.localPath as localPath9_, mountpoint0_.username as username9_, mountpoint0_.active as active9_, mountpoint0_.serverId as serverId9_ from MountPoint mountpoint0_, Server server1_ where mountpoint0_.serverId=server1_.id and server1_.guid=? and mountpoint0_.username=?
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,953 [AutoMounter] DEBUG StringType - binding 'http://10.0.0.191:80/CSConnector' to parameter: 1
2011/10/10 08:47:11,953 [AutoMounter] DEBUG StringType - binding 'administrator' to parameter: 2
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - processing result set
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - result set row: 0
2011/10/10 08:47:11,953 [AutoMounter] DEBUG IntegerType - returning '2003' as column: id9_
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - result row: EntityKey[com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,953 [AutoMounter] DEBUG Loader - Initializing object from ResultSet: [com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,953 [AutoMounter] DEBUG AbstractEntityPersister - Hydrating entity: [com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,953 [AutoMounter] DEBUG IntegerType - returning '2' as column: generation9_
2011/10/10 08:47:11,954 [AutoMounter] DEBUG StringType - returning null as column: localPath9_
2011/10/10 08:47:11,954 [AutoMounter] DEBUG StringType - returning 'administrator' as column: username9_
2011/10/10 08:47:11,954 [AutoMounter] DEBUG BooleanType - returning 'false' as column: active9_
2011/10/10 08:47:11,954 [AutoMounter] DEBUG IntegerType - returning '2003' as column: serverId9_
2011/10/10 08:47:11,954 [AutoMounter] DEBUG TwoPhaseLoad - Version: 2
2011/10/10 08:47:11,954 [AutoMounter] DEBUG Loader - done processing result set (1 rows)
2011/10/10 08:47:11,954 [AutoMounter] DEBUG AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011/10/10 08:47:11,954 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,954 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,954 [AutoMounter] DEBUG Loader - total objects hydrated: 1
2011/10/10 08:47:11,954 [AutoMounter] DEBUG TwoPhaseLoad - resolving associations for [com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,954 [AutoMounter] DEBUG DefaultLoadEventListener - loading entity: [com.adobe.drive.data.internal.model.Server#2003]
2011/10/10 08:47:11,954 [AutoMounter] DEBUG DefaultLoadEventListener - entity found in session cache
2011/10/10 08:47:11,954 [AutoMounter] DEBUG TwoPhaseLoad - adding entity to second-level cache: [com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,955 [AutoMounter] DEBUG EhCache - key: com.adobe.drive.data.internal.model.MountPoint#2003
2011/10/10 08:47:11,955 [AutoMounter] DEBUG MemoryStore - com.adobe.drive.data.internal.model.MountPointCache: com.adobe.drive.data.internal.model.MountPointMemoryStore miss for com.adobe.drive.data.internal.model.MountPoint#2003
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Cache - com.adobe.drive.data.internal.model.MountPoint cache - Miss
2011/10/10 08:47:11,955 [AutoMounter] DEBUG EhCache - Element for com.adobe.drive.data.internal.model.MountPoint#2003 is null
2011/10/10 08:47:11,955 [AutoMounter] DEBUG TwoPhaseLoad - done materializing entity [com.adobe.drive.data.internal.model.MountPoint#2003]
2011/10/10 08:47:11,955 [AutoMounter] DEBUG StatefulPersistenceContext - initializing non-lazy collections
2011/10/10 08:47:11,955 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,955 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (
from Asset where vnode.mountPointId = :mountPointId and visibility = :visibility
)
2011/10/10 08:47:11,955 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,955 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (
from Asset where vnode.mountPointId = :mountPointId and visibility = :visibility
)
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Cascade - processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Cascade - cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,955 [AutoMounter] DEBUG Collections - Collection found: [com.adobe.drive.data.internal.model.Server.mountpoints#2003], was: [com.adobe.drive.data.internal.model.Server.mountpoints#2003] (uninitialized)
2011/10/10 08:47:11,955 [AutoMounter] DEBUG DefaultAutoFlushEventListener - Dont need to execute flush
2011/10/10 08:47:11,955 [AutoMounter] DEBUG HQLQueryPlan - find:
from Asset where vnode.mountPointId = :mountPointId and visibility = :visibility
2011/10/10 08:47:11,955 [AutoMounter] DEBUG QueryParameters - named parameters: {visibility=SAFESAVE_PENDING, mountPointId=2003}
2011/10/10 08:47:11,955 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,955 [AutoMounter] DEBUG SQL - select asset0_.id as id12_, asset0_.generation as generation12_, asset0_.remoteId as remoteId12_, asset0_.remoteType as remoteType12_, asset0_.projectId as projectId12_, asset0_.type as type12_, asset0_.name as name12_, asset0_.nameHash as nameHash12_, asset0_.creationTime as creatio10_12_, asset0_.modificationTime as modific11_12_, asset0_.reference as reference12_, asset0_.visibility as visibility12_, asset0_.isProtected as isProte14_12_, asset0_.localBasicETag as localBa15_12_, asset0_.localPropertiesETag as localPr16_12_, asset0_.localVersionsETag as localVe17_12_, asset0_.localContentETag as localCo18_12_, asset0_.remoteBasicETag as remoteB19_12_, asset0_.remotePropertiesETag as remoteP20_12_, asset0_.remoteVersionsETag as remoteV21_12_, asset0_.remoteContentETag as remoteC22_12_, asset0_.parentId as parentId12_, asset0_.linkedAssetId as linkedA24_12_, asset0_.headVersionId as headVer25_12_, asset0_.workingCopyId as working26_12_, asset0_.lockId as lockId12_, asset0_.infotext as infotext12_, asset0_.shared as shared12_, asset0_.rootContainerId as rootCon30_12_, asset0_.unionType as unionType12_ from Asset asset0_, VNode vnode1_ where asset0_.id=vnode1_.assetId and vnode1_.mountPointId=? and asset0_.visibility=?
2011/10/10 08:47:11,955 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,956 [AutoMounter] DEBUG IntegerType - binding '2003' to parameter: 1
2011/10/10 08:47:11,956 [AutoMounter] DEBUG AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011/10/10 08:47:11,956 [AutoMounter] DEBUG Loader - processing result set
2011/10/10 08:47:11,956 [AutoMounter] DEBUG Loader - done processing result set (0 rows)
2011/10/10 08:47:11,956 [AutoMounter] DEBUG AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011/10/10 08:47:11,956 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,956 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,956 [AutoMounter] DEBUG Loader - total objects hydrated: 0
2011/10/10 08:47:11,956 [AutoMounter] DEBUG StatefulPersistenceContext - initializing non-lazy collections
2011/10/10 08:47:11,956 [AutoMounter] DEBUG SessionImpl - setting flush mode to: AUTO
2011/10/10 08:47:11,956 [AutoMounter] DEBUG QueryPlanCache - unable to locate HQL query plan in cache; generating (UPDATE Asset SET localContentETag = NULL WHERE id IN (SELECT asset FROM VNode WHERE mountPointId =2003))
2011/10/10 08:47:11,957 [AutoMounter] DEBUG QueryTranslatorImpl - parse() - HQL: UPDATE com.adobe.drive.data.internal.model.Asset SET localContentETag = NULL WHERE id IN (SELECT asset FROM com.adobe.drive.data.internal.model.VNode WHERE mountPointId =2003)
2011/10/10 08:47:11,958 [AutoMounter] DEBUG AST - --- HQL AST ---
\-[UPDATE] 'UPDATE'
+-[FROM] 'FROM'
| \-[RANGE] 'RANGE'
| \-[DOT] '.'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[IDENT] 'com'
| | | | | | \-[IDENT] 'adobe'
| | | | | \-[IDENT] 'drive'
| | | | \-[IDENT] 'data'
| | | \-[IDENT] 'internal'
| | \-[IDENT] 'model'
| \-[IDENT] 'Asset'
+-[SET] 'SET'
| \-[EQ] '='
| +-[IDENT] 'localContentETag'
| \-[NULL] 'NULL'
\-[WHERE] 'WHERE'
\-[IN] 'in'
+-[IDENT] 'id'
\-[IN_LIST] 'inList'
\-[QUERY] 'query'
+-[SELECT_FROM] 'SELECT_FROM'
| +-[FROM] 'FROM'
| | \-[RANGE] 'RANGE'
| | \-[DOT] '.'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[DOT] '.'
| | | | | | | +-[IDENT] 'com'
| | | | | | | \-[IDENT] 'adobe'
| | | | | | \-[IDENT] 'drive'
| | | | | \-[IDENT] 'data'
| | | | \-[IDENT] 'internal'
| | | \-[IDENT] 'model'
| | \-[IDENT] 'VNode'
| \-[SELECT] 'SELECT'
| \-[IDENT] 'asset'
\-[WHERE] 'WHERE'
\-[EQ] '='
+-[IDENT] 'mountPointId'
\-[NUM_INT] '2003'
2011/10/10 08:47:11,958 [AutoMounter] DEBUG ErrorCounter - throwQueryException() : no errors
2011/10/10 08:47:11,959 [AutoMounter] DEBUG HqlSqlBaseWalker - update << begin [level=1, statement=update]
2011/10/10 08:47:11,959 [AutoMounter] DEBUG FromElement - FromClause{level=1} : com.adobe.drive.data.internal.model.Asset (no alias) -> asset0_
2011/10/10 08:47:11,959 [AutoMounter] DEBUG HqlSqlWalker - attempting to resolve property [localContentETag] as a non-qualified ref
2011/10/10 08:47:11,959 [AutoMounter] DEBUG HqlSqlWalker - attempting to resolve property [id] as a non-qualified ref
2011/10/10 08:47:11,959 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias} -> {synthetic-alias}
2011/10/10 08:47:11,959 [AutoMounter] DEBUG FromElement - handling property dereference [com.adobe.drive.data.internal.model.Asset (null) -> id (class)]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG DotNode - getDataType() : id -> org.hibernate.type.IntegerType@9c22ff
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromElementType - Using non-qualified column reference [id -> ([id])]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias}.id -> id
2011/10/10 08:47:11,960 [AutoMounter] DEBUG HqlSqlBaseWalker - select << begin [level=2, statement=update]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromElement - FromClause{level=2} : com.adobe.drive.data.internal.model.VNode (no alias) -> vnode1_
2011/10/10 08:47:11,960 [AutoMounter] DEBUG HqlSqlWalker - attempting to resolve property [asset] as a non-qualified ref
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias} -> {synthetic-alias}
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromElement - handling property dereference [com.adobe.drive.data.internal.model.VNode (null) -> asset (class)]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG DotNode - getDataType() : asset -> org.hibernate.type.ManyToOneType(com.adobe.drive.data.internal.model.Asset)
2011/10/10 08:47:11,960 [AutoMounter] DEBUG DotNode - dereferenceShortcut() : property asset in com.adobe.drive.data.internal.model.VNode does not require a join.
2011/10/10 08:47:11,960 [AutoMounter] DEBUG DotNode - terminal propertyPath = [asset]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias}.asset -> vnode1_.assetId
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromElement - handling property dereference [com.adobe.drive.data.internal.model.VNode (null) -> asset (class)]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG HqlSqlWalker - attempting to resolve property [mountPointId] as a non-qualified ref
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias} -> {synthetic-alias}
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromElement - handling property dereference [com.adobe.drive.data.internal.model.VNode (null) -> mountPointId (class)]
2011/10/10 08:47:11,960 [AutoMounter] DEBUG DotNode - getDataType() : mountPointId -> org.hibernate.type.IntegerType@9c22ff
2011/10/10 08:47:11,960 [AutoMounter] DEBUG FromReferenceNode - Resolved : {synthetic-alias}.mountPointId -> vnode1_.mountPointId
2011/10/10 08:47:11,960 [AutoMounter] DEBUG HqlSqlBaseWalker - select : finishing up [level=2, statement=update]
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HqlSqlWalker - processQuery() : ( SELECT ( {select clause} ( vnode1_.assetId {synthetic-alias} asset ) ) ( FromClause{level=2} VNode vnode1_ ) ( WHERE ( = ( vnode1_.mountPointId {synthetic-alias} mountPointId ) 2003 ) ) )
2011/10/10 08:47:11,961 [AutoMounter] DEBUG JoinProcessor - Using FROM fragment [VNode vnode1_]
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HqlSqlBaseWalker - select >> end [level=2, statement=update]
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HqlSqlBaseWalker - update : finishing up [level=1, statement=update]
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HqlSqlBaseWalker - update >> end [level=1, statement=update]
2011/10/10 08:47:11,961 [AutoMounter] DEBUG AST - --- SQL AST ---
\-[UPDATE] UpdateStatement: 'UPDATE' querySpaces (VNode,Asset)
+-[FROM] FromClause: 'FROM' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[asset0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'Asset' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=Asset,tableAlias=asset0_,origin=null,colum s={,className=com.adobe.drive.data.internal.model.Asset}}
+-[SET] SqlNode: 'SET'
| \-[EQ] BinaryLogicOperatorNode: '='
| +-[IDENT] IdentNode: 'localContentETag' {originalText=localContentETag}
| \-[NULL] SqlNode: 'NULL'
\-[WHERE] SqlNode: 'WHERE'
\-[IN] InLogicOperatorNode: 'in'
+-[DOT] DotNode: 'id' {propertyName=id,dereferenceType=4,propertyPath=id,path={synthetic-alias}.id,tableAlias=a sset0_,className=com.adobe.drive.data.internal.model.Asset,classAlias=null}
| +-[IDENT] IdentNode: '{synthetic-alias}' {originalText={synthetic-alias}}
| \-[IDENT] IdentNode: 'id' {originalText=id}
\-[IN_LIST] SqlNode: 'inList'
\-[SELECT] QueryNode: 'SELECT' querySpaces (VNode,Asset)
+-[SELECT_CLAUSE] SelectClause: '{select clause}'
| \-[DOT] DotNode: 'vnode1_.assetId' {propertyName=asset,dereferenceType=ROOT_LEVEL,propertyPath=asset,path={synthetic-alias}. asset,tableAlias=vnode1_,className=com.adobe.drive.data.internal.model.VNode,classAlias=nu ll}
| +-[IDENT] IdentNode: '{synthetic-alias}' {originalText={synthetic-alias}}
| \-[IDENT] IdentNode: 'asset' {originalText=asset}
+-[FROM] FromClause: 'FROM' FromClause{level=2, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[vnode1_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'VNode vnode1_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=VNode,tableAlias=vnode1_,origin=null,colum s={,className=com.adobe.drive.data.internal.model.VNode}}
\-[WHERE] SqlNode: 'WHERE'
\-[EQ] BinaryLogicOperatorNode: '='
+-[DOT] DotNode: 'vnode1_.mountPointId' {propertyName=mountPointId,dereferenceType=4,propertyPath=mountPointId,path={synthetic-al ias}.mountPointId,tableAlias=vnode1_,className=com.adobe.drive.data.internal.model.VNode,c lassAlias=null}
| +-[IDENT] IdentNode: '{synthetic-alias}' {originalText={synthetic-alias}}
| \-[IDENT] IdentNode: 'mountPointId' {originalText=mountPointId}
\-[NUM_INT] LiteralNode: '2003'
2011/10/10 08:47:11,961 [AutoMounter] DEBUG ErrorCounter - throwQueryException() : no errors
2011/10/10 08:47:11,961 [AutoMounter] DEBUG ErrorCounter - throwQueryException() : no errors
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HQLQueryPlan - HQL param location recognition took 0 mills (UPDATE Asset SET localContentETag = NULL WHERE id IN (SELECT asset FROM VNode WHERE mountPointId =2003))
2011/10/10 08:47:11,961 [AutoMounter] DEBUG QueryPlanCache - located HQL query plan in cache (UPDATE Asset SET localContentETag = NULL WHERE id IN (SELECT asset FROM VNode WHERE mountPointId =2003))
2011/10/10 08:47:11,961 [AutoMounter] DEBUG Cascade - processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,961 [AutoMounter] DEBUG Cascade - cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,961 [AutoMounter] DEBUG Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.adobe.drive.data.internal.model.Server.mountpoints
2011/10/10 08:47:11,961 [AutoMounter] DEBUG Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.adobe.drive.data.internal.model.Server
2011/10/10 08:47:11,961 [AutoMounter] DEBUG Collections - Collection found: [com.adobe.drive.data.internal.model.Server.mountpoints#2003], was: [com.adobe.drive.data.internal.model.Server.mountpoints#2003] (uninitialized)
2011/10/10 08:47:11,961 [AutoMounter] DEBUG DefaultAutoFlushEventListener - Dont need to execute flush
2011/10/10 08:47:11,961 [AutoMounter] DEBUG HQLQueryPlan - executeUpdate: UPDATE Asset SET localContentETag = NULL WHERE id IN (SELECT asset FROM VNode WHERE mountPointId =2003)
2011/10/10 08:47:11,961 [AutoMounter] DEBUG QueryParameters - named parameters: {}
2011/10/10 08:47:11,961 [AutoMounter] DEBUG SessionFactoryImpl - evicting second-level cache: com.adobe.drive.data.internal.model.Asset
2011/10/10 08:47:11,962 [AutoMounter] DEBUG AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011/10/10 08:47:11,962 [AutoMounter] DEBUG SQL - update Asset set localContentETag=null where id in (select vnode1_.assetId from VNode vnode1_ where vnode1_.mountPointId=2003)
2011/10/10 08:47:11,962 [AutoMounter] DEBUG AbstractBatcher - preparing statement
2011/10/10 08:47:11,963 [AutoMounter] DEBUG AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011/10/10 08:47:11,963 [AutoMounter] DEBUG AbstractBatcher - closing statement
2011/10/10 08:47:11,964 [AutoMounter] DEBUG JDBCTransaction - rollback
2011/10/10 08:47:11,965 [AutoMounter] DEBUG JDBCTransaction - rolled back JDBC Connection
2011/10/10 08:47:11,965 [AutoMounter] DEBUG JDBCContext - after transaction completion
2011/10/10 08:47:11,965 [AutoMounter] DEBUG ConnectionManager - aggressively releasing JDBC connection
2011/10/10 08:47:11,965 [AutoMounter] DEBUG ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011/10/10 08:47:11,965 [AutoMounter] DEBUG DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2011/10/10 08:47:11,965 [AutoMounter] DEBUG SessionImpl - after transaction completion
2011/10/10 08:47:11,965 [AutoMounter] DEBUG SessionFactoryImpl - evicting second-level cache: com.adobe.drive.data.internal.model.Asset
2011/10/10 08:47:11,965 [AutoMounter] DEBUG UpdateTimestampsCache - Invalidating space [Asset], timestamp: 5399466934128640
2011/10/10 08:47:11,966 [AutoMounter] DEBUG SessionImpl - closing session
2011/10/10 08:47:11,966 [AutoMounter] DEBUG ConnectionManager - connection already null in cleanup : no action
2011/10/10 08:47:11,966 [AutoMounter] ERROR AutoMounter - Failed to mount server ADAMDB