BugMakers :)

Frankly speaking, when I was writing previous blogpost I got surprised to discover that DQL update statement preserves the value of r_lock_owner attribute:

API> revert,c,09024be98006b104
...
OK
API> get,c,09024be98006b104,r_lock_owner
...
dmadmin
API> ?,c,update dm_document objects set object_name='xxx' where r_object_id='09024be98006b104'
objects_updated
---------------
              1
(1 row affected)
[DM_QUERY_I_NUM_UPDATE]info:  "1 objects were affected by your UPDATE statement."


API> revert,c,09024be98006b104
...
OK
API> get,c,09024be98006b104,r_lock_owner
...
dmadmin
API> 

Unfortunately, it is not true when you update objects, which behaviour is customized via TBO:

API> retrieve,c,bs_doc_cash
...
09bc2c71806d6ffe
API> checkout,c,l
...
09bc2c71806d6ffe
API> ?,c,update bs_doc_cash objects set object_name='xxx' where r_object_id='09bc2c71806d6ffe'
objects_updated
---------------
              1
(1 row affected)
[DM_QUERY_I_NUM_UPDATE]info:  "1 objects were affected by your UPDATE statement."


API> revert,c,09bc2c71806d6ffe
...
OK
API> get,c,09bc2c71806d6ffe,r_lock_owner
...

API>

but:

API> checkout,c,09bc2c71806d6ffe
...
09bc2c71806d6ffe
API> apply,c,,EXEC,QUERY,S,update bs_doc_cash objects set object_name='xxx' where r_object_id='09bc2c71806d6ffe',BOF_DQL,B,F
...
q0
API> next,c,q0
...
OK
API> dump,c,q0
...
USER ATTRIBUTES

  objects_updated                 : 1

SYSTEM ATTRIBUTES


APPLICATION ATTRIBUTES


INTERNAL ATTRIBUTES


API> revert,c,09bc2c71806d6ffe
...
OK
API> get,c,09bc2c71806d6ffe,r_lock_owner
...
dmadmin
API> 

Explanation for dfc.diagnostics.resources.enable

It is bit weird, but everybody who previously asked me about session leaks didn’t properly understand the root cause of the problem – the typical question was: we started getting a lot of DM_API_E_NO_SESSION errors, we increased value of concurrent_sessions parameter in server.ini, but this didn’t help. Well, I have written this blogpost in order to shed a light on session leaks in DFC. First of all, you may face with two following errors:

DfServiceException:: THREAD: main; MSG: [DM_SESSION_E_MAX_SESSIONS_EXCEEDED]
  error:  "Maximum number of server sessions exceeded"; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:44)
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:34)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.newSessionByAddr(NetwiseDocbaseRpcClient.java:118)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.beginSession(DocbaseConnection.java:299)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.open(DocbaseConnection.java:130)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.<init>(DocbaseConnection.java:100)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.<init>(DocbaseConnection.java:60)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionFactory.newDocbaseConnection(DocbaseConnectionFactory.java:26)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.createNewConnection(DocbaseConnectionManager.java:180)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:110)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)

and

DfServiceException:: THREAD: main; MSG: [DM_API_E_NO_SESSION]
  error:  "There are no more available sessions."; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getConnectionFromPool(DocbaseConnectionManager.java:168)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:94)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)

The first one (DM_SESSION_E_MAX_SESSIONS_EXCEEDED) means that you are running out of Content Server sessions (concurrent_sessions parameter in server.ini), the second one (DM_API_E_NO_SESSION) means that you are running out of DFC sessions (dfc.session.max_count parameter in dfc.propetries), the problem is both errors may relate to either incorrect sizing or programming mistake. So, before trying to investigate memory leaks you need to eliminate sizing issue – it is might be bit challenging because dumb DFC does not provide any runtime statistics about sessions (recent DFC versions support dfc.connection.profile_connections and dfc.connection.trace_connections_only flags in dfc.properties, these flags cause com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager class to write extra debug information into log files, but I would prefer something more reliable, JMX for example), so, let’s pretend that sizing issue is not our case. What is the next?

Official documentation (DFC Development Guide) states following:

and there are at least two mistakes:

  1. it also logs information about leaks of stream objects, which were created through ISysObjectInternal#getStream method, corresponding log message looks like:
    [Resource Housekeeper] ERROR com.documentum.fc.impl.util.io.InputStreamHandle$DisposableData  - [DFC_STREAM_NOT_CLOSED] Unclosed stream found during garbage collection, com.documentum.fc.client.content.impl.PullerInputStream@28aac04e.
    com.documentum.fc.impl.util.ThrowableStack: Stack when stream was created
    	at com.documentum.fc.client.content.impl.ContentInputStream.<init>(ContentInputStream.java:17)
    	at com.documentum.fc.client.content.impl.PusherPullerContentAccessor.buildStreamFromContext(PusherPullerContentAccessor.java:46)
    	at com.documentum.fc.client.content.impl.PusherPullerContentAccessor.getStream(PusherPullerContentAccessor.java:28)
    	at com.documentum.fc.client.content.impl.ContentAccessorFactory.getStream(ContentAccessorFactory.java:37)
    	at com.documentum.fc.client.content.impl.Store.getStream(Store.java:63)
    	at com.documentum.fc.client.content.impl.FileStore___PROXY.getStream(FileStore___PROXY.java)
    	at com.documentum.fc.client.content.impl.Content.getStream(Content.java:185)
    	at com.documentum.fc.client.content.impl.Content___PROXY.getStream(Content___PROXY.java)
    	at com.documentum.fc.client.content.impl.ContentManager.getStream(ContentManager.java:84)
    	at com.documentum.fc.client.content.impl.ContentManager.getStream(ContentManager.java:53)
    	at com.documentum.fc.client.DfSysObject.getStream(DfSysObject.java:1994)
  2. the last statement is incorrect, correct is: if DFC wasn’t buggy it would place an appropriate message in the log

