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;

clip_image002

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;

image

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.

image

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;


&nbsp;

¬í 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.

imageUsing 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.

image

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.

image

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.

image

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?);

clip_image006

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.

7 Comments

  1. Hi Nicke,

    Nice to see you use App Compat to solve this issue and a very good write up.
    Thumbs up!

    November 7, 2011
    Reply
  2. User RajAttaluri posted a very useful tip on AppVirtGuru.com in this post: http://www.appvirtguru.com/viewtopic.php?f=9&t=3694#p17792

    I tested it with MarketMaker and can confirm this works at least up to the same point(login) as Nicke’s fix. Logging still seems to be working. I modified the envlist tag from my OSD file like this:

    -Dsun.nio.ch.disableSystemWideOverlappingFileLockCheck=true

    Can’t say what the big downside is off disabling this checking but the big advantage is we don’t need to deploy something on the actual client.

    July 3, 2012
    Reply
    • Oops tag info got lost. But the variable: JAVA_TOOL_OPTIONS have the value: -Dsun.nio.ch.disableSystemWideOverlappingFileLockCheck=true

      July 3, 2012
      Reply
    • nickekallen said:

      Great share Jurjen!

      July 4, 2012
      Reply
  3. Raj Attaluri said:

    I am also not sure the downside is off disabling this checking.I decided to use this fix based on this OverlappingFileLock check functionality is new in Java 1.6 and the application worked with previous versions of Java where this check functionality doesn’t exist.

    In the link its mentioned “If this system property is set (or is set to some value other than false) then java.nio.channels.FileChannel.lock checks for overlapping file locks obtained using this FileChannel instance only. Locks acquired by other FileChannel instances to the same file are not checked.”

    The application works fine if installed locally. So it seems the APP-V client may applying the file lock and Java throwing the exception error as it finds another file channel instance locked the file.

    July 5, 2012
    Reply
    • nickekallen said:

      Hello,
      Not really sure why this happens either – but yes, it relates to App-V providing another layer and locking files within the virtual environment. As long as the file is in the native file-system – it all works well.
      The env var fix is much nicer than my previous recommendation for a shim – however, it seems that this is ressolved as far as I know in App-V v5.

      July 5, 2012
      Reply

Leave a Reply

Your email address will not be published. Required fields are marked *