Not receiving any data in a Response after a POST in a Reverse Proxy Scenario

Topics: Developer Forum, User Forum
Oct 1, 2011 at 10:27 AM

Hi everyone,

I have being trying once and again all sorts of alternatives to solve this problem without success, so any help would be very appreciated.

Scenario:

I am using IIRF 2.1 in a IIS 7.5 Website (Windows Server 2008 R2 Enterprise x64) as a Reverse Proxy, so all incoming Browser Requests from Domain A can be proxied to another Webserver (Tomcat/Apache) in a Domain B.

Problem:

Every GET requests are OK, and some POST request as well. However there are some critial POST requests that returns the 200 OK Status (by using Fiddler HTTP debugger) but the response is empty (Content-Lenght = 0).

I have logged the request, and it ends with the next error message:

IirfProxy_RelayRequestWithMessageBody: Error in WinHttpAddRequestHeaders: 87

I am unable to know the cause of the problem and how to solve it, so I would appreciate much your suggestions or ideas.

Below you will find the extrated data from the log file.

Analysis LOG FILE:

Sat Oct 01 12:15:05 -  3128 - -------------------------------------------------------
Sat Oct 01 12:15:05 -  3128 - Ionic ISAPI Rewriting Filter (IIRF) 2.1.2.0 x64 RELEASE
Sat Oct 01 12:15:05 -  3128 - IIRF was built on: Aug 17 2011 09:59:20
Sat Oct 01 12:15:05 -  3128 - Cached: DLL_PROCESS_ATTACH
Sat Oct 01 12:15:05 -  3128 - Cached: Process ID: 3852
Sat Oct 01 12:15:05 -  3128 - Cached: ReadServerConfig: C:\Windows\System32\inetsrv\IIRF\IirfGlobal.ini(7): EventsForIniOpen setting is now: OFF
Sat Oct 01 12:15:05 -  3128 - Cached: ReadServerConfig: C:\Windows\System32\inetsrv\IIRF\IirfGlobal.ini(8): NotifyLog setting is now: ON
Sat Oct 01 12:15:05 -  3128 - Cached: DLL_PROCESS_ATTACH - complete
Sat Oct 01 12:15:05 -  3128 - Cached: GetFilterVersion
Sat Oct 01 12:15:05 -  3128 - GetLogFile: app:'/LM/W3SVC/3/ROOT'  new log:'c:\IIRFLogs\iirf.3852.log'
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: actual log file 'c:\IIRFLogs\iirf.3852.log'
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: ini file: 'C:\inetpub\wwwroot\IIRF\Iirf.ini'
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: ini file timestamp: 2011/09/30 20:19:36 Romance Daylight Time
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: cfg(0x02917E80)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: LogLevel = 5
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: pass 2
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(10): IterationLimit 10
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(11): MaxMatchCount 10
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(12): RewriteEngine will be enabled.
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(13): StatusInquiry ON (--) (--)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(13): IIRF Status Inquiry is enabled at path '/iirfStatus' for local requests only.
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(14): UrlDecoding will be enabled.
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(15): ProxyPreserveHost will be disabled.
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(16): ProxyTimeouts 0 0 0 0
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(16): Proxy Timeout Values IN SECONDS are now: Resolve=0, Connect=0, Send=0, Receive=0
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(18): IterationLimit 0
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(18): WARNING: multiple IterationLimit directives. Don't do this.
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(27): ProxyPass (rule 1)  '^/(.+)(TO2.+DVT)(.+)$'  'https://smc-t-bmc-ms.smc-test.local/$1TO2%3ACreateIncident_%2BDVT$3'   (null)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(29): ProxyPass (rule 2)  '^/(.+)(SRS:ServiceRequestConsole)(/enduser.+)$'  'https://smc-t-bmc-ms.smc-test.local/$1SRS%3AServiceRequestConsole$3'      [I]
Sat Oct 01 12:15:05 -  3128 - ParseRuleModifierFlags: '[I]'
Sat Oct 01 12:15:05 -  3128 - ParseRuleModifierFlags: token 'I'
Sat Oct 01 12:15:05 -  3128 - rule: Case Insensitive match
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(33): ProxyPass (rule 3)  '^/(arsys.+)\s(.+)$'  'https://smc-t-bmc-ms.smc-test.local$0'      [I]
Sat Oct 01 12:15:05 -  3128 - ParseRuleModifierFlags: '[I]'
Sat Oct 01 12:15:05 -  3128 - ParseRuleModifierFlags: token 'I'
Sat Oct 01 12:15:05 -  3128 - rule: Case Insensitive match
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(38): ProxyPass (rule 4)  '^/(arsys/.*)$'  'https://smc-t-bmc-ms.smc-test.local/$1'   (null)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(40): ProxyPass (rule 5)  '^/(adfs/.*)$'  'https://smc-t-fsrf.smc-test.local/$1'   (null)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: C:\inetpub\wwwroot\IIRF\Iirf.ini(43): ProxyPass (rule 6)  '^/int/(.+)$'  'http://bmc-dry.wh.telefonica:81/$1'   (null)
Sat Oct 01 12:15:05 -  3128 - CountIniLines: ini file C:\inetpub\wwwroot\IIRF\Iirf.ini (45 lines)
Sat Oct 01 12:15:05 -  3128 - ReadVdirConfig: Done reading INI for the root vdir, found 6 rules (0 errors, 1 warnings) on 45 lines, in 1 modules
Sat Oct 01 12:15:05 -  3128 - GetVdirConfig: Obtain  vdir '/LM/W3SVC/3/ROOT' (era=0) (rc=1) (Expired=0) (ptr=0x02917E80)...
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: SF_NOTIFY_URL_MAP
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: cfg= 0x02917E80
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: SF_NOTIFY_AUTH_COMPLETE
Sat Oct 01 12:15:05 -  3128 - DoRewrites
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: getting 'url'
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: 78 bytes   ptr:0x013289A0
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: 'url' = '/arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: getting 'QUERY_STRING'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: 17 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: result 'cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: getting 'method'
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: 5 bytes   ptr:0x01328BE0
Sat Oct 01 12:15:05 -  3128 - GetHeader_AutoFree: 'method' = 'POST'
Sat Oct 01 12:15:05 -  3128 - DoRewrites: New Url, before decoding: '/arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - DoRewrites: Url (decoded): '/arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: depth=0
Sat Oct 01 12:15:05 -  3128 - GetServerVariable: getting 'SCRIPT_NAME'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable: 61 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable: result '/arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/'
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: no RewriteBase
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: Rule 1: pattern: ^/(.+)(TO2.+DVT)(.+)$  subject: /arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: Rule 1: -1 (No match)
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: Rule 2: pattern: ^/(.+)(SRS:ServiceRequestConsole)(/enduser.+)$  subject: /arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: Rule 2: 4 matches
Sat Oct 01 12:15:05 -  3128 - ReplaceServerVariables: alloc 68 bytes
Sat Oct 01 12:15:05 -  3128 - ReplaceServerVariables: in='https://smc-t-bmc-ms.smc-test.local/$1SRS%3AServiceRequestConsole$3' out='https://smc-t-bmc-ms.smc-test.local/$1SRS%3AServiceRequestConsole$3'
Sat Oct 01 12:15:05 -  3128 - GenerateReplacementString: alloc 116 bytes
Sat Oct 01 12:15:05 -  3128 - ApplyUrlEncoding: in 'https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - ApplyUrlEncoding: out 'https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GenerateReplacementString: result 'https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: Result (length 114): https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - EvaluateRules: returning 999
Sat Oct 01 12:15:05 -  3128 - DoRewrites: Proxy to: 'https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: getting 'ALL_RAW'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: 4581 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: result 'Cache-Control: no-cache