So, what does happen when we enable dfc.diagnostics.resources.enable? The short answer is: if your code suffers from leaks of transaction sessions DFC replaces them by a memory leak 🙂

Now the long answer. DFC manages following types of sessions:

  • com.documentum.fc.client.impl.session.Session
  • com.documentum.fc.client.impl.session.WeakSessionHandle
  • com.documentum.fc.client.impl.session.StrongSessionHandle
  • com.documentum.fc.client.impl.session.DynamicSessionHandle

the first one is the real/original session, last three are decorators. We typically deal with StrongSessionHandle (IDfSessionManager#getSession) and DynamicSessionHandle (IDfTypedObject#getSession):

@Test
public void test() throws Exception {
    IDfClientX clientX = new DfClientX();
    IDfClient client = clientX.getLocalClient();
    IDfSessionManager sessionManager = client.newSessionManager();
    IDfLoginInfo loginInfo = clientX.getLoginInfo();
    loginInfo.setUser("dmadmin");
    loginInfo.setPassword("dmadmin");
    sessionManager.setIdentity("DCTM_DEV", loginInfo);
    IDfSession session = sessionManager.getSession("DCTM_DEV");
    System.out.println("session managers return "
            + session.getClass().getName());
    IDfSysObject object = (IDfSysObject) session
            .getObjectByQualification("dm_document");
    System.out.println("typed objects store "
            + object.getSession().getClass().getName());
    sessionManager.release(session);
    sessionManager.flushSessions();
    System.out.println("we may use dynamic session handles "
            + "even if original session was released");
    object.getString("object_name");
    object.save();
    System.out.println("we may not use strong session handles "
            + "if it was released");
    object = (IDfSysObject) session.getObjectByQualification("dm_document");
}

session managers return com.documentum.fc.client.impl.session.StrongSessionHandle
typed objects store com.documentum.fc.client.impl.session.DynamicSessionHandle
we may use dynamic session handles even if original session was released
we may not use strong session handles if it was released

com.documentum.fc.common.DfRuntimeException: Using session handle that has already been released

	at com.documentum.fc.client.impl.session.StrongSessionHandle.referenceSession(StrongSessionHandle.java:64)
	at com.documentum.fc.client.impl.session.SessionHandle.referenceScopableSession(SessionHandle.java:74)
	at com.documentum.fc.client.impl.session.SessionHandle.getObjectByQualification(SessionHandle.java:752)

And when we enable dfc.diagnostics.resources.enable DFC starts keeping track of StrongSessionHandle instances, i.e. if instance of StrongSessionHandle class wasn’t properly released DFC logs corresponding error. How would you implement such functionality? Actually the implementation is pretty straightforward – we need to know circumstances under which our object was constructed, in order to do that we save construction stack into object and log that stack in finalize() method, something like:

public class FinalizationDemo {

    private final boolean _diagnosticsEnabled = true;

    @Test
    public void test() throws Exception {
        try {
            while (true) {
                IResource resource = getResource();
            }
        } catch (OutOfMemoryError error) {
            error.printStackTrace();
            System.exit(1);
        }
    }

    private IResource getResource() {
        return new Resource();
    }

    interface IResource extends Closeable {

        boolean isClosed();

    }

    class Resource implements IResource {

        private boolean _closed;

        private Throwable _construction;

        private final byte[] data = new byte[1000 * 100];

        public Resource() {
            if (_diagnosticsEnabled) {
                _construction = new Exception();
            }
        }

        @Override
        public void close() throws IOException {
            System.out.println("Closed");
            _closed = true;
            _construction = null;
        }

        @Override
        public boolean isClosed() {
            return _closed;
        }

        @Override
        protected void finalize() throws Throwable {
            if (_construction != null && !isClosed()) {
                _construction.printStackTrace();
            }
        }
    }

}

ECD’s implementation is different – instead of using finalizers they use weak references, moreover before logging error message they try to cleanup resources (such behaviour suffers from side effects described in previous post) and their code looks like:

public class DisposableDemo {

    private final ReferenceQueue<WeakReference> _queue = new ReferenceQueue<>();
    private final Map<Reference, IDisposable> _data = Collections
            .synchronizedMap(new IdentityHashMap<Reference, IDisposable>());

    private final boolean _diagnosticsEnabled = true;

    public DisposableDemo() {
        Thread thread = new Thread(new DisposingTask());
        thread.setPriority(Thread.MAX_PRIORITY);
        thread.start();
    }

    class DisposingTask implements Runnable {
        @Override
        public void run() {
            try {
                Reference reference;
                while ((reference = _queue.remove()) != null) {
                    IDisposable disposable = _data.remove(reference);
                    if (disposable == null) {
                        continue;
                    }
                    try {
                        disposable.dispose();
                    } catch (IOException ex) {
                        ex.printStackTrace();
                    }
                }
            } catch (InterruptedException ex) {
                Thread.currentThread().interrupt();
            }
        }
    }

    private void register(Object resource, IDisposable disposable) {
        WeakReference reference = new WeakReference(resource, _queue);
        _data.put(reference, disposable);
    }

    @Test
    public void test() throws Exception {
        try {
            while (true) {
                IResource resource = getResource();
                // System.gc();
            }
        } catch (OutOfMemoryError error) {
            error.printStackTrace();
            System.exit(1);
        }
    }

    private IResource getResource() {
        IResource resource = new Resource();
        ResourceDecorator decorator = new ResourceDecorator(resource);
        if (_diagnosticsEnabled) {
            register(decorator, decorator._disposable);
        }
        return decorator;
    }

    interface IDisposable {

        void dispose() throws IOException;

    }

    interface IResource extends Closeable {

        boolean isClosed();

    }

    class Resource implements IResource {

        private boolean _closed;

        private final byte[] data = new byte[1000 * 100];

        @Override
        public void close() throws IOException {
            System.out.println("Closed");
            _closed = true;
        }

        @Override
        public boolean isClosed() {
            return _closed;
        }

    }

    class ResourceDecorator implements IResource {

        private final IResource _resource;

        private final IDisposable _disposable;

        public ResourceDecorator(IResource resource) {
            _resource = resource;
            if (_diagnosticsEnabled) {
                _disposable = new Disposable(_resource);
            } else {
                _disposable = null;
            }
        }

        @Override
        public void close() throws IOException {
            _resource.close();
        }

        @Override
        public boolean isClosed() {
            return _resource.isClosed();
        }
    }

    // !!! must not refer to ResourceDecorator
    static class Disposable implements IDisposable {

        private IResource _resource;

        private final Throwable _construction;

        public Disposable(IResource resource) {
            _resource = resource;
            _construction = new Exception();
        }

        @Override
        public void dispose() throws IOException {
            if (!_resource.isClosed()) {
                // closing resource
                _resource.close();
                // log construction stacktrace
                _construction.printStackTrace();
            }
        }

    }

}

Side effects of dfc.diagnostics.resources.enable

Assuming that I set correct credentials and we do know how to set dfc preferences in runtime, what does code below print?

@Test
public void test() throws Exception {
    int count = 0;
    try {
        DfPreferences preferences = DfPreferences.getInstance();
        preferences.loadProperty(DfPreferences.DFC_SESSION_MAX_COUNT, 50);
        while (++count > 0) {
            IDfClientX clientX = new DfClientX();
            IDfClient client = clientX.getLocalClient();
            IDfSessionManager sessionManager = client.newSessionManager();
            IDfLoginInfo loginInfo = clientX.getLoginInfo();
            loginInfo.setUser("dmadmin");
            loginInfo.setPassword("dmadmin");
            sessionManager.setIdentity("DCTM_DEV", loginInfo);
            IDfSession session = sessionManager.getSession("DCTM_DEV");
        }
    } finally {
        System.out.println("Session count: " + count);
    }
}

Actually, the answer is obvious – that buggy code creates 50 sessions and fails:

Session count: 50

DfServiceException:: THREAD: main; MSG: [DM_API_E_NO_SESSION]error:  "There are no more available sessions."
; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getConnectionFromPool(DocbaseConnectionManager.java:168)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:94)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)
	at SessionDemo.test(SessionDemo.java:30)

