In the previous installment, I outlined what you might find in the personal vDisk (PVD) filter driver log. That log contains entries generated during early machine boot, when PVD is locating its disk and getting the machine ready for persistent personalization. That log also (possibly) contains error messages and information when the PVD driver finds a resource it can’t intercept, redirect, or process. When these types of errors are encountered, the result is generally application incompatibility (fortunately this is a rare occurrence.)

What’s not in the PVD driver log, however, is anything related to the maintenance or management of the PVD disk. In the previous installment, we just assumed that there would be a properly initialized PVD disk with the user’s application area VHD present – I didn’t explain how that disk was prepared in the first place.

The part of the PVD feature that manages the PVD disk is the PVD User Mode Service (CtxPvdSvc). The service is responsible for a number of important things.

In the base VM:

  • Handle inventory creation and template VHD preparation

During initial VM preparation:

  • Detecting the unformatted disk attached to the VM during the first boot (this is the disk attached by the provisioner to the VM during creation)
  • Formatting the disk on the first boot and copying the template VHD from the base image (created during inventory operation)
  • Rebooting the VM after initial preparation

On image update:

  • Compute differences made between new base VM inventory and previous inventory, merging those changes into the user PVD

With such a large number of important responsibilities, it shouldn’t be surprising that the service log (C:\ProgramData\Citrix\personal vDisk\Logs\PvdSvcLog.txt) can become quite large.

Today, we’ll look at what is logged during an inventory operation. Next time, we’ll look at the log entries generated during image update. Like last time, I’ve omitted log entries that are irrelevant for the purposes of this blog.

 

[INFO ][02-23-2012 14:04:29]WSFileSystem.cpp        [1582] Removed file C:\ProgramData\Citrix\personal vDisk\UserData.VDESK.TEMPLATE
[INFO ][02-23-2012 14:04:29]VDeskNativeUtil.cpp     [1553] OS Version:6.1, Build:7601, PlatID:2, MaintStr:Service Pack 1, SPVersion:1.0, Suite:0x100, ProdType:1
[INFO ][02-23-2012 14:04:29]VDeskNativeUtil.cpp     [1561] PvD Build Number 21
[ERROR][02-23-2012 14:04:29]VDeskNativeUtil.cpp     [1522] DoPVSCheck: Failed to retrieve PVS product version. Err=0x2
[INFO ][02-23-2012 14:04:29]ImageUpdateVDeskNativeOP.cpp[0444] Created temporary memory dump file
[INFO ][02-23-2012 14:04:29]ImageUpdateVDeskNativeOP.cpp[0703] START CREATE-INVENTORY C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:04:29]WSFileSystem.cpp        [2126] Compression Enabled on C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:04:29]WSSidHelper.cpp         [1173] Path C:\ProgramData\Citrix\personal vDisk\Inventory is now secure

Inventory operations begin by setting up the service, and detecting various other components that may be installed (PVS, for example).

 

[INFO ][02-23-2012 14:04:29]WSFileSystem.cpp        [1808] \\?\C:\Documents and Settings is reparse type 0xa0000003 , SubstName:\??\C:\Users,PrintName:C:\Users
[INFO ][02-23-2012 14:04:50]WSFileSystem.cpp        [1808] \\?\C:\ProgramData\Application Data is reparse type 0xa0000003 , SubstName:\??\C:\ProgramData,PrintName:C:\ProgramData
[INFO ][02-23-2012 14:04:50]WSFileSystem.cpp        [1808] \\?\C:\ProgramData\Desktop is reparse type 0xa0000003 , SubstName:\??\C:\Users\Public\Desktop,PrintName:C:\Users\Public\Desktop
[INFO ][02-23-2012 14:04:50]WSFileSystem.cpp        [1808] \\?\C:\ProgramData\Documents is reparse type 0xa0000003 , SubstName:\??\C:\Users\Public\Documents,PrintName:C:\Users\Public\Documents
...
...
...
[INFO ][02-23-2012 14:05:06]WSFileSystem.cpp        [1808] \\?\C:\Users\Public\Documents\My Pictures is reparse type 0xa0000003 , SubstName:\??\C:\Users\Public\Pictures,PrintName:C:\Users\Public\Pictures
[INFO ][02-23-2012 14:05:06]WSFileSystem.cpp        [1808] \\?\C:\Users\Public\Documents\My Videos is reparse type 0xa0000003 , SubstName:\??\C:\Users\Public\Videos,PrintName:C:\Users\Public\Videos
[INFO ][02-23-2012 14:06:44]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::WSFileSystem::snapit took 134 secs

Inventory creation involves surveying the files and registry key/values on the base VM, so that a PVD resource catalog can be created to match the base VM’s content. In order to do this, we recursively scan the base VM filesystem, recording each file we see. Reparse points present in the base VM are treated specially, so those are outlined in the log. In this particular example, the file scan operation took 2m14s (134s).

 

