Using HttpWebRequest to make SOAP requests over 4KB results in 500 Internal Server Error

Question

I'm having real trouble with accessing a SOAP service when request sizes are large. The methods used (HttpWebRequest) work fine when making shorter SOAP calls but as soon as the size of the XML tips over 4KB I can see the requests being truncated in the network logs and they ultimately result in a 500 Internal Server Error from the target server. I also have to attach a client certificate to the calls and can't wire up to the web service via a reference in this scenario, hence using HttpWebRequest.

Private Function GetResponse(ByVal sSoapUri As String, ByVal sSoapMessage As String, ByVal sSoapAction As String, ByVal bAttachCert As Boolean, _cert As X509Certificate) As XmlDocument
    Try
        Dim oHttpReq As HttpWebRequest = DirectCast(WebRequest.CreateDefault(New Uri(sSoapUri)), HttpWebRequest)
        oHttpReq.ContentType = "text/xml; charset=utf-8"
        oHttpReq.Method = "POST"
        oHttpReq.Accept = "text/xml"
        oHttpReq.Headers.Add("soapaction", sSoapAction)
        oHttpReq.ServicePoint.Expect100Continue = False  ' <-- I've tried this both on and off to no avail
        If bAttachCert Then oHttpReq.ClientCertificates.Add(_cert)
        Dim oReqStream As New StreamWriter(oHttpReq.GetRequestStream(), Encoding.UTF8)
        oReqStream.Write(sSoapMessage)  '<-- This string is in just over 4K in length
        oReqStream.Flush()
        oReqStream.Close()

        Dim oHttpResp As HttpWebResponse = TryCast(oHttpReq.GetResponse(), HttpWebResponse)
        Dim oRespStream As Stream = oHttpResp.GetResponseStream()
        oHttpReq = Nothing
        Dim oXmlResp As New XmlDocument
        oXmlResp.Load(oRespStream)
        oRespStream.Flush()
        oRespStream.Close()
        Return oXmlResp
    Catch ex As WebException
        Return Nothing
    End Try
End Function

Is there a fundamental problem with posting data over 4KB?