Now, less obvious code:

@Test
public void test() throws Exception {
    int count = 0;
    try {
        DfPreferences preferences = DfPreferences.getInstance();
        preferences.loadProperty(DfPreferences.DFC_SESSION_MAX_COUNT, 50);
        preferences.loadProperty(DfPreferences.DFC_DIAGNOSTICS_RESOURCES_ENABLE, true);
        while (++count > 0) {
            IDfClientX clientX = new DfClientX();
            IDfClient client = clientX.getLocalClient();
            IDfSessionManager sessionManager = client.newSessionManager();
            IDfLoginInfo loginInfo = clientX.getLoginInfo();
            loginInfo.setUser("dmadmin");
            loginInfo.setPassword("dmadmin");
            sessionManager.setIdentity("DCTM_DEV", loginInfo);
            IDfSession session = sessionManager.getSession("DCTM_DEV");
        }
    } finally {
        System.out.println("Session count: " + count);
    }
}

the result is bit confusing – code creates more than 50 sessions and fails:

...
25586 [Resource Housekeeper] ERROR com.documentum.fc.client.impl.session.StrongSessionHandle$DisposableData  - [DFC_SESSION_NOT_RELEASED] Unreleased session found during garbage collection, Session{id=29, iid=29, serial=1, docbase=DCTM_DEV, user=dmadmin, serversession=none}
com.documentum.fc.impl.util.ThrowableStack: Stack when session was obtained
	at SessionDemo.test(SessionDemo.java:31)
...

Session count: 94

DfServiceException:: THREAD: main; MSG: [DM_API_E_NO_SESSION]error:  "There are no more available sessions."
; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getConnectionFromPool(DocbaseConnectionManager.java:168)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:94)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)
	at SessionDemo.test(SessionDemo.java:31)