[INFO ][02-23-2012 14:06:44]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR SOFTWARE @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:18]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR SOFTWARE @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:18]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateRegistryInventory took 34 secs
[INFO ][02-23-2012 14:07:18]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR SYSTEM\CurrentControlSet @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:19]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR SYSTEM\CurrentControlSet @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:19]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR SAM @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:19]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR SAM @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:19]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR SECURITY @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:19]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR SECURITY @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\services\{D1CF5596-BD2A-47C9-AB7B-8CBC9D05DD72}, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\services\{68CCC7B9-CFB7-42E3-AA3C-3ADB6F815580}, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\services\Windows Workflow Foundation 4.0.0.0\Linkage, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\services\Windows Workflow Foundation 3.0.0.0\Linkage, Location:0 Attribute:0
...
...
...
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\Control\Class\{4D36E974-E325-11CE-BFC1-08002BE10318}, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\Control\Class\{4D36E973-E325-11CE-BFC1-08002BE10318}, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]vDeskCatalogHelper.cpp  [0103] Create catalog entry \REGISTRY\MACHINE\SYSTEM\CurrentControlSet\Control\Class\{4D36E972-E325-11CE-BFC1-08002BE10318}, Location:0 Attribute:0
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR VDCATALOG @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0288] END CREATE REGISTRY INVENTORY FOR VDCATALOG @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR RINGTHREE @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0288] END CREATE REGISTRY INVENTORY FOR RINGTHREE @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR S-1-5-18 @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR S-1-5-18 @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:20]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR S-1-5-19 @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:21]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR S-1-5-19 @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:21]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR S-1-5-20 @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:21]ImageUpdateVDeskNativeOP.cpp[0307] END CREATE REGISTRY INVENTORY FOR S-1-5-20 @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:21]ImageUpdateVDeskNativeOP.cpp[0254] START CREATE REGISTRY INVENTORY FOR Components @ C:\ProgramData\Citrix\personal vDisk\Inventory
[INFO ][02-23-2012 14:07:23]ImageUpdateVDeskNativeOP.cpp[0288] END CREATE REGISTRY INVENTORY FOR Components @ C:\ProgramData\Citrix\personal vDisk\Inventory with success
[INFO ][02-23-2012 14:07:23]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateRegistryInventory took 2 secs
[INFO ][02-23-2012 14:07:29]ImageUpdateVDeskNativeOP.cpp[0886] END CREATE-INVENTORY, STATUS 0
[INFO ][02-23-2012 14:07:29]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::BuildInventory took 180 secs

Similarly, the inventory operation snapshots the registry hives and subkeys on the machine. You’ll note that multiple root hive keys are snapshotted (eg, SOFTWARE, SYSTEM, and the built-in user profiles). Registry scanning complete, the inventory operation took exactly 3 minutes, 180s in this case (so far). At this point, the inventory data is in the service memory, and has not yet been transformed into a template VHD (which will, in turn, become the starting point for all user PVD application area VHDs created from this base VM).

 

[INFO ][02-23-2012 14:07:29]ImageUpdateVDeskNativeOP.cpp[0460] Removed temporary memory dump file
[INFO ][02-23-2012 14:07:29]VDeskNativeActivation.cpp[2151] Mounted guest hive from inventory for fixup
[INFO ][02-23-2012 14:07:29]WSSidHelper.cpp         [1173] Path C:\ProgramData\Citrix\personal vDisk\Inventory\36625390-2101-4d43-9c86-1e0172666659.VDESK is now secure
[WARN ][02-23-2012 14:07:29]VDeskNativeVDIConfig.cpp[0147] RegQueryValueEx failed for EnableVPN, Error:2
[INFO ][02-23-2012 14:07:29]VDeskNativeVDIConfig.cpp[0467] Support for User Installed VPN Client is disabled
[INFO ][02-23-2012 14:07:29]WSSidHelper.cpp         [1173] Path C:\ProgramData\Citrix\personal vDisk\UserData.vhd.tmp is now secure
[INFO ][02-23-2012 14:07:30]VDeskNativeActivation.cpp[0628] Mounted C:\ProgramData\Citrix\personal vDisk\UserData.vhd.tmp at M:\
[INFO ][02-23-2012 14:07:32]WSSidHelper.cpp         [1173] Path M:\CitrixPvD\Settings\Inventory is now secure
[INFO ][02-23-2012 14:07:32]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateVDeskFileSystemAndCatalogStageONE took 2 secs

The service then creates UserData.vhd.tmp and mounts it at an unused letter (temporarily, and in this case M: )

 

