FFS v5.22 suddenly started crashing

[ozo-sf]

Trying to synchronize WXP-SP3 computer and FFS v5.22 (32bit) suddenly has started to crash in the middle of "Synchronize" execution. After that there is no way to pass that step. I'm always getting the same crash again and again... :(

Error signature:
AppName: freefilesync_win32.exe AppVer: 5.22.0.0 MosName: msxml3.dll
ModVer: 8.100.1052.0 Offset: 0002ae76

Exception:
Code: 0xc0000092 FlagsL 0x00000000
Recird: 0x0000000000000000 Address: 0x00000000749aae76

What should I do?

Synchronization method is common "Mirror". "Compare" works just fine, but when I ask it to "Synchronize", it always crashes... Problem is persistent now. I never have it before.

[Zenju]

It's good that you're able to reproduce the problem, so there's some chance to find out what's happening:

I've created two debugging versions of 5.22. First try to reproduce the crash with the non-optimized version. If the problem does not show up, try the optimized version instead.
Then when it crashes and we're lucky there's already an "exception.dmp" file in your working directory. If not, open Process Explorer, right-click the FreeFileSync_win32.exe and create a minidump file manually. Then send this file to me via email. Additionally, while you're in process explorer, take a screenshot of the call stack of the main thread: in case the dump files are corrupted, I might at least get some hint at what FFS is doing at the time it crashes.

