The Last Pickle

While trying to find out where the HTTP Authentication was carried out when a HTTP request is made to a SQL Server 2005 SOAP Endpoint I was sucked into a tracing rat hole. SQL Server 2005 HTTP endpoints using the Windows system HTTP stack commonly known by its file name HTTP.sys. All HTTP applications on a Windows machine will typically be a consumer of HTTP.sys, this includes IIS.

I though this could be where the HTTP request was authenticated so set off to work out how to trace the request through the service. Eventually I located Event Tracing in HTTP.sys: Part 1 – Capturing a Trace by Jeff Balsey from the HTTP.sys team (this is a three part article). The first thing to note is there there is NO tracing for HTTP.sys under OS’s prior to Vista, this is the first time I’ve been grateful for Vista.

As the article describes start a trace for HTTP.sys with:

    logman start httptrace -p Microsoft-Windows-HttpService 0xFFFF -o httptrace.etl -ets

Where httptrace.etl is the name (and path) of the log file. End the trace with:

    logman stop httptrace -ets

The article describes how to transform the raw binary trace file into either an XML or CSV file. However I found it possible to open the file using the Vista Event Viewer without transforming it. The article also says there are 65 different events logged by HTTP.sys, I’ve not been able to find a list but it seems that the Request has an event ID of 3 and the responses have a different ID depending on the HTTP status code.

Initially I tested the tracing against an endpoint configured with Integrated HTTP authentication over HTTP with Windows SQL Server login (the default). The web method called a USP in the master DB that just returned the list of principals in the server, this was created using the TSQL below.

    user master;
    go
    
    create procedure usp_getPrincipals
    as
    select * from sys.server_principals
    go
    
    CREATE ENDPOINT soap_endpoint 
    STATE = STARTED
    AS HTTP(
       PATH = '/sql', 
       AUTHENTICATION = (integrated), 
       PORTS = ( clear ), 
       SITE = '*'
       )
    FOR SOAP (
       WEBMETHOD 'GetPrincipals' 
                (name='master.dbo.usp_getPrincipals' 
                 ),
       WSDL = DEFAULT,   
       SCHEMA = STANDARD,
       DATABASE = 'master',
       NAMESPACE = 'http://tempUri.org/'
       );

The SOAP endpoint will respond on any non reserved host names on the server under the /sql path, so to test it I opened the URL http://localhost/sql?wsdl in Internet Explorer and provided my local machine (non domain) login. The ?wsdl parameter requests the endpoint to return the Web Services Description Language document for the service, an easy way to test connectivity.

Note that as per Endpoint Authentication Types Digest authentication does not support local windows accounts so go with Integrated.

The log messages show the client and the server establishing a connection, negotiating authentication and the finally sending the data.

The initial request has an event ID of 3 and generated a HTTP 401 not authorised response logged with event ID 8.

    Event ID 3
    Delivered request to server application (request pointer 0x87dab468, 
    request ID 17798225733810651162, site ID 0) 
    from request queue  for URI http://localhost:80/sql?wsdl with status 0.
    
    Event ID 8
    Server application passed response (request ID 17798225733810651162, 
    connection ID 17798225733273780249, 
    method GET, header length 2311090408, number of entity chunks 0, cache policy 0) 
    with status code 401.

This resulted in a second request as the client tried to negotiate, again receiving a HTTP 401 for its trouble.

    Event ID 3
    Delivered request to server application (request pointer 0x89e18a38, 
    request ID 18230571293743251527, site ID 0) 
    from request queue  for URI http://localhost:80/sql?wsdl with status 0.
    
    Event ID 8 
    Server application passed response (request ID 18230571293743251527, 
    connection ID 18230571293206380614, 
    method GET, header length 2311090408, number of entity chunks 0, cache policy 0) 
    with status code 401.

Finally the client made a request with the correct authorisation details and received a HTTP 200 success response and the data, this was logged with Event ID 4.

    Event ID 3
    Delivered request to server application (request pointer 0x89e18a38, 
    request ID 18230571293743251528, site ID 0) 
    from request queue  for URI http://localhost:80/sql?wsdl with status 0.
    
    Event ID 4
    Server application passed response (request ID 18230571293743251528, 
    connection ID 18230571293206380614, 
    method GET, header length 168, number of entity chunks 3, cache policy 0) 
    with status code 200.

The connection ID changed between the first and second call, the logging showed that a new connection was made between the first and second attempt but not between the second and third attempt, not sure why.

I ran a second test where I provided incorrect credentials three times when connecting, that resulted in 9 request-response pairs where the response was HTTP 401 as above.