Content-Length and cbTotalBytes disagree

Topics: Developer Forum, User Forum
Feb 27, 2011 at 6:08 PM

Hi,

A little bit of background - I am writing my own implementation of a WebDAV servlet on Glassfish 3.01, hidden behind IIS 6 in out Win2003 server.

Glassfish is running on port 8080, but our firewall prevents direct access to that port, so I am using IIRF with ProxyPass

This is the rule:

RewriteCond %{HTTP_URL} /webdav/(.*)$   [I]
ProxyPass ^/websav/(.*) http://sameserver.org:8080/webdav/$1

From my development machine, I have access to both 80 and 8080, so I am pretty sure my code is working fine (works on 8080 which is not going through IIS/IIRF).

When I access my server through port 80 (I tried many different WebDAV clients) and the client sends a PRODFIND, the following line is reported in the IIRF log:

GenProxyRequestHeadersString: protocol error detected: Content-Length and cbTotalBytes(0x00000000) disagree

On the servlet side, I receive the full set of headers (including the IIRF added ones), but any attempt to read the data sent past the header blocks, as in fact the servlet never receives any data. 30 seconds later, IIS sends to the waiting client a timeout message.

I am not sure what's going on, but I am quite sure it is caused by the method being "PROPFIND", as my servlet uses GETs (returns the same response as PROPFIND, just with a different HTTP respose code) and POSTs (can read the data in the request) without any issue.

This is the relevant section of the IIRF log with LogLevel 5:


Sun Feb 27 14:30:51 -   580 - Cached: DLL_THREAD_DETACH
Sun Feb 27 14:30:51 -   580 - IsIniFileUpdated: F:\websites\wmrfid\Iirf.ini NO
Sun Feb 27 14:30:51 -   580 - GetVdirConfig: Obtain  vdir '/LM/W3SVC/90429529/Root' (era=5) (rc=1) (Expired=0) (ptr=0x01EE60A0)...
Sun Feb 27 14:30:51 -   580 - HttpFilterProc: SF_NOTIFY_URL_MAP
Sun Feb 27 14:30:51 -   580 - HttpFilterProc: cfg= 0x01EE60A0
Sun Feb 27 14:30:51 -   580 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Sun Feb 27 14:30:51 -   580 - DoRewrites
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: getting 'url'
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: 20 bytes   ptr:0x000CFE68
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: 'url' = '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'QUERY_STRING'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 1 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result ''
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: getting 'method'
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: 9 bytes   ptr:0x000CF360
Sun Feb 27 14:30:51 -   580 - GetHeader_AutoFree: 'method' = 'PROPFIND'
Sun Feb 27 14:30:51 -   580 - DoRewrites: New Url, before decoding: '/webdav/product/' 
Sun Feb 27 14:30:51 -   580 - DoRewrites: Url (no decoding): '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - EvaluateRules: depth=0
Sun Feb 27 14:30:51 -   580 - GetServerVariable: getting 'SCRIPT_NAME'
Sun Feb 27 14:30:51 -   580 - GetServerVariable: 20 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: result '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - EvaluateRules: no RewriteBase
Sun Feb 27 14:30:51 -   580 - EvaluateRules: Rule 1: pattern: ^/webdav/(.*)  subject: /webdav/product/
Sun Feb 27 14:30:51 -   580 - EvaluateRules: Rule 1: 2 match
Sun Feb 27 14:30:51 -   580 - EvaluateRules: Rule 1: evaluating condition
Sun Feb 27 14:30:51 -   580 - EvalCondition: cond 0x01EEB3A8
Sun Feb 27 14:30:51 -   580 - GetServerVariable: getting 'HTTP_URL'
Sun Feb 27 14:30:51 -   580 - GetServerVariable: 20 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: result '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: alloc 20 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: getting 'HTTP_URL'
Sun Feb 27 14:30:51 -   580 - GetServerVariable: 20 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: result '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: vName(HTTP_URL) value(/webdav/product/)
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: in='%{HTTP_URL}' out='/webdav/product/'
Sun Feb 27 14:30:51 -   580 - EvalCondition: ts1 '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: alloc 21 bytes
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: result '/webdav/product/'
Sun Feb 27 14:30:51 -   580 - EvalCondition: t(/webdav/product/) op(~) p(/webdav/(.*)$)
Sun Feb 27 14:30:51 -   580 - EvalCondition: match result: 2 (match)
Sun Feb 27 14:30:51 -   580 - EvalCondition: Cond t(%{HTTP_URL}) op(~) p(/webdav/(.*)$) => TRUE
Sun Feb 27 14:30:51 -   580 - EvalCondition: Child is non NULL (parent= 0x01EEB3A8) (child= 0x01EE8E60)
Sun Feb 27 14:30:51 -   580 - EvalCondition: Current condition evaluates to TRUE
Sun Feb 27 14:30:51 -   580 - EvalCondition: Logical AND, ergo we evaluate the Child
Sun Feb 27 14:30:51 -   580 - EvalCondition: cond 0x01EE8E60
Sun Feb 27 14:30:51 -   580 - GetServerVariable: getting 'HTTPS'
Sun Feb 27 14:30:51 -   580 - GetServerVariable: 4 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: result 'off'
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: alloc 4 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: getting 'HTTPS'
Sun Feb 27 14:30:51 -   580 - GetServerVariable: 4 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable: result 'off'
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: vName(HTTPS) value(off)
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: in='%{HTTPS}' out='off'
Sun Feb 27 14:30:51 -   580 - EvalCondition: ts1 'off'
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: alloc 5 bytes
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: result 'off'
Sun Feb 27 14:30:51 -   580 - EvalCondition: t(off) op(~) p(^off$)
Sun Feb 27 14:30:51 -   580 - EvalCondition: match result: 1 (match)
Sun Feb 27 14:30:51 -   580 - EvalCondition: Cond t(%{HTTPS}) op(~) p(^off$) => TRUE
Sun Feb 27 14:30:51 -   580 - EvalConditionList: rule 1, TRUE, Rule will apply
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: alloc 36 bytes
Sun Feb 27 14:30:51 -   580 - ReplaceServerVariables: in='http://sameserver.org:8080/webdav/$1' out='http://sameserver.org:8080/webdav/$1'
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: alloc 43 bytes
Sun Feb 27 14:30:51 -   580 - GenerateReplacementString: result 'http://sameserver.org:8080/webdav/product/'
Sun Feb 27 14:30:51 -   580 - EvaluateRules: Result (length 41): http://sameserver.org:8080/webdav/product/
Sun Feb 27 14:30:51 -   580 - EvaluateRules: returning 999
Sun Feb 27 14:30:51 -   580 - DoRewrites: Proxy to: 'http://sameserver.org:8080/webdav/product/'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'REQUEST_METHOD'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 9 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'PROPFIND'
Sun Feb 27 14:30:51 -   580 - IirfProxy_SendRequest: http://sameserver.org:8080/webdav/product/
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'REMOTE_ADDR'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 15 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'xxx.xxx.177.215'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'LOCAL_ADDR'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 13 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'xxx.xxx.4.18'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'HTTP_REFERER'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 128 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result ''
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'HTTP_USER_AGENT'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 72 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'HTTP_ACCEPT'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 85 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'SERVER_NAME'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 11 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'sameserver.org'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: getting 'ALL_RAW'
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: 512 bytes
Sun Feb 27 14:30:51 -   580 - GetServerVariable_AutoFree: result 'Cache-Control: no-cache