another code:

@Test
public void test() throws Exception {
    int count = 0;
    try {
        DfPreferences preferences = DfPreferences.getInstance();
        preferences.loadProperty(DfPreferences.DFC_SESSION_MAX_COUNT, 50);
        preferences.loadProperty(DfPreferences.DFC_DIAGNOSTICS_RESOURCES_ENABLE, true);
        while (++count > 0) {
            IDfClientX clientX = new DfClientX();
            IDfClient client = clientX.getLocalClient();
            IDfSessionManager sessionManager = client.newSessionManager();
            IDfLoginInfo loginInfo = clientX.getLoginInfo();
            loginInfo.setUser("dmadmin");
            loginInfo.setPassword("dmadmin");
            sessionManager.setIdentity("DCTM_DEV", loginInfo);
            IDfSession session = sessionManager.getSession("DCTM_DEV");
            System.gc();
        }
    } finally {
        System.out.println("Session count: " + count);
    }
}

the result is weird – code prints a lot of diagnostics messages but does not fail:

...
115902 [Resource Housekeeper] ERROR com.documentum.fc.client.impl.session.StrongSessionHandle$DisposableData  - [DFC_SESSION_NOT_RELEASED] Unreleased session found during garbage collection, Session{id=1, iid=1207, serial=1, docbase=DCTM_DEV, user=dmadmin, serversession=none}
com.documentum.fc.impl.util.ThrowableStack: Stack when session was obtained
	at SessionDemo.test(SessionDemo.java:31)
...

and the last example:

@Test
public void test() throws Exception {
    int count = 0;
    try {
        DfPreferences preferences = DfPreferences.getInstance();
        preferences.loadProperty(DfPreferences.DFC_SESSION_MAX_COUNT, 50);
        preferences.loadProperty(DfPreferences.DFC_DIAGNOSTICS_RESOURCES_ENABLE, true);
        while (++count > 0) {
            IDfClientX clientX = new DfClientX();
            IDfClient client = clientX.getLocalClient();
            IDfSessionManager sessionManager = client.newSessionManager();
            IDfLoginInfo loginInfo = clientX.getLoginInfo();
            loginInfo.setUser("dmadmin");
            loginInfo.setPassword("dmadmin");
            sessionManager.setIdentity("DCTM_DEV", loginInfo);
            IDfSession session = sessionManager.getSession("DCTM_DEV");
            session.beginTrans();
            System.gc();
        }
    } finally {
        System.out.println("Session count: " + count);
    }
}

result is even more weird – code does not print diagnostic messages and fails:

4964 [Resource Housekeeper] ERROR com.documentum.fc.client.impl.connection.docbase.DocbaseConnection  - Connection put back in pool with transaction active, Connection{id=1, docbase=DCTM_DEV, user=dmadmin, state=FREE}

Session count: 50

DfServiceException:: THREAD: main; MSG: [DM_API_E_NO_SESSION]error:  "There are no more available sessions."
; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getConnectionFromPool(DocbaseConnectionManager.java:168)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:94)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)
	at SessionDemo.test(SessionDemo.java:31)

Corresponding thread dump:

"Resource Housekeeper" #13 daemon prio=10 os_prio=31 tid=0x00007fb78c1bd800 nid=0x5703 in Object.wait() [0x0000700001452000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000006c0dc9828> (a com.documentum.fc.client.impl.connection.docbase.DocbaseConnection)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.waitForCorrectSharingContext(DocbaseConnection.java:820)
	- locked <0x00000006c0dc9828> (a com.documentum.fc.client.impl.connection.docbase.DocbaseConnection)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.evaluateRpc(DocbaseConnection.java:1108)
	- locked <0x00000006c0dc9828> (a com.documentum.fc.client.impl.connection.docbase.DocbaseConnection)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.applyForBool(DocbaseConnection.java:1198)
	- locked <0x00000006c0dc9828> (a com.documentum.fc.client.impl.connection.docbase.DocbaseConnection)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.apply(DocbaseConnection.java:1183)
	at com.documentum.fc.client.impl.docbase.DocbaseApi.endTrans(DocbaseApi.java:1757)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.cleanupFromUnexpectedTransactionState(DocbaseConnection.java:729)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.quiesce(DocbaseConnection.java:663)
	- locked <0x00000006c0dc9828> (a com.documentum.fc.client.impl.connection.docbase.DocbaseConnection)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.returnConnectionToPool(DocbaseConnectionManager.java:663)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.release(DocbaseConnectionManager.java:270)
	at com.documentum.fc.client.impl.session.Session.releaseConnection(Session.java:248)
	at com.documentum.fc.client.impl.session.PooledSessionFactory$SessionListener.onDisconnect(PooledSessionFactory.java:114)
	at com.documentum.fc.client.impl.session.Session.notifyListenersOfDisconnect(Session.java:395)
	at com.documentum.fc.client.impl.session.Session.disconnect(Session.java:312)
	at com.documentum.fc.client.impl.session.Session.decrementReferenceCount(Session.java:3687)
	at com.documentum.fc.client.impl.session.StrongSessionHandle$DisposableData.dispose(StrongSessionHandle.java:127)
	at com.documentum.fc.internal.reshousekeeper.ResourceHousekeeper$1$1.run(ResourceHousekeeper.java:52)

