USMT loadstate caught in an (near) infinite loop?

Question

I'm attempting to introduce USMT into my company's environment for all of our future migrations. While doing some testing, I have a backup store that refuses to restore, with some very bizarre results.

When extracting a small MIG file (600MB), that would normally only take a couple of minutes to complete - it goes on and on for about 20-30 minutes. The loadstate.log file get enormous, filled with this, just repeating (over about a million lines in the log):

2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Compressed=C:, Mapped=C:, DestExpanded=C:\
2013-06-21 18:08:23, Info                  [0x080000] Creating stream copy in C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5290.tmp (362 bytes)
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Links C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5290.tmp and C:\Users\SYPKENJM\AppData\Roaming\Microsoft\Windows\Recent\Local (C) (667).lnk differ in target paths: 'C:\' vs. 'C:\'
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Compressed=C:, Mapped=C:, DestExpanded=C:\
2013-06-21 18:08:23, Info                  [0x080000] Creating stream copy in C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5291.tmp (362 bytes)
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Links C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5291.tmp and C:\Users\SYPKENJM\AppData\Roaming\Microsoft\Windows\Recent\Local (C) (668).lnk differ in target paths: 'C:\' vs. 'C:\'
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Compressed=C:, Mapped=C:, DestExpanded=C:\
2013-06-21 18:08:23, Info                  [0x080000] Creating stream copy in C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5292.tmp (362 bytes)
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Links C:\Users\SYPKENJM\AppData\Local\Temp\tmp848C.tmp\Temp\tmp5292.tmp and C:\Users\SYPKENJM\AppData\Roaming\Microsoft\Windows\Recent\Local (C) (669).lnk differ in target paths: 'C:\' vs. 'C:\'
2013-06-21 18:08:23, Info                  [0x080000] pCompareLnkContent: Compressed=C:, Mapped=C:, DestExpanded=C:\

I can see some hidden lnk files in there that match these log entries (like, "Local (C) 581.lnk", but I don't know where they came from. This machine was imaged fresh just for this USMT test, so it seems that USMT must have created those files. The loadstate.log ends up being about 180MB, then it finally moves on.

I've ran usmtutils /extract, and it extracts very quickly - and those Local (C) ###.lnk files are there, in appdata/microsoft/windows/recent folder. It's just a lnk that points to the C:\ drive.

Anyone have any insights, troubleshooting steps, or similar experiences?

Answer 1

I believe I have an explanation to this strange behavior.

1. It appears that the "ignore irrelevant links" functionality breaks on links that point to the root of a drive. For example, I had a LNK file in the "recent" folder that was pointing to the "F:\" drive. The comparison ran the compare and returned false because "F:\" was not equal to "F:".

2. Each time I ran the loadstate to restore, it would add a copy of the link in question, to the C:\ drive (or F:\ drive). (in addition to all of the LNK that it backed up from the last scanstate run.

3. The machine that I'm testing on, I was doing a lot of tests, backing up and restoring, repeatedly. 1 LNK turned into (2+1)=3, which turned into (6+1)=7, which turned into (14+1)=15, 31, 63, 127, 255, 511... and so on. The LNK comparison process apparently has to compare every similar lnk to every other lnk, so it's O(n²) iterations (based on the output of the log). That got out of hand really quickly. One loadstate log grew to 150MB at log level 5, and the next one was 300MB before I eventually cancelled the process.