Connection: Keep-Alive

Pragma: no-cache

Content-Length: 303

Content-Type: text/xml; charset=utf-8

Accept: text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8

Accept-Charset: utf-8, utf-8;q=0.5, *;q=0.5

Accept-Encoding: x-gzip, x-deflate, gzip, deflate

Accept-Language: en-GB,en-US;q=0.9,en;q=0.8

Host: sameserver.org

User-Agent: Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)

Depth: 0

X-REWRITE-URL: /webdav/product/

'
Sun Feb 27 14:30:51 -   580 - ProxyRequest: host(sameserver.org)  path+query(/webdav/product/)
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: Cache-Control: no-cache

Connection: Keep-Alive

Pragma: no-cache

Content-Length: 303

Content-Type: text/xml; charset=utf-8

Accept: text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8

Accept-Charset: utf-8, utf-8;q=0.5, *;q=0.5

Accept-Encoding: x-gzip, x-deflate, gzip, deflate

Accept-Language: en-GB,en-US;q=0.9,en;q=0.8

Host: sameserver.org

User-Agent: Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)

Depth: 0

X-REWRITE-URL: /webdav/product/

Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Cache-Control: no-cache
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Connection: Keep-Alive
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Pragma: no-cache
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Content-Length: 303
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Content-Type: text/xml; charset=utf-8
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Accept: text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Accept-Charset: utf-8, utf-8;q=0.5, *;q=0.5
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Accept-Encoding: x-gzip, x-deflate, gzip, deflate
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Host: sameserver.org
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr User-Agent: Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr Depth: 0
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: hdr X-REWRITE-URL: /webdav/product/
Sun Feb 27 14:30:51 -   580 - ParseAllRaw: found 13 headers
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: rh(0x01EE85C8) nh(sameserver.org) sn(sameserver.org) la(xxx.xxx.4.18) ra(xxx.xxx.177.215) ts(0)
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: protocol error detected: Content-Length and cbTotalBytes(0x00000000) disagree
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Host: sameserver.org
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Via: 1.1 xxx.xxx.4.18 (IIRF v2.1)
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header X-Forwarded-Server: sameserver.org
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header X-Forwarded-For: xxx.xxx.177.215
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Cache-Control: no-cache
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Connection: Keep-Alive
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Pragma: no-cache
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Content-Length: 303
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Content-Type: text/xml; charset=utf-8
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Accept: text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Accept-Charset: utf-8, utf-8;q=0.5, *;q=0.5
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Accept-Encoding: x-gzip, x-deflate, gzip, deflate
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header X-Forwarded-Host: sameserver.org
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header User-Agent: Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header Depth: 0
Sun Feb 27 14:30:51 -   580 - GenProxyRequestHeadersString: header X-REWRITE-URL: /webdav/product/
Sun Feb 27 14:30:51 -   580 - ProxyRequest: WinHttpConnect sameserver.org 8080
Sun Feb 27 14:30:51 -   580 - ProxyRequest: WinHttpOpenRequest: PROPFIND /webdav/product/
Sun Feb 27 14:30:51 -   580 - ProxyRequest: WinHttpAddRequestHeaders
Sun Feb 27 14:30:51 -   580 - ProxyRequest: WinHttpSendRequest
Sun Feb 27 14:30:51 -   580 - ProxyRequest: WinHttpReceiveResponse