Try to explain results 🙂

Copying version tree. Part II

Wow, Marian Caikovski have found a bug in my old blogpost about copying version tree 🙂 Though it is not clear what “The described method will work even if the root version in the source object has been previously deleted. But the copies will not be entirely valid.” does mean, because I observe the following behaviour:

Connected to Documentum Server running Release 7.3.0000.0214  Linux64.Postgres
Session id is s0
API> create,c,dm_document
...
0902987880002cf1
API> save,c,l
...
OK
API> checkout,c,l
...
0902987880002cf1
API> checkin,c,l
...
0902987880002cfc
API> fetch,c,0902987880002cfc
...
OK
API> checkout,c,l
...
0902987880002cfc
API> checkin,c,l
...
0902987880002cfe
API> destroy,c,0902987880002cf1
...
OK
API> fetch,c,0902987880002cf1
...
OK
API> saveasnew,c,l
...
[DM_SYSOBJECT_E_IS_DELETED]error:  
  "The sysobject '' has been deleted and can not be updated/deleted."

which could be fixed using following trick:

API> set,c,l,i_is_deleted
SET> F   
...
OK
API> saveasnew,c,l
...
0902987880002cf3

The complete code is available on github.

WTF???

I like large deployments because large deployments mean a lot of challenges 🙂 And the new challenge is: ACLs are fucking slow because EMC fails to write fast code. Let’s check how long does it take to create ACL with 60000 accessors on DFC side (I do know that it is not a good idea to create ACLs with more than 32767 accessors, but I like drawing cool charts):

public class DfAclTest extends DfcTestSupport {

    @Test
    public void aclTest() throws Exception {
        IDfSession session = getSession();
        int multiplier = 1000;
        IDfACL acl = (IDfACL) session.newObject("dm_acl");
        System.out.println("\n=========== CREATE ===========");
        long start = System.currentTimeMillis();
        for (int i = 1; i <= 60; i++) {
            grant(acl, (i - 1) * multiplier, multiplier);
            System.out.println("accessors: " + (i * multiplier) + ", time: "
                    + (System.currentTimeMillis() - start));

        }
        System.out.println("\n=========== UPDATE ===========");
        start = System.currentTimeMillis();
        for (int i = 1; i <= 60; i++) {
            grant(acl, (i - 1) * multiplier, multiplier);
            System.out.println("accessors: " + (i * multiplier) + ", time: "
                    + (System.currentTimeMillis() - start));

        }
    }

    private static void grant(IDfACL acl, int offset, int amount)
        throws DfException {
        for (int i = offset; i < amount + offset; i++) {
            acl.grant(String.valueOf(i), 3, null);
        }
    }

}

and results are really impressive:

=========== CREATE ===========
...
accessors: 60000, time: 1155926
...
=========== UPDATE ===========
...
accessors: 60000, time: 3564534