EDIT There seems to be no doubt now that the request is being truncated - here is an extract of the log file - the start of it is where the stream starts to be written for the request, and the end is when it stops all of a sudden (not closing out the request/envelope

System.Net Verbose: 0 : [13196] Data from ConnectStream#53511455::ResubmitWrite
System.Net Verbose: 0 : [13196] (printing 1024 out of 5137)
System.Net Verbose: 0 : [13196] 00000000 : EF BB BF 3C 3F 78 6D 6C-20 76 65 72 73 69 6F 6E : ...<?xml version
System.Net Verbose: 0 : [13196] 00000010 : 3D 22 31 2E 30 22 20 65-6E 63 6F 64 69 6E 67 3D : ="1.0" encoding=
System.Net Verbose: 0 : [13196] 00000020 : 22 75 74 66 2D 38 22 3F-3E 0D 0A 3C 73 6F 61 70 : "utf-8"?>..<soap
System.Net Verbose: 0 : [13196] 00000030 : 3A 45 6E 76 65 6C 6F 70-65 20 78 6D 6C 6E 73 3A : :Envelope xmlns:
System.Net Verbose: 0 : [13196] 00000040 : 73 6F 61 70 3D 22 68 74-74 70 3A 2F 2F 73 63 68 : soap="http://sch
System.Net Verbose: 0 : [13196] 00000050 : 65 6D 61 73 2E 78 6D 6C-73 6F 61 70 2E 6F 72 67 : emas.xmlsoap.org
System.Net Verbose: 0 : [13196] 00000060 : 2F 73 6F 61 70 2F 65 6E-76 65 6C 6F 70 65 2F 22 : /soap/envelope/"
System.Net Verbose: 0 : [13196] 00000070 : 20 78 6D 6C 6E 73 3A 78-73 69 3D 22 68 74 74 70 :  xmlns:xsi="http
System.Net Verbose: 0 : [13196] 00000080 : 3A 2F 2F 77 77 77 2E 77-33 2E 6F 72 67 2F 32 30 : ://www.w3.org/20
System.Net Verbose: 0 : [13196] 00000090 : 30 31 2F 58 4D 4C 53 63-68 65 6D 61 2D 69 6E 73 : 01/XMLSchema-ins
System.Net Verbose: 0 : [13196] 000000A0 : 74 61 6E 63 65 22 20 78-6D 6C 6E 73 3A 78 73 64 : tance" xmlns:xsd
System.Net Verbose: 0 : [13196] 000000B0 : 3D 22 68 74 74 70 3A 2F-2F 77 77 77 2E 77 33 2E : ="http://www.w3.
System.Net Verbose: 0 : [13196] 000000C0 : 6F 72 67 2F 32 30 30 31-2F 58 4D 4C 53 63 68 65 : org/2001/XMLSche
System.Net Verbose: 0 : [13196] 000000D0 : 6D 61 22 20 78 6D 6C 6E-73 3A 77 73 73 65 3D 22 : ma" xmlns:wsse="
System.Net Verbose: 0 : [13196] 000000E0 : 68 74 74 70 3A 2F 2F 64-6F 63 73 2E 6F 61 73 69 : http://docs.oasi
System.Net Verbose: 0 : [13196] 000000F0 : 73 2D 6F 70 65 6E 2E 6F-72 67 2F 77 73 73 2F 32 : s-open.org/wss/2
System.Net Verbose: 0 : [13196] 00000100 : 30 30 34 2F 30 31 2F 6F-61 73 69 73 2D 32 30 30 : 004/01/oasis-200
System.Net Verbose: 0 : [13196] 00000110 : 34 30 31 2D 77 73 73 2D-77 73 73 65 63 75 72 69 : 401-wss-wssecuri
System.Net Verbose: 0 : [13196] 00000120 : 74 79 2D 73 65 63 65 78-74 2D 31 2E 30 2E 78 73 : ty-secext-1.0.xs
System.Net Verbose: 0 : [13196] 00000130 : 64 22 20 78 6D 6C 6E 73-3A 77 73 75 3D 22 68 74 : d" xmlns:wsu="ht
System.Net Verbose: 0 : [13196] 00000140 : 74 70 3A 2F 2F 64 6F 63-73 2E 6F 61 73 69 73 2D : tp://docs.oasis-
System.Net Verbose: 0 : [13196] 00000150 : 6F 70 65 6E 2E 6F 72 67-2F 77 73 73 2F 32 30 30 : open.org/wss/200
System.Net Verbose: 0 : [13196] 00000160 : 34 2F 30 31 2F 6F 61 73-69 73 2D 32 30 30 34 30 : 4/01/oasis-20040
System.Net Verbose: 0 : [13196] 00000170 : 31 2D 77 73 73 2D 77 73-73 65 63 75 72 69 74 79 : 1-wss-wssecurity
System.Net Verbose: 0 : [13196] 00000180 : 2D 75 74 69 6C 69 74 79-2D 31 2E 30 2E 78 73 64 : -utility-1.0.xsd
System.Net Verbose: 0 : [13196] 00000190 : 22 3E 0D 0A 20 20 3C 73-6F 61 70 3A 48 65 61 64 : ">..  <soap:Head
System.Net Verbose: 0 : [13196] 000001A0 : 65 72 3E 0D 0A 20 20 20-20 3C 77 73 73 65 3A 53 : er>..    <wsse:S
System.Net Verbose: 0 : [13196] 000001B0 : 65 63 75 72 69 74 79 3E-0D 0A 20 20 20 20 20 20 : ecurity>..      
System.Net Verbose: 0 : [13196] 000001C0 : 3C 77 73 73 65 3A 42 69-6E 61 72 79 53 65 63 75 : <wsse:BinarySecu
System.Net Verbose: 0 : [13196] 000001D0 : 72 69 74 79 54 6F 6B 65-6E 20 56 61 6C 75 65 54 : rityToken ValueT
System.Net Verbose: 0 : [13196] 000001E0 : 79 70 65 3D 22 45 78 70-65 72 69 61 6E 57 41 53 : ype="SupplierWAS
System.Net Verbose: 0 : [13196] 000001F0 : 50 22 20 45 6E 63 6F 64-69 6E 67 54 79 70 65 3D : P" EncodingType=
System.Net Verbose: 0 : [13196] 00000200 : 22 77 73 73 65 3A 42 61-73 65 36 34 42 69 6E 61 : "wsse:Base64Bina
System.Net Verbose: 0 : [13196] 00000210 : 72 79 22 20 77 73 75 3A-49 64 3D 22 53 65 63 75 : ry" wsu:Id="Secu
System.Net Verbose: 0 : [13196] 00000220 : 72 69 74 79 54 6F 6B 65-6E 20 22 3E 4E 6B 55 74 : rityToken ">NkUt
System.Net Verbose: 0 : [13196] 00000230 : 52 45 55 74 4E 54 63 74-4E 55 59 74 4F 44 49 74 : REUtNTctNUYtODIt
System.Net Verbose: 0 : [13196] 00000240 : 52 54 67 74 51 55 4D 74-4E 54 55 74 4D 54 41 74 : RTgtQUMtNTUtMTAt
System.Net Verbose: 0 : [13196] 00000250 : 51 6A 45 74 4E 55 51 74-52 6A 45 74 4E 55 55 74 : QjEtNUQtRjEtNUUt
System.Net Verbose: 0 : [13196] 00000260 : 4D 7A 45 74 4F 44 6B 74-4E 7A 67 74 4D 54 63 74 : MzEtODktNzgtMTct
System.Net Verbose: 0 : [13196] 00000270 : 4E 45 45 74 4F 55 55 74-4E 45 55 74 4D 6A 45 74 : NEEtOUUtNEUtMjEt
System.Net Verbose: 0 : [13196] 00000280 : 4D 30 4D 74 52 45 59 74-4D 30 51 74 4D 45 4D 74 : M0MtREYtM0QtMEMt
System.Net Verbose: 0 : [13196] 00000290 : 4E 54 6B 74 4F 54 51 74-52 44 67 74 4D 54 6B 74 : NTktOTQtRDgtMTkt
System.Net Verbose: 0 : [13196] 000002A0 : 4F 44 51 74 4D 6A 67 74-4F 44 67 74 52 55 55 74 : ODQtMjgtODgtRUUt
System.Net Verbose: 0 : [13196] 000002B0 : 4F 44 51 74 4F 55 59 74-4F 54 51 74 52 44 6B 74 : ODQtOUYtOTQtRDkt
System.Net Verbose: 0 : [13196] 000002C0 : 52 55 4D 74 51 7A 45 74-52 44 4D 74 4E 44 6B 74 : RUMtQzEtRDMtNDkt
System.Net Verbose: 0 : [13196] 000002D0 : 52 6B 55 74 52 55 55 74-52 44 51 74 52 44 49 74 : RkUtRUUtRDQtRDIt
System.Net Verbose: 0 : [13196] 000002E0 : 4F 54 4D 74 52 44 49 74-4F 45 45 74 52 44 49 74 : OTMtRDItOEEtRDIt
System.Net Verbose: 0 : [13196] 000002F0 : 51 6B 45 74 51 6B 59 74-4F 44 6B 74 4F 54 6B 74 : QkEtQkYtODktOTkt
System.Net Verbose: 0 : [13196] 00000300 : 51 7A 49 74 51 30 45 74-4E 44 59 74 4D 45 55 74 : QzItQ0EtNDYtMEUt
System.Net Verbose: 0 : [13196] 00000310 : 4F 54 6B 74 4F 54 41 74-4D 55 4D 74 52 6B 59 74 : OTktOTAtMUMtRkYt
System.Net Verbose: 0 : [13196] 00000320 : 4E 55 45 74 51 54 59 74-4D 44 51 74 4D 30 59 74 : NUEtQTYtMDQtM0Yt
System.Net Verbose: 0 : [13196] 00000330 : 51 30 55 74 4E 7A 41 74-4E 54 63 74 51 54 4D 74 : Q0UtNzAtNTctQTMt
System.Net Verbose: 0 : [13196] 00000340 : 52 45 4D 74 4D 6A 45 74-4F 54 49 74 4D 55 59 74 : REMtMjEtOTItMUYt
System.Net Verbose: 0 : [13196] 00000350 : 4D 55 45 74 52 6A 45 74-4D 6A 41 74 4F 54 4D 74 : MUEtRjEtMjAtOTMt
System.Net Verbose: 0 : [13196] 00000360 : 4E 7A 55 74 51 6A 4D 74-51 6A 67 74 4E 44 4D 74 : NzUtQjMtQjgtNDMt
System.Net Verbose: 0 : [13196] 00000370 : 4D 44 41 74 4F 55 49 74-4D 6A 45 74 4E 6B 51 74 : MDAtOUItMjEtNkQt
System.Net Verbose: 0 : [13196] 00000380 : 52 6A 59 74 51 55 45 74-4E 54 6B 74 4F 55 49 74 : RjYtQUEtNTktOUIt
System.Net Verbose: 0 : [13196] 00000390 : 51 6A 67 74 4D 55 51 74-4F 45 45 74 51 7A 4D 74 : QjgtMUQtOEEtQzMt
System.Net Verbose: 0 : [13196] 000003A0 : 51 7A 67 74 4E 6B 4D 74-52 6A 49 74 52 54 55 74 : QzgtNkMtRjItRTUt
System.Net Verbose: 0 : [13196] 000003B0 : 52 55 49 74 4E 30 59 74-51 6A 6B 74 4D 7A 59 74 : RUItN0YtQjktMzYt
System.Net Verbose: 0 : [13196] 000003C0 : 4E 6A 59 74 4E 6A 45 74-4D 45 55 74 4F 54 55 74 : NjYtNjEtMEUtOTUt
System.Net Verbose: 0 : [13196] 000003D0 : 52 6A 49 74 51 7A 49 74-52 55 4D 74 4D 44 51 74 : RjItQzItRUMtMDQt
System.Net Verbose: 0 : [13196] 000003E0 : 4E 7A 6B 74 52 55 55 74-52 6B 59 74 4D 45 51 74 : NzktRUUtRkYtMEQt
System.Net Verbose: 0 : [13196] 000003F0 : 4E 6A 4D 74 52 54 59 74-4E 54 63 74 4E 54 67 74 : NjMtRTYtNTctNTgt
System.Net.Sockets Verbose: 0 : [13196] Socket#63449475::Receive()
System.Net.Sockets Verbose: 0 : [13196] Data from Socket#63449475::Receive
System.Net.Sockets Verbose: 0 : [13196] 00000000 : 17 03 01 02 61                                  : ....a
System.Net.Sockets Verbose: 0 : [13196] Exiting Socket#63449475::Receive()  -> Int32#5
System.Net.Sockets Verbose: 0 : [13196] Socket#63449475::Receive()

UPDATE I have tried changing the size of the buffer in the StreamWriter, and now the network log seems to be completing the writing. Is it possible that it's something to do with the Stream - the service is firstly checking my certificate which is sent with the request, then accepting my streamed data. The revised code is shown below:

    Dim oReqStream As New StreamWriter(oHttpReq.GetRequestStream(), Encoding.UTF8, 4096)

Answer 1

Transpired that my messages were not being truncated.

One major curve ball on this was that my logging had a maxdatasize set as 1024, so when the logs were written, they appeared truncated but in fact they were all present. This became apparent when I set the maxdatasize key to be greater than the data being sent. Extract from the final config section below:

<system.diagnostics>
    <sources>
      <source name="System.Net" tracemode="includehex" maxdatasize="8192">
        <listeners>
          <add name="System.Net"/>
        </listeners>
      </source>
      <source name="System.Net.Sockets" tracemode="includehex" maxdatasize="8192">
        <listeners>
          <add name="System.Net"/>
        </listeners>
      </source>
    </sources>
    <switches>
      <add name="System.Net" value="Verbose"/>
      <add name="System.Net.Sockets" value="Verbose"/>
    </switches>
    <sharedListeners>
      <add name="System.Net" type="System.Diagnostics.TextWriterTraceListener" initializeData="c:\network.log"/>
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>

The internal server 500 error was due to a totally unrelated problem on the server side.