This is sniffed with Wireshark:


PROPFIND /webdav/product/ HTTP/1.1

Host: sameserver.org

Connection: Keep-Alive

User-Agent: Mozilla/5.0 (compatible; Konqueror/4.6; Linux) KHTML/4.6.0 (like Gecko)

Pragma: no-cache

Cache-control: no-cache

Accept: text/html, image/jpeg;q=0.9, image/png;q=0.9, text/*;q=0.9, image/*;q=0.9, */*;q=0.8

Accept-Encoding: x-gzip, x-deflate, gzip, deflate

Accept-Charset: utf-8, utf-8;q=0.5, *;q=0.5

Accept-Language: en-GB,en-US;q=0.9,en;q=0.8

Authorization: Basic xxxxxxxxxxxxxw==

Depth: 0

Content-Type: text/xml; charset=utf-8

Content-Length: 303



<!--?xml version="1.0" encoding="utf-8" ?-->
HTTP/1.1 408 Request Time-out

Date: Sun, 27 Feb 2011 19:00:13 GMT

Server: Microsoft-IIS/6.0
 


Any clue?

Feb 27, 2011 at 6:12 PM

Just a note - the post is somehow missing the full xml file in the Wireshark trace,

<!--?xml version="1.0" encoding="utf-8" ?-->
<?xml version="1.0" encoding="utf-8" ?><D:propfind xmlns:D="DAV:"><D:prop><D:creationdate/><D:getcontentlength/><D:displayname/><D:source/><D:getcontentlanguage/><D:getcontenttype/><D:executable/><D:getlastmodified/><D:getetag/><D:supportedlock/><D:lockdiscovery/><D:resourcetype/></D:prop></D:propfind>

(303 bytes)

Mar 4, 2011 at 10:41 PM

I traced the problem to this statement in Proxy.c:

    if (strcmp("POST", varMethod)==0 || (strcmp("PUT", varMethod)==0)) {
        // Need to read the POST Data.  Cannot do it from a ISAPI filter.
        // Must rewrite to the IIRF Extension, which will then do the proxying.
        // Caller will do that.
        return 1;
    }

I think that adding PROPFIND would solve, even if it would be probably better to handle that way any request method when

1) it is not a method guaranteed NOT to have additional data (ie GET, HEAD etc)

2) the method is unknown and the Content-Length is not 0.

 

Coordinator
Mar 8, 2011 at 4:30 PM

Mr Condor,

Thanks for the report. I think you're correct - the Proxy module in IIRF is set up to handle PUT and POST specially, but it does not handle PROPFIND, as you have discovered.

I agree with your analysis - What I want the proxy to do is to handle any request method that sends additional data. The test for PUT or  POST was a heuristic for that purpose.  Obviously that test was insufficient.

I'll need to change it.  Before doing so, I will need to determine exactly which verbs are guaranteed to not send additional data.  GET, HEAD, and OPTIONS are three.  I'll need the complete list. 

Coordinator
Mar 8, 2011 at 4:34 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.