Connection: Keep-Alive

Content-Length: 13

Content-Type: application/x-www-form-urlencoded

Accept: */*

Accept-Language: es-ES

Cookie: JSESSIONID=8B878C15D73FB0A29D13E7229D28133B; IP-Restriction-GUID=8e9dc87cf92928fa:-6818ef15:132b5104d5e:-7fac; Remedy_AuthCookie=UserName=mnc.usrmnc1@cspdry.wh.telefonica&Password=adGRW6ao1epkvHWebp1rxui4VVwllE3DzOzMdAn8GX6Mz9vbB5YXN8OM793sRXYImRwrAB8c3LvwmfKR7FrrhdhE9rUhPnO5wiHRs3hMY3XUgn+18Zs8G2lqVfFLSvMsmmaJXZJV3P9/JRLCpxPRjm2zvOk3AjAG+qQbIQtuQ2o=; Remedy_AuthCookie2=UserName=mnc.usrmnc1@cspdry.wh.telefonica&Password=adGRW6ao1epkvHWebp1rxui4VVwllE3DzOzMdAn8GX6Mz9vbB5YXN8OM793sRXYImRwrAB8c3LvwmfKR7FrrhdhE9rUhPnO5wiHRs3hMY3XUgn+18Zs8G2lqVfFLSvMsmmaJXZJV3P9/JRLCpxPRjm2zvOk3AjAG+qQbIQtuQ2o=; NSC_U_tnd-u-cnd-nt-iuuqt=ffffffff09fa129645525d5f4f58455e445a4a42378b; NSC_U_tnd-u-gtsg-iuuqt=ffffffff09fa129445525d5f4f58455e445a4a423660; Remedy_AuthCookie2=UserName=mnc.usrmnc1@cspdry.wh.telefonica&Password=kZ4TNvNLTGKwFsqro84Lpobz+744taBw1tL/lx9/MG8yf7weRsUz/+CA0Rlqpo1GPdD+hUgpKyi7AV4+ybW0hbjvXuI80JqVDh9v69/hJ+6Wlzpo5qXpefRU8xL480CkgcvA1HMq+DgvUjRoWtzivhQjIojegOZjG2YChdbX8QQ=; _WebSsoAuth=eNrNV1mTokAS/isdzqNhAwoKRnfHFoeICsohHi8bHMUll1CI+usXtO3p7pnZnd2n1QgtsrIyv/zqqyx9Ka0kHoOyhAUKs/TpYyTxr51/jkZO36EtvNe3B3aPHPa9Hu2STm80wonmbVEDB3aepLKsoJSWyErRa6ePE0SPwHs4YRD4mCDHFLN/9yleOwFCeTnGsDJxeqjnlYX3fBvCEj3HmWPFmOV6JdZ5kq0oK0xYlA2W1w7RGML0q+GcxGk5bvG/dqoiHWdWGZbj1EpgOUbOWAfyYkw842PrUVLn7eVWLZelbtgayiclQyz0sgL+CXfjsEyXBfBQi/6zD/HweY8KKjeEqQO1ppQidNr4H4m+ubx9ZcFuPpPyFx6K8lJiL9jXld+ef58M+1bmI717CtsQLcNjLrbCRM+qwoHvTLbmO5NJ6BRZmXlo7EEXFtadvBZ0g7l167nF5bkOnhGMG/bS0LHu29YQ3aYoMVRUJXrBvmd65M6yQ9goxsumVhn8ZXp6xs4VTFFmJ3ONFGqCtqtDTRCrpa6+PjJ9ifvB1XvZ78ShAKaoQdxG1ZGFYNI8P321/0HMODWmho0ovjrLEAWZ+x80mIzzRod1VrgPveiVHUEHvT8pzRLJbYN6ISyeJlmRWOh+XFqdOAFMrPK5YarMrPw5K3zMaWktsfVK6bwlqfNclUXzRfzDKfNfduedia9JHvx8AMH+HUMP/lCjN7tC8PvE/185X/E+fYzaZa+dvHY7X21lbjnwLzB2voc2rbiCb4c9aSgnZWGI83pSHouMJhd5Zl+7I5JEFlsTaIHFZwaTRfrijWqolesr1uUArsXHPCPElct3g7Wfzy/hCJhk92Jv8MCOTttKovHZ0eQD5jRksGDWHW7ia55Rx20OPW1NnxckjXMH3zkBYiofu7x/WkdatkHX8BSokZRF0F/uI7G/4wLX3tJqe15+V8F36y+GT3uuh35qoap4bx4ftNV1/VwPbmz1cRzHcAZrHNwy9H907qug2x7QtxfOSm+bGYfXT8foCcR+VoQoSP4QksAIvA3Zg2en5xBk+qPzhH3C85dhviArSqtXBhZxi6RBDxZtb31aa9Jr58ffXYJvL0ZhpWVzlSTlp/F/hwOmJxhnOXR75aOcG6S/D/cHdrDP4PjQb26N/4WnD47uIe6qwSjOpRM9ONfRpk+nHlrbuyOfrLeHXaOzz54v2Ae3zfizFj527+7ojZLJId/Xul8aVSyZows5O3PK7ijPg1l4YIaCBSlmtEwCjrsAck8615DSplC0eEIOJxo7GMj1PokZDpWzyjwulbqbYznFFYoTe/TBsqHCjZpDR/GbRXcZnaq1TneRiS1itZqczNNViBamXSgxObKMC1Rdl0r3aEYEM3wukJo7EAo7V0eFTb/eC/kE/mUOL/eqthTO8Bay7iOu/RHitW0VvsmSxFsGx4FY9EEtscCX5p7IGawPbi+NBwrrH47BIRSZGmeBup4AHhiyJtR8veNNVeWFOrjaG7lyRfPq8gBOavwsN1aZ39VLAxAKb1o3m/GwCTebLIIzdwUz1ldMFuwMcFAsWaVrXr3FnQr1XnWSSepu1ufJFZh3v0zmYy22RTOpR0plbZRAEuiLrNY159/WLYRaMQxTPosG2N7XyLLAZZXTJ6LFVoudgVrZIhPtNnXt72/5ZvNsLwUnRwGqwLIq4P0dDmRJnIFMZIGCHy8nNzpOgF4f0SpQF7NLVhmn0h5mk63KxF12U5JH4mqqko0NnP20zLuzFOufD1IhbBmxmSi6tiNdIytzL3rUeFPeArppOE+2inXOMzOMCjgdZNRoGp3Fo21vhwNMP1gpXg80DvhWrK8EenfGJUFczQRvt01ORyH1fBgfpnqab+iZx5E7D/gyC4AY+d669j2p5ltONHwF1CnWbB4PfKOW2YZ5Yu3OVFWWmwI5rhTbfWXbGRa/zfG+ummIsImEWeA0Jlsi7ubDbpgHambFE6e+Aq/ldqrLgsiDjc8a/tZM; _WebSsoAuth0=i8Fa3jvdXKIHlL2GlJEgGvo8x4b+TprXuybketpwLHgRS8t8/TP3FXBBxGbuVKuXIX2675WKdn3hpPbNiyuYlZMwpc0xrdaQyxHRzmR+6o6jIidV6xX4mUcGc1EW97ktroeLy6d1OsPvtzNc21AXu38uFwMF7S4Evmi0tL2NKXy/VfBFolzc3+kfLLmmBtBoOtRP7sVcMuKU6S+WaELFWz4luz6u7wsSA1t6UfV5HmMpNYpOgVmk4kYAODlhzAD0Y0yZZuEo1AlrdegO0z1cMstDZbiHAUseranNOblp0j6axMZKpZCUKAk27KKdGOwoH9vhxHVy3ub7oXbE7EGxhfgMJPqEnnsJtybJNXLUoNpcyRWWT91zJjYNBj9BDRSniIkvpp7LF9vkV5k7Gkz628sg4Ws2pUc+M2dXgds3ZMEecKY8NYZeWB94nNGW5+YKStAwosFwMhjtamvj6AmD1gLNEsRgfurTslkvpVU9zDy7KgS5XnN6wWq0rcXq6jwjg2hpLHaxFlBd3UCpul+m/Rm7ohiIFzG/nev1a9PIvnepu+XewbCPrvaz3338Pnj8wXr7F/S13zg=

Host: iirf-dry.wh.telefonica

Max-Forwards: 10

Referer: https://bmc-dry.wh.telefonica/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2

User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729)

X-Original-URL: /arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2

X-Forwarded-For: 10.30.172.6:60073

X-ARR-SSL: 2048|128|C=US, O="VeriSign, Inc.", OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)10, CN=VeriSign Class 3 Secure Server CA - G3|C=ES, S=Madrid, L=Madrid, O=Telefonica International Wholesale Services, OU=It, OU=Terms of use at www.verisign.com/rpa (c)05, CN=*.wh.telefonica

X-ARR-LOG-ID: d67d40d6-5b85-4a17-b59c-400e5c75c6e9

'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: getting 'REQUEST_METHOD'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: 5 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_AutoFree: result 'POST'
Sat Oct 01 12:15:05 -  3128 - IirfProxy_TryRelayEmptyBodyRequest: https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: Cache-Control: no-cache

Connection: Keep-Alive

Content-Length: 13

Content-Type: application/x-www-form-urlencoded

Accept: */*