i.e. if we were need to create ACL with 60000 records it would take 20 minutes, if we decided to update each record in that ACL it would take one hour 🙂 I was unable to understand how it was possible to write so slow algorithm and decided to somehow optimize it, fortunately it didn’t take much time – I just changed two methods in com.documentum.fc.client.DfACL:

  1. findEntry – from
    for (int i = 0, limit = getAccessorCount(); i < limit; i++) {
        if (getAccessorPermitType(i) == permitType 
                && getAccessorName(i).equals(accessorName)) {

    to

            int start = findString(ACCESSOR_NAME, accessorName);
            if (start < 0) {
                return  -1;
            }
    
            for (int i = start, limit = getAccessorCount(); i < limit; i++) {
                if (getAccessorName(i).equals(accessorName)
                        && getAccessorPermitType(i) == permitType) {
    
  2. updateAuditTrail to
    return

and got another impressive results.

First optimization only:

=========== CREATE ===========
...
accessors: 60000, time: 456957
...
=========== UPDATE ===========
...
accessors: 60000, time: 537209

First and second optimizations:

=========== CREATE ===========
...
accessors: 60000, time: 136213
...
=========== UPDATE ===========
...
accessors: 60000, time: 131164

Chart:

aspects or not aspects…

Some time ago I wrote a post about no progress in Documentum platform, and the opinion about aspects feature was, I would say, neutral rather than negative, now, after two years of using aspects I can say without doubts: never ever use Documentum aspects, avoid repeating my mistake – EMC’s implementations is completely unreliable and slow. Let’s explain…

At first, I do not want to discuss DFC Aspect Model:

because it hard to imagine situation when you really need to build TBO classes in runtime – EMC tried use this feature in XCP2 and had failed. So, this feature is defective by design, and I would like to talk about additional attributes which we can introduce using aspects.

Well, how does Content Server behave when it fetches aspect-enabled objects? Let’s discover it’s behaviour using previously demonstrated technique (I specially issue two fetches because the first one performs a lot of irrelevant caching queries related to information about types and TBOs):

Connected to Documentum Server running Release 7.2.0030.0195  Linux64.Oracle
Session id is s0
API> apply,c,,SQL_TRACE,SESSION_ID,S,01024be980005db7,LEVEL,I,10
...
q0
API> ?,c,q0
result      
------------
T           
(1 row affected)

API> fetch,c,09024be98001f94e
...
OK
API> fetch,c,09024be98001f94f
...
OK
API> Bye

and the result is:

-- determine object type by r_object_id
SELECT dm_dbalias_B.I_TYPE
  FROM DMI_OBJECT_TYPE dm_dbalias_B
 WHERE dm_dbalias_B.R_OBJECT_ID = :dmb_handle;

-- retrieve object's data from database
  SELECT *
    FROM CUSTOM_TYPE_RV dm_dbalias_B, CUSTOM_TYPE_SV dm_dbalias_C
   WHERE (    dm_dbalias_C.R_OBJECT_ID = :dmb_handle
          AND dm_dbalias_C.R_OBJECT_ID = dm_dbalias_B.R_OBJECT_ID)
ORDER BY dm_dbalias_B.R_OBJECT_ID, dm_dbalias_B.I_POSITION;

-- retrieve aspect's data from database
  SELECT *
    FROM DMI_03024BE98000025B_RV dm_dbalias_B,
         DMI_03024BE98000025B_SV dm_dbalias_C
   WHERE (    dm_dbalias_C.R_OBJECT_ID = :dmb_handle
          AND dm_dbalias_C.R_OBJECT_ID = dm_dbalias_B.R_OBJECT_ID)
ORDER BY dm_dbalias_B.R_OBJECT_ID, dm_dbalias_B.I_POSITION;

-- check whether object is actual or not
SELECT dm_dbalias_B.R_OBJECT_ID
  FROM DM_SYSOBJECT_S dm_dbalias_B
 WHERE (    dm_dbalias_B.R_OBJECT_ID = :dmb_objectp
        AND dm_dbalias_B.I_VSTAMP = :dmb_versionp);

If you compare these queries with queries described in What happens when smart guy does not sit back blogpost you will find that the existence of aspect introduces two new queries, i.e.:

-- retrieve aspect's data from database
  SELECT *
    FROM DMI_03024BE98000025B_RV dm_dbalias_B,
         DMI_03024BE98000025B_SV dm_dbalias_C
   WHERE (    dm_dbalias_C.R_OBJECT_ID = :dmb_handle
          AND dm_dbalias_C.R_OBJECT_ID = dm_dbalias_B.R_OBJECT_ID)
ORDER BY dm_dbalias_B.R_OBJECT_ID, dm_dbalias_B.I_POSITION;

-- check whether object is actual or not
SELECT dm_dbalias_B.R_OBJECT_ID
  FROM DM_SYSOBJECT_S dm_dbalias_B
 WHERE (    dm_dbalias_B.R_OBJECT_ID = :dmb_objectp
        AND dm_dbalias_B.I_VSTAMP = :dmb_versionp);

So, it is obvious that aspects have negative performance impact, what about reliability? Try to guess what is the purpose of the last select statement:

-- check whether object is actual or not
SELECT dm_dbalias_B.R_OBJECT_ID
  FROM DM_SYSOBJECT_S dm_dbalias_B
 WHERE (    dm_dbalias_B.R_OBJECT_ID = :dmb_objectp
        AND dm_dbalias_B.I_VSTAMP = :dmb_versionp);

Though, there is much simpler question – why, when fetching object’s data from database, Content Server issues following statement:

  SELECT *
    FROM CUSTOM_TYPE_RV dm_dbalias_B, CUSTOM_TYPE_SV dm_dbalias_C
   WHERE (    dm_dbalias_C.R_OBJECT_ID = :dmb_handle
          AND dm_dbalias_C.R_OBJECT_ID = dm_dbalias_B.R_OBJECT_ID)
ORDER BY dm_dbalias_B.R_OBJECT_ID, dm_dbalias_B.I_POSITION;

but not two much more simple statements:

  SELECT *
    FROM CUSTOM_TYPE_SV dm_dbalias_C
   WHERE (    dm_dbalias_C.R_OBJECT_ID = :dmb_handle);

  SELECT *
    FROM CUSTOM_TYPE_RV dm_dbalias_B
   WHERE (    dm_dbalias_B.R_OBJECT_ID = :dmb_handle)
ORDER BY dm_dbalias_B.R_OBJECT_ID, dm_dbalias_B.I_POSITION;

?

The clue for the last question is a statement-level read consistency, i.e. in case of single query the result is always consistent, in case of two queries – doesn’t. Now the purpose of the last select statement in aspect example is clear: Content Server successively retrieves object’s data, aspect’s data, and after that Content Server checks whether the object have been changed since the first query or not. And now the most interesting thing: what happens if last select statement returns nothing? Nothing good. It is really hard to reproduce the situation but I have succeeded and wrote following test case:

/**
 * @author Andrey B. Panfilov <andrey@panfilov.tel>
 */
public class DfExceptionsTest extends DfcTestSupport {

    @Test
    @Ignore
    public void testSoftFetch() throws Exception {
        final IDfSession s1 = Sessions.brandNew(getSession()
                .getSessionManager(), getSession().getDocbaseName());
        final IDfSession s2 = Sessions.brandNew(getSession()
                .getSessionManager(), getSession().getDocbaseName());

        TestFetch testFetch = new TestFetch(s2, "09024be98001f94e");
        Thread t = new Thread(testFetch);
        t.start();

        ApplyExecSQL cmd = (ApplyExecSQL) DfAdminCommand
                .getCommand(IDfAdminCommand.APPLY_EXEC_SQL);
        cmd.setQuery("update dm_sysobject_s set i_vstamp=i_vstamp+1 "
                + "where r_object_id='09024be98001f94e'");

        for (int i = 0; i < 10000; i++) {
            cmd.execute(s1);
        }

        t.interrupt();
        assertFalse(testFetch._failed);
    }

    class TestFetch implements Runnable {

        private final IDfSession _session;

        private final String _objectId;

        private boolean _failed;

        public TestFetch(IDfSession session, String objectId) {
            _session = session;
            _objectId = objectId;
        }

        @Override
        public void run() {
            try {
                for (int i = 0; i < 100000; i++) {
                    _session.getObject(DfIdUtil.getId(_objectId));
                    _session.flushObject(DfIdUtil.getId(_objectId));
                }
            } catch (DfException ex) {
                ex.printStackTrace();
                _failed = true;
            }
        }
    }

}

which reproduces two different exceptions:

DfException:: THREAD: Thread-9; MSG: [DM_OBJ_MGR_E_UNABLE_TO_FETCH_CONSISTENT_OBJECT_SNAPSHOT]
   error:  "Unable to fetch object 09024be98001f94e alongwith its aspect attributes with consistency"; ERRORCODE: 100; 
NEXT: null
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:57)
	at com.documentum.fc.client.impl.connection.docbase.MessageEntry.getException(MessageEntry.java:39)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseMessageManager.getException(DocbaseMessageManager.java:137)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.checkForMessages(NetwiseDocbaseRpcClient.java:310)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.applyForObject(NetwiseDocbaseRpcClient.java:653)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection$8.evaluate(DocbaseConnection.java:1380)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.evaluateRpc(DocbaseConnection.java:1139)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.applyForObject(DocbaseConnection.java:1372)
	at com.documentum.fc.client.impl.docbase.DocbaseApi.parameterizedFetch(DocbaseApi.java:107)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.fetchFromServer(PersistentDataManager.java:191)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.getData(PersistentDataManager.java:82)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObjectFromServer(PersistentObjectManager.java:355)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObject(PersistentObjectManager.java:311)
	at com.documentum.fc.client.impl.session.Session.getObject(Session.java:963)
	at com.documentum.fc.client.impl.session.SessionHandle.getObject(SessionHandle.java:653)

and

DfIdNotFoundException:: THREAD: Thread-9; MSG: [DM_API_E_EXIST]
  error:  "Document/object specified by 09024be98001f94e does not exist."; ERRORCODE: 100; 
NEXT: DfException:: THREAD: Thread-9; MSG: [DM_OBJ_MGR_E_UNABLE_TO_FETCH_CONSISTENT_OBJECT_SNAPSHOT]
  error:  "Unable to fetch object 09024be98001f94e alongwith its aspect attributes with consistency"; ERRORCODE: 100; 
NEXT: null
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:49)
	at com.documentum.fc.client.impl.connection.docbase.MessageEntry.getException(MessageEntry.java:39)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseMessageManager.getException(DocbaseMessageManager.java:137)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.checkForMessages(NetwiseDocbaseRpcClient.java:310)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.applyForObject(NetwiseDocbaseRpcClient.java:653)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection$8.evaluate(DocbaseConnection.java:1380)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.evaluateRpc(DocbaseConnection.java:1139)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.applyForObject(DocbaseConnection.java:1372)
	at com.documentum.fc.client.impl.docbase.DocbaseApi.parameterizedFetch(DocbaseApi.java:107)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.fetchFromServer(PersistentDataManager.java:191)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.getData(PersistentDataManager.java:82)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObjectFromServer(PersistentObjectManager.java:355)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObject(PersistentObjectManager.java:311)
	at com.documentum.fc.client.impl.session.Session.getObject(Session.java:963)
	at com.documentum.fc.client.impl.session.SessionHandle.getObject(SessionHandle.java:653)
Caused by: DfException:: THREAD: Thread-9; MSG: [DM_SYSOBJECT_E_CANT_FETCH_INVALID_ID]
  error:  "Cannot fetch a sysobject - Invalid object ID : 09024be98001f94e"; ERRORCODE: 100; 
NEXT: null
	... 19 more
Followed by: DfException:: THREAD: Thread-9; MSG: [DM_OBJ_MGR_E_UNABLE_TO_FETCH_CONSISTENT_OBJECT_SNAPSHOT]
  error:  "Unable to fetch object 09024be98001f94e alongwith its aspect attributes with consistency"; ERRORCODE: 100; 
NEXT: null
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:57)
	at com.documentum.fc.client.impl.connection.docbase.MessageEntry.getException(MessageEntry.java:39)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseMessageManager.getException(DocbaseMessageManager.java:137)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.checkForMessages(NetwiseDocbaseRpcClient.java:310)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.applyForObject(NetwiseDocbaseRpcClient.java:653)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection$8.evaluate(DocbaseConnection.java:1380)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.evaluateRpc(DocbaseConnection.java:1139)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.applyForObject(DocbaseConnection.java:1372)
	at com.documentum.fc.client.impl.docbase.DocbaseApi.parameterizedFetch(DocbaseApi.java:107)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.fetchFromServer(PersistentDataManager.java:191)
	at com.documentum.fc.client.impl.objectmanager.PersistentDataManager.getData(PersistentDataManager.java:82)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObjectFromServer(PersistentObjectManager.java:355)
	at com.documentum.fc.client.impl.objectmanager.PersistentObjectManager.getObject(PersistentObjectManager.java:311)
	at com.documentum.fc.client.impl.session.Session.getObject(Session.java:963)
	at com.documentum.fc.client.impl.session.SessionHandle.getObject(SessionHandle.java:653)

The last one is extremely weird because DFC hides the real error under DfIdNotFoundException. Now let’s check what Content Server thinks about DM_OBJ_MGR_E_UNABLE_TO_FETCH_CONSISTENT_OBJECT_SNAPSHOT error:

SEVERITY: ERROR
DESCRIPTION: D Unable to fetch object %s alongwith its aspect attributes with consistency
CAUSE: This error occurs when a client fetches an object that has aspect attributes, and that either the normal or aspect attributes have changed perhaps by a different session while Content Server was fetching the aspect attributes after fetching the normal attributes from the database.
ACTION: Application should refetch the object.
PARAMS:

Why does the fucking DFC do not reiterate fetch after DM_OBJ_MGR_E_UNABLE_TO_FETCH_CONSISTENT_OBJECT_SNAPSHOT error?

Encryption madness. Part IV

Interesting, dm_crypto_create utility is able to create AES128, AES192 and AES256 encryption keys, note -algorithm argument:

[dmadmin@docu72dev01 ~]$ dm_crypto_create --help
Option --help has no meaning !!
Usage: dm_crypto_db_create [-lockbox <lockbox>] [-lockboxpassphrase [lockboxpassphrase]] 
                           [-keyname <keyname>] [-location <location>] 
                           [-passphrase [passphrase]] [-noprompt] [-move] 
                           [-check] [-algorithm] [-help] 

  -lockbox  - Optional lockbox to store administration key.
  -lockboxpassphrase  - Passphrase for the lockbox.
               Should be specified for a new lockbox.
  -keyname  - Optional name of the administration key to be stored in lockbox.
  -location  - Optional location of the administration key file.
  -passphrase  - Optional passphrase to protect the administration key.
               If not specified a default passphrase will be used.
  -move     - Optional argument to move existing key into lockbox.

  -check     - Optional argument to check for an existing administration key at
               the specified location.

  -algorithm   - Optional argument to specify the algorithm used for generating key.
                Valid values are AES_128_CBC, AES_192_CBC and AES_256_CBC. 
  -noprompt  - Optional flag to not prompt for default passphrase confirmation.
  -help      - Print this help/usage information.

** If -location is not specified, environment variable 
   DM_CRYPTO_FILE or DOCUMENTUM will be used to determine the location.
** -passphrase and -noprompt options are exclusive.

** It is suggested that you specify a passphrase **

but DFC recognises AES128 keys only – AES256 fails with “PBKDF2WithHmacSHA256 SecretKeyFactory not available” error (this factory is available since Java8 only):

 ~]$ dm_crypto_create -location /tmp/aek.key -noprompt -algorithm AES_256_CBC

