For sequencing in App-V 5, the new ETW model simplifies the process and moves App-V to the Windows standards for event tracing. Even better, the sequencer not only has two logs to worry about (operational and administrative) but a simple process can occur to enable more verbose debug logging.
In App-V 4.6, the process was not that simple. While the logs did not write to the Event Viewer-able logs, all but one are text-based which makes for easy manipulation with your favorite log parser. I prefer Trace32 of course! These log files are stored in the logs subdirectory of the Sequencer installation directory which defaults to C:\Program Files\ Program Files\Microsoft Application Virtualization Sequencer\Logs. Certain logs pertain to specific functions so the relevancy will vary on whatever your troubleshooting scenario might be.
SFT-Seq-log.txt: The majority of sequencer logging occurs here (Uploads to virtual environment, downloads from the virtual environment, service starts and service stops, etc.)
SFTrbt.txt: This is the sequencer reboot log file. When the 4.6 sequencer simulates reboots, the elements that are processed will be tracked in this log file.
SFTCallBack.txt: This is a more simple logs that allows you to reconsile process starts and stops during sequencing. It works great in conjunction with a process monitor log.
Filter.log: Outside of working with Microsoft Support, this log is not very useful as it is obfuscated. It tracks file activity but must be decoded with an internal utility. You can enable further tracking into a file called files.txt which will contain a log of all files created in the VFS. This can be enabled (although it will increase sequencing time) by enabling the following value in the registry:
- Key: HKEY_LOCAL_MACHINE\Software\Microsoft\SoftGrid\4.5\Sequencer\Configuration\
- Value: FileManifest
- Data Type: REG_DWORD
- Data: 1
SFTrpc.txt: This is the log file created by the monitoring element SFTRPC.EXE and in addition to also capturing process startup and shutdowb, will also contain verbose diagnostic information about each monitored shortcut.
In addition to the sequencer logs, you can also leverage process monitor (http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx) and verbose MSI logging (http://madvirtualizer.wordpress.com/2014/03/17/enabling-advanced-windows-installer-logging/) if you encounter errors within the application during sequencing.
App-V 4.6 is still very prevalent out there and will be for a while. With the releases of Windows 8 and Windows 8.1 brought additional service packs for the App-V 4.6 client which means upgrades and/new installs for newer operating systems. Several weeks back on this blog, I went over how to enable advanced MSI logging for troubleshooting MSI installs and upgrades (Remember VOICEWARMUP – http://madvirtualizer.wordpress.com/2014/03/17/enabling-advanced-windows-installer-logging/ ) but I would like to now address some follow up emails I received. Admins would like more specific information on how to go through and read that potentially enormous log in order to find out what is failing where and when.
I would never advising reading a verbose MSI installation log from start to finish especially when dealing with potentially asynchronous actions. MSI logs also have an excessive amount of rollback information incorporated into the log upon failed installations. The seasoned IT Pro often looks for specific keywords such as “error” and “failed” and that can be misleading as not all logs generate these types of messages. In addition, searching on the string “error” can also yield false positives as well.
When I am looking at Verbose MSI logs of App-V 4.6 client installs, I usually analyze the log by doing the following:
- Searching for the error string generated in the App-V Installer User Interface with quotations.
- Searching using the string “1603.” See if it indicates that a custom action has failed.
- Searching using the string “Value 3.” This will indicate an install error. This can also help to identify the custom action failure.
- Searching for string “IsInBadState()” can also be helpful if there is an issue with a failed driver install. This is especially useful in troubleshooting an upgrade. Usually when this occurs, you usually need to delete the driver configuration and state of the specific App-V file system driver specified in order to reattempt the upgrade.
Finally if you need to walk through the App-V custom actions, you can do so by searching by the strings ‘SWI” or “SGC” as all of the App-V custom actions begin with these prefixes.
CustomAction SWI41sp1UpgradeFix returned actual error code 1603
You can walk through the logging of each key App-V custom action. Once you’ve identified what custom action failed, you can then use the following reference to find out specifically what was being attempted with the custom action here: http://support.microsoft.com/kb/2465574. Even though it specifies SP1, it is still valid and helpful for SP2 and SP3. For example the action reference above would be:
Installer : Client
Method name: SWI41sp1UpgradeFix
Description: Modifies an installed instance of the Softgrid 4.1SP1/4.2 client application to correctly support upgrading to a later version.
You can then dive deeper into the timeline of the action and align it with a more deep logging utility such as Process Monitor.
App-V 4.5 and 4.6 virtualize at the user mode layer. One of the most identifying factors of seeing that a thread stack is that of a virtualized application is the presence of the SFTLDR.DLL file. This is what is injected into every process a virtual application will create. This file is responsible for ensuring proper redirections and translations necessary to make virtualization function properly by:
- File changes to included virtual directory and file paths are redirected to the VFS
- Registry changes hooked and redirected to the virtual registry
- The spoofing of objects
- The spoofing of COM GUIDS
In addition to the common troubleshooting methods such as disabling local interaction and disabling object spoofing, you can also take things further by disabling various virtualization components using the System Guard Overrides in App-V 4.x. These are not meant to be solutions but isolation factors in case you need to modify mappings. Many of these can be set at the registry level affecting the entire client or at the application level using the OSD file.
All of the registry values mentioned are located under HKLM\SOFTWARE\Microsoft\SoftGrid\4.5\SystemGuard\Overrides:
Disabling Virtual Services
You can disable virtual services on a per package basis by adding in the <VIRTUAL_SERVICES_DISABLED> tag under the <POLICY> XML element in the OSD file. You can disable the subsystem for the entire client by going adding the DisableVirtualServices DWORD value with a value of 1. If this is enabled, the sftldr.dll will not hook the service APIs.
Disabling the Virtual Registry
You can disable the virtual registry on a per package basis by adding in the <VIRTUAL_REGISTRY_DISABLED> tag under the <POLICY> XML element in the OSD file. You can disable the subsystem for the entire client by going adding the DisableVreg DWORD value with a value of 1. If this is enabled, the sftldr.dll will not hook the virtual registry calls.
Disabling the Virtual File System
You can disable the virtual file system on a per package basis by adding in the <VIRTUAL_FILE_SYSTEM_DISABLED> tag under the <POLICY> XML element in the OSD file. You can disable the subsystem for the entire client by going adding the DisableVFS DWORD value with a value of 1. If this is enabled, the sftldr.dll will not hook virtual file system calls.
Finally, if you are really interested in going to the extreme . . .
You can disable ALL hooking. Can be useful when you are launching an application that is locally installed but still being brought into the virtual bubble. This allows you to turn it on and off if troubleshooting odd behavior. This is done at the client level which is why it is definitely only a troubleshooting option. You can disable hooking by adding in the registry value DisableSftldr DWORD value with a value of 42. Why 42? Well because that is the answer to everything in the universe. This basically makes the sftldr.dll (which is the primary hook DLL) dormant. MAVINJECT32 (or MAVINJECT64 if a 64-bit system) will still inject this DLL though. It will just remain dormant. This is a last resort.
If you are working with an application that has been virtualized with App-V 4.x and that application is not functioning as expected, one of the first steps in troubleshooting should always be to try to determine if the issue is related to sequencing or related to virtualization. For the standard application, Devirtualization is pretty straight-forward and pointed out in the following article:
One you have determined that the issue is likely a virtualization issue (done by successfully de-virtualizing using the article above) then you can proceed to quickly troubleshoot the issues further using a variety of approaches. One good source for V 4 troubleshooting is John Behneman’s post on the App-V team blog: http://blogs.technet.com/b/appv/archive/2012/11/14/3494514.aspx
You can also take this further by enabling the SFTLDR unhandled exception log (SFTLDR.LOG) which tracks hidden errors within the SFTLDR hook DLL which is the most critical virtualization DLL.
To enable the SFTLDR.LOG, create a string (REG_SZ) value called UnhandledExceptionFilterLocation within the following registry key: HKLM\SOFTWARE\Microsoft\SoftGrid\4.5\SystemGuard
For the Value data, you will want to put in the path to an existing directory that is at least one level deep from the root of the drive (i.e. C:\\TEMP\\SFTLDR.LOG.) Also note that I have to double the slash count for paths.
The SFTLDR.LOG file looks like this:
[08/27/2014 18:21:26.379] [03ac] [0a38] [Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\hail.exe] HookedLoadLibraryExW. lpLibFileName=Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\test.dll
[08/27/2014 18:21:26.379] [03ac] [0a38] [Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\hail.exe] HookedLoadLibraryExW: SXS start
[08/27/2014 18:21:26.379] [03ac] [0a38] [Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\hail.exe] HookedLoadLibraryExW: No mapping for Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\test.dll
[08/27/2014 18:21:26.410] [03ac] [0a38] [Q:\KK_HAWT.BTY\LISTA\RUN\FIRST\hail.exe] HookedLoadLibraryExW: LoadLibrary failed (1). dwLastError=14001
I recently resolved a long standing issue that affected legacy web applications running inside a MED-V 2.0 workspace. Often web applications will trigger documents and other objects that will launch within their respective host application either through an instance of that application via COM or through a special control via ActiveX (like PDF documents.)
On more than one occasion involving one or more application the parent windowed application (usually a legacy version of Internet Explorer) will trigger an application to launch containing critical data sent to that application by way of the web application. Usually this followed a Java process that would crunch some data and then generate a document object, populate the data and then launch the form from within Microsoft Word. What was happening in every case of this issue was – the Word Window never displayed when running inside a MED-V workspace.
Make sure the problem is not resolved with the super-secret hotfix.
First of all, if you are experiencing the occasional disappearing window, there was an out of band hotfix for the Windows XP RDPShell that addressed disappearing windows. You can call up Microsoft support and request this hotfix by its name (KB2446473.) However, this only addresses a flaw in the RDPShell and did not likely apply in the cases I mentioned above because these problems were not intermittent. They were very consistent and could be reproduced consistently.
Tracking it down . . .
Running the workspace in full screen mode never exhibited the issue. This issue only occurred when running in the seamless mode of MED-V. Launching a parallel command prompt in the workspace and running tlist.exe revealed that the WINWORD.EXE process was running so the application was not crashing. Killing the MEDVGUEST.EXE process from a command prompt prior to attempting to reproduce the problem caused the issue to go away as well. This led to me down the path of investigating what was really going on. The active Word window was being sent behind the browser window and was not being brought to the foreground for the RAIL mechanism used by MED-V to display the active window. Further debugging revealed LockSetForegroundWindow as a common denominator. Some research into the SetForegroundWindow function (http://msdn.microsoft.com/en-us/library/ms633539(VS.85).aspx) and/or LockSetForegroundWindow function (http://msdn.microsoft.com/en-us/library/ms633532(VS.85).aspx) yielded a way to control this.
- HKEY_CURRENT_USER\Control Panel\Desktop
- Value: ForegroundLockTimeout
- Data Type: DWORD
If the time required to launch the Word application window is less than the value specified in the ForegroundLockTimeout, the application will be launched behind the Internet Explorer window.
If the time taken to load the Word window is greater than the time set in ForegroundLockTimeout registry key, the window will be launched on top of Internet Explorer. Setting this value inside the workspace to 0 resolved the issue.
While this may likely resolve all instances of this type of problem bear in mind that I also learned that if the base priority of Internet Explorer is higher than the Microsoft Word window, it will still be launched behind the Internet Explorer window to avoid active window focus change.
The Role of Server Groups in App-V 4
Server groups are for configuring a server or server farm to have alternate provider policies, server-centric application management, and/or alternate logging pipelines to databases.
Provider policies are bound to users and servers by way of server groups. Provider Policies can control client configuration for:
- Publishing/Refresh Intervals
- In prior versions of Softgrid, this also controlled Authentication methods. This has been deprecated in 4.5. Only Windows Authentication is supported
- Type of License enforcement
Some Administrators would rather manage their provider policies by server as opposed to simply user groups, therefore they use this method. After creation of the server group object, an administrator can then associate an alternate provider policy with the server group:
Provider Policies can also toggle application usage on and off. Alternate Pipelines for logs can control excessive database traffic going out on the WAN
Application Association and Management
You can also associate applications with a specific server group:
Assigning applications to a specific server group involves configuring the application itself for server group membership. You will then see the application show up under the “Applications” tab in the properties of the server group.
The applications tab is for informational purposes only to determine a quick view of which applications associated with each server group are currently enabled.
Once you create a server group, you can also use this to control the pipeline for logging. This will require at least one server object to reside in the group. This has to originate as a pre-created server object. You can pre-create a server object by right-clicking the server group and selecting “New Application Virtualization Management Server.”
Once your servers have been configured/installed inside the server group, you can control the log pipeline methodology (although the options are more limited starting with version 4.5 and later. While the “File” option is available in the interface, it no longer works on versions 4.5 and later. The only log type supported is SQL Database.
By default, the destination is the AppVirt Database using the same SQL server that was specified when the database was first created during the installation of the first App-V server. The default event type is “Warnings/Errors.”
Given the potential growth of the MESSAGE_LOG table inside the SQL data store and the additional web traffic it can create, some App-V server administrators will leverage local datastores for logging while using a central App-V datastore for application and overall management control. Each server can then send these messages to that server’s MESSAGE_LOG table.
For those of you still using App-V 4 (hopefully at least App-V 4.6 on the client side and 4.5 SP2 on the server side due to supportability) you may have been reading about how App-V 5 resolves a lot of limitations of App-V 4 – especially those that revolve around scalability. I dealt with many customers in support and still get questions on existing App-V 4.x deployments. The most common one revolves around keeping the existing 4.5 server(s) running optimally. I figured I would let the users out there (who are still using App-V 4.5 servers) know that I know they are still out there and remind them of the key factors that lead to performance issues
Watch the Cores and Dispatcher
App-V 4.5 runs usually on four instances of the core process (SGHWVR.EXE or SQLQVR.EXE if using the lightweight streaming server) as well as the dispatcher service. These are usually the key processes to monitor for CPU spikes. In normal operation, utilization should be evenly dispersed. In some cases you may see one or more spiked out due to likely one of the related issues listed below:
Update 4.5 Server to at least 4.5 SP2 plus these Hotfixes.
You should be running at the very least HF2 for App-V 4.5 SP2 with this hotfix being applied:
“Hotfix Package 2 for Microsoft Application Virtualization 4.5 SP2: March 2011” http://support.microsoft.com/kb/2507096/en-us
The App-V 4.5 Management Server should be updated to at least version plus the following should you be working with SQL database mirroring:
“FIX: An App-V 4.5 SP2 server cannot recover when an application virtualization database fails over” http://support.microsoft.com/kb/2873468/en-us
In addition to these hotfixes, you may want to also include this out of band fix which involves adjusting the back end database. I personally worked on this issue while I was in support and I can tell you that this fix makes a tremendous impact but must be done with caution:
“A publishing refresh might time out and return the 0A-10000005 error code on an App-V 4.5 client” us
Check the Database Values of Server Objects
If you are running with a less than optimal amount of cores or suspect performance issues after pre-creation of server objects prior to scaling out, you could be falling victim to the default limited values that come with pre-creating server objects. Check out this article to resolve it: http://blogs.technet.com/b/appv/archive/2010/05/10/pre-creation-of-server-objects-may-yield-certain-sub-optimal-values-in-the-app-v-sql-database.aspx
Large SFT-Server.LOG file
When the server log gets too large or is set to a high verbosity level, it can impact performance. Regular maintenance of the log files (planned purging) as well as setting an optimal verbosity level (2 likely) will prevent this from occurring. The logging level for the Application Virtualization Management Server can be changed in the registry at:
Keeping it at a level no greater than 3 is recommended.
Large APPLICATION_USAGE and MESSAGE_LOG tables
These tables can grow very large if unchecked, be it intentionally (i.e. no SQL agent running, running SQL Express) or unintentionally. The background of this long standing issues can be found here: http://blogs.technet.com/b/appv/archive/2008/08/04/troubleshooting-softgrid-database-growth-issues.aspx
The trouble is that you might be encountering this issue because the SQL jobs are not running properly or at all. Especially if you are running a more recent version of SQL Server or have just migrated databases. The Technet gallery has some scripts that can help you fix these jobs should they be failing:
SQL script that creates the SQL 4 Jobs that are required by the App-V DB: http://gallery.technet.microsoft.com/SQL-script-that-creates-b6345446
SQL script to allow App-V Check Usage History job to run on SQL 2008: http://gallery.technet.microsoft.com/SQL-script-to-allow-App-V-959bc1d4
SQL script to allow App-V Check Usage History job to run on SQL 2008 #2: http://gallery.technet.microsoft.com/SQL-script-to-allow-App-V-f656ac69
Limitations of Ephemeral Ports Used for RTSP
Delays in launching and launch timeouts can be traced to a defining limit in the amount of service requests an App-V management or streaming server can hold. This is due to the ephemeral port range defined by the default App-V 4.5 server configuration – http://blogs.technet.com/b/gladiatormsft/archive/2011/08/31/how-to-adjust-increase-reduce-the-rtcp-rtp-port-ranges-for-use-with-rtsp.aspx
Streaming Performance due to improperly configured Offloading or Block Size
Both the Underlying TCP offloading stack configuration and the block size for RTSP can be factors to slow streaming performance:
TCP Offloading Information: http://support.microsoft.com/kb/951037
RTSP Streaming Issue with block size: http://blogs.technet.com/b/gladiatormsft/archive/2011/11/28/the-default-block-size-of-64kb-in-app-v-4-6-and-later-may-cause-slow-streaming-with-certain-network-configurations.aspx
As App-V 4.5 is in extended support, the likelihood of new problems is low but not impossible with App-V 4.6 SP3 running on modern operating systems. However, I would recommend you verify the above before contacting support.