Bob,
I have determined that the problem appears to occur in jmri.util.FileUtilSupport.findFiles. It does not return the set of found files. I did some code modifications to help find the point of failure which required transferring the modified jar file to the XP system. The XP system has 4.19.6 installed.
2020-05-10 16:03:17,375 decoderdefn.DecoderIndexFile DEBUG - DecoderIndexFile creating instance: jmri.jmrit.decoderdefn.DecoderIndexFile@62cba9 [initialize decoder index] 2020-05-10 16:03:17,375 decoderdefn.DecoderIndexFile DEBUG - readFile decoderIndex.xml [initialize decoder index] 2020-05-10 16:03:18,437 decoderdefn.DecoderIndexFile DEBUG - found fileVersion of 1004 [initialize decoder index] 2020-05-10 16:03:18,453 decoderdefn.DecoderIndexFile DEBUG - readMfgSection sees 168 children [initialize decoder index] 2020-05-10 16:03:18,578 decoderdefn.DecoderIndexFile DEBUG - DecoderIndexFile before update: jmri.jmrit.decoderdefn.DecoderIndexFile@62cba9 [initialize decoder index] 2020-05-10 16:03:18,593 decoderdefn.DecoderIndexFile DEBUG - DecoderIndexFile try update: jmri.jmrit.decoderdefn.DecoderIndexFile@62cba9 [initialize decoder index] 2020-05-10 16:03:18,593 util.FileUtilSupport INFO - findFiles: name = decoderIndex.xml, root = C:\Program Files\JMRI\. [initialize decoder index]
.......... The return from findFiles is missing due to the NPE. It should look like the following: 2020-05-10 16:07:08,498 util.FileUtilSupport INFO - findFiles: return = [/Users/das/Git/JMRI/xml/decoderIndex.xml] [initialize decoder index] .........
2020-05-10 16:03:18,593 decoderdefn.DecoderIndexFile INFO - updateIndexIfNeeded failed: {} [initialize decoder index] java.lang.NullPointerException at java.nio.file.FileTreeWalker.next(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:283) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:253) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:214) at jmri.util.FileUtil.findFiles(FileUtil.java:174) at jmri.jmrit.decoderdefn.DecoderIndexFile.updateIndexIfNeeded(DecoderIndexFile.java:254) at jmri.jmrit.decoderdefn.DecoderIndexFile$Initializer.getDefault(DecoderIndexFile.java:682) at jmri.InstanceManager.getInstance(InstanceManager.java:321) at jmri.InstanceManager.getNullableDefault(InstanceManager.java:233) at jmri.InstanceManager.getDefault(InstanceManager.java:204) at apps.Apps.lambda$new$2(Apps.java:357) at java.lang.Thread.run(Unknown Source) 2020-05-10 16:03:18,609 util.FileUtilSupport INFO - findFiles: name = decoderIndex.xml, root = C:\Program Files\JMRI\. [initialize decoder index] 2020-05-10 16:03:18,625 decoderdefn.DecoderIndexFile ERROR - Exception during decoder index update: [initialize decoder index] java.lang.NullPointerException at java.nio.file.FileTreeWalker.next(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:283) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:253) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:214) at jmri.util.FileUtil.findFiles(FileUtil.java:174) at jmri.jmrit.decoderdefn.DecoderIndexFile.updateIndexIfNeeded(DecoderIndexFile.java:259) at jmri.jmrit.decoderdefn.DecoderIndexFile$Initializer.getDefault(DecoderIndexFile.java:682) at jmri.InstanceManager.getInstance(InstanceManager.java:321) at jmri.InstanceManager.getNullableDefault(InstanceManager.java:233) at jmri.InstanceManager.getDefault(InstanceManager.java:204) at apps.Apps.lambda$new$2(Apps.java:357) at java.lang.Thread.run(Unknown Source) 2020-05-10 16:03:18,625 decoderdefn.DecoderIndexFile DEBUG - DecoderIndexFile returns instance jmri.jmrit.decoderdefn.DecoderIndexFile@62cba9 [initialize decoder index] 2020-05-10 16:03:18,625 jmri.InstanceManager DEBUG - initializer created default of jmri.jmrit.decoderdefn.DecoderIndexFile [initialize decoder index]
Dave Sand
toggle quoted message
Show quoted text
----- Original message ----- From: Dave Sand <ds@...> To: " [email protected]" < [email protected]> Subject: Re: [jmriusers] Win XP and JMRI 4.18 Date: Saturday, May 09, 2020 11:19 PM Bob, The JMRI 4.0 install was removed using Control Panel and Windows Explorer. The user JMRI directory was renamed. JMRI 4.18 was installed. To JMRI it looks like a new JMRI install. The first PanelPro run creates the Settings structure and the default profile. After setting the connection to a LocoBuffer-USB and adding the JMRI console log to start up actions, I do a save and restart. Except the restart never occurs since the PanelPro process stills active in the Task Manager Processes pane but not in the Applications pane. After killing the process, I can start PanelPro and it comes up successfully, except for the decoder index error, which occurs in both the original startup and second one. An attempt to re-create the decoder index results in a Java exception. Dave Sand ----- Original message ----- From: Bob Jacobsen <rgj1927@...> To: [email protected]Subject: Re: [jmriusers] Win XP and JMRI 4.18 Date: Saturday, May 09, 2020 10:39 PM I suggest moving the roster folder and roster.xml file aside to see if you can get it to start up. Alternately, just move the roster.xml file. Do you have anything decoder-related in the PanelPro startup actions? Bob On May 9, 2020, at 4:30 PM, Dave Sand <ds@...> wrote:
I am helping a friend upgrade from JMRI 4.0 to 4.18.
Instead of trying to upgrade that far or with multiple steps, it made sense to do a fresh install of 4.18. The old version of JMRI was removed using the Windows Control Panel and the left over JMRI directory was removed from C:\Program Files. The existing JMRI settings directory was renamed.
After installing JMRI 4.18, I started PanelPro, did the connection setting to a LocoBuffer-USB, and add the system console to startup actions. After doing the Save with restart, JMRI appeared to shutdown but never restarted. Starting PanelPro again resulted in a message saying it was already running. I killed the left over one using task manager. Additional testing of both PanelPro and DecoderPro showed that shutdown is never completed.
Here is the log from the first session:
2020-05-09 16:55:06,828 util.Log4JUtil INFO - * JMRI log ** [main] 2020-05-09 16:55:08,515 util.Log4JUtil INFO - This log is appended to file: C:\Documents and Settings\user1\JMRI\log\messages.log [main] 2020-05-09 16:55:08,515 util.Log4JUtil INFO - This log is stored in file: C:\Documents and Settings\user1\JMRI\log\session.log [main] 2020-05-09 16:55:08,765 apps.Apps INFO - PanelPro version 4.18+R37ad3d0 starts under Java 1.8.0_66 on Windows 9X (unknown) x86 v5.1 at Sat May 09 16:55:08 CDT 2020 [main] 2020-05-09 16:55:22,765 profile.ProfileManager INFO - Created default profile "My JMRI Railroad" [main] 2020-05-09 16:55:31,234 apps.Apps INFO - Starting with profile My_JMRI_Railroad.3f09d193 [main] 2020-05-09 16:55:46,062 node.NodeIdentity INFO - Using 85f167a6-ef19-4607-8cc0-2aee227f5724 as the JMRI storage identity for profile id 3f09d193 [AWT-EventQueue-0] 2020-05-09 16:55:46,171 managers.JmriUserPreferencesManager INFO - No saved user preferences file [AWT-EventQueue-0] 2020-05-09 16:55:46,171 apps.Apps INFO - No saved preferences, will open preferences window. Searched for C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\ProfileConfig.xml [main] 2020-05-09 16:55:46,171 util.FileUtilSupport INFO - File path program: is C:\Program Files\JMRI\ [main] 2020-05-09 16:55:46,187 util.FileUtilSupport INFO - File path preference: is C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\ [main] 2020-05-09 16:55:46,187 util.FileUtilSupport INFO - File path profile: is C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\ [main] 2020-05-09 16:55:46,203 util.FileUtilSupport INFO - File path settings: is C:\Documents and Settings\user1\JMRI\ [main] 2020-05-09 16:55:46,203 util.FileUtilSupport INFO - File path home: is C:\Documents and Settings\user1\ [main] 2020-05-09 16:55:46,250 util.FileUtilSupport INFO - File path scripts: is C:\Program Files\JMRI\jython\ [main] 2020-05-09 16:55:53,750 apps.Apps ERROR - Error in trying to initialize decoder index file null [initialize decoder index] 2020-05-09 16:56:27,765 throttle.ThrottlesPreferences INFO - Did not find throttle preferences file. This is normal if you haven't save the preferences before [main] 2020-05-09 16:56:27,859 hrottle.AbstractWiThrottlePreferences INFO - Could not find WiThrottle preferences file (C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\throttle\WiThrottlePreferences.xml). Normal if preferences have not been saved before. [main] 2020-05-09 16:56:51,765 PanelPro.PanelPro INFO - Main initialization done [main] 2020-05-09 16:57:50,156 throttle.PowerManagerButton INFO - No power manager instance found, panel not active [AWT-EventQueue-0] 2020-05-09 16:57:50,281 throttle.ThrottlesPreferences INFO - Did not find throttle preferences file. This is normal if you haven't save the preferences before [AWT-EventQueue-0] 2020-05-09 16:57:50,296 jmrit.XmlFile INFO - No C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\throttle\ThrottlesPreferences.xml file to backup [AWT-EventQueue-0] 2020-05-09 16:57:51,796 jmrit.XmlFile INFO - No C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\throttle\WiThrottlePreferences.xml file to backup [AWT-EventQueue-0] 2020-05-09 16:57:52,046 logix.WarrantPreferences ERROR - _fileName null. Could not create warrant preferences file. [AWT-EventQueue-0] 2020-05-09 16:57:57,531 managers.DefaultShutDownManager INFO - Normal termination complete [AWT-EventQueue-0]
After starting PanelPro normally, I noticed that there was an error relating to the decoderIndex. The error is also present in the first log.
2020-05-09 17:01:25,562 util.Log4JUtil INFO - * JMRI log ** [main] 2020-05-09 17:01:25,562 util.Log4JUtil INFO - This log is appended to file: C:\Documents and Settings\user1\JMRI\log\messages.log [main] 2020-05-09 17:01:25,578 util.Log4JUtil INFO - This log is stored in file: C:\Documents and Settings\user1\JMRI\log\session.log [main] 2020-05-09 17:01:25,593 apps.Apps INFO - PanelPro version 4.18+R37ad3d0 starts under Java 1.8.0_66 on Windows 9X (unknown) x86 v5.1 at Sat May 09 17:01:25 CDT 2020 [main] 2020-05-09 17:01:26,187 apps.Apps INFO - Starting with profile My_JMRI_Railroad.3f09d193 [main] 2020-05-09 17:01:26,718 node.NodeIdentity INFO - Using 85f167a6-ef19-4607-8cc0-2aee227f5724 as the JMRI storage identity for profile id 3f09d193 [AWT-EventQueue-0] 2020-05-09 17:01:27,093 xml.AbstractSerialConnectionConfigXml INFO - Starting to connect for "LocoNet" [main] 2020-05-09 17:01:28,484 locobufferusb.LocoBufferUsbAdapter INFO - LocoBuffer-USB adapter set hardware flow control, mode=2 RTSCTS_OUT=2 RTSCTS_IN=1 [main] 2020-05-09 17:01:28,515 locobuffer.LocoBufferAdapter INFO - COM5 port opened at 57600 baud with DTR: true RTS: true DSR: true CTS: true CD: false [main] 2020-05-09 17:01:28,953 loconet.LnPacketizer INFO - lnPacketizer Started [main] 2020-05-09 17:01:31,062 util.FileUtilSupport INFO - File path program: is C:\Program Files\JMRI\ [main] 2020-05-09 17:01:31,062 util.FileUtilSupport INFO - File path preference: is C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\ [main] 2020-05-09 17:01:31,093 util.FileUtilSupport INFO - File path profile: is C:\Documents and Settings\user1\JMRI\My_JMRI_Railroad.jmri\ [main] 2020-05-09 17:01:31,093 util.FileUtilSupport INFO - File path settings: is C:\Documents and Settings\user1\JMRI\ [main] 2020-05-09 17:01:31,093 util.FileUtilSupport INFO - File path home: is C:\Documents and Settings\user1\ [main] 2020-05-09 17:01:31,093 util.FileUtilSupport INFO - File path scripts: is C:\Program Files\JMRI\jython\ [main] 2020-05-09 17:01:32,562 apps.Apps ERROR - Error in trying to initialize decoder index file null [initialize decoder index] 2020-05-09 17:01:33,062 PanelPro.PanelPro INFO - Main initialization done [main]
After seeing the decoder index error again, I used the Debug menu option to "Recreate Decoder Index".
2020-05-09 17:03:10,750 decoderdefn.DecoderIndexFile INFO - update decoder index [AWT-EventQueue-0] 2020-05-09 17:03:10,765 jmri.InstanceManager ERROR - Proceeding to initialize class jmri.jmrit.decoderdefn.DecoderIndexFile while already in initialization [AWT-EventQueue-0] java.lang.Exception: Thread "AWT-EventQueue-0" at jmri.InstanceManager.getInstance(InstanceManager.java:275) at jmri.InstanceManager.getNullableDefault(InstanceManager.java:233) at jmri.InstanceManager.getDefault(InstanceManager.java:204) at jmri.jmrit.decoderdefn.DecoderIndexFile.forceCreationOfNewIndex(DecoderIndexFile.java:368) at jmri.jmrit.decoderdefn.DecoderIndexCreateAction.actionPerformed(DecoderIndexCreateAction.java:36) at javax.swing.AbstractButton.fireActionPerformed(Unknown Source) at javax.swing.AbstractButton$Handler.actionPerformed(Unknown Source) at javax.swing.DefaultButtonModel.fireActionPerformed(Unknown Source) at javax.swing.DefaultButtonModel.setPressed(Unknown Source) at javax.swing.AbstractButton.doClick(Unknown Source) at javax.swing.plaf.basic.BasicMenuItemUI.doClick(Unknown Source) at javax.swing.plaf.basic.BasicMenuItemUI$Handler.mouseReleased(Unknown Source) at java.awt.Component.processMouseEvent(Unknown Source) at javax.swing.JComponent.processMouseEvent(Unknown Source) at java.awt.Component.processEvent(Unknown Source) at java.awt.Container.processEvent(Unknown Source) at java.awt.Component.dispatchEventImpl(Unknown Source) at java.awt.Container.dispatchEventImpl(Unknown Source) at java.awt.Component.dispatchEvent(Unknown Source) at java.awt.LightweightDispatcher.retargetMouseEvent(Unknown Source) at java.awt.LightweightDispatcher.processMouseEvent(Unknown Source) at java.awt.LightweightDispatcher.dispatchEvent(Unknown Source) at java.awt.Container.dispatchEventImpl(Unknown Source) at java.awt.Window.dispatchEventImpl(Unknown Source) at java.awt.Component.dispatchEvent(Unknown Source) at java.awt.EventQueue.dispatchEventImpl(Unknown Source) at java.awt.EventQueue.access$500(Unknown Source) at java.awt.EventQueue$3.run(Unknown Source) at java.awt.EventQueue$3.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.awt.EventQueue$4.run(Unknown Source) at java.awt.EventQueue$4.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.awt.EventQueue.dispatchEvent(Unknown Source) at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source) at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source) at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source) at java.awt.EventDispatchThread.pumpEvents(Unknown Source) at java.awt.EventDispatchThread.pumpEvents(Unknown Source) at java.awt.EventDispatchThread.run(Unknown Source) 2020-05-09 17:03:10,812 jmri.InstanceManager ERROR - Prior initialization: [AWT-EventQueue-0] java.lang.Exception: Thread initialize decoder index at jmri.InstanceManager.setInitializationState(InstanceManager.java:830) at jmri.InstanceManager.getInstance(InstanceManager.java:272) at jmri.InstanceManager.getNullableDefault(InstanceManager.java:233) at jmri.InstanceManager.getDefault(InstanceManager.java:204) at apps.Apps.lambda$2(Apps.java:384) at java.lang.Thread.run(Unknown Source) 2020-05-09 17:03:11,375 ptionhandler.UncaughtExceptionHandler ERROR - Uncaught Exception caught by jmri.util.exceptionhandler.UncaughtExceptionHandler [AWT-EventQueue-0] java.lang.NullPointerException at java.nio.file.FileTreeWalker.next(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at java.nio.file.Files.walkFileTree(Unknown Source) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:278) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:249) at jmri.util.FileUtilSupport.findFiles(FileUtilSupport.java:210) at jmri.util.FileUtil.findFiles(FileUtil.java:175) at jmri.jmrit.decoderdefn.DecoderIndexFile.updateIndexIfNeeded(DecoderIndexFile.java:239) at jmri.jmrit.decoderdefn.DecoderIndexFile$Initializer.getDefault(DecoderIndexFile.java:657) at jmri.InstanceManager.getInstance(InstanceManager.java:321) at jmri.InstanceManager.getNullableDefault(InstanceManager.java:233) at jmri.InstanceManager.getDefault(InstanceManager.java:204) at jmri.jmrit.decoderdefn.DecoderIndexFile.forceCreationOfNewIndex(DecoderIndexFile.java:368) at jmri.jmrit.decoderdefn.DecoderIndexCreateAction.actionPerformed(DecoderIndexCreateAction.java:36) at javax.swing.AbstractButton.fireActionPerformed(Unknown Source) at javax.swing.AbstractButton$Handler.actionPerformed(Unknown Source) at javax.swing.DefaultButtonModel.fireActionPerformed(Unknown Source) at javax.swing.DefaultButtonModel.setPressed(Unknown Source) at javax.swing.AbstractButton.doClick(Unknown Source) at javax.swing.plaf.basic.BasicMenuItemUI.doClick(Unknown Source) at javax.swing.plaf.basic.BasicMenuItemUI$Handler.mouseReleased(Unknown Source) at java.awt.Component.processMouseEvent(Unknown Source) at javax.swing.JComponent.processMouseEvent(Unknown Source) at java.awt.Component.processEvent(Unknown Source) at java.awt.Container.processEvent(Unknown Source) at java.awt.Component.dispatchEventImpl(Unknown Source) at java.awt.Container.dispatchEventImpl(Unknown Source) at java.awt.Component.dispatchEvent(Unknown Source) at java.awt.LightweightDispatcher.retargetMouseEvent(Unknown Source) at java.awt.LightweightDispatcher.processMouseEvent(Unknown Source) at java.awt.LightweightDispatcher.dispatchEvent(Unknown Source) at java.awt.Container.dispatchEventImpl(Unknown Source) at java.awt.Window.dispatchEventImpl(Unknown Source) at java.awt.Component.dispatchEvent(Unknown Source) at java.awt.EventQueue.dispatchEventImpl(Unknown Source) at java.awt.EventQueue.access$500(Unknown Source) at java.awt.EventQueue$3.run(Unknown Source) at java.awt.EventQueue$3.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.awt.EventQueue$4.run(Unknown Source) at java.awt.EventQueue$4.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(Unknown Source) at java.awt.EventQueue.dispatchEvent(Unknown Source) at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source) at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source) at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source) at java.awt.EventDispatchThread.pumpEvents(Unknown Source) at java.awt.EventDispatchThread.pumpEvents(Unknown Source) at java.awt.EventDispatchThread.run(Unknown Source) 2020-05-09 17:03:25,250 managers.DefaultShutDownManager INFO - Normal termination complete [AWT-EventQueue-0]
I then did the PanelPro Quit following by a kill using Windows Task Manager.
Dave Sand
-- Bob Jacobsen rgj1927@...
|