• Notes error 4063: Database %1 has not been opened yet

    By Kim Acket 6 years ago

    Paul,

    I'm having some difficulties with the OpenLog database, after restarting domino all is functioning again. But fairly regularly a message like shown below is displayed, like I said this will go away when we restart the domino service.

    The function calling the openLog is located in the function WriteToConsole

    public static void WriteToConsole(String message) {
    
        if (pw == null) {
            pw = new PrintWriter(System.out, true);
        }
        if (Utils.isStringEmpty(CurrentDatabase)) {
            try {
                CurrentDatabase = DominoTools.getNotesSession().getCurrentDatabase().getFilePath();
            } catch (Exception ex) {
               // handle exception
            }
        }
        pw.println("XPages Log ========> : " + CurrentDatabase + " : " + message);
        if (outputUnitTest) {
            String UnitTestOutPut = (String) Utils.getScopeMap(Utils.SCOPE.View).get("UnitTestOutput");
            UnitTestOutPut = UnitTestOutPut + "\r\n" + message;
            Utils.getScopeMap(Utils.SCOPE.View).put("UnitTestOutput", UnitTestOutPut);
        }
        try {
            OpenLogUtil.logEvent(null, message, Level.INFO, null);// FAILS HERE line 54
        } catch (Exception ex) {
            ex.printStackTrace(pw);
        }
    }
    

    Below a print out of the console; the first line is just a print statement to the console, the exact same text is then logged to the database - which gives us the error and stack strace

    02/20/2018 09:43:29 PM HTTP JVM: XPages Log ========> : projects\jpiX\Duke-Cliffside_2016_XP.NSF : Loaded - Vendor PDF Database
    02/20/2018 09:43:29 PM HTTP JVM: OpenLogItem error: Notes error 4063: Database %1 has not been opened yet
    02/20/2018 09:43:29 PM HTTP JVM: OpenLogItem error trace:
    02/20/2018 09:43:29 PM HTTP JVM: NotesException: Database %1 has not been opened yet
    02/20/2018 09:43:29 PM HTTP JVM: at lotus.domino.local.Database.NcreateDocument(Native Method)
    02/20/2018 09:43:29 PM HTTP JVM: at lotus.domino.local.Database.createDocument(Unknown Source)
    02/20/2018 09:43:29 PM HTTP JVM: at com.paulwithers.openLog.OpenLogItem.writeToLog(OpenLogItem.java:1214)
    02/20/2018 09:43:29 PM HTTP JVM: at com.paulwithers.openLog.OpenLogItem.logEvent(OpenLogItem.java:1065)
    02/20/2018 09:43:29 PM HTTP JVM: at com.paulwithers.openLog.OpenLogUtil.logEvent(OpenLogUtil.java:168)
    02/20/2018 09:43:29 PM HTTP JVM: at com.jacobs.JPI.Core.WriteToConsole(Core.java:54)
    02/20/2018 09:43:29 PM HTTP JVM: at com.jacobs.JPI.Databases.Initialize(Databases.java:419)
    02/20/2018 09:43:29 PM HTTP JVM: at com.jacobs.JPI.Main.Initialize(Main.java:138)
    02/20/2018 09:43:29 PM HTTP JVM: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    02/20/2018 09:43:29 PM HTTP JVM: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:90)
    02/20/2018 09:43:29 PM HTTP JVM: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
    02/20/2018 09:43:29 PM HTTP JVM: at java.lang.reflect.Method.invoke(Method.java:508)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.types.JavaAccessObject.call(JavaAccessObject.java:322)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.types.FBSObject.call(FBSObject.java:161)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.ASTTree.ASTCall.interpret(ASTCall.java:197)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.ASTTree.ASTBlock.interpret(ASTBlock.java:100)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.ASTTree.ASTTry.interpret(ASTTry.java:109)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.ASTTree.ASTProgram.interpret(ASTProgram.java:119)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.ASTTree.ASTProgram.interpretEx(ASTProgram.java:139)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression.interpretExpression(JSExpression.java:435)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression.access$1(JSExpression.java:424)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression$2.run(JSExpression.java:414)
    02/20/2018 09:43:29 PM HTTP JVM: at java.security.AccessController.doPrivileged(AccessController.java:686)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression.interpretExpression(JSExpression.java:410)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression.evaluateValue(JSExpression.java:251)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.jscript.JSExpression.evaluateValue(JSExpression.java:234)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.javascript.JavaScriptInterpreter.interpret(JavaScriptInterpreter.java:222)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.binding.javascript.JavaScriptMethodBinding.invoke(JavaScriptMethodBinding.java:111)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.component.UIViewRootEx.initBeforeContents(UIViewRootEx.java:1621)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.page.compiled.AbstractCompiledPage.initComponent(AbstractCompiledPage.java:333)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.page.compiled.AbstractCompiledPage.createTree(AbstractCompiledPage.java:256)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.page.compiled.AbstractCompiledPage.createViewRoot(AbstractCompiledPage.java:167)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.application.ViewHandlerExImpl.
    createViewRoot(ViewHandlerExImpl.java:521)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.application.ViewHandlerExImpl.createViewRoot(ViewHandlerExImpl.java:567)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.application.ViewHandlerExImpl.doCreateView(ViewHandlerExImpl.java:142)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.application.ViewHandlerEx.createView(ViewHandlerEx.java:90)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.webapp.FacesServlet.serviceView(FacesServlet.java:250)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.webapp.FacesServletEx.serviceView(FacesServletEx.java:157)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.webapp.FacesServlet.service(FacesServlet.java:159)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.webapp.FacesServletEx.service(FacesServletEx.java:138)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.xsp.webapp.DesignerFacesServlet.service(DesignerFacesServlet.java:103)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.ComponentModule.invokeServlet(ComponentModule.java:588)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.domino.xsp.module.nsf.NSFComponentModule.invokeServlet(NSFComponentModule.java:1335)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.ComponentModule$AdapterInvoker.invokeServlet(ComponentModule.java:865)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.ComponentModule$ServletInvoker.doService(ComponentModule.java:808)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.ComponentModule.doService(ComponentModule.java:577)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.domino.xsp.module.nsf.NSFComponentModule.doService(NSFComponentModule.java:1319)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.domino.xsp.module.nsf.NSFService.doServiceInternal(NSFService.java:662)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.domino.xsp.module.nsf.NSFService.doService(NSFService.java:482)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.LCDEnvironment.doService(LCDEnvironment.java:357)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.designer.runtime.domino.adapter.LCDEnvironment.service(LCDEnvironment.java:313)
    02/20/2018 09:43:29 PM HTTP JVM: at com.ibm.domino.xsp.bridge.http.engine.XspCmdManager.service(XspCmdManager.java:272)

    • By Paul S Withers 6 years ago

      The stack trace shows it's failing on writing to wherever it's intending to log the error. Here's the relevant chunk of code https://stash.openntf.org/projects/OPENLOG/repos/xpages-openlog-logger/browse/OpenLogOSGi/com.paulwithers.openLog/src/com/paulwithers/openLog/OpenLogItem.java#1202.

      If you've got the xsp property to log to email, you'll see it's using signer access to write to mail.box (or if there are multiple mail.boxes on the Domino server, it just picks one of them, even if none are actually called mail.box).

      Otherwise it's writing to the database defined in the xsp property or, if you don't have one set, OpenLog.nsf. You'll see it's checking for database is null and it's not generating that error. So it looks like it can't write to that database for some reason.

      The most likely cause is that the user triggering the error doesn't have at least depositor access to the OpenLog database.

      If they have access, it would also be useful to check whether Domino runs a consistency check on the OpenLog database on startup. If it does, there may also have been a problem that prevented it writing to the database when logging the error. I have seen OpenLog databases get quite large, which is why I now use the xsp property to set an expireDate and add an archiving setting on the database to ensure logs are only kept for e.g. 90 days. Another possible cause, depending on timing, is that another process is locking the OpenLog database, e.g. backups.

      Hopefully that gives you a better understanding of what's happening at that point and potential causes. It would be interesting to know what you find out. Maybe the code can catch this error and write to the console instead, although that would not be able to log as much as it logs to OpenLog.

      • By Kim Acket 6 years ago

        Paul,

        We do have a dedicated OpenLog db on all servers and the XPages project uses the following:
        xsp.openlog.debugLevel=2
        xsp.openlog.expireDate=30
        xsp.openlog.filepath=JPI_Log.nsf
        xsp.openlog.supressEventStack=false

        This JPI_Log.nsf database is setup to allow -default- Author access with Create Documents checked. The database itself is about 140MB, I will have a look at the consistency checks.

        Couldn't we just try to re-open the database if it fails the first time?

        public boolean writeToLog() {

           // exit early if there is no database
            Database db = null;
            boolean retval = false;
            Document logDoc = null;
            RichTextItem rtitem = null;
            Database docDb = null;
        
            try {
                if (!StringUtil.equals(getCurrentDatabasePath(), ExtLibUtil.getCurrentDatabase().getFilePath())) {
                    reinitialiseSettings();
                }
        
                if (StringUtil.isEmpty(getLogEmail())) {
                    db = getLogDb();
                    if (db == null) {
                        db = createLogDbFromTemplate();
                    }
                } else {
                    db = getSessionAsSigner().getDatabase(getThisServer(), "mail.box", false);
                }
                if (db == null) {
                    System.out.println("Could not retrieve database at path " + getLogDbName());
                    return false;
                } else {
                   // Maybe we can test if it's open if not Open the db?
                      if(!db.isOpen()){ 
                         db.Open();
                       }
                    // Added opening db if not opened
                 }
        
                logDoc = db.createDocument();
                rtitem = logDoc.createRichTextItem("LogDocInfo");