6 Replies Latest reply on Oct 17, 2011 1:05 AM by hverlinde

    Auto-connect does not work

    hverlinde
    hverlinde Oct 5, 2011 5:36 AM

      When we enable the option "Automatically connect to this server when computer starts" for our custom connector, the server consistently fails to automount after restart (Windows).

      This must be a problem in our connector since the automount feature does seem to work when using the CMIS connector.

      However we do not understand why automount fails why manually mounting the same drive succeeds.

       

      At first we thought that this could be because the automount starts while certain other required services are not running yet.

      But we can also reproduce the problem when running the command "C:\Program Files (x86)\Common Files\Adobe\CS5ServiceManager\CS5ServiceManager.exe -launchedbylogin" from the command line some time after starting up.

      What exactly is the difference between running this command and mounting a server manually through Adobe Drive?

       

      Where should we start looking for possible causes for this issue?

      Can we obtain any kind of additional logging? From the log file it seems that our custom connector handlers are never called but maybe logging is disabled during auto-connect?

      Can we debug this somehow? When we start the CS5ServiceManager with the "launchedbylogin" option it seems the eclipse workspace is not used.

       

      Thanks in advance for any help you could provide.

       

      Logging for auto-connect:

       

      2011/10/05 14:25:52,686 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: store_credentials

      2011/10/05 14:25:52,688 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: retrieve_credentials

      2011/10/05 14:25:52,688 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: delete_credentials

      2011/10/05 14:25:52,689 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: authenticate

      2011/10/05 14:25:52,690 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: logout

      2011/10/05 14:25:52,691 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: update_extensions

      2011/10/05 14:25:52,698 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: store_preference

      2011/10/05 14:25:52,699 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: retrieve_preference

      2011/10/05 14:25:52,700 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: delete_preference

      2011/10/05 14:25:57,581 [Component Resolve Thread (Bundle 3)] WARN  PersistenceService - {activate} Mapping not found: 'OSGI-INF/mapping.xml' in bundle 'com.adobe.csi.core'

      2011/10/05 14:25:57,581 [Component Resolve Thread (Bundle 3)] WARN  PersistenceService - {activate} Mapping not found: 'OSGI-INF/queries.xml' in bundle 'com.adobe.csi.core'

      2011/10/05 14:25:58,616 [Component Resolve Thread (Bundle 3)] INFO  ContentCache - Cache location set to: C:\Users\Hannes\AppData\Roaming\Adobe\CS5ServiceManager\diskcache

      2011/10/05 14:25:58,644 [Component Resolve Thread (Bundle 3)] INFO  AutoMountService - Starting automatically mounting servers

      2011/10/05 14:25:58,645 [AutoMounter] INFO  AutoMounter - Automounting servers

      2011/10/05 14:25:58,708 [AutoMounter] ERROR AutoMounter - Failed to mount server ADAMTEST

      2011/10/05 14:25:59,111 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_add_server

      2011/10/05 14:25:59,114 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_browse_servers

      2011/10/05 14:25:59,117 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_check_network_connectivity

      2011/10/05 14:25:59,120 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_empty_cache

      2011/10/05 14:25:59,123 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_explore_servers

      2011/10/05 14:25:59,125 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_messages

      2011/10/05 14:25:59,129 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_preferences

      2011/10/05 14:25:59,132 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_service_info

      2011/10/05 14:25:59,135 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_mount_server

      2011/10/05 14:25:59,141 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_move_cache

      2011/10/05 14:25:59,144 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_move_cache_status

      2011/10/05 14:25:59,146 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_open_volume

      2011/10/05 14:25:59,149 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_remove_server

      2011/10/05 14:25:59,151 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_save_preferences

      2011/10/05 14:25:59,153 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_unmount_server

      2011/10/05 14:25:59,155 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_verify_server

      2011/10/05 14:25:59,158 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_prepare_migration

      2011/10/05 14:25:59,160 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_do_migration

      2011/10/05 14:25:59,162 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_check_migration_status

      2011/10/05 14:25:59,165 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_pause_migration

      2011/10/05 14:25:59,167 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_continue_migration

      2011/10/05 14:25:59,170 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_cancel_migration

      2011/10/05 14:25:59,173 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_PrefPath

      2011/10/05 14:25:59,176 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_connectors_info

      2011/10/05 14:25:59,179 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_work_offline

      2011/10/05 14:25:59,182 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_work_online

      2011/10/05 14:25:59,187 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_set_transition_state

      2011/10/05 14:25:59,189 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_offline_work

      2011/10/05 14:25:59,192 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_is_offline_work_conflict

      2011/10/05 14:25:59,194 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_conflict_resolve

      • 1396 Views
      • Tags:
        • 1. Re: Auto-connect does not work
          Lee Hui Level 2
          Lee Hui Oct 8, 2011 2:51 AM (in response to hverlinde)

          To view more log info, please change the settings of log4j.xml in the CS5ServiceManager configuration folder:

          • Win32: C:\Program Files\Common Files\Adobe\CS5ServiceManager\configuration
          • Win64: C:\Program Files (x86)\Common Files\Adobe\CS5ServiceManager\configuration
          • Mac OS X: /Library/Application Support/Adobe/CS5ServiceManager/configuration

           

          I suggest you to do a test with the url like: http://192.168.35.25:8080. (Use ip address to connect your server)

           

          Could you share your rough implementation for IGetServerInfoHandler and IConnectHanlder?

          • 2. Re: Auto-connect does not work
            hverlinde Level 1
            hverlinde Oct 10, 2011 12:03 AM (in response to Lee Hui)

            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

            • 3. Re: Auto-connect does not work
              Lee Hui Level 2
              Lee Hui Oct 10, 2011 12:29 AM (in response to hverlinde)

              I think you need to set logging level to DEBUG for certain packages, not for all. For example, only log packages starting with 'com.adobe'.

               

              Please check IGetConnectionDetails and IConnectHandler. They both set UUID info. Please make sure they have the same values for a certain server.

              • 4. Re: Auto-connect does not work
                hverlinde Level 1
                hverlinde Oct 14, 2011 6:15 AM (in response to Lee Hui)

                Our implementation of the IGetConnectionDetailsHandler interface always sets the exact same UUID as the implementation of the IConnectHandler interface.

                 

                Do you have any idea why we get logging from our own connector (e.g. "DEBUG ConnectHandler - IN") when we connect through the Drive UI but not when we run the autoconnect command?

                Does this mean that our handlers are never called by Drive during autoconnect? Would this imply that the problem is not in our client code?

                 

                 

                With only "com.adobe" (and our own package namespace) set to DEBUG level, we get the following log during autoconnect:

                 

                2011/10/14 15:01:15,096 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: store_credentials

                2011/10/14 15:01:15,141 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: retrieve_credentials

                2011/10/14 15:01:15,144 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: delete_credentials

                2011/10/14 15:01:15,146 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: authenticate

                2011/10/14 15:01:15,148 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: logout

                2011/10/14 15:01:15,150 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: update_extensions

                2011/10/14 15:01:15,172 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: store_preference

                2011/10/14 15:01:15,175 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: retrieve_preference

                2011/10/14 15:01:15,178 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: delete_preference

                2011/10/14 15:01:19,536 [Component Resolve Thread (Bundle 3)] WARN  PersistenceService - {activate} Mapping not found: 'OSGI-INF/mapping.xml' in bundle 'com.adobe.csi.core'

                2011/10/14 15:01:19,536 [Component Resolve Thread (Bundle 3)] WARN  PersistenceService - {activate} Mapping not found: 'OSGI-INF/queries.xml' in bundle 'com.adobe.csi.core'

                2011/10/14 15:01:22,636 [Component Resolve Thread (Bundle 3)] INFO  ContentCache - Cache location set to: C:\Users\Hannes\AppData\Roaming\Adobe\CS5ServiceManager\diskcache

                2011/10/14 15:01:22,653 [Component Resolve Thread (Bundle 3)] INFO  AutoMountService - Starting automatically mounting servers

                2011/10/14 15:01:22,654 [AutoMounter] INFO  AutoMounter - Automounting servers

                2011/10/14 15:01:23,226 [AutoMounter] ERROR AutoMounter - Failed to mount server ADAMTEST

                2011/10/14 15:01:24,165 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_add_server

                2011/10/14 15:01:24,167 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_browse_servers

                2011/10/14 15:01:24,169 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_check_network_connectivity

                2011/10/14 15:01:24,171 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_empty_cache

                2011/10/14 15:01:24,173 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_explore_servers

                2011/10/14 15:01:24,175 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_messages

                2011/10/14 15:01:24,178 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_preferences

                2011/10/14 15:01:24,180 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_service_info

                2011/10/14 15:01:24,182 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_mount_server

                2011/10/14 15:01:24,188 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_move_cache

                2011/10/14 15:01:24,190 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_move_cache_status

                2011/10/14 15:01:24,192 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_open_volume

                2011/10/14 15:01:24,195 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_remove_server

                2011/10/14 15:01:24,197 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_save_preferences

                2011/10/14 15:01:24,199 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_unmount_server

                2011/10/14 15:01:24,201 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_verify_server

                2011/10/14 15:01:24,203 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_prepare_migration

                2011/10/14 15:01:24,205 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_do_migration

                2011/10/14 15:01:24,208 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_check_migration_status

                2011/10/14 15:01:24,210 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_pause_migration

                2011/10/14 15:01:24,212 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_continue_migration

                2011/10/14 15:01:24,214 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_cancel_migration

                2011/10/14 15:01:24,217 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_PrefPath

                2011/10/14 15:01:24,219 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_connectors_info

                2011/10/14 15:01:24,221 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_work_offline

                2011/10/14 15:01:24,223 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_work_online

                2011/10/14 15:01:24,226 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_set_transition_state

                2011/10/14 15:01:24,228 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_get_offline_work

                2011/10/14 15:01:24,230 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_is_offline_work_conflict

                2011/10/14 15:01:24,232 [Component Resolve Thread (Bundle 3)] INFO  InvokeHandler - Added ServiceReference for: ad_conflict_resolve

                • 5. Re: Auto-connect does not work
                  Lee Hui Level 2
                  Lee Hui Oct 15, 2011 2:07 AM (in response to hverlinde)

                  For your first question, my concern is about UUID. You said they are same for the implementation of the IGetConnectionDetailsHandler and IConnectHandler. Have you printed out that two values? Hope you can help to double confirm it.

                  For the second question, yes. Your ConnectHandler is not invoked by Adobe Drive if that log is not printed out. I guess Adobe Drive fails to get your server info via UUID.

                  For the third question, no. Because your other connector handlers implementation may affect it. You issue can help us to improve our code/documentation. In order to figure out this issue, could you send the following folders(including subfolders and subfiles) to my mail box(huli@adobe.com):

                  • C:\Users\{user name}\AppData\Roaming\Adobe\CS5ServiceManager\database
                  • C:\Users\{user name}\AppData\Roaming\Adobe\CS5ServiceManager\logs

                   

                  Thanks,

                  Hui

                  1 person found this helpful
                  • 6. Re: Auto-connect does not work
                    hverlinde Level 1
                    hverlinde Oct 17, 2011 1:05 AM (in response to Lee Hui)

                    Hi Hui,

                     

                    Basically, the code related to UUID looks like this in IConnectHandler:

                     

                    response.setUuid(uuid);

                    _factory.setUuid(uuid);

                     

                    And in IGetConnectionDetailsHandler, we use the following code:

                     

                    response.setUuid(_factory.getUuid());

                     

                    So yes, I am positive that we use the same UUID value in all handlers.

                     

                    I sent you the requested folders through email.

                    We really appreciate your help in trying to identify the problem.

                     

                    Hannes