bitly/nsq — pull request #509 by allgeek (2014-12-03 23:37:13+00:00)
Title: nsqd: Switch from using win32 ReplaceFile to MoveFileEx calls during atomic_rename

nsqd on Windows still encounters occasional panics during atomic_rename(). Pull request #493 corrected the issue on my local machine and when running tests, but still triggered panics within a minute under a 'cold startup under load' scenario with a production workload immediately publishing to many new topics on an AWS Windows 2008R2 instance (attempting to simulate the volume a Windows/.NET application will be pumping into a local nsqd - we'll be using Linux in most places but must use Windows to colocate nsqd with a legacy producer).

Troubleshooting, I've discovered a few issues with the current code, and some odd behavior with the syscalls into the win32 API that led me to ultimately switch to the win32 MoveFileEx call rather than ReplaceFile.

* Existing code had a comment about GetLastError() not working. I dug into that, and discovered that win32 GetLastError() is thread-specific; but of course a goroutine could move threads. I tried using runtime.LockOSThread() / runtime.UnlockOSThread() but still was unable to get a meaningful value out of GetLastError().

* I dug into the internals of the Windows syscall implementation; the proc.Call() implementation used when we invoke ReplaceFile() actually calls GetLastError() for you and returns any error as the third result (documented on [line 272 of pkg/syscall/dll_windows.go](https://golang.org/src/pkg/syscall/dll_windows.go)). That error was being thrown away in the existing atomic_rename() implementation (`ret, _, _ := procReplaceFile.Call()`). I changed the code to capture the error from procReplaceFile rather than performing a subsequent explicit call to procGetLastError, and was able to properly implement handling for the expected error case when the file to be replaced does not exist (i.e., fresh startup for the nsqd.dat, or a new topic/channel .dat creation).

* Unfortunately that still did not fix things; a panic would eventually occur; even with synchronization to prevent two goroutines from renaming to the same target file concurrently as we had discussed in PR #493. Attempts to trace from the GoLang side didn't show anything meaningful (although did confirm the synchronization logic was working).

* I then used the Sysinternals [Process Explorer](http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx) to capture the win32 calls, and began seeing some very odd behavior prior to the panic. At some point, file IO operations would attempt to access a weird filename - it wasn't properly rooted in my nsqd data-path (instead was rooted to the working directory of the nsqd process), and contained multibyte characters (Chinese or something):

```
Operation: CreateFile
Result: NAME NOT FOUND
Path: C:\Test\bins\壀舨À
TID: 3972

Operation: CreateFile
Result: SUCCESS
Path: C:\Test\bins\㨴吠敨猠獹整⁭慣湮瑯映湩⁤桴⁥楦敬猠数楣楦摥‮桔⁥祳瑳浥挠湡潮⁴楦摮琠敨映汩⁥灳捥晩敩⹤ ~RF3848863.TMP
TID: 784

Operation: SetRenameInformationFile
Result: SUCCESS
Path: C:\Test\nsq_data\ActionLogV1.diskqueue.meta.dat
TID: 3216
ReplaceIfExists: True
FileName: C:\Test\bins\舷À~RF3848863.TMP

Operation: SetRenameInformationFile
Result: SUCCESS
Path: C:\Test\nsq_data\CommunicationHistoryV1.diskqueue.meta.dat
TID: 784
ReplaceIfExists: True
FileName: C:\Test\bins\㨴吠敨猠獹整⁭慣湮瑯映湩⁤桴⁥楦敬猠数楣楦摥‮桔⁥祳瑳浥挠湡潮⁴楦摮琠敨映汩⁥灳捥晩敩⹤ ~RF3848863.TMP
```

That definitely looked like heap corruption or something similar. Many other similar erroneous calls were present. Within 200 milliseconds there was a new scary type of odd behavior - a rename of a 'topic A' temp metadata file to the 'topic B' metadata file:

```
Operation: SetRenameInformationFile
Result: SUCCESS
Path: C:\Test\nsq_data\SeatsBookingInfoV1.diskqueue.meta.dat.2636022012808217135.tmp
TID: 3216
ReplaceIfExists: True
FileName: C:\Test\nsq_data\ActionLogV1.diskqueue.meta.dat
```

Tracing on the GoLang side confirmed that is NOT what we supplied as arguments to the ReplaceFile call; as expected, we were really trying to rename 'SeatsBookingInfoV1.diskqueue.meta.dat.2636022012808217135.tmp' to 'SeatsBookingInfoV1.diskqueue.meta.dat'.

This corruption ultimately ended up causing the 'unexplainable' code path and panic.

I spent a bit more time troubleshooting what may be causing the corruption (auditing any usage of the unsafe package in nsqd, digging further into the Syscall implementation, etc), and did not find anything obvious. I also tried using ReplaceFileW() instead of ReplaceFile() [explicitly using the Unicode variant] with no change in behavior.

I ultimately decided to revisit the atomic rename problem altogether, and discovered many solutions were relying on the win32 MoveFileEx instead of ReplaceFile, including [goleveldb](https://github.com/syndtr/goleveldb/blob/master/leveldb/storage/file_storage_windows.go) and numerous suggestions on the golang-nuts list and elsewhere. The primary difference between [MoveFileEx](http://msdn.microsoft.com/en-us/library/windows/desktop/aa365240%28v=vs.85%29.aspx) and [ReplaceFile](http://msdn.microsoft.com/en-us/library/windows/desktop/aa365512%28v=vs.85%29.aspx) is that ReplaceFile can preserve more of the ACLs and attributes from the original file being replaced. In the nsqd usage that shouldn't be a concern - nsqd creates these files and does not explicitly care about ACLs/attributes; those would naturally inherit from the ACLs of the data-path, and the newly created metadata file would also inherit the same ACLs. The primary 'loss' is that the Creation Date of the metadata file will always reflect the most recent creation, rather than the original topic creation date. nsqd does not rely on this attribute, and I don't think that is necessary information for administrators.

Thankfully with MoveFileEx we don't need to have fallback logic for handling the 'error' when the file to be replaced does not exist, so the win32 API interaction is atomic and synchronization to prevent concurrent renames to the same target file is not necessary (I don't think the current nsqd usage would actually do concurrent renames to the same file anyway).

I'm including with this PR my additional change to randomize the filename of the topic metadata temp file (as we had in pull request #493 for the main nsqd metadata file), which was necessary to thread together all the activity while troubleshooting, and is safer.

I'm certainly open to collaboration if someone wants to dig further into the heap corruption I was seeing with ReplaceFile - whether it's an issue with our win32 interop, with Go itself, or is a bug in ReplaceFile. That being said, MoveFile has been working solidly so far - while I'm still curious, I just don't have the time right now to dig further into that.

I've also included a test which may not be worth retaining for ongoing usage (although luckily it's for Windows only); it creates two sets of 500 source files and concurrently renames to a set of 500 target files (so the first rename for a target will not replace, and the second rename will). It's a bit of a 'stress' test; with the old code, I was able to intermittently reproduce the panics with as few as 50 source files, although it'd happen more frequently with higher file counts. I've run the test with the new code with a TEST_FILE_COUNT as high as 10000 and have not seen any issues.

Let me know if you'd prefer to have the test excluded from the PR, or have any other questions/concerns. I've got lots of logs captured from my troubleshooting attempts :)