Infrastructure at your Service

Morgan Patou

Documentum – D2 Folder structure import failure with wsctf browser plugin

Earlier today, I talked about the Export/Download that wasn’t working randomly. In the end, it was both linked to the wsctf browser plugin (that didn’t provide the necessary cookies in the download request) as well as the “loadBalancedContentServer” parameter (that was wrongly set to false). For the previous issue, setting the “loadBalancedContentServer” property to true was sufficient to solve it (see more details on the previous blog). For this blog, unfortunately, the issue has a very similar description but the solution applied previously won’t help and I will explain here why.

 

In the same HA environment, using D2 16.5.1 P04, a second error was spotted and that was while using the folder structure import into D2 (Import > Folder structure). At that time, the Export/Download problem was already solved and it was therefore working properly. This new issue could be replicated all the time because I was the only one working on this environment. With less D2 pod or with more users working at the same time, it could potentially work from time to time (if the good conditions are met). Looking at the D2 logs, while the folder structure import is started, showed that the process started properly on the D2 pod I was currently logged into but then a piece of the process ran on another D2 pod and finally a last piece ran on yet another D2 pod. In the end, three different pods were all working on the same import request. The root cause here is also that the wsctf browser plugin doesn’t include the cookies and therefore there is a random distribution of the requests but it fails in the end because of missing files and that’s what I wanted to show here.

 

To understand the below logs, here is the setup and distribution of the Managed Servers of this WebLogic Domain on Kubernetes (each pod = 1 MS):

  • wsd2-0 (replica 0), hosting msD2-00, using -Djava.io.tmpdir=$WS_TMP_FOLDER/msD2-00
  • wsd2-1 (replica 1), hosting msD2-01, using -Djava.io.tmpdir=$WS_TMP_FOLDER/msD2-01
  • wsd2-2 (replica 2), hosting msD2-02, using -Djava.io.tmpdir=$WS_TMP_FOLDER/msD2-02
  • wsd2-3 (replica 3), hosting msD2-03, using -Djava.io.tmpdir=$WS_TMP_FOLDER/msD2-03

 

Below are the logs that were generated for a single folder structure import. I put them in chronological order:

