Troubleshooting Custom FTP Providers with ETW

I recently received a question from a customer about troubleshooting custom FTP providers, and I recommended using the FTP service's Event Tracing for Windows (ETW) features in order to help troubleshoot the problem. I've helped a lot of customers use this little-known feature of the FTP service, so I thought that it would make a great subject for a quick blog.

By way of explanation, the FTP service in IIS 7.5 and IIS 8.0 allows developers to write their own custom functionality, and over the past several years I have written several walkthroughs and blogs that illustrate how you can create your own custom FTP providers:

• Custom Authentication Providers:
  • How to Use Managed Code (C#) to Create a Simple FTP Authentication Provider
  • How to Use Native Code (C++) to Create a Simple FTP Authentication Provider
  • How to Use Managed Code (C#) to Create an FTP Authentication Provider using an XML Database
  • How to Use Managed Code (C#) to Create an FTP Authentication and Authorization Provider using an XML Database
  • How to Use Managed Code (C#) to Create an FTP Authentication Provider with Dynamic IP Restrictions
  • FTP and LDAP - Part 1: How to Use Managed Code (C#) to Create an FTP Authentication Provider that uses an LDAP Server
  • How to Create an Authentication Provider for FTP 7.5 using BlogEngine.NET's XML Membership Files
• Custom Home Directory Providers:
  • How to Use Managed Code (C#) to Create a Simple FTP Home Directory Provider
  • How to Use Managed Code (Visual Basic) to Create a Simple FTP Home Directory Provider
  • How to Use Native Code (C++) to Create a Simple FTP Home Directory Provider
  • How to use Managed Code (C#) to create an FTP Home Directory Provider that is based on the Remote Client IP Address
  • How to Use Managed Code (C#) to Create an FTP Home Directory Provider for the Days of the Week
• Custom Logging Providers:
  • How to Use Managed Code (C#) to Create a Simple FTP Logging Provider
  • How to Use Managed Code (Visual Basic) to Create a Simple FTP Logging Provider
  • How to Use Native Code (C++) to Create a Simple FTP Logging Provider
• Custom Functionality Providers:
  • How to Use Managed Code (C#) to Create an FTP Provider that Prevents Leeching
  • How to Use Managed Code (C#) to Create an FTP Provider that Sends an Email when Files are Uploaded

That being said, sometimes things go wrong, and when that happens, I use some FTP ETW troubleshooting tricks that I'd like to share.

Setting up FTP ETW Tracing

Several years ago I wrote a blog about FTP and ETW Tracing, where I described how to turn on the FTP service's ETW tracing through a batch file, and then it used Log Parser to render the output in a datagrid for analysis. In the interests of completeness, here is the batch file again:

@echo off rem====================================================================== echo Verifying that LogParser.exe is in the path... LogParser -h >nul 2>nul if errorlevel 1 (   echo.   echo Error:   echo.   echo   LogParser.exe is was not found. It is required for parsing traces.   echo.   echo Recommended actions:   echo.   echo   - If LogParser is installed then fix the PATH   echo     variable to include the LogParser directory   echo.   echo   - If LogParser is not installed, then install   echo     it from the following location:   echo.   echo   https://www.microsoft.com/downloads/details.aspx?FamilyID=890cd06b-abf8-4c25-91b2-f8d975cf8c07   echo.   goto :EOF ) else (   echo Done.   echo. ) rem====================================================================== echo Starting the ETW session for full FTP tracing... logman start "ftp" -p "IIS: Ftp Server" 255 5 -ets echo. echo Now reproduce your problem. echo. echo After you have reproduced your issue, hit any key to close the FTP echo tracing session. Your trace events will be displayed automatically. echo. pause>nul rem====================================================================== echo. echo Closing the ETW session for full FTP tracing... logman stop "ftp" -ets rem====================================================================== echo. echo Parsing the results - this may take a long time depending on the size of the trace... LogParser "select EventTypeName, UserData from ftp.etl" -e 2 -o:DATAGRID -compactModeSep " | " -rtp 20

When you save and run this batch file, it will display something like the following:

C:\FTP_ETW.cmd Verifying that LogParser.exe is in the path... Done. Starting the ETW session for full FTP tracing... The command completed successfully. Now reproduce your problem. After you have reproduced your issue, hit any key to close the FTP tracing session. Your trace events will be displayed automatically.

When you see this displayed, you will need to reproduce your problem, and FTP's ETW tracing will record the troubleshooting information.

Once you have reproduced your problem, hit a key to end the ETW session, and you will see the following message displayed:

Closing the ETW session for full FTP tracing... The command completed successfully. Parsing the results - this may take a long time depending on the size of the trace...

The batch file will eventually call Log Parser to parse the ETW events, and a dialog like the following will be displayed:

Troubleshooting Custom FTP Providers with ETW Tracing

Now that you know how to set up FTP's ETW tracing, let's examine what you should be looking for in the tracing information.In all of the examples in this blog, I am using the XML-based authentication provider that is documented in the How to Use Managed Code (C#) to Create an FTP Authentication Provider using an XML Database walkthrough.

The following illustration highlights several lines that show the FTP service starting its authentication process, loading my custom authentication provider, and ending the authentication process after I have successfully logged in:

This example shows what everything looks like when it works as expected, so now let's look at what happens when something goes wrong.

If I use the same provider, but I enter my username or password incorrectly, I will see the following lines in the trace:

This example informs you that the provider was loaded successfully, but the logon failed. The error code that is returned is 0x8007052E - this hexadecimal 32-bit value can be split into 16-bit values:

• 8007 - This code informs you that this is a Win32 error.
• 052E - This code coverts to 1326 in decimal, and if you enter "NET HELPMSG 1326" from a command-prompt, that will tell you that the error was "Logon failure: unknown user name or bad password. "

If I continue to use the same provider as earlier, and I delete the XML file that my provider uses, then I will receive the following error:

Once again, this example informs you that the provider was loaded successfully, but an error occurred. In this specific case you see the actual details that the XML file exists, and that is an error that is returned by a throw() statement in the provider. The error code that is returned is 0x80070057 - and once again this hexadecimal 32-bit value can be split into 16-bit values:

• 8007 - This code informs you that this is a Win32 error.
• 0057 - This code coverts to 87 in decimal, and if you enter "NET HELPMSG 87" from a command-prompt, that will tell you that the error was "The parameter is incorrect. "

If I replace the missing XML file for the provider, but I remove all of the permissions to the file, I get the following error:

As in the previous examples, this informs you that the provider was loaded successfully, but an error occurred. You can't look up the 0x80131500 error code by using "NET HELPMSG" from a command-prompt, but that doesn't matter since the error description informs you of the problem - access to the path where the file is located was denied.

If I enter a bad provider name, I get the following error:

Unlike the previous examples, this informs you that the provider was not loaded successfully. The description for this error informs you that it could not load the provider, and it gives you the assembly information. In addition to the error description, the error code that is returned by the FTP service is 0x80070002 - and once again this hexadecimal 32-bit value can be split into 16-bit values:

• 8007 - This code informs you that this is a Win32 error.
• 0002 - This code is obviously 2 in decimal, so if you enter "NET HELPMSG 2" from a command-prompt, that will tell you that the error was "The system cannot find the file specified. "

So now let's look at a common perplexing problem:

This example shows the same 0x8007052E error code that we looked at in a previous example, but you'll notice that any reference to the provider is conspicuously absent from the trace - this means that the FTP service made no attempt to load the custom authentication provider. In this specific case, even though I had correctly registered my custom FTP authentication provider on the system, I had not added or enabled the custom authentication provider for my FTP site.

Summary

In this blog I showed you how to troubleshoot several different errors with FTP custom authentication providers by using FTP's ETW features.

As a parting thought, I should point out that the most-common error that I run into when creating my own providers is the last example. Believe it or not, I nearly always miss a step when I am creating a new provider and I forget to add a setting here or there which will cause the FTP service to completely ignore my provider. A perfect example is when I am writing custom home directory providers - I always remember to add the provider to the global list of FTP providers, and I usually remember to add the provider to the list of custom features for my FTP site, but I forget to configure my FTP site to use custom user isolation and my provider is ignored. (Darn, darn, darn...)

;-]

Comments

• Anonymous
  November 07, 2013
  The comment has been removed