Sunday, September 6, 2009

When the impossible happens, reconsider the assumptions of what is possible

Ever since Secure Endpoints started receiving OpenAFS for Windows crash reports from Microsoft there have been a small number of reports each month in applications that load libafsauthent.dll (afscreds.exe, netidmgr.exe, ...) and others that perform afs pioctls. It has been the rare case that a mindump has been available. The dumps that have been provided have made no sense. Its been clear that the stack or heap has been overwritten but other than that there has not been enough data to provide a clue where to start looking.

Last week OpenAFS 1.5.62 was released. It was an important release that fixed a long standing data corruption error. Something I have been trying to find for more than a year. Combine it with the support for WKSSVC and SRVSVC services providing vastly improved share name enumeration and Windows 7 compatibility and 1.5.62 was a release that I wanted everyone to upgrade to. Unfortunately, the release proved to have two downsides that did not come out during testing. First, Cygwin applications could not access /afs. Second, roaming profiles in some environments failed to work. The Cygwin compatibility problem was traced to the addition of (supposedly mandatory) extended responses to NTCreateAndX requests. The roaming profiles issue was caused by previously unseen requests to open directories as "Directory::$DATA" instead of "Directory".

Given the importance of the 1.5.62 release and the show stopper nature of the two issues that had been introduced with it, I spent a good portion of this Labor Day weekend testing it. Lo and behold, during testing Network Identity Manager crashed in the Visual Studio 8 CRT memcpy(). The crash signature looked similar to many I have seen in the past but this time I had access to not just the stack trace but the entire memory image to examine in a live debugger. Not surprisingly, the state of the process made no sense. It was unclear if the stack had been damaged. Could the data be real? The memcpy() was attempting to read data out of a buffer populated by a pioctl(). The buffer size is 16KB. The data that should have be returned should not have been more than a few hundred bytes. Yet, the memcpy() was attempting to read beyond the end of the buffer. Examining the contents of the buffer closely showed that the data in the buffer did not match the request. Instead of the buffer containing a GetToken response it contained a WhichCell response. Parse the string "Freelance.Local.Root" as if it were a marshalled token and all hell breaks loose.

Two questions came to mind. First, why is there no data validation of the data received via the pioctl()? Second, how in the world did the wrong response end up being received in the first place? The lack of data validation although completely wrong is not all that surprising. This source code has not been modified since the original IBM contribution. It wasn't causing any problems and therefore didn't attract attention. The response confusion was surprising.

The OpenAFS pioctl() interface on Microsoft Windows works by implementing a transceive (an atomic write request / read response) operation using CreateFile(), WriteFile(), ReadFile(), CloseFile(). The OpenAFS SMB server treats a NTCreateAndX operation on the magic file name "_._AFS_IOCTL_._" as the trigger to indicate that a pioctl() is being performed. Each time the file is opened a new smb file identifier is allocated. The caller writes the pioctl request to the file and then when the first read is issued, the requested operation is performed and the response data is queued up and sent in response. The caller issues ReadFile calls until end of file is reached and then the file is closed. Given this model, how is it that the response could possibly get confused?

My first theory was that a bug in the OpenAFS SMB server was issuing the same file id to two requestors. After close examination of the code it turns out that due to a thread safety issue there was a race that could result in that scenario. After fixing the race, I attempted to prove that the race was the cause of the problem. I kicked off five scripts executing a different pioctl operation 100,000 times. The client side bug was obviously being triggered but there was no evidence that the race I discovered had anything to do with it. Especially considering the fact that the problem continued to occur after the fix to prevent the race was installed.

The next step was to examine the behavior of the five scripts using Sysinternal's Process Monitor while filtering on all access to paths beginning with "\\afs". The output was quite revealing. It showed that requests and their responses based solely upon the length of the response were mismatched. Some ReadFile() operations failed with end of file errors on the first read.

At this point it was time to start examining the trace output of afsd_service. What I discovered was that the smb_IoctlPrepareWrite() and smb_IoctlPrepareRead() functions were being called multiple times on the same smb file id. The theory that the same pioctl instance was being used for requests from multiple processes proved to be correct. The question remained, why was it happening? Further examination of the trace output showed something even more curious. A large number of NTCreateAndX calls were missing from the output. I expected to see one NTCreateAndX operation for each pioctl request. In fact, that was a basic assumption that the original author of the pioctl interface must have assumed was true. Too bad for all of us that it isn't.

As it turns out the Microsoft SMB redirector chooses to avoid multiple NTCreateAndX calls for a file if all of the active requests have the same security privileges and request the same access modes. Instead, the SMB redirector manages the various open/close operations locally and only closes the file after it has been idle. The CreateFile operations were issued with FILE_SHARE_READ|FILE_SHARE_WRITE share mode. This permitted multiple apps to open the file simultaneously and perform writes and reads. If two processes open the file and write a request before the first process reads its response, the first process will receive the response meant for the second process and the second process will receive an end of file error. One solution is to remove the FILE_SHARE_WRITE in order to ensure that only one process can open the pioctl file at a time.

It is now possible to run the five simultaneous pioctl performing scripts without a single error. Even so, data validation checks have been added to libafsauthent.dll to prevent invalid input from crashing applications in the future. I'm now looking forward to the 1.5.63 release and examining the Windows Error Reporting logs in a couple of months to confirm that the random crashes are no longer being reported.