#######
### Logs on 1st D2 pod accessed (currently logged into - wsd2-3)
### Starting the process, filling the properties and clicking on the start import
#######
2020-03-28 16:18:29,096 UTC [INFO ] ([ACTIVE] ExecuteThread: '94' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.p.s.s.dialog.RpcDialogServiceImpl       : Context Repo1-1585412250771-morgan_patou-1788227800 with ID =  and dialogName ImportFolderDialog
...
2020-03-28 16:19:07,317 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d2fs.dctm.api.services.D2ServiceProfile   : Plugins (0.003s)
2020-03-28 16:19:07,386 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.api.services.D2Service      : D2SavePropertiesService - Standard Servlet :
2020-03-28 16:19:07,454 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.d.a.s.p.D2SavePropertiesService         : Object ID = 090f1234809a993f
2020-03-28 16:19:07,474 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.a.c.documentset.D2DocumentSetSwitch     : D2DocumentSetSwitch.getDocumentSetList end: 0.000s
2020-03-28 16:19:07,517 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.a.c.documentset.D2DocumentSetSwitch     : D2DocumentSetSwitch.getDocumentSetList end: 0.000s
2020-03-28 16:19:07,543 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.api.services.D2Service      : D2SavePropertiesService - Result : D2SavePropertiesResult => {}
2020-03-28 16:19:07,544 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.api.services.D2Service      : D2SavePropertiesService - Free memory=481.97684 MB, Total memory=1.0 GB
2020-03-28 16:19:07,544 UTC [INFO ] ([ACTIVE] ExecuteThread: '46' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.api.services.D2Service      : D2SavePropertiesService - END (0.230s) =====================================
2020-03-28 16:19:07,852 UTC [INFO ] ([ACTIVE] ExecuteThread: '54' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.d.w.s.download.D2DownloadService        : Link targets : []


#######
### Logs on 2nd D2 pod accessed (wsd2-1)
### First sub-request (same import)
#######
2020-03-28 16:19:08,040 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.x3.portal.server.X3HttpSessionListener  : Created http session HK9n8dQhE2-WeriIi7UVynZIN7x-v6JQB2ehL7-o33jHyrtvY_g7!785191258!1585412348040
2020-03-28 16:19:08,045 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - START =====================================
2020-03-28 16:19:08,045 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - HTTP Headers
Remote : 10.10.10.10 (10-10-10-10.ingress-nginx.ingress-nginx.svc.cluster.local)
Locale : en_US
Request Protocol : HTTP/1.1
Request Method : POST
Context Path : /D2
Request URI : /D2/servlet/ImportStructure
Request encoding : null
Request Parameters :
        masterId : 090f1234809a993f
        contentId : 0b0f1234809a943e
        strucConf : Default folder structure import
        folder : C:\Users\morgan_patou\Downloads\TestImport
        id : 090f1234809a993f
        _locale : en
        fileName : TestFile.txt
        _username : morgan_patou
        uid : Repo1-1585412250771-morgan_patou-1788227800
        _docbase : Repo1
        _timeZoneId : Europe/Zurich
        last : false
        _password : ********
Request Headers :
        Host : d2.domain.com
        X-Request-ID : c42495cfddb8895ef556d0b9499118a4
        X-Real-IP : 10.10.0.1
        X-Forwarded-For : 10.10.0.1
        X-Forwarded-Host : d2.domain.com
        X-Forwarded-Port : 443
        X-Forwarded-Proto : https
        X-Original-URI : /D2/servlet/ImportStructure
        X-Scheme : https
        Content-Length : 2391
        User-Agent : python-requests/2.21.0
        Accept-Encoding : gzip, deflate
        Accept : application/json
        Content-Type : multipart/form-data; boundary=92fbbeceb4bcc427446e4b4bc363d23
Http Session :
2020-03-28 16:19:08,045 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - Standard Servlet :
2020-03-28 16:19:08,046 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - Free memory=352.96313 MB. Total memory=1.0 GB.
2020-03-28 16:19:08,047 UTC [INFO ] ([ACTIVE] ExecuteThread: '29' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - END (0.006s) =====================================


#######
### Logs on 3rd D2 pod accessed (wsd2-0)
### Second sub-request (same import)
#######
2020-03-28 16:19:08,189 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.x3.portal.server.X3HttpSessionListener  : Created http session KVd0OhIANP6hOsaiqNiyk1btCYB-G3i8eTRjXWOj7ImCqIVnwPyp!-948416399!1585412348189
2020-03-28 16:19:08,198 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - START =====================================
2020-03-28 16:19:08,199 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - HTTP Headers
Remote : 10.10.10.10 (10-10-10-10.ingress-nginx.ingress-nginx.svc.cluster.local)
Locale : en_US
Request Protocol : HTTP/1.1
Request Method : POST
Context Path : /D2
Request URI : /D2/servlet/ImportStructure
Request encoding : null
Request Parameters :
        masterId : 090f1234809a993f
        contentId : 0b0f1234809a943e
        strucConf : Default folder structure import
        folder : C:\Users\morgan_patou\Downloads\TestImport
        id : 090f1234809a993f
        _locale : en
        fileName : import_structure4ga5dgjs.xml
        _username : morgan_patou
        uid : Repo1-1585412250771-morgan_patou-1788227800
        _docbase : Repo1
        _timeZoneId : Europe/Zurich
        last : true
        _password : ********
Request Headers :
        Host : d2.domain.com
        X-Request-ID : 6ef85a137e9e20ccbbd81ddbb6898c6c
        X-Real-IP : 10.10.0.1
        X-Forwarded-For : 10.10.0.1
        X-Forwarded-Host : d2.domain.com
        X-Forwarded-Port : 443
        X-Forwarded-Proto : https
        X-Original-URI : /D2/servlet/ImportStructure
        X-Scheme : https
        Content-Length : 2600
        User-Agent : python-requests/2.21.0
        Accept-Encoding : gzip, deflate
        Accept : application/json
        Content-Type : multipart/form-data; boundary=df774e60a79eb3d3400d05417455cf4e
Http Session :
2020-03-28 16:19:08,199 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - Standard Servlet :
2020-03-28 16:19:09,657 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.a.c.documentset.D2DocumentSetSwitch     : D2DocumentSetSwitch.getDocumentSetList end: 0.001s
2020-03-28 16:19:09,702 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.a.c.documentset.D2DocumentSetSwitch     : D2DocumentSetSwitch.getDocumentSetList end: 0.000s
2020-03-28 16:19:14,197 UTC [ERROR] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : Upload failed
com.documentum.fc.client.DfSysObjectException: [DM_SYSOBJECT_E_CANT_ACCESS_FILE]error:  "Cannot access file '$WS_TMP_FOLDER/msD2-01/DefaultFileRenamePolicy.rename3568065702834064539.txt' due to Operating System error."
        at com.documentum.fc.client.DfSysObjectException.newCantAccessFileException(DfSysObjectException.java:180)
        at com.documentum.fc.client.DfSysObject.verifyFiles(DfSysObject.java:2198)
        at com.documentum.fc.client.DfSysObject.doSetFile(DfSysObject.java:2134)
        at com.documentum.fc.client.DfSysObject.setFileEx(DfSysObject.java:2125)
        at com.documentum.fc.client.DfSysObject.setFile(DfSysObject.java:2120)
        at com.documentum.fc.client.DfDocument___PROXY.setFile(DfDocument___PROXY.java)
        at com.emc.d2.api.config.modules.structure.D2StructureConfig.importFiles(D2StructureConfig.java:1021)
        at com.emc.d2.api.config.modules.structure.D2StructureConfig.importStructure(D2StructureConfig.java:748)
        at com.emc.d2.api.config.modules.structure.D2StructureConfig.importStructureFiles(D2StructureConfig.java:452)
        ...
        at weblogic.work.SelfTuningWorkManagerImpl.runWorkUnderContext(SelfTuningWorkManagerImpl.java:652)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:420)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:360)
2020-03-28 16:19:14,202 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - Free memory=281.8924 MB. Total memory=1.0 GB.
2020-03-28 16:19:14,203 UTC [INFO ] ([ACTIVE] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet      : ImportStructure - END (6.013s) =====================================

 

So what happen exactly? Well you probably understood already but basically the import request was triggered on the correct D2 pod. Unfortunately, after that, a first sub-request was sent to another D2 pod. This one succeeded so there is no issue. But then a second sub-request was sent to yet another D2 pod and this one failed saying that the file “$WS_TMP_FOLDER/msD2-01/DefaultFileRenamePolicy.rename3568065702834064539.txt” wasn’t accessible. If you look at the table I put earlier, the request failed on wsd2-0 while the message indicates a path of “$WS_TMP_FOLDER/msD2-01“: this is the temporary folder of the wsd2-1 pod… Therefore, the import started on the wsd2-1 pod, it created some temporary files locally but then the next sub-request was sent to another pod and this one do not have the temporary folder locally which resulted in an import failure.

 

A workaround would be to share the temporary folders between the D2 pods. I didn’t test that but I don’t see why it wouldn’t work (or at least work a little bit better). Obviously, this might cause some additional issues because I believe that the temporary folders are cleaned periodically if the files aren’t used. Since you would have a shared usage, it could probably remove files that are still used by other pods. It’s not a good workaround anyway so let’s just forget about it.

 

Except that, I don’t see another simple workaround. Regarding the previous blog I mentioned before, I would have opened an OpenText SR asking if it’s expected that the cookies aren’t sent with the wsctf browser plugin mode. Since I faced another issue also related to the same root cause but for which I don’t have a simple solution, I changed a little bit what I wanted to put in the ticket and opened the OpenText SR#4459303 to discuss this issue. Our dedicated support replied in a few minutes that it is a know issue, referenced as DTWO-48180. This is normally fixed in D2 16.5.1 P05 (latest patch, released on 31-Jan-2020). However, the P05 Patch Note doesn’t have any mention of this DTWO-48180 or anything related to wsctf+cookies. Therefore, they opened a documentation bug to add it in the Patch Note. I guess I will have to upgrade from the P04 to the P05 in the coming days to see if it does solve the missing cookies issue while using the wsctf browser plugin!

 

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Morgan Patou
Morgan Patou

Senior Consultant & Technology Leader ECM