Accept-Language: es-ES

<REMOVED UNNECESARY COOKIE DATA>

Host: iirf-dry.wh.telefonica

Max-Forwards: 10

Referer: https://bmc-dry.wh.telefonica/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2

User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729)

X-Original-URL: /arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2

X-Forwarded-For: 10.30.172.6:60073

X-ARR-SSL: 2048|128|C=US, O="VeriSign, Inc.", OU=VeriSign Trust Network, ....

X-ARR-LOG-ID: d67d40d6-5b85-4a17-b59c-400e5c75c6e9

Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Cache-Control: no-cache
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Connection: Keep-Alive
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Content-Length: 13
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Content-Type: application/x-www-form-urlencoded
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Accept: */*
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Accept-Language: es-ES
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Cookie: JSESSIONID=8B878C15D73FB0A29D13E7229D28133B; IP-Restriction-GUID=8e9dc87cf92928fa:-6818ef15:132b5104d5e:-7fac;

 <REMOVED UNNECESARY COOKIE DATA>

Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Host: iirf-dry.wh.telefonica
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Max-Forwards: 10
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr Referer: https://bmc-dry.wh.telefonica/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729)
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr X-Original-URL: /arsys/forms/smc-t-bmc-as/SRS:ServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr X-Forwarded-For: 10.30.172.6:60073
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr X-ARR-SSL: 2048|128|C=US, O="VeriSign, Inc.", OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)10, CN=VeriSign Class 3 Secure Server ....
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: hdr X-ARR-LOG-ID: d67d40d6-5b85-4a17-b59c-400e5c75c6e9
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: found 15 headers
Sat Oct 01 12:15:05 -  3128 - DoRewrites: internal rewrite to: '/proxy.iirf?path=/LM/W3SVC/3/ROOT&url=https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: SF_NOTIFY_URL_MAP
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: cfg= 0x02917E80
Sat Oct 01 12:15:05 -  3128 - GetVdirConfig_FromPath: Obtain  site '/LM/W3SVC/3/ROOT' (era=0) (rc=2) (Expired=0) (ptr=0x02917E80)...
Sat Oct 01 12:15:05 -  3128 - HttpExtensionProc: Proxy to 'https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'REMOTE_ADDR'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 13 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result '10.30.172.29'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'LOCAL_ADDR'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 13 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result '10.30.172.29'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'HTTP_REFERER'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 109 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result 'https://bmc-dry.wh.telefonica/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'HTTP_USER_AGENT'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: Buffer not large enough.
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 138 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result 'Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729)'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'HTTP_ACCEPT'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 4 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result '*/*'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'SERVER_NAME'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 23 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result 'iirf-dry.wh.telefonica'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: getting 'ALL_RAW'
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: ???
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: 4581 bytes
Sat Oct 01 12:15:05 -  3128 - GetServerVariable_EX: result 'ALL_RAW'
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: url(https://smc-t-bmc-ms.smc-test.local/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2)
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: host(smc-t-bmc-ms.smc-test.local)  path+query(/arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2)
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: ALL_RAW
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: no colon (ALL_RAW) cycle(0)
Sat Oct 01 12:15:05 -  3128 - ParseAllRaw: found 1 headers
Sat Oct 01 12:15:05 -  3128 - GenProxyRequestHeadersString: rh(0x00000000) nh(smc-t-bmc-ms.smc-test.local) sn(iirf-dry.wh.telefonica) la(10.30.172.29) ra(10.30.172.29) ts(13)
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: varAccept 0x02A172C0 (*/*)
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: WinHttpConnect smc-t-bmc-ms.smc-test.local 443
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: WinHttpOpenRequest POST /arsys/forms/smc-t-bmc-as/SRS%3AServiceRequestConsole/enduser/?cacheid=5785fba2
Sat Oct 01 12:15:05 -  3128 - RelayRequestWithMessageBody: WinHttpAddRequestHeaders
Sat Oct 01 12:15:05 -  3128 - IirfProxy_RelayRequestWithMessageBody: Error in WinHttpAddRequestHeaders: 87
Sat Oct 01 12:15:05 -  3128 - ReleaseArrayCharP: pc= 0x02A1A690
Sat Oct 01 12:15:05 -  3128 - ReleaseArrayCharP: pc[0]= 0x02917200
Sat Oct 01 12:15:05 -  3128 - ReleaseArrayCharP: pc[1]= 0x02A17080
Sat Oct 01 12:15:05 -  3128 - ReleaseArrayCharP: pc[2]= 0x00000000
Sat Oct 01 12:15:05 -  3128 - ReleaseArrayCharP: pc[3]= 0x00000000
Sat Oct 01 12:15:05 -  3128 - HttpExtensionProc: done
Sat Oct 01 12:15:05 -  3128 - HttpFilterProc: SF_NOTIFY_LOG
Sat Oct 01 12:15:05 -  3128 - ReleaseOrExpireVdirConfig: vdir '/LM/W3SVC/3/ROOT' (era=0) (rc=0) (Expired=0) (ptr=0x02917E80)...
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              

 

Coordinator
Oct 2, 2011 at 7:57 PM

At first look, It appears to be a bug in IIRF to me.  Errno 87 is ERROR_INVALID_PARAMETER, which suggests that the call to WinHttpAddRequestHeaders was made with incorrect parameters, specifically, invalid http headers. 

I can't tell what headers are passed.  Is the problem readily reproducible?  If so, set the IIRF loglevel to 6, and re-run it.  IIRF will emit the headers into the logfile. That would give me some extra insight into why the call to WinHttpAddReqestHeaders is generating the error. 

I see one problem already: the encoding of the URL that gets proxied isn't quite right. I'm not sure if that problem would result in the error you're seeing, or not. I will have a closer look, and fix that. In the meantime if you could send me the log content, that would be great. 

Coordinator
Oct 2, 2011 at 8:02 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.
Coordinator
Oct 2, 2011 at 8:06 PM

Also:  In the IIRF log, I see a header that is 4581 bytes. That's a big header; I'll want to check to make sure it was really passed correctly. There are some messages in the log file that are a little different for that particular header.   I'll review the code to make sure  that large headers are handled correctly.

Coordinator
Oct 2, 2011 at 8:32 PM

An update  - yes, the large request header is the source of the problem you are seeing.  You don't need to re-run and post another log. I see the problem.

There's a hard-coded limit in IIRF on the size of a request header - it is 4k for each header.The header in your case is just over that. IIRF is not passing the header correctly, in fact when the header is larger than 4k, IIRF passes a dummy string that is not a valid header. Which gives you the 87 error. 

There are really two problems here in IIRF:

  • When the request exceeds the size of IIRF's hardcoded limit, IIRF just silently passes through that error, and instead of formatting the large header correctly, it formats a dummy string.  IIRF should fail fast and emit a clear error message into the log. 
  • There's no way to modify the hardcoded limit in IIRF.

I can fix this pretty quickly.  I will need you to re-run with an updated binary, and let me know if that fixes your problem. I will let you know here, when it's ready to test.

 

Coordinator
Oct 2, 2011 at 8:50 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.
Oct 2, 2011 at 9:13 PM

Hello Cheeso,

First of all, thank you very much for your time and efforts to analyse and solve this problem!

You are absolutely right, and the size of the header is quite big. That is because encrypted user information and credential data is passed over from one domain to another by using the Cookie Header.

In fact the only way I found to pass over cookie data between different domains is by mean of a Reverse Proxy Server (IIS 7.5 in this case).

I am waiting for your updated binary to test it in our current scenario.

Thank you again,

Juanjo

Coordinator
Oct 2, 2011 at 9:50 PM

ok, the patched binaries are ready for you to test.  Visit the workitem at http://iirf.codeplex.com/workitem/31541 , read the instructions there for testing.

Follow those instructions, and report your results back here.

 

Coordinator
Oct 2, 2011 at 9:51 PM

Hello Juanjo,

no problem, I am glad to help out.  I will be interested to hear the results of your test.

-Cheeso

Oct 3, 2011 at 4:06 PM

Hello again Cheeso,

I am very glad to let you know that I've just tested the x64 patched binary and it has been succesful. It worked perfectly.

Thank you so much for your quick, kind and effective answer. I really appreciate your excellent work!

Juanjo

 

 

Coordinator
Oct 3, 2011 at 5:36 PM

Hello Juanjo,

Glad to hear it. Thanks for getting back to me.

You can safely use that binary, there's no danger or risk.  It is a DEBUG binary which means it will run more slowly than the release binary that I ship in the installer.  This may or may not be an issue for you, at your levels of load.

Just a reminder: for sure, you should lower the LogLevel for IIRF.   You don't want to log those large Headers, for every proxied transaction, unless you need to for diagnostic purposes. 

I will produce a real release with this update, and some documentation changes, in the next few days.