VASSAL Does not start up again after first time quit

See below for contents of log. thanks for helping.

C:\Users\tread_000\AppData\Roaming\VASSAL>type errorLog
2013-12-01 13:21:36,335 [0-main] INFO VASSAL.launch.StartUp - Starting
2013-12-01 13:21:36,345 [0-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
2013-12-01 13:21:36,346 [0-main] INFO VASSAL.launch.StartUp - Java version 1.6.
0_45
2013-12-01 13:21:36,346 [0-main] INFO VASSAL.launch.StartUp - VASSAL version 3.
2.8
2013-12-01 13:21:36,536 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManager -
Manager
2013-12-01 13:21:45,533 [0-SwingWorker-pool-124347474-thread-1] INFO VASSAL.lau
nch.AbstractLaunchAction - Loading module file D:\Users\Tim\VASSAL Modules\sor-5
-player-v5.0.4.vmod
2013-12-01 13:21:45,842 [0-SwingWorker-pool-124347474-thread-1] INFO VASSAL.lau
nch.TilingHandler - No images to tile.
2013-12-01 13:21:45,844 [0-SwingWorker-pool-124347474-thread-1] INFO VASSAL.lau
nch.AbstractLaunchAction - Loading module Sword of Rome
2013-12-01 13:21:45,859 [0-SwingWorker-pool-124347474-thread-1] INFO VASSAL.too
ls.io.ProcessLauncher - launching C:\Program Files\Java\jre6\bin\java -Xms256M -
Xmx512M -DVASSAL.id=1 -DVASSAL.port=50987 -Duser.home=C:\Users\tread_000 -cp lib
\Vengine.jar VASSAL.launch.Player --load – D:\Users\Tim\VASSAL Modules\sor-5-pl
ayer-v5.0.4.vmod
2013-12-01 13:21:47,647 [1-main] INFO VASSAL.launch.StartUp - Starting
2013-12-01 13:21:47,666 [1-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
2013-12-01 13:21:47,666 [1-main] INFO VASSAL.launch.StartUp - Java version 1.6.
0_45
2013-12-01 13:21:47,666 [1-main] INFO VASSAL.launch.StartUp - VASSAL version 3.
2.8
2013-12-01 13:21:47,667 [1-main] INFO VASSAL.launch.Launcher - Player
2013-12-01 13:21:49,739 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - VASSAL images folder found at jar:file:/C:/Program%20Files%20(x86)/VASSAL/
lib/Vengine.jar!/images/
2013-12-01 13:21:49,753 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family go-up created for go-up.png
2013-12-01 13:21:49,754 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family go-down created for go-down.png
2013-12-01 13:21:49,754 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family calculator created for calculator.png
2013-12-01 13:21:49,755 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family network-server created for network-server.png
2013-12-01 13:21:49,755 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family yes created for yes.png
2013-12-01 13:21:49,756 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family no created for no.png
2013-12-01 13:21:49,756 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family VASSAL-jabber created for VASSAL-jabber.png
2013-12-01 13:21:49,757 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family VASSAL created for VASSAL.png
2013-12-01 13:21:49,757 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family network-idle created for network-idle.png
2013-12-01 13:21:49,759 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family jabber created for jabber.png
2013-12-01 13:21:49,760 [1-IconFactory-preload] INFO VASSAL.tools.icon.IconFact
ory - Icon family bug created for bug.svg
2013-12-01 13:21:52,867 [1-AWT-EventQueue-0] WARN VASSAL.launch.BasicModule - S
word of Rome version v5.0.4 (beta)
2013-12-01 13:58:45,719 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManagerWi
ndow - Exiting
2013-12-01 13:58:45,762 [1-AWT-EventQueue-0] INFO VASSAL.build.GameModule - Exi
ting
2013-12-01 13:58:46,233 [0-IPC receiver for 554977315] ERROR VASSAL.tools.ipc.IP
CMessageReceiver -
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(Unknown Source) ~[na:1.6.0_45]
at java.net.SocketInputStream.read(Unknown Source) ~[na:1.6.0_45]
at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source) ~[na:1
.6.0_45]
at java.io.ObjectInputStream$BlockDataInputStream.peek(Unknown Source) ~
[na:1.6.0_45]
at java.io.ObjectInputStream$BlockDataInputStream.peekByte(Unknown Sourc
e) ~[na:1.6.0_45]
at java.io.ObjectInputStream.readObject0(Unknown Source) ~[na:1.6.0_45]
at java.io.ObjectInputStream.readObject(Unknown Source) ~[na:1.6.0_45]
at VASSAL.tools.ipc.IPCMessageReceiver.run(IPCMessageReceiver.java:34) ~
[Vengine.jar:na]
at java.lang.Thread.run(Unknown Source) [na:1.6.0_45]

C:\Users\tread_000\AppData\Roaming\VASSAL>

Thus spake comdotski:

See below for contents of log. thanks for helping.

This looks like a log from a successful run where the Sword of Rome
module was loaded. Does the time “2013-12-01 13:21:36” in the log
match when you had the failed run?


J.

I took another look at this and again tried to reproduce the problem experienced, which I could do regularly taking steps as per the OP.

I noticed though that when this problem occurred, it did not over write the log file from the last time there was a successful startup and exit of VASSAL - hence the example I showed above was for a successful opening of the SOR module. See below for the typing of the error log for (just starting VASSAL, not opening any module):

  1. The errorLog WHILEthe program is run successfully for the first time
  2. The log after the first successful run and VASSAL exited, and
  3. The log after the problem.

Seems that the failure is occurring before the log is written for the subsequent failed runs. Hope that makes sense. See the 3 steps below. Again thanks for helping.

"\Users\tread_000\AppData\Roaming\VASSAL>type errorLog
13-12-02 19:55:49,434 [0-main] INFO VASSAL.launch.StartUp - Starting
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - Java version 1.6.0_45
13-12-02 19:55:49,445 [0-main] INFO VASSAL.launch.StartUp - VASSAL version 3.2.8
13-12-02 19:55:49,670 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManager - Manager

\Users\tread_000\AppData\Roaming\VASSAL>type errorLog
13-12-02 19:55:49,434 [0-main] INFO VASSAL.launch.StartUp - Starting
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - Java version 1.6.0_45
13-12-02 19:55:49,445 [0-main] INFO VASSAL.launch.StartUp - VASSAL version 3.2.8
13-12-02 19:55:49,670 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManager - Manager
13-12-02 19:57:05,275 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManagerWindow - Exiting

\Users\tread_000\AppData\Roaming\VASSAL>type errorLog
13-12-02 19:55:49,434 [0-main] INFO VASSAL.launch.StartUp - Starting
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
13-12-02 19:55:49,444 [0-main] INFO VASSAL.launch.StartUp - Java version 1.6.0_45
13-12-02 19:55:49,445 [0-main] INFO VASSAL.launch.StartUp - VASSAL version 3.2.8
13-12-02 19:55:49,670 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManager - Manager
13-12-02 19:57:05,275 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManagerWindow - Exiting"

Thus spake comdotski:

Seems that the failure is occurring before the log is written for the
subsequent failed runs. Hope that makes sense. See the 3 steps below.
Again thanks for helping.

"\Users\tread_000\AppData\Roaming\VASSAL>type errorLog

What else is in \Users\tread_000\AppData\Roaming\VASSAL after a failed
run?


J.

Contents as follows …

"C:\Users\tread_000\AppData\Roaming\VASSAL>dir
Volume in drive C is Performance mSATA
Volume Serial Number is 8895-B896

Directory of C:\Users\tread_000\AppData\Roaming\VASSAL

02/12/2013 08:49 PM .
02/12/2013 08:49 PM …
02/12/2013 11:45 PM 4,332 errorLog
01/12/2013 12:39 PM ext
02/12/2013 08:51 PM 12 key
02/12/2013 11:45 PM 0 lock
01/12/2013 12:38 PM plugins
02/12/2013 08:49 PM 576 Preferences
02/12/2013 08:52 PM prefs
02/12/2013 08:52 PM tiles
4 File(s) 4,920 bytes
6 Dir(s) 84,943,044,608 bytes free

C:\Users\tread_000\AppData\Roaming\VASSAL>"

Thus spake comdotski:

Contents as follows …

"C:\Users\tread_000\AppData\Roaming\VASSAL>dir
Volume in drive C is Performance mSATA
Volume Serial Number is 8895-B896

Directory of C:\Users\tread_000\AppData\Roaming\VASSAL

02/12/2013 08:49 PM .
02/12/2013 08:49 PM …
02/12/2013 11:45 PM 4,332 errorLog
01/12/2013 12:39 PM ext
02/12/2013 08:51 PM 12 key
02/12/2013 11:45 PM 0 lock
01/12/2013 12:38 PM plugins
02/12/2013 08:49 PM 576 Preferences
02/12/2013 08:52 PM prefs
02/12/2013 08:52 PM tiles
4 File(s) 4,920 bytes
6 Dir(s) 84,943,044,608 bytes free

C:\Users\tread_000\AppData\Roaming\VASSAL>"

Do you know the time of the last failed run?


J.

Last failed run would have been about 11:45pm.

Thus spake comdotski:

Last failed run would have been about 11:45pm.

Delete the files named lock and key, then try launching VASSAL.
What happens?


J.

I had to reproduce the problem again (which I could), then tried to delete the files as per instructions. See below:

"C:\Users\tread_000\AppData\Roaming\VASSAL>dir
Volume in drive C is Performance mSATA
Volume Serial Number is 8895-B896

Directory of C:\Users\tread_000\AppData\Roaming\VASSAL

02/12/2013 08:49 PM .
02/12/2013 08:49 PM …
04/12/2013 07:10 PM 0 errorLog
01/12/2013 12:39 PM ext
04/12/2013 07:10 PM 12 key
04/12/2013 07:10 PM 0 lock
01/12/2013 12:38 PM plugins
02/12/2013 08:49 PM 576 Preferences
02/12/2013 08:52 PM prefs
02/12/2013 08:52 PM tiles
4 File(s) 588 bytes
6 Dir(s) 83,559,366,656 bytes free

C:\Users\tread_000\AppData\Roaming\VASSAL>del key

C:\Users\tread_000\AppData\Roaming\VASSAL>del lock
C:\Users\tread_000\AppData\Roaming\VASSAL\lock
The process cannot access the file because it is being used by another process.

C:\Users\tread_000\AppData\Roaming\VASSAL>"

As you can see the ‘lock’ file could not be deleted.

As I mentioned before, I believe the problem is at least in part that the java processes are not closing properly on exit of VASSAL. If I track them down and end them via task manager, the ‘lock’ file can then be deleted (I tried it and it worked), and afterwards VASSAL will restart properly.

Hope my analysis helps. Thanks for your continued assistance.

Thus spake comdotski:

As you can see the ‘lock’ file could not be deleted.

As I mentioned before, I believe the problem is at least in part that
the java processes are not closing properly on exit of VASSAL. If I
track them down and end them via task manager, the ‘lock’ file can then
be deleted (I tried it and it worked), and afterwards VASSAL will
restart properly.

That would explain why you’re not able to restart VASSAL—the lock
file is how VASSAL tells if the Module Manager is already running,
to prevent you from having two of them running simultaneously.

We need to determine why Java is not exiting.

What is the least you can do which triggers the problem? Does it
happen without even opening a module?


J.

The least to reproduce is just to start VASSAL then quit, then try to start again. No Module opening required. :open_mouth:

Thus spake comdotski:

The least to reproduce is just to start VASSAL then quit, then try to
start again. No Module opening required.

How are you exiting the Module Manager?


J.

I can reproduce the problem using File->Quit or closing the window by clicking on the ‘x’ icon on the window.

Thus spake comdotski:

I can reproduce the problem using File->Quit or closing the window by
clicking on the ‘x’ icon on the window.

So, you’re quitting in the expected way, and “Exiting” makes it to the
errorLog. The relevant code looks like this:

logger.info(“Exiting”);
System.exit(0);

It would be useful to know if execution makes it to the second line,
and if so, whether our shutdown hook for cleaning up temp files is
finishing. I’ve made a test build for you:

vassalengine.sourceforge.net/bui … indows.exe

Try to reproduce the problem with this build, and post the errorLog
here.


J.

See below for the details after reproducing the problem … again there are multiple instances of Java running as seen in the Task Manager. Thanks for your persistence and assistance.

"C:\Users\tread_000\AppData\Roaming\VASSAL>dir
Volume in drive C is Performance mSATA
Volume Serial Number is 8895-B896

Directory of C:\Users\tread_000\AppData\Roaming\VASSAL

04/12/2013 08:16 PM .
04/12/2013 08:16 PM …
05/12/2013 07:28 PM 0 errorLog
01/12/2013 12:39 PM ext
05/12/2013 07:28 PM 12 key
05/12/2013 07:29 PM 0 lock
01/12/2013 12:38 PM plugins
02/12/2013 08:49 PM 576 Preferences
02/12/2013 08:52 PM prefs
02/12/2013 08:52 PM tiles
04/12/2013 08:17 PM tmp
4 File(s) 588 bytes
7 Dir(s) 83,198,627,840 bytes free

C:\Users\tread_000\AppData\Roaming\VASSAL>type errorlog
2013-12-05 19:28:39,160 [0-main] INFO VASSAL.launch.StartUp - Starting
2013-12-05 19:28:39,173 [0-main] INFO VASSAL.launch.StartUp - OS Windows 8 6.2
2013-12-05 19:28:39,173 [0-main] INFO VASSAL.launch.StartUp - Java version 1.6.0_45
2013-12-05 19:28:39,173 [0-main] INFO VASSAL.launch.StartUp - VASSAL version 3.2.9-svn8953
2013-12-05 19:28:40,030 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManager - Manager
2013-12-05 19:28:54,408 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManagerWindow - Exiting
2013-12-05 19:28:54,408 [0-AWT-EventQueue-0] INFO VASSAL.launch.ModuleManagerWindow - About to call System.exit(0)

C:\Users\tread_000\AppData\Roaming\VASSAL>"

Thus spake comdotski:

2013-12-05 19:28:54,408 [0-AWT-EventQueue-0] INFO
VASSAL.launch.ModuleManagerWindow - About to call System.exit(0)

So, System.exit(0) is running, but our shutdown hook never starts.
I.e., Java is not hanging in our code. It looks like you have either
a bad Java installation or you’re hitting a bug in Java, or possibly
you’re having a permissions problem with the files in
C:\Users\tread_000\AppData\Roaming\VASSAL\tmp.

What I would do is:

  • Delete everything in C:\Users\tread_000\AppData\Roaming\VASSAL\tmp,
    then run VASSAL.

  • Reinstall Java. Maybe try Java 7 if you can. Note that you should
    reboot between reinstalling Java and starting VASSAL.

Do either of these change the behavior you’re seeing?


J.

Thanks … I’ll give it a go and let you know how I get on.

The problem seems to have been solved.

I tried the suggestion to delete the tmp folder which did not work. I also deleted the entire VASSAL folder above the tmp folder and this did not help either. So I went to uninstall Java to prepare for a re-install, and noticed that both Java 7 and Java 6 were present. Thinking this might be a problem, I uninstalled Java 6. Trying after the uninstall I cannot reproduce the problem.

Thanks a heap for your assistance in getting to the root of the problem, it seems that Java 7 (32 bit) and Java 6 (64 bit) do not play well together, at least for VASSAL.

Let me know if I can help further, in case you need more details.

I can now get on with playing :smiley: , and back to the SOR 5 Player game development with confidence.

Tim

Thus spake comdotski:

I tried the suggestion to delete the tmp folder which did not work. I
also deleted the entire VASSAL folder above the tmp folder and this did
not help either. So I went to uninstall Java to prepare for a
re-install, and noticed that both Java 7 and Java 6 were present.
Thinking this might be a problem, I uninstalled Java 6. Trying after the
uninstall I cannot reproduce the problem.

We’ve known that Java 6 and Java 7 don’t play well togther for quite
some time, but the particular manifestation of this you had is one I
hadn’t seen before. Our “VASSAL Does Not Start” page has a section
about Java 6 and Java 7:

vassalengine.org/wiki/VASSAL_Does_Not_Start

It didn’t occur to me to point you there due to the fact that VASSAL
ran sometimes for you. Whenever I’ve seen this problem with conflicting
version of Java before, VASSAL won’t start at all.

I’m glad the problem is solved for you now.


J.

Thanks a bunch! The same problem was occuring for me on a new computer. Sure enough after uninstalling Java 6 VASAL works perfectly.