** Will use default passphrase **



Please wait. This will take a few seconds ...
** Successfully created key store /tmp/aek.key using algorithm AES_256_CBC
[dmadmin@docu72dev01 ~]$ iapi DCTM_DEV
Please enter a user (dmadmin): 
Please enter password for dmadmin: 


        EMC Documentum iapi - Interactive API interface
        (c) Copyright EMC Corp., 1992 - 2015
        All rights reserved.
        Client Library Release 7.2.0030.0072


Connecting to Server using docbase DCTM_DEV
[DM_SESSION_I_SESSION_START]info:  "Session 01024be98000746a started for user dmadmin."


Connected to Documentum Server running Release 7.2.0030.0195  Linux64.Oracle
Session id is s0
API> initcrypto,c,/tmp/aek.key
...
Unexpected problem with key generation: PBKDF2WithHmacSHA256 SecretKeyFactory not available


API> 

AES192 fails with “Unsupported algorithm ID: 4” error:

 ~]$ dm_crypto_create -location /tmp/aek.key -noprompt -algorithm AES_192_CBC

** Will use default passphrase **



Please wait. This will take a few seconds ...
** Successfully created key store /tmp/aek.key using algorithm AES_192_CBC
[dmadmin@docu72dev01 ~]$ iapi DCTM_DEV
Please enter a user (dmadmin): 
Please enter password for dmadmin: 


        EMC Documentum iapi - Interactive API interface
        (c) Copyright EMC Corp., 1992 - 2015
        All rights reserved.
        Client Library Release 7.2.0030.0072


Connecting to Server using docbase DCTM_DEV
[DM_SESSION_I_SESSION_START]info:  "Session 01024be98000746d started for user dmadmin."


Connected to Documentum Server running Release 7.2.0030.0195  Linux64.Oracle
Session id is s0
API> initcrypto,c,/tmp/aek.key
...
Unsupported algorithm ID: 4


API> 

I have checked DFC and found out that EMC made mess not only of encryption algorithm names on CS side – their understanding of cryptography on java side is also extremely poor.