CMCMarkets and horrible Java

Fellow MVP Jurjen van Leeuwen dropped me an application that hadn’t been so successful in sequencing – based on a specific version of java (1.6.0.10 I think) that is installed along with the application itself.

The end-result of a sequence, after implementing the runasinvoker-fix to avoid issues with UAC, is the following;

Not that fun – and doesn’t tell me a whole lot.

The installed folder containing the application (one level up only contains the jre160 folder and the installer.log) looks like this;

Q:\MM5 Norway\MM5>dir
Volume in drive Q is App Virt
Volume Serial Number is 1010-1010
Directory of Q:\MM5 Norway\MM5
2011-10-26  10:11    <DIR>          .
2011-10-26  10:13    <DIR>          ..
2011-10-26  10:11    <DIR>          logs
2011-10-26  14:17             1 558 lasterror.ser
2011-10-26  14:12                23 nfo.ver
2011-10-26  10:03    <DIR>          resources
2009-06-24  16:48            59 576 iiDownloader.exe
2009-06-24  16:21           348 160 msvcr71.dll
2011-10-26  10:06           575 216 iiLauncher.exe
2011-10-26  10:06                14 iiLauncher.ver
2011-10-26  10:06                14 iiAppStart.ver
2011-10-26  10:06         1 328 938 iiAppStart.exe
2011-10-26  10:11           309 435 file.db
2011-10-26  10:11        11 769 946 cfile.db
2009-06-24  16:21                16 jre.dat
2009-06-24  16:49                16 freshInstall.dat
12 File(s)     14 392 912 bytes
4 Dir(s)   7 321 260 032 bytes free
Q:\MM5 Norway\MM5>

As you can imagine – logs contain specific log-files and lasterror.ser contains the lasterror.

Reviewing what activity happens during the initial execution using the Count Value Occurrencesfrom Process Monitor we can have an overview of what is happening;

There seems to be several process running during the startup and if we take into account that iiLauncher.exe has the most occurrences we can assume that this one fails. Using Process Monitor to identify when it would attempt to write to lasterror.ser could be an indication of when the application fails and if iiLauncher.exe is the executable that is writing to the lasterror.ser.

The above screenshot shows the first time the lasterror.ser is accessed by a process directly and reviewing the activity around it reveals no direct failure. The file rt.jar is accessed heavily by iiLauncher.exe and an attempt to access a .log.lck file (probably a lock attempt on a log-file) is successful. Lets review lasterror.ser and see if we can determine what of the above activity is relevant.

Lasterror, after our failed start, looks like this;

 

¬í sr (frontend.shutdown.error.ApplicationErrorXGõ®Ô*
L
m_creationTimet Ljava/util/Date;L   m_messaget Ljava/lang/String;L m_optionalThrowablet Ljava/lang/Throwable;[
m_stackTracet ‑[Ljava/lang/StackTraceElement;xpsr
java.util.DatehjKYt
xpw  3?NÀ6xt Failed to start launcher.sr .java.nio.channels.OverlappingFileLockExceptionkJJ5ñ^[1]  xr ­java.lang.IllegalStateExceptionæWUæšFòH[1]  xr java.lang.RuntimeExceptionž_G
4ƒå[1]  xr java.lang.ExceptionÐý­>;Ä[1]  xr java.lang.ThrowableÕÆ5'9w¸Ë
L causeq ~
L
detailMessageq ~ [1][
stackTraceq ~
xpq ~
pur ‑[Ljava.lang.StackTraceElement;[1]F*<<ý"9[1]  xp
sr java.lang.StackTraceElementa           Åš&6Ý…[1]
I
lineNumberL
declaringClassq ~ [1]L fileNameq ~ [1]L

methodNameq ~ [1]xpÿÿÿÿt .sun.nio.ch.FileChannelImpl$SharedFileLockTablept                                  checkListsq ~ ÿÿÿÿq ~ pt
addsq ~ ÿÿÿÿt sun.nio.ch.FileChannelImplpt tryLocksq ~ ÿÿÿÿt java.nio.channels.FileChannelpq ~ sq ~ ÿÿÿÿt java.util.logging.FileHandlerpt                                             openFilessq ~ ÿÿÿÿq ~ pt <init>sq ~    ¢t .frontend.remote.logging.DownloadLoggingDefaultt DownloadLoggingDefault.javat setUpDefaultLoggersq ~   !t 2frontend.remote.logging.DownloadLoggingInitialisert ­DownloadLoggingInitialiser.javat createDefaultJavaLoggersq ~    ¹q ~ &q ~ 't resetLoggingConfigurationsq ~    wq ~ &q ~ 't

initialisesq ~   |t (frontend.remote.launcher.UpgradeLaunchert UpgradeLauncher.javaq ~ ,sq ~   !q ~ .q ~ /t
runsq ~   œq ~ .q ~ /t
mainxuq ~
sq ~   Aq ~ .q ~ /t handleThrowablesq ~   ;q ~ .q ~ /q ~ 1sq ~   œq ~ .q ~ /q ~ 3w              2x

The error probably relates to an attempted file lock in the nio-module. Considering the activity we reviewed above – it could be the previously mentioned .lck.log-file that is having a problem.

A similar error has been posted here – which I believe Jurjen also addressed.
http://www.appvirtguru.com/viewtopic.php?f=9&t=3769
This one also travels the same path;
http://www.appvirtguru.com/viewtopic.php?f=9&t=3694

Now, Jurjen made a very good comment within the first thread – there seems to be a problem when locking files within the virtual environment. After reviewing a couple of procmon-traces – the only locations that was attempted to write to was %TEMP% and the q:\mm5 norway\mm5\logs (where the .log.lck file was located).

Also – the procmon trace told me that there were two files that were running; iiDownloader.exe, iiLauncher.exe. However, in the installation folder there were three executables named iiXXXX.exe (iiAppstart.exe was the last one). Potentially all of these could have a problem, but so far iiDownloader.exe has not revealed any problems and iiLauncher.exe potentially has problems.

Using ACT (Application Comapbility Toolkit) a shim was produced to redirect all file-writes for \logs to %LOCALAPPDATA% for the process iiLauncher.exe. Read more about the process of using the specific shim CorrectFilePaths from Vijay. He does an excellent job explaining the entire process. Chris Jackson has one remark (afterall – he is the Appcompat-guy) that the folder we are redirecting to needs to exist. Remko Weijnen did quite a few write-ups which explains several scenarios that this can be used for. Even vendors recommends using shims!
Shims are very easily installed from ACT and can also be installed using a command-line tool– which makes the testing task very easy. Once installed – the shim is effective immediately and thus our next startup should show if the shim has made a difference.

Suddenly the initial error message has disappeared and instead we have a very brief glimpse of the above screen. Something has changed and perhaps we have removed a first obstacle.

Using Cross Reference Summary we reveal that a new process has shown up – iiAppstart.exe. Using File Summary with aggressive filtering (only include iiAppstart.exe) we can see that it also has a similar behavior of accessing .lck files.

Therefore we create a new shim which implements the same fix for iiAppstart.exe as we previously created for iiLauncher.exe and save it into the same database (.sdb)-file usint ACT.

Once the shim is installed the following shows up (which would count as a success, right?);

Using Process Monitor in this case revealed no direct failures – ACCESS DENIED and FILE NOT FOUND were not relevant. By tracking what application was ran, what files were read and what files were written to we could determine potential root causes and implement probable solutions very quickly.