I had a case today where all Documentum components were up and running, including D2 but while accessing its login page, the repositories wouldn’t appear and a message “An unexpected error occurred. Please refresh your browser” would pop-up in the lower-right corner and disappear quickly. Refreshing the browser or opening a private window wouldn’t do anything. In such cases, of course the first thing to do would be to make sure the docbroker and repositories are responding but if it is the case, then what could be the problem? The root cause of this can be several things I assume since it’s a rather generic behavior but I saw that a few times already and it might not be really obvious at first glance so sharing some thoughts about it might prove useful for someone.
Here is the login screen of D2 having the issue:
In my case, the repositories were apparently available on the Content Server and responding (connection through iapi/idql working). The next step would probably be to check the D2 logs with DEBUG enabled to make sure to capture as much as possible. This is what you would see in the logs whenever accessing the D2 login URL:
2020-11-29 11:12:36,434 UTC [DEBUG] ([ACTIVE] ExecuteThread: '37' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.utils.X3PortalJspUtils : D2 full build version: 16.5.1050 build 096 2020-11-29 11:12:36,435 UTC [DEBUG] ([ACTIVE] ExecuteThread: '37' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.utils.X3PortalJspUtils : patch version: 16.5.1050 2020-11-29 11:12:36,886 UTC [DEBUG] ([ACTIVE] ExecuteThread: '66' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.s.s.labels.X3ResourceBundleFactory : getAllBundle for resources.i18n en 2020-11-29 11:12:36,924 UTC [DEBUG] ([ACTIVE] ExecuteThread: '99' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.p.s.s.settings.RpcSettingsServiceImpl : Fetching Server properties 2020-11-29 11:12:36,940 UTC [DEBUG] ([ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.p.s.s.settings.RpcSettingsServiceImpl : Fetching Server shiro.ini 2020-11-29 11:12:36,942 UTC [DEBUG] ([ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.p.s.s.settings.RpcSettingsServiceImpl : Fetching Server adminMessage Settings 2020-11-29 11:12:36,978 UTC [DEBUG] ([ACTIVE] ExecuteThread: '84' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x.s.s.labels.X3ResourceBundleFactory : getAllBundle for resources.i18n en_US 2020-11-29 11:12:37,709 UTC [DEBUG] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.common.dctm.objects.DfDocbaseMapEx : Load docbases from docbrocker 0.623s 2020-11-29 11:12:37,711 UTC [INFO ] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d2fs.dctm.web.services.D2fsRepositories : Loaded repositories from docbroker: GR_Repo,Repo1 2020-11-29 11:12:37,712 UTC [INFO ] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d2fs.dctm.web.services.D2fsRepositories : loginRepositoryFilter=GR_Repo 2020-11-29 11:12:37,713 UTC [INFO ] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d2fs.dctm.web.services.D2fsRepositories : Filtering out repository GR_Repo 2020-11-29 11:12:37,713 UTC [DEBUG] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2.api.config.D2OptionsCache : D2Info element not for in cache 2020-11-29 11:12:37,713 UTC [ERROR] ([ACTIVE] ExecuteThread: '26' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2.api.config.D2OptionsCache : Trying to fetch D2Info before it's been set 2020-11-29 11:12:37,815 UTC [DEBUG] ([ACTIVE] ExecuteThread: '51' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2.api.D2Session : D2Session::initTBOEx after tbos from map 0.000s 2020-11-29 11:12:37,815 UTC [DEBUG] ([ACTIVE] ExecuteThread: '51' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2.api.D2Session : D2Session::initTBOEx after tbos C6-dbor bundle 0.001s 2020-11-29 11:12:38,808 UTC [INFO ] ([ACTIVE] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.x3.portal.server.X3HttpSessionListener : Created http session 3tGeYTFa9ChEQJP-V7GdMyQreCk3t7_BFfS3EixfHtTbO6qFtOg3!781893690!1606648358808 2020-11-29 11:12:38,809 UTC [DEBUG] ([ACTIVE] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.utils.X3PortalJspUtils : XSRF_TOKEN not found in session 2020-11-29 11:12:38,811 UTC [DEBUG] ([ACTIVE] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.utils.X3PortalJspUtils : D2 full build version: 16.5.1050 build 096 2020-11-29 11:12:38,811 UTC [DEBUG] ([ACTIVE] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.utils.X3PortalJspUtils : patch version: 16.5.1050
At first glance, the log content doesn’t look so strange, there are no obvious warnings or errors clearly showing the issue. As you can see, the list of repositories is present, it’s filtered properly so the drop-down should display something but it’s not. The only message that might give you some hint is the one error and its associated debug message just before about the D2OptionsCache: the D2Info elements aren’t in the cache while D2 is trying to use it. In this case, the only way to clearly see what is actually the issue would be to restart the Application Server of D2 to force the LoadOnStartup to be re-executed. Maybe this is only true if the LoadOnStartup is enabled. I didn’t test without but it might be worth to check whether D2 is able to refresh it at runtime in this case. After a restart of the Application Server, it becomes clear what the problem is:
2020-11-29 11:18:28,421 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.services.ServiceBeanPostProcessor : Initialized Bean : d2fs
2020-11-29 11:18:28,426 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.services.ServiceBeanPostProcessor : Initialized Bean : subscriptionsService
2020-11-29 11:18:28,427 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.services.ServiceBeanPostProcessor : Service Bean is set to Remote
2020-11-29 11:18:28,431 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.services.ServiceBeanPostProcessor : Initialized Bean : exceptionResolver
2020-11-29 11:18:28,433 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.services.ServiceBeanPostProcessor : Initialized Bean : soapProvider
2020-11-29 11:18:28,503 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.dctm.servlets.init.LoadOnStartup : DFC version : 16.4.0200.0080
2020-11-29 11:18:28,543 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - START =====================================
2020-11-29 11:18:28,544 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - HTTP Headers
Remote : null (null)
Locale : null
Request Protocol : null
Request Method : null
Context Path : /D2
Request URI : null
Request encoding : null
Request Parameters :
Request Headers :
2020-11-29 11:18:30,799 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - Plugins (0.001s)
2020-11-29 11:18:30,803 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - Start plugin before : D2-Widget v16.5.1050 build 096
2020-11-29 11:18:30,804 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - End plugin before : D2-Widget v16.5.1050 build 096 0.000s
2020-11-29 11:18:30,806 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - Standard Servlet :
2020-11-29 11:18:30,808 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.dctm.servlets.init.LoadOnStartup : Cache BOCS URL disabled.
2020-11-29 11:18:40,865 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.emc.d2fs.dctm.servlets.init.LoadOnStartup : Free memory=3.1386707 GB, Total memory=4.0 GB
2020-11-29 11:18:50,217 UTC [ERROR] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - DfException:: THREAD: [ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)'; MSG: [DM_STORAGE_E_NOT_ACCESSIBLE]error: "Storage area filestore_01 is not currently accessible. Reason: errno: 2, message: No such file or directory."; ERRORCODE: 100; NEXT: null
2020-11-29 11:18:50,220 UTC [ERROR] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : {}
com.documentum.fc.common.DfException: [DM_STORAGE_E_NOT_ACCESSIBLE]error: "Storage area filestore_01 is not currently accessible. Reason: errno: 2, message: No such file or directory."
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:329)
at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.applyForInt(NetwiseDocbaseRpcClient.java:600)
at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection$6.evaluate(DocbaseConnection.java:1382)
at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.evaluateRpc(DocbaseConnection.java:1180)
at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.applyForInt(DocbaseConnection.java:1375)
at com.documentum.fc.client.impl.docbase.DocbaseApi.makePuller(DocbaseApi.java:630)
at com.documentum.fc.client.impl.connection.docbase.RawPuller.<init>(RawPuller.java:22)
at com.documentum.fc.client.impl.session.Session.makePuller(Session.java:3796)
at com.documentum.fc.client.impl.session.SessionHandle.makePuller(SessionHandle.java:2468)
at com.documentum.fc.client.content.impl.BlockPuller.<init>(BlockPuller.java:27)
at com.documentum.fc.client.content.impl.PusherPullerContentAccessor.buildStreamFromContext(PusherPullerContentAccessor.java:40)
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:64)
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.namelessGetFile(ContentManager.java:252)
at com.documentum.fc.client.content.impl.ContentManager.getFile(ContentManager.java:198)
at com.documentum.fc.client.content.impl.ContentManager.getFile(ContentManager.java:173)
at com.documentum.fc.client.DfSysObject.getFileEx2(DfSysObject.java:1978)
at com.documentum.fc.client.DfSysObject.getFileEx(DfSysObject.java:1970)
at com.documentum.fc.client.DfSysObject.getFile(DfSysObject.java:1965)
at com.emc.d2.api.config.modules.property.D2PropertyConfig___PROXY.getFile(D2PropertyConfig___PROXY.java)
at com.emc.common.java.xml.XmlCacheValue.<init>(XmlCacheValue.java:63)
at com.emc.common.java.xml.XmlCacheImpl.getXmlDocument(XmlCacheImpl.java:154)
at com.emc.common.java.xml.XmlCacheImpl.getXmlDocument(XmlCacheImpl.java:182)
at com.emc.d2fs.dctm.servlets.init.LoadOnStartup.loadXmlCache(LoadOnStartup.java:501)
at com.emc.d2fs.dctm.servlets.init.LoadOnStartup.refreshCache(LoadOnStartup.java:424)
at com.emc.d2fs.dctm.servlets.init.LoadOnStartup.processRequest(LoadOnStartup.java:208)
at com.emc.d2fs.dctm.servlets.D2HttpServlet.execute(D2HttpServlet.java:244)
at com.emc.d2fs.dctm.servlets.D2HttpServlet.doGetAndPost(D2HttpServlet.java:510)
at com.emc.d2fs.dctm.servlets.D2HttpServlet.doGet(D2HttpServlet.java:113)
at com.emc.d2fs.dctm.servlets.init.LoadOnStartup.init(LoadOnStartup.java:136)
at javax.servlet.GenericServlet.init(GenericServlet.java:244)
...
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:420)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:360)
2020-11-29 11:18:50,230 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.dctm.web.services.D2fsSessionManager : Using non-sso shiro SSO filter with non-sso.enableDFCPrincipalMode=false
2020-11-29 11:18:50,231 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.d.dctm.web.services.D2fsSessionManager : Not using DFC Principal Support
2020-11-29 11:18:50,232 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - Free memory=2.5813167 GB. Total memory=4.0 GB.
2020-11-29 11:18:50,232 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - com.emc.d2fs.dctm.servlets.D2HttpServlet : LoadOnStartup - END (21.726s) =====================================
2020-11-29 11:18:50,235 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.servlet.init.LogMemory : D2SecurityConfiguration : Start
2020-11-29 11:18:50,235 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.servlet.init.LogMemory : ServletContext: D2
2020-11-29 11:18:50,269 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.servlet.init.LogMemory : D2SecurityConfiguration : End
2020-11-29 11:18:50,270 UTC [INFO ] ([ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)') - c.e.x3.portal.server.servlet.init.LogMemory : Free memory=2.5780156 GB, Total memory=4.0 GB
So, as you can see above, the issue is actually linked to the Data of the repositories that weren’t available and it is only displayed during the LoadOnStartup execution, then it’s not showing-up anymore. Here, it was the NAS that was unreachable at that time and therefore D2 was impacted and nobody could login to D2. From my point of view, it’s a pity that D2 behaves this way… Even if the Data/Documents aren’t reachable, in a perfect world this shouldn’t prevent you from logging into the system and using it, except for actions involving the content of the documents of course. Browsing the repository, checking properties and some other stuff should work without issue but it’s not because of how Documentum is designed and how it works.
Because the LoadOnStartup actions are only executed at startup (if it is enabled), then it means that once the Data of the repositories are back, you will need to restart D2 again, otherwise the issue will remain. Therefore, if you have this issue and even if the Data are currently available, it might be worth to check whether it was available when D2 started. In addition to that, a restart of D2 never really hurts…
If you encountered this behavior of D2 with another root cause, feel free to share!
![Thumbnail [60x60]](https://www.dbi-services.com/blog/wp-content/uploads/2022/08/MOP_web-min-scaled.jpg)
![Thumbnail [90x90]](https://www.dbi-services.com/blog/wp-content/uploads/2022/08/OLS_web-min-scaled.jpg)
![Thumbnail [90x90]](https://www.dbi-services.com/blog/wp-content/uploads/2022/08/GME_web-min-scaled.jpg)
![Thumbnail [90x90]](https://www.dbi-services.com/blog/wp-content/uploads/2022/08/ATR_web-min-scaled.jpg)