0

I have a set of WCF SOAP web services. A few of the service operations allows users to submit data. I want to log the payload from these requests to a SQL Server database. For clients that just read data, I only want to log simple metadata.

This is my data model: enter image description here

I have a class that implements the IParameterInspector interface. All service operations requests are logged in the BeforeCall method: time of request, operation name, userid and target endpoint.

public class LogParameterInspector : IParameterInspector
{
    private static WebServiceLog WebServiceLog = WebServiceLog.GetInstance();
    private bool IsOperationIgnorable(string operationName)
    {
        //Ignore GETs for service metadata
        return string.Equals(operationName, "get", StringComparison.InvariantCultureIgnoreCase);
    }

    public void AfterCall(string operationName, object[] outputs, object returnValue, object correlationState)
    {
        if (IsOperationIgnorable(operationName))
            return;

        SsnWebServiceContext.Current.Response.CreatedDate = DateTime.Now;

        //Calls stored procedure
        WebServiceLog.LogServerResponseToDb(SsnWebServiceContext.Current.Response);
    }

    public object BeforeCall(string operationName, object[] inputs)
    {
        if (IsOperationIgnorable(operationName))
            return null;

        SsnWebServiceContext.Current.Request.CreatedDate = DateTime.Now;
        SsnWebServiceContext.Current.Request.OperationName = operationName;

        foreach (var item in inputs)
        {
            if (item == null) continue;

            if (item.GetType().GetInterfaces().Any(x => x.IsGenericType && x.GetGenericTypeDefinition() == typeof(IRequest<>)))
            {
                var header = item
                    .GetType()
                    .GetProperties()
                    .Single(p => p.Name == "Header")
                    .GetValue(item, null) as IRequestHeader;

                SsnWebServiceContext.Current.Request.UserIdentification = header?.UserName;
            }
        }

        //Calls stored procedure
        WebServiceLog.LogClientRequestToDb(SsnWebServiceContext.Current.Request);

        return null;
    }


}

The message payload is explicitly logged in the few service operations that require it. (Calling the same stored procedure as in BeforeCall. The procedure checks if a record with the given GUID already exists, and if so, updates it).

I have a class that implements IExtension<OperationContext>. This class gives me access to request/response data through the lifetime of a request.

public class SsnWebServiceContext : IExtension<OperationContext>
{
    //Helper property for syntax purposes
    public static SsnWebServiceContext Current => OperationContext.Current.Extensions.Find<SsnWebServiceContext>();

    //Called when extension is added to OperationContext. Useful for initializing stuff.
    public void Attach(OperationContext owner)
    {
        var tmp = Guid.NewGuid();

        Request = Request ?? new ClientRequest();
        Request.SetReadOnlyGuid(tmp);

        Response = Response ?? new ServerResponse();
        Response.SetReadOnlyGuid(tmp);
    }

    //Called when extension is removed from OperationContext. Use for for cleanup.
    public void Detach(OperationContext owner)
    {
    }

    public ClientRequest Request { get; set; }
    public ServerResponse Response { get; set; }
}

My custom context is added to OperationContext through a class that implements IDispatchMessageInspector. This is also where I create a copy of the message stream for future reference.

public class ContextDispatchMessageInspector : IDispatchMessageInspector
{
    public object AfterReceiveRequest(ref Message request, IClientChannel channel, InstanceContext instanceContext)
    {

        using (var buffer = request.CreateBufferedCopy(int.MaxValue))
        {
            OperationContext.Current.Extensions.Add(new SsnWebServiceContext
            {
                Request = new ClientRequest
                {
                    Message = buffer.CreateMessage(),
                    TargetRole = OperationContext.Current.IncomingMessageHeaders?.To?.ToString()
                }
            });

            request = buffer.CreateMessage();
        }

        return null; //Correlation state passed to BeforeSendReply
    }

    public void BeforeSendReply(ref Message reply, object correlationState)
    {
        OperationContext.Current.Extensions.Remove(SsnWebServiceContext.Current);
    }
}

All my endpoints are configured for basicHttpBinding with the following settings:

<bindings>
  <basicHttpBinding>
    <binding name="SSNBinding" maxBufferSize="2147483647" maxReceivedMessageSize="2147483647" >
      <security mode="None"></security>
    </binding>
  </basicHttpBinding>
</bindings>

Problem:

The logging works fine, except for larger messages. When I try to view some of the XML messages in SSMS, I get the following error:

enter image description here

If I copy the XML content into a text editor, it's clear that the entire message has not been logged. I have found that this occurs only for requests where users are uploading files bigger than around 2MB. Files are uploaded as base64 encoded strings, and the logged XML content is truncated somewhere in the middle of the encoded string.

Weirdly (to me) the file seems to have been transferred successfully, even if it hasn't been logged completely. I've reproduced the behaviour locally, using SOAP UI and base64 encoding a large image: The request took a while (timed out after 1 minute in SOAP UI), but still completed succesfully some time later; I downloaded and viewed the image, and it was not corrupt. I got the same result with a large Word document.

Any suggestions on what I can do to prevent my logs from being truncated would be highly appreciated!

matsho
  • 111
  • 1
  • 12

1 Answers1

1

Your problem is not that the data is truncated in the table, but that SSMS limits the size of data in the output. So do not worry about missing data. your code is fine. That's why no errors are reported.

To check read the data using code (using plain ADO.Net for example), you will see that all the data is stored.

See some solutions: http://blog.extreme-advice.com/2013/03/05/error-fix-unable-to-show-xml-the-following-error-happened-there-is-an-unclosed-literal-string/

https://www.mssqltips.com/sqlservertip/2795/prevent-truncation-of-dynamically-generated-results-in-sql-server-management-studio/

SQL Server truncation and 8192 limitation

Community
  • 1
  • 1
Peter Bons
  • 26,826
  • 4
  • 50
  • 74
  • Thank you - the first link did the job! I feel more than slighly embarrassed, as the error message actually had the solution in it... – matsho Sep 13 '16 at 09:01
  • Yes well, it took me some time myself when I was faced with this error a while ago. – Peter Bons Sep 13 '16 at 10:16