[INFO ][02-23-2012 14:07:32]ImageUpdateVDeskNativeOP.cpp[0912] START CREATE-PACKAGE-EX(FULL) M:\CitrixPvD\Settings\Inventory\VER-TEMP
[INFO ][02-23-2012 14:07:37]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::WSFileSystem::save_diff_native took 2 secs
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for SOFTWARE, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for SYSTEM\CurrentControlSet, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for SAM, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for SECURITY, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for VDCATALOG, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for RINGTHREE, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for S-1-5-18, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for S-1-5-19, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for S-1-5-20, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[0349] Registry diff package not created for Components, Previous inventory not available
[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[1008] END CREATE-PACKAGE-VDESKNATIVE, STATUS 0
[INFO ][02-23-2012 14:07:37]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreatePackageEx took 4 secs
[INFO ][02-23-2012 14:07:37]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateVDeskFileSystemAndCatalogStageTWO took 4 secs

The service then proceeds to populate the template VHD with the registry catalogs previously calculated. At this point, the inventory/image update rules are consulted to know which catalog entries should be populated into the template VHD (see my talk from Synergy last May, SYN119, for information on these rules files.)

 

[INFO ][02-23-2012 14:07:37]ImageUpdateVDeskNativeOP.cpp[2651] START CREATE-VDESKNATIVE-FILESYSTEM USING M:\CitrixPvD\Settings\Inventory\DIFF @ M:\
[ERROR][02-23-2012 14:07:41]WSFileSystem.cpp        [2773] GetNamedSecurityInfo failed for \\?\C:\pagefile.sys,Error32
[INFO ][02-23-2012 14:07:57]ImageUpdateVDeskNativeOP.cpp[3011] File \ProgramData\Microsoft\Crypto\RSA\MachineKeys\f686aace6942fb7f7ceb231212eef4a4_4f1ad374-580d-47d5-82f2-addc7216dfb0 of size 2.161 KB got relocated to the guest volume
[INFO ][02-23-2012 14:07:57]ImageUpdateVDeskNativeOP.cpp[3011] File \ProgramData\Microsoft\Crypto\RSA\S-1-5-18\6d14e4b1d8ca773bab785d1be032546e_4f1ad374-580d-47d5-82f2-addc7216dfb0 of size 47 Bytes got relocated to the guest volume
[INFO ][02-23-2012 14:07:57]ImageUpdateVDeskNativeOP.cpp[3011] File \ProgramData\Microsoft\Crypto\RSA\S-1-5-18\83aa4cc77f591dfc2374580bbd95f6ba_4f1ad374-580d-47d5-82f2-addc7216dfb0 of size 45 Bytes got relocated to the guest volume
[INFO ][02-23-2012 14:08:11]ImageUpdateVDeskNativeOP.cpp[3011] File \Windows\inf\setupapi.app.log of size 1.495 MB got relocated to the guest volume
...
...
...
[INFO ][02-23-2012 14:09:00]ImageUpdateVDeskNativeOP.cpp[3011] File \Windows\System32\wbem\Repository\MAPPING3.MAP of size 50.696 KB got relocated to the guest volume
[INFO ][02-23-2012 14:09:01]ImageUpdateVDeskNativeOP.cpp[3011] File \Windows\System32\wbem\Repository\OBJECTS.DATA of size 15.704 MB got relocated to the guest volume
[INFO ][02-23-2012 14:09:49]ImageUpdateVDeskNativeOP.cpp[3033] Number of files relocated 64, Total size of all files relocated 37.144 MB
[INFO ][02-23-2012 14:09:49]ImageUpdateVDeskNativeOP.cpp[3055] END CREATE-VDESKNATIVE-FILESYSTEM, STATUS 0
[INFO ][02-23-2012 14:09:49]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::BuildVDeskFileSystem took 132 secs
[INFO ][02-23-2012 14:09:50]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateVDeskFileSystemAndCatalogStageFinal took 132 secs
[INFO ][02-23-2012 14:09:50]ImageUpdateOP.cpp       [0081] RingCube::ImageUpdate::IUVDESKNATIVE_OP::CreateVDeskFileSystemAndCatalog took 139 secs
[INFO ][02-23-2012 14:09:51]VDeskNativeActivation.cpp[0650] Template VHD C:\ProgramData\Citrix\personal vDisk\UserData.VDESK.TEMPLATE successfully created

Similarly, the file content of the template VHD is also created, based again on the rules from the rules files. Certain files are “pre-staged” into the template VHD (see above where certain files “got relocated to the guest volume”). These are things that need to have write access from PVD’s perspective – we can’t leave these on the base VM or they will be reverted as soon as the VM is reset. These types of files include certificates/keys from the base VM, as well as Antivirus software definitions.

Once the inventory is created, the template vHD is dismounted and saved as UserData.VDESK.TEMPLATE.

What could go wrong during inventory creation, and what might one see in the log? Inventory creation errors are usually due to one of a few common problems:

  • Insufficient space in the template VHD for prestaged files (the template VHD is only 2GB in size, and if you have more than 2GB of prestaged files, this operation will fail). This usually occurs when your base VM has a large amount of antivirus definitions stored in it.
  • Failure to analyze the filesystem or registry on the base VM for some reason. This might happen if there is another application installed in the base that interferes with PVD’s inventory survey, and usually is attributable to over-zealous security applications. You might need to disable (not uninstall) such security software before taking the PVD inventory.

Next time, we’ll look at the other part of the PVD service log, which is generated during image update operations.