[404, Invalid URL: http://freefilesync.sourceforge.net/FreeFileSync_5.22_Win32-debug-no-opt.zip]
[404, Invalid URL: http://freefilesync.sourceforge.net/FreeFileSync_5.22_Win32-debug-opt.zip]

[ozo-sf]

Unfortunately I can't launch either of the them. Both are crashing at start:
[404, Invalid URL: http://freefilesync.sourceforge.net/FreeFileSync_5.22_Win32-debug-no-opt.zip]
Error signature:
AppName: freefilesync_win32.exe AppVer: 5.23.0.0 MosName: freefilesync_win32.exe
ModVer: 5.23.0.0 Offset: 00005cd0

Exception Information:
Code: 0xc0000001d FlagsL 0x00000000
Record: 0x0000000000000000 Address: 0x0000000000405cd0

[404, Invalid URL: http://freefilesync.sourceforge.net/FreeFileSync_5.22_Win32-debug-opt.zip]
Error signature:
AppName: freefilesync_win32.exe AppVer: 5.23.0.0 MosName: freefilesync_win32.exe
ModVer: 5.23.0.0 Offset: 00004ea00

Exception Information:
Code: 0xc0000001d FlagsL 0x00000000
Record: 0x0000000000000000 Address: 0x0000000000404ea0

[Zenju]

That's due to your CPU not supporting SSE2 instructions, like reported here: viewtopic.php?t=2171&p=9261#p9261

Maybe this is already a hint on what's the problem with 0xc0000092.

Let's try this again. I've recompiled without SSE2 and re-updated the two archives above.

[ozo-sf]

You're right. CPU doesn't support SSE2 instructions. Official build v5.22 has fixed that and it was working well until two days ago. And now I'm stuck with new problem.

Unfortunately the two new packages have similar problems:
debug-no-opt FreeFileSync_Win32.exe [CRC32: C6FCA9D9] Offset: 00005cd0
debug-opt FreeFileSync_Win32.exe [CRC32: 629EF869] Offset: 00004ed0
Are you sure you've removed the SSE2 instruction set option form compilation?

[Zenju]

SSE2 instructions seemed to have been linked in by the dependent libraries wxWidgets and boost. I've recompiled everything without SSE2 and updated the links above.

[ozo-sf]

First run of no-opt version has produced "exception.dmp" file.
What tool you'd recommend to open and view the file? I'd like to see its content before I send it to you.

[ozo-sf]

I guess I've found one. It's "dumpchk.exe" and it produced this analysis report:
------------------------------------------------------------------
Loading dump file D:\Sys\bin\FreeFileSync\exception.dmp
----- User Mini Dump Analysis

MINIDUMP_HEADER:
Version A793 (5128)
NumberOfStreams 8
Flags 1

Streams:
Stream 0: type ThreadListStream (3), size 000004E4, RVA 00000178
Stream 1: type ModuleListStream (4), size 000018E8, RVA 0000065C
59 modules
RVA 00000660, 00400000 - 00b14000: 'D:\Sys\bin\FreeFileSync\Bin\FreeFileSync_Win32.exe'
RVA 000006CC, 7c900000 - 7c9b2000: 'C:\WINDOWS\system32\ntdll.dll'
RVA 00000738, 7c800000 - 7c8f6000: 'C:\WINDOWS\system32\kernel32.dll'
RVA 000007A4, 773d0000 - 774d3000: 'C:\WINDOWS\WinSxS\X86_Microsoft.Windows.Common-Controls_6595b64144ccf1df_6.0.2600.6028_x-ww_61e65202\comctl32.dll'
RVA 00000810, 77c10000 - 77c68000: 'C:\WINDOWS\system32\msvcrt.dll'
RVA 0000087C, 77dd0000 - 77e6b000: 'C:\WINDOWS\system32\advapi32.dll'
RVA 000008E8, 77e70000 - 77f03000: 'C:\WINDOWS\system32\rpcrt4.dll'
RVA 00000954, 77fe0000 - 77ff1000: 'C:\WINDOWS\system32\secur32.dll'
RVA 000009C0, 77f10000 - 77f59000: 'C:\WINDOWS\system32\gdi32.dll'
RVA 00000A2C, 7e410000 - 7e4a1000: 'C:\WINDOWS\system32\user32.dll'
RVA 00000A98, 77f60000 - 77fd6000: 'C:\WINDOWS\system32\shlwapi.dll'
RVA 00000B04, 76b40000 - 76b6d000: 'C:\WINDOWS\system32\winmm.dll'
RVA 00000B70, 73000000 - 73026000: 'C:\WINDOWS\system32\winspool.drv'
RVA 00000BDC, 763b0000 - 763f9000: 'C:\WINDOWS\system32\comdlg32.dll'
RVA 00000C48, 7c9c0000 - 7d1d8000: 'C:\WINDOWS\system32\shell32.dll'
RVA 00000CB4, 774e0000 - 7761e000: 'C:\WINDOWS\system32\ole32.dll'
RVA 00000D20, 77120000 - 771ab000: 'C:\WINDOWS\system32\oleaut32.dll'
RVA 00000D8C, 63000000 - 630e6000: 'C:\WINDOWS\system32\wininet.dll'
RVA 00000DF8, 00340000 - 00349000: 'C:\WINDOWS\system32\normaliz.dll'
RVA 00000E64, 1a400000 - 1a532000: 'C:\WINDOWS\system32\urlmon.dll'
RVA 00000ED0, 5dca0000 - 5de88000: 'C:\WINDOWS\system32\iertutil.dll'
RVA 00000F3C, 59a60000 - 59b01000: 'C:\WINDOWS\system32\dbghelp.dll'
RVA 00000FA8, 77c00000 - 77c08000: 'C:\WINDOWS\system32\version.dll'
RVA 00001014, 71b20000 - 71b32000: 'C:\WINDOWS\system32\mpr.dll'
RVA 00001080, 76390000 - 763ad000: 'C:\WINDOWS\system32\imm32.dll'
RVA 000010EC, 629c0000 - 629c9000: 'C:\WINDOWS\system32\lpk.dll'
RVA 00001158, 74d90000 - 74dfb000: 'C:\WINDOWS\system32\usp10.dll'
RVA 000011C4, 5cd70000 - 5cd77000: 'C:\WINDOWS\system32\serwvdrv.dll'
RVA 00001230, 5b0a0000 - 5b0a7000: 'C:\WINDOWS\system32\umdmxfrm.dll'
RVA 0000129C, 10000000 - 10025000: 'D:\Sys\bin\FreeFileSync\Bin\Thumbnail_Win32.dll'
RVA 00001308, 769c0000 - 76a74000: 'C:\WINDOWS\system32\userenv.dll'
RVA 00001374, 01380000 - 01398000: 'D:\Sys\bin\FreeFileSync\Bin\FindFilePlus_Win32.dll'
RVA 000013E0, 5ad70000 - 5ada8000: 'C:\WINDOWS\system32\uxtheme.dll'
RVA 0000144C, 01410000 - 0141e000: 'C:\Programs\JS Pager\CBT.dll'
RVA 000014B8, 3aa00000 - 3aa42000: 'C:\Programs\ABBYY Lingvo 12\LvHook.dll'
RVA 00001524, 755c0000 - 755ee000: 'C:\WINDOWS\system32\MSCTFIME.IME'
RVA 00001590, 76380000 - 76385000: 'C:\WINDOWS\system32\msimg32.dll'
RVA 000015FC, 02070000 - 0207e000: 'D:\Sys\Tools\Organize\tinySpell\tskh1930.dll'
RVA 00001668, 77b40000 - 77b62000: 'C:\WINDOWS\system32\apphelp.dll'
RVA 000016D4, 76fd0000 - 7704f000: 'C:\WINDOWS\system32\clbcatq.dll'
RVA 00001740, 77050000 - 77115000: 'C:\WINDOWS\system32\comres.dll'
RVA 000017AC, 77a20000 - 77a74000: 'C:\WINDOWS\system32\cscui.dll'
RVA 00001818, 76600000 - 7661d000: 'C:\WINDOWS\system32\cscdll.dll'
RVA 00001884, 77920000 - 77a13000: 'C:\WINDOWS\system32\setupapi.dll'
RVA 000018F0, 02390000 - 02655000: 'C:\WINDOWS\system32\xpsp2res.dll'
RVA 0000195C, 75f60000 - 75f67000: 'C:\WINDOWS\system32\drprov.dll'
RVA 000019C8, 71c10000 - 71c1e000: 'C:\WINDOWS\system32\ntlanman.dll'
RVA 00001A34, 5b860000 - 5b8b6000: 'C:\WINDOWS\system32\netapi32.dll'
RVA 00001AA0, 71cd0000 - 71ce7000: 'C:\WINDOWS\system32\netui0.dll'
RVA 00001B0C, 71c90000 - 71cd0000: 'C:\WINDOWS\system32\netui1.dll'
RVA 00001B78, 71c80000 - 71c87000: 'C:\WINDOWS\system32\netrap.dll'
RVA 00001BE4, 71bf0000 - 71c03000: 'C:\WINDOWS\system32\samlib.dll'
RVA 00001C50, 75f70000 - 75f7a000: 'C:\WINDOWS\system32\davclnt.dll'
RVA 00001CBC, 325c0000 - 325d2000: 'C:\Programs\Microsoft Office\OFFICE11\MSOHEV.DLL'
RVA 00001D28, 031e0000 - 0320e000: 'D:\Sys\bin\FreeFileSync\Bin\Shadow_XP_Win32.dll'
RVA 00001D94, 753e0000 - 7544d000: 'C:\WINDOWS\system32\vssapi.dll'
RVA 00001E00, 76b20000 - 76b31000: 'C:\WINDOWS\system32\atl.dll'
RVA 00001E6C, 74980000 - 74aa3000: 'C:\WINDOWS\system32\msxml3.dll'
RVA 00001ED8, 76bf0000 - 76bfb000: 'C:\WINDOWS\system32\psapi.dll'
Stream 2: type MemoryListStream (5), size 000005A4, RVA 00008519
90 memory ranges
range# Address Size
0 7c90e494 00000100
1 00a12000 0004a3a0
2 00a5d000 0000000d
3 7c97e000 00004a20
4 7c885000 00004460
5 77462000 00000a50
6 77c5d000 000067c8
7 77e46000 00004628
8 77efc000 00000ed8
9 77fee000 00000480
10 77f54000 00001160
11 7e471000 00001180
12 77fcd000 00000ff8
13 76b60000 00001c58
14 73021000 0000176c
15 763e1000 00003460
16 7cbc0000 0001c1d0
17 77607000 000069fc
18 771a1000 00002058
19 630b1000 00006838
20 00346000 0000068c
21 1a4c9000 0000b008
22 5de6b000 000041a0
23 59af0000 00004a70
24 77c05000 000002fc
25 71b2f000 00000238
26 763a6000 0000088c
27 629c6000 000001d4
28 74dd5000 0000f29c
29 5cd74000 00000a68
30 5b0a4000 00000004
31 1001e000 00003260
32 76a61000 00001da4
33 01393000 00003000
34 5ada1000 00000e88
35 01418000 000002a8
36 0141a000 00000768
37 3aa34000 0000437c
38 3aa39000 00000010
39 755e8000 00000568
40 76382000 000000b0
41 02079000 000018dc
42 0207b000 00000038
43 77b5e000 000008c4
44 77043000 00004a12
45 77052000 00000004
46 77a44000 000010e4
47 76613000 00001d00
48 7799e000 00001860
49 75f64000 00000258
50 71c1b000 00000048
51 5b8af000 000027f8
52 71ce1000 00000124
53 71ccc000 000000b8
54 71c84000 0000000a
55 71c00000 00000354
56 75f77000 00000288
57 325cf000 00000790
58 03205000 00003d00
59 03209000 00000002
60 7543b000 0000a360
61 76b2c000 00000348
62 74a4a000 000100e0
63 76bf5000 00003208
64 0012b2b4 00004d4c
65 0127fea4 0000015c
66 0275fe14 000001ec
67 02fffcbc 00000344
68 054afe14 000001ec
69 034cfcb0 00000350
70 035cfcb0 00000350
71 036cfcb0 00000350
72 037cfcb0 00000350
73 038cfcb0 00000350
74 039cfcb0 00000350
75 03acfcb0 00000350
76 03bcfcb0 00000350
77 03ccfcb0 00000350
78 03dcfcb0 00000350
79 03ecfcb0 00000350
80 03fcfcb0 00000350
81 040cfcb0 00000350
82 041cfcb0 00000350
83 042cfcb0 00000350
84 043cfcb0 00000350
85 044cfcb0 00000350
86 045cfcb0 00000350
87 046cfcb0 00000350
88 055afcb0 00000350
89 056afcb0 00000350
Stream 3: type ExceptionStream (6), size 000000A8, RVA 000000D0
Stream 4: type SystemInfoStream (7), size 00000038, RVA 00000080
Stream 5: type ??? (15), size 00000018, RVA 000000B8
Stream 6: type UnusedStream (0), size 00000000, RVA 00000000
Stream 7: type UnusedStream (0), size 00000000, RVA 00000000


Windows XP Version 2600 (Service Pack 3) UP Free x86 compatible
Debug session time: Wed Oct 09 13:00:13 2013
System Uptime: not available
The call to LoadLibrary(ext) failed with error 2.
Please check your debugger configuration and/or network access
PEB NULL...
Finished dump check

[ozo-sf]

Report above was produced by "dumpchk.exe" v5.1.2600.0.

Here is report, which is produces with "dumpchk.exe" v6.7.5.0. I've removed Streams 0, 1, 2 as they're the same as already reported above. I hope this report will help you to find out the problem with crash.

Microsoft (R) Windows Debugger Version 6.7.0005.0
Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [D:\Sys\bin\FreeFileSync\exception.dmp]
User Mini Dump File: Only registers, stack and portions of memory are available

Symbol search path is: * Invalid *
****************************************************************************
* Symbol loading may be unreliable without a symbol search path. *
* Use .symfix to have the debugger choose a symbol path. *
* After setting your symbol path, use .reload to refresh symbol locations. *
****************************************************************************
Executable search path is:
Windows XP Version 2600 (Service Pack 3) UP Free x86 compatible
Product: WinNt, suite: SingleUserTS
Debug session time: Wed Oct 9 13:00:13.000 2013 (GMT-7)
System Uptime: not available
Process Uptime: 0 days 0:02:14.000
...........................................................
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(cb0.f14): Unknown exception - code c0000092 (first/second chance not available)
----- User Mini Dump Analysis

MINIDUMP_HEADER:
Version A793 (5128)
NumberOfStreams 8
Flags 1
0001 MiniDumpWithDataSegs

Streams:
...
Stream 3: type ExceptionStream (6), size 000000A8, RVA 000000D0
ThreadID 3860
ExceptionCode C0000092
ExceptionRecord 0
ExceptionAddress 749aae76
Context record RVA 3050, size 2cc
Stream 4: type SystemInfoStream (7), size 00000038, RVA 00000080
ProcessorArchitecture 0000 (PROCESSOR_ARCHITECTURE_INTEL)
ProcessorLevel 0006
ProcessorRevision 0B01
NumberOfProcessors 01
MajorVersion 00000005
MinorVersion 00000001
BuildNumber 00000A28 (2600)
PlatformId 00000002 (VER_PLATFORM_WIN32_NT)
CSDVersionRva 00001F44
Length: 28
Buffer: {'Service Pack 3'}
Product: WinNt, suite: SingleUserTS
Stream 5: type MiscInfoStream (15), size 00000018, RVA 000000B8
Stream 6: type UnusedStream (0), size 00000000, RVA 00000000
Stream 7: type UnusedStream (0), size 00000000, RVA 00000000


Windows XP Version 2600 (Service Pack 3) UP Free x86 compatible
Product: WinNt, suite: SingleUserTS
kernel32.dll version: 5.1.2600.5781 (xpsp_sp3_qfe.090321-1341)
Debug session time: Wed Oct 9 13:00:13.000 2013 (GMT-7)
System Uptime: not available
Process Uptime: 0 days 0:02:14.000
Kernel time: 0 days 0:00:10.000
User time: 0 days 0:00:24.000
*** ERROR: Symbol file could not be found. Defaulted to export symbols for ntdll.dll -
PEB NULL...
Finished dump check

[ozo-sf]

And here is stack, produced by WinDbg:

0:000> k
ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong.
0012b2c8 01c89e27 ntdll!KiFastSystemCallRet
0012b3a0 7c910222 0x1c89e27
0012b3cc 7c910222 ntdll!RtlAllocateHeap+0x15e
0012b3d0 7c911046 ntdll!RtlAllocateHeap+0x15e
0012b3d4 7c9101db ntdll!wcsncpy+0xa6d
0012b470 7c913aeb ntdll!RtlAllocateHeap+0x117
0012b488 7c90d18a ntdll!RtlDetermineDosPathNameType_U+0x715
*** ERROR: Symbol file could not be found. Defaulted to export symbols for dbghelp.dll -
0012b90c 59a8b4b5 ntdll!ZwCreateSection+0xc
0012b944 59a8b75e dbghelp!MiniDumpReadDumpStream+0x49c
0012b964 59a8b97b dbghelp!MiniDumpReadDumpStream+0x745
0012baa0 59a8ba78 dbghelp!MiniDumpReadDumpStream+0x962
*** ERROR: Module load completed but symbols could not be loaded for FreeFileSync_Win32.exe
0012bb00 00418fda dbghelp!MiniDumpWriteDump+0xc8
*** WARNING: Unable to verify checksum for LvHook.dll
*** ERROR: Symbol file could not be found. Defaulted to export symbols for LvHook.dll -
0012bb3c 3aa1db64 FreeFileSync_Win32+0x18fda
*** ERROR: Symbol file could not be found. Defaulted to export symbols for kernel32.dll -
0012bdb8 7c8438d2 LvHook!UnregisterHook+0x1c834
0012fff0 00000000 kernel32!ValidateLocale+0xa0da

[Zenju]

I fear I'll need to have the full dump file for analysis to have any chance of finding out what's happening.

[ozo-sf]

OK. Please let me know what you see there.

[Zenju]

OK. Please let me know what you see there.

Thanks! The problem is originating from the Volume Shadow Copy
component. From the assembly instructions it looks like it's again the
SSE2 problem, although the Win32 exception code is 0xC0000092.

I've recompiled Shadow_XP_Win32.dll without SSE2 including the dependent
libraries.
Can you check if this fixes the problem for you? First try to test it
with the regular FFS 5.22 installation, if it fails, use the no-opt
debug version for troubleshooting.

Replace the following file with the one in FFS installation subdirectory
"bin"
[404, Invalid URL: http://freefilesync.sourceforge.net/Shadow_XP_Win32.dll]

In order to test the shadow copy service on XP you first need a locked
file. You can do this by first changing some file on the source side,
then lock it with the following tool:
[404, Invalid URL: http://freefilesync.sourceforge.net/TestLockFile.exe]

FFS will then try to copy this locked file, get a sharing violation, and
try to copy via VSS. Hopefully this works now without a crash.

Regards, Zenju

[ozo-sf]

Thank you, Zenju.
I'll test new files soon.

[ozo-sf]

That's it. The problem was with Volume Shadow Copy component. And it works now well. Thank you for the fix!

[Zenju]

Excellent! :)

[ozo-sf]

While we've found the problem, I'd like to take the opportunity to ask you a question. I'm observing strange behavior of FFS and can't find an answer why is it.

I'm moving (upgrading) form one HD disk to another and from WXP-SP2 (all updates are up to SP3) to WXP-SP3. Both HDs (data drives) are within the same laptop, which I boot from one HD or another. At this time content of both HD is identical (I use FFS to sync it with remote storage). The weird thing is:
- when I run FFS-Compare for old HD it takes about 30+ sec to complete
- when I run FFS-Compare for new HD it takes almost 4 times longer to do the same job.

Both HDs have similar performance (at least it can't explain x4 increase of Comparison time and I can see it while FFS works with local files - see below). I guess both network parameters in both WXP-SP2 and WXP-SP3 installations are tweeted similarly.

The difference that I see is:
- when I run Compare on old HD, the line showing current files, shows local files all the time (up to 54,000 files)
- when I run Compare on new HD I see it's working with local files up until it tells me it's done with around 28,000 files and then it starts showing the corresponding remote files (starting with \\192.168.0.X\path\file) until it's done with all files (around 54,000 total). And this phase takes a lot of time...

What's the difference between FFS indicating local files (like D:\path\file) and remote files (like \\IP\path\file)?

Why I don't see remote files in old HS (while processing all 54,000 files) and see them after FFS done with about 28,000 in new HD?

Reason why I'm asking is Comparison in new HD now takes about x4 times longer than similar job in old HD and I don't know how to fix it.

Thanks you in advance :)

[Zenju]

A solved problem would not be complete without the occassional unrelated follow-up question ;)

As you probably know, FFS uses multiple threads to scan all directories in parallel: There's one thread per directory. However the status text field only ever shows what's currently scanned on the first of the still running threads. Otherwise it would be distracting if the file paths shown would jump around between the threads and directories as they are scanned. The numbers however correspond to the data of all threads combined so far.

In your first example, the fact that you don't see "\192.168.0.X" means that the network is faster than or equally fast as your local disk.

In your second example however it's slower: The network is scanned by the second thread and its paths are shown only after the first thread, the local disc, has finished.

So the slowdown seems to be caused by the network somehow. Maybe the SP3 upgrade applied suboptimal network drivers or changed some other network-related setting.

[ozo-sf]

Thanks a lot, Zenju. It's very interesting. In my case I have 11 folder pairs to compare. It means that 22 additional threads are created at Compare time, all working in parallel. And because network is slower now, I start see networked path in status line after a while... It seems logical conclusion. Thanks.

Is there any way to get some stats on how long generally it takes for FFS to work with remote (usually right) folders and how long it takes with local (usually left) folders? Some summary time for all threads, may be?

I try to compare what's the difference in both installation is and can't find anything, that I did differently. I indeed did networks tweaking, but I did it the same way in both cases (I usually document it well to make sure). May be you're right, and there is some change in SP3, that is responsible for this result. But interestingly enough, while the time to Compare takes now about 4 times longer, I don't see much difference while I do Synchronization. Time for that is approximately the same and I always watch it in "Networking" tab in "Task Manager"... That's puzzling :)

[Zenju]

> get some stats

The simplest way is to setup and scan a single directory only. FFS doesn't complain if the second folder of a pair is missing, since this scenario is sometimes useful: e.g. in your case, or for analyzing the space distribution hierarchy using the overview panel.

[ozo-sf]

Thank you for the idea. Testing it this way now :)

I've noticed that when I run one folder test and watch Networking tab in Task Manager, it shows steady 3% utilization. When I run the whole synchronization, I'm getting up to 20%, slowly degrading to 15%, 10% etc. Of course it means that less threads are working via network at that time. But the followed question arises - why when I run only one thread network utilization is always 3%? CPU is not maxed out. There is certainly a potential to use more... Is there some threshold in each thread, that limits it 3% (and not more)?

BTW, it'd be helpful to see after the run "Time elapsed" stat for that run. What I try to watch on far right side of FFS disappears very quickly when sync is done...