Return-Path: X-Original-To: apmail-hc-httpclient-users-archive@www.apache.org Delivered-To: apmail-hc-httpclient-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 250D3C147 for ; Mon, 5 Aug 2013 20:17:31 +0000 (UTC) Received: (qmail 90953 invoked by uid 500); 5 Aug 2013 20:17:30 -0000 Delivered-To: apmail-hc-httpclient-users-archive@hc.apache.org Received: (qmail 90808 invoked by uid 500); 5 Aug 2013 20:17:29 -0000 Mailing-List: contact httpclient-users-help@hc.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "HttpClient User Discussion" Delivered-To: mailing list httpclient-users@hc.apache.org Received: (qmail 90795 invoked by uid 99); 5 Aug 2013 20:17:29 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 05 Aug 2013 20:17:29 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,NORMAL_HTTP_TO_IP,RCVD_IN_DNSWL_LOW,SPF_PASS,WEIRD_PORT X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of aoscherov@salesforce.com designates 209.85.212.52 as permitted sender) Received: from [209.85.212.52] (HELO mail-vb0-f52.google.com) (209.85.212.52) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 05 Aug 2013 20:17:15 +0000 Received: by mail-vb0-f52.google.com with SMTP id f12so3277656vbg.39 for ; Mon, 05 Aug 2013 13:16:54 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type:x-gm-message-state; bh=FG6MHqXEBuzCGxtZXV10+j8C+hcMpTFLovRiUbVaePU=; b=YkSbNJJN77B8N3oS9YSK+aRyjiO0OWcskcjroT9qLdOgcSOc1kDl4Z1aWwlsx4zvC/ cXuPgZiIhtPFRo3wU2johc838Fs0mIV2JCEvBRFZ0NHLHoj1zCbYnchdpbhhKIEhoF1F CbBpt+5ZGrUnIGtsE3jeD9S/ST/7MJhCMUgeA7U21jsza67qFRu+KQXgOn+6/305LuKx M08PmFOCkmfrxHtapdBMfSBysVxEE47pOIz85DQDCIXDf61Vw/BNMNiKZqQdrFtLziMm tYJ2WNRCChP2n3GoLU8yRhUXmRGchp+QQRHYU7fd+HJQ7b6dmbYI4gIt8X2ClfFE2U7Z 4A3w== MIME-Version: 1.0 X-Received: by 10.220.164.70 with SMTP id d6mr1461341vcy.19.1375733814400; Mon, 05 Aug 2013 13:16:54 -0700 (PDT) Received: by 10.221.57.198 with HTTP; Mon, 5 Aug 2013 13:16:54 -0700 (PDT) In-Reply-To: <1375728899.13686.3.camel@ubuntu> References: <1375727286.13686.0.camel@ubuntu> <1375728899.13686.3.camel@ubuntu> Date: Mon, 5 Aug 2013 13:16:54 -0700 Message-ID: Subject: Re: Http asyc client doesn't handle correctly large requests in presence of authentication challenge From: Alex Oscherov To: HttpClient User Discussion Content-Type: multipart/alternative; boundary=047d7b414aa4502c2e04e338fdc7 X-Gm-Message-State: ALoCoQl3Njkph0+B8YKTrHidTnGBo1t4EyGFAnkW6URgovCS8vBptzUtohYS3A8/T5tqjjAGCD4L X-Virus-Checked: Checked by ClamAV on apache.org --047d7b414aa4502c2e04e338fdc7 Content-Type: text/plain; charset=ISO-8859-1 Oleg, I just pasted log below. I hope you get it this way. If not I will think of something else Thanks a lot Alex 2013/08/05 11:44:08:714 PDT [DEBUG] MainClientExec - [exchange: 1] start execution 2013/08/05 11:44:08:722 PDT [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2013/08/05 11:44:08:733 PDT [DEBUG] RequestAuthCache - Auth cache not set in the context 2013/08/05 11:44:08:734 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] Request connection for {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443 2013/08/05 11:44:08:735 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection request: [route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] 2013/08/05 11:44:08:760 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection leased: [id: http-outgoing-0][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20] 2013/08/05 11:44:08:766 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] Connection allocated: Managed connection 2013/08/05 11:44:08:768 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][r:]: Set attribute http.nio.exchange-handler 2013/08/05 11:44:08:768 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:]: Event set [w] 2013/08/05 11:44:08:768 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE]: Connected 2013/08/05 11:44:08:769 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state 2013/08/05 11:44:08:769 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Request ready 2013/08/05 11:44:08:887 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 Upgrade session 10.0.115.37:47996<->10.224.203.221:443 [ACTIVE][rw:][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0] 2013/08/05 11:44:08:887 PDT [DEBUG] MainClientExec - [exchange: 1] Attempt 1 to execute request 2013/08/05 11:44:08:887 PDT [DEBUG] MainClientExec - Target auth state: UNCHALLENGED 2013/08/05 11:44:08:888 PDT [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> POST /EWS/Exchange.asmx HTTP/1.1 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> Content-type: text/xml; charset=utf-8 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> Keep-Alive: 300 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> User-Agent: ExchangeServicesClient/0.0.0.0 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> Accept: text/xml 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> Transfer-Encoding: chunked 2013/08/05 11:44:08:888 PDT [DEBUG] headers - http-outgoing-0 >> Host: mc-ex4-1-sfm.s2x.uncrap.local 2013/08/05 11:44:08:889 PDT [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive 2013/08/05 11:44:08:891 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0]: Event set [w] 2013/08/05 11:44:08:924 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Output ready 2013/08/05 11:44:08:925 PDT [DEBUG] MainClientExec - [exchange: 1] produce content 2013/08/05 11:44:08:925 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] [chunk-coded; completed: false] 2013/08/05 11:44:08:927 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4373][0]: 4347 bytes written 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "POST /EWS/Exchange.asmx HTTP/1.1[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Content-type: text/xml; charset=utf-8[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Keep-Alive: 300[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "User-Agent: ExchangeServicesClient/0.0.0.0[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Accept: text/xml[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Transfer-Encoding: chunked[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Host: mc-ex4-1-sfm.s2x.uncrap.local[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "[\r][\n]" 2013/08/05 11:44:08:927 PDT [DEBUG] wire - http-outgoing-0 >> "1000[\r][\n]" 2013/08/05 11:44:08:928 PDT [DEBUG] wire - http-outgoing-0 >> "abhijat@s2x.uncrap.localAlexalex.bla@foo.comOscherovAlexanderal.brum@bum.comOsherovFirstNameFirstName0LastName0@test.comLastName0FirstNameFirstName1LastName1@test.comLastName1FirstNameFirstName2LastName2@test.comLastName2FirstNameFirstName3LastName3@test.comLastName3FirstNameFirstName4LastName4@test.comLastName4FirstNameFirstName5LastName5@test.comLastName5FirstNameFirstName6LastName6@test.comLastName6FirstNameFirstName7LastName7@test.comLastName7FirstNameFirstName8LastName8@test.comLastName8FirstNameFirstName9LastName9@test.comLastName9FirstNameFirstName10LastName10@test.comLastName10FirstNameFirstName11LastName11@test.comLastName11FirstNameFirstName12LastName12@test.comLastName12FirstNameFirstName13LastName13@test.comLastName13FirstNameFirstName14LastName14@test.comLastName14FirstNameFirstName15La[\r][\n]" 2013/08/05 11:44:08:928 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Output ready 2013/08/05 11:44:08:928 PDT [DEBUG] MainClientExec - [exchange: 1] produce content 2013/08/05 11:44:08:928 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] [chunk-coded; completed: false] 2013/08/05 11:44:08:930 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4170][0]: 4104 bytes written 2013/08/05 11:44:08:930 PDT [DEBUG] wire - http-outgoing-0 >> "1000[\r][\n]" 2013/08/05 11:44:08:930 PDT [DEBUG] wire - http-outgoing-0 >> " stName15@test.comLastName15FirstNameFirstName16LastName16@test.comLastName16FirstNameFirstName17LastName17@test.comLastName17FirstNameFirstName18LastName18@test.comLastName18FirstNameFirstName19LastName19@test.comLastName19FirstNameFirstName20LastName20@test.comLastName20FirstNameFirstName21LastName21@test.comLastName21FirstNameFirstName22LastName22@test.comLastName22FirstNameFirstName23LastName23@test.comLastName23FirstNameFirstName24LastName24@test.comLastName24FirstNameFirstName25LastName25@test.comLastName25FirstNameFirstName26LastName26@test.comLastName26FirstNameFirstName27LastName27@test.comLastName27FirstNameFirstName28LastName28@test.comLastName28FirstNameFirstName29LastName29@test.comLastName29FirstNameFirstName30LastName30@test.comLastName30FirstNameFirstName31LastName31@test.comLastName31FirstNameFirstName32LastName32@test.comLastName32FirstNameFirstName33LastName33@test.comLastName33FirstNameFirstName34LastName34@test.comLastName34FirstNameFirstName35LastName35@test.com LastName35FirstName10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4170][0]: 4104 bytes written 2013/08/05 11:44:08:933 PDT [DEBUG] wire - http-outgoing-0 >> "1000[\r][\n]" 2013/08/05 11:44:08:933 PDT [DEBUG] wire - http-outgoing-0 >> "e> FirstName36LastName36@test.comLastName36FirstNameFirstName37LastName37@test.comLastName37FirstNameFirstName38LastName38@test.comLastName38FirstNameFirstName39LastName39@test.comLastName39FirstNameFirstName40LastName40@test.comLastName40FirstNameFirstName41LastName41@test.comLastName41FirstNameFirstName42LastName42@test.comLastName42FirstNameFirstName43LastName43@test.comLastName43FirstNameFirstName44LastName44@test.comLastName44FirstNameFirstName45LastName45@test.comLastName45FirstNameFirstName46LastName46@test.comLastName46FirstNameFirstName47LastName47@test.comLastName47FirstNameFirstName48LastName48@test.comLastName48FirstNameFirstName49LastName49@test.comLastName49FirstNameFirstName50LastName50@test.comLastName50FirstNameFirstName51LastName51@test.comLastName51FirstNameFirstName52LastName52@test.comLastName52FirstNameFirstName53LastName53@test.comLastName53FirstNameFirstName54LastName54@test.comLastName54FirstNameFirstName55LastName55@test.comLastName55FirstNameFirstName56LastName56@test.com LastName5610.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4170][0]: 4104 bytes written 2013/08/05 11:44:08:935 PDT [DEBUG] wire - http-outgoing-0 >> "1000[\r][\n]" 2013/08/05 11:44:08:935 PDT [DEBUG] wire - http-outgoing-0 >> "name>FirstNameFirstName57LastName57@test.comLastName57FirstNameFirstName58LastName58@test.comLastName58FirstNameFirstName59LastName59@test.comLastName59FirstNameFirstName60LastName60@test.comLastName60FirstNameFirstName61LastName61@test.comLastName61FirstNameFirstName62LastName62@test.comLastName62FirstNameFirstName63LastName63@test.comLastName63FirstNameFirstName64LastName64@test.comLastName64FirstNameFirstName65LastName65@test.comLastName65FirstNameFirstName66LastName66@test.comLastName66FirstNameFirstName67LastName67@test.comLastName67FirstNameFirstName68LastName68@test.comLastName68FirstNameFirstName69LastName69@test.comLastName69FirstNameFirstName70LastName70@test.comLastName70FirstNameFirstName71LastName71@test.comLastName71FirstNameFirstName72LastName72@test.comLastName72FirstNameFirstName73LastName73@test.comLastName73FirstNameFirstName74LastName74@test.comLastName74FirstNameFirstName75LastName75@test.comLastName75FirstNameFirstName76LastName76@test.comLastName76FirstNameFirstName77LastName77@tes[\r][\n]" 2013/08/05 11:44:08:936 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:rw][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0]: 369 bytes read 2013/08/05 11:44:08:936 PDT [DEBUG] wire - http-outgoing-0 << "HTTP/1.1 401 Unauthorized[\r][\n]" 2013/08/05 11:44:08:936 PDT [DEBUG] wire - http-outgoing-0 << "Server: Microsoft-IIS/7.5[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "Set-Cookie: exchangecookie=e4816087401747ed9e2080d41eae52b3; expires=Tue, 05-Aug-2014 18:44:08 GMT; path=/; HttpOnly[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: Negotiate[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: NTLM[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: Basic realm="mc-ex4-1-sfm.s2x.uncrap.local"[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "X-Powered-By: ASP.NET[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "Date: Mon, 05 Aug 2013 18:44:08 GMT[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "Content-Length: 0[\r][\n]" 2013/08/05 11:44:08:937 PDT [DEBUG] wire - http-outgoing-0 << "[\r][\n]" 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << HTTP/1.1 401 Unauthorized 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << Server: Microsoft-IIS/7.5 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << Set-Cookie: exchangecookie=e4816087401747ed9e2080d41eae52b3; expires=Tue, 05-Aug-2014 18:44:08 GMT; path=/; HttpOnly 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: Negotiate 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: NTLM 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: Basic realm="mc-ex4-1-sfm.s2x.uncrap.local" 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << X-Powered-By: ASP.NET 2013/08/05 11:44:08:943 PDT [DEBUG] headers - http-outgoing-0 << Date: Mon, 05 Aug 2013 18:44:08 GMT 2013/08/05 11:44:08:944 PDT [DEBUG] headers - http-outgoing-0 << Content-Length: 0 2013/08/05 11:44:08:944 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Response received 2013/08/05 11:44:08:944 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: Event cleared [w] 2013/08/05 11:44:08:944 PDT [DEBUG] MainClientExec - [exchange: 1] Response received HTTP/1.1 401 Unauthorized 2013/08/05 11:44:08:951 PDT [DEBUG] ResponseProcessCookies - Cookie accepted: "[version: 0][name: exchangecookie][value: e4816087401747ed9e2080d41eae52b3][domain: mc-ex4-1-sfm.s2x.uncrap.local][path: /][expiry: Tue Aug 05 11:44:08 PDT 2014]". 2013/08/05 11:44:08:951 PDT [DEBUG] MainClientExec - Authentication required 2013/08/05 11:44:08:952 PDT [DEBUG] MainClientExec - mc-ex4-1-sfm.s2x.uncrap.local:443 requested authentication 2013/08/05 11:44:08:952 PDT [DEBUG] TargetAuthenticationStrategy - Authentication schemes in the order of preference: [negotiate, Kerberos, NTLM, Digest, Basic] 2013/08/05 11:44:08:952 PDT [WARN] TargetAuthenticationStrategy - Authentication scheme negotiate not supported 2013/08/05 11:44:08:952 PDT [DEBUG] TargetAuthenticationStrategy - Challenge for Kerberos authentication scheme not available 2013/08/05 11:44:08:952 PDT [WARN] TargetAuthenticationStrategy - Authentication scheme NTLM not supported 2013/08/05 11:44:08:952 PDT [DEBUG] TargetAuthenticationStrategy - Challenge for Digest authentication scheme not available 2013/08/05 11:44:08:960 PDT [DEBUG] MainClientExec - Selected authentication options: [BASIC] 2013/08/05 11:44:08:960 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Input ready 2013/08/05 11:44:08:960 PDT [DEBUG] MainClientExec - [exchange: 1] Consume content 2013/08/05 11:44:08:960 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: 0 bytes read 2013/08/05 11:44:08:960 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: Close 2013/08/05 11:44:08:961 PDT [DEBUG] MainClientExec - [exchange: 1] Connection can be kept alive indefinitely 2013/08/05 11:44:08:961 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] releasing connection 2013/08/05 11:44:08:961 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:rw][CLOSING][r][NEED_WRAP][0][0][0][0]: Remove attribute http.nio.exchange-handler 2013/08/05 11:44:08:961 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection released: [id: http-outgoing-0][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] 2013/08/05 11:44:08:961 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] Request connection for {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443 2013/08/05 11:44:08:961 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection request: [route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] 2013/08/05 11:44:08:961 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.37:47996<->10.224.203.221:443[ACTIVE][rw:rw][CLOSING][rw][NEED_WRAP][0][0][0][0]: Event set [w] 2013/08/05 11:44:08:962 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [CLOSED] [content length: 0; pos: 0; completed: true] 2013/08/05 11:44:08:963 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection leased: [id: http-outgoing-1][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20] 2013/08/05 11:44:08:963 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] Connection allocated: Managed connection 2013/08/05 11:44:08:963 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][r:]: Set attribute http.nio.exchange-handler 2013/08/05 11:44:08:963 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:]: Event set [w] 2013/08/05 11:44:08:963 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE]: Connected 2013/08/05 11:44:08:963 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state 2013/08/05 11:44:08:963 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Request ready 2013/08/05 11:44:08:964 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 Upgrade session 10.0.115.37:47997<->10.224.203.221:443 [ACTIVE][rw:][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0] 2013/08/05 11:44:08:964 PDT [DEBUG] MainClientExec - [exchange: 1] Attempt 2 to execute request 2013/08/05 11:44:08:964 PDT [DEBUG] MainClientExec - Target auth state: CHALLENGED 2013/08/05 11:44:08:964 PDT [DEBUG] MainClientExec - Generating response to an authentication challenge using basic scheme 2013/08/05 11:44:08:965 PDT [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED 2013/08/05 11:44:08:965 PDT [DEBUG] headers - http-outgoing-1 >> POST /EWS/Exchange.asmx HTTP/1.1 2013/08/05 11:44:08:965 PDT [DEBUG] headers - http-outgoing-1 >> Content-type: text/xml; charset=utf-8 2013/08/05 11:44:08:965 PDT [DEBUG] headers - http-outgoing-1 >> Keep-Alive: 300 2013/08/05 11:44:08:965 PDT [DEBUG] headers - http-outgoing-1 >> User-Agent: ExchangeServicesClient/0.0.0.0 2013/08/05 11:44:08:965 PDT [DEBUG] headers - http-outgoing-1 >> Accept: text/xml 2013/08/05 11:44:08:966 PDT [DEBUG] headers - http-outgoing-1 >> Transfer-Encoding: chunked 2013/08/05 11:44:08:966 PDT [DEBUG] headers - http-outgoing-1 >> Host: mc-ex4-1-sfm.s2x.uncrap.local 2013/08/05 11:44:08:966 PDT [DEBUG] headers - http-outgoing-1 >> Connection: Keep-Alive 2013/08/05 11:44:08:966 PDT [DEBUG] headers - http-outgoing-1 >> Authorization: Basic UzJYLlVOQ1JBUC5MT0NBTC9zMnhhZG1pbjoxMjN0ZXN0IQ== 2013/08/05 11:44:08:966 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0]: Event set [w] 2013/08/05 11:44:08:972 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Output ready 2013/08/05 11:44:08:972 PDT [DEBUG] MainClientExec - [exchange: 1] produce content 2013/08/05 11:44:08:972 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] [chunk-coded; completed: false] 2013/08/05 11:44:08:972 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][53][0]: 0 bytes written 2013/08/05 11:44:08:972 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Output ready 2013/08/05 11:44:08:972 PDT [DEBUG] MainClientExec - [exchange: 1] produce content 2013/08/05 11:44:08:972 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] [chunk-coded; completed: false] 2013/08/05 11:44:08:973 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4853][0]: 4817 bytes written 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "POST /EWS/Exchange.asmx HTTP/1.1[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Content-type: text/xml; charset=utf-8[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Keep-Alive: 300[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "User-Agent: ExchangeServicesClient/0.0.0.0[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Accept: text/xml[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Transfer-Encoding: chunked[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Host: mc-ex4-1-sfm.s2x.uncrap.local[\r][\n]" 2013/08/05 11:44:08:973 PDT [DEBUG] wire - http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] wire - http-outgoing-1 >> "Authorization: Basic UzJYLlVOQ1JBUC5MT0NBTC9zMnhhZG1pbjoxMjN0ZXN0IQ==[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] wire - http-outgoing-1 >> "[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] wire - http-outgoing-1 >> "1000[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] wire - http-outgoing-1 >> "t.comLastName77FirstNameFirstName78LastName78@test.comLastName78FirstNameFirstName79LastName79@test.comLastName79FirstNameFirstName80LastName80@test.comLastName80FirstNameFirstName81LastName81@test.comLastName81FirstNameFirstName82LastName82@test.comLastName82FirstNameFirstName83LastName83@test.comLastName83FirstNameFirstName84LastName84@test.comLastName84FirstNameFirstName85LastName85@test.comLastName85FirstNameFirstName86LastName86@test.comLastName86FirstNameFirstName87LastName87@test.comLastName87FirstNameFirstName88LastName88@test.comLastName88FirstNameFirstName89LastName89@test.comLastName89FirstNameFirstName90LastName90@test.comLastName90FirstNameFirstName91LastName91@test.comLastName91FirstNameFirstName92LastName92@test.comLastName92FirstNameFirstName93LastName93@test.comLastName93FirstNameFirstName94LastName94@test.comLastName94FirstNameFirstName95LastName95@test.comLastName95FirstNameFirstName96LastName96@test.comLastName96FirstNameFirstName97LastName97@test.com LastName97FirstName> "188[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] wire - http-outgoing-1 >> "dresses>FirstName98LastName98@test.comLastName98FirstNameFirstName99LastName99@test.com LastName99[\r][\n]" 2013/08/05 11:44:08:974 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Output ready 2013/08/05 11:44:08:974 PDT [DEBUG] MainClientExec - [exchange: 1] produce content 2013/08/05 11:44:08:974 PDT [DEBUG] MainClientExec - [exchange: 1] Request completed 2013/08/05 11:44:08:974 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] [chunk-coded; completed: true] 2013/08/05 11:44:08:974 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][74][0]: 5 bytes written 2013/08/05 11:44:08:975 PDT [DEBUG] wire - http-outgoing-1 >> "0[\r][\n]" 2013/08/05 11:44:08:975 PDT [DEBUG] wire - http-outgoing-1 >> "[\r][\n]" 2013/08/05 11:44:08:975 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][r][NOT_HANDSHAKING][0][0][74][0]: Event cleared [w] 2013/08/05 11:44:08:981 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: 305 bytes read 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "HTTP/1.1 400 Bad Request[\r][\n]" 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "Cache-Control: private[\r][\n]" 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "Server: Microsoft-IIS/7.5[\r][\n]" 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "Set-Cookie: exchangecookie=bbe9d2eb198e4c17a014b4be12f59a48; expires=Tue, 05-Aug-2014 18:44:08 GMT; path=/; HttpOnly[\r][\n]" 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "X-AspNet-Version: 2.0.50727[\r][\n]" 2013/08/05 11:44:08:981 PDT [DEBUG] wire - http-outgoing-1 << "X-Powered-By: ASP.NET[\r][\n]" 2013/08/05 11:44:08:982 PDT [DEBUG] wire - http-outgoing-1 << "Date: Mon, 05 Aug 2013 18:44:08 GMT[\r][\n]" 2013/08/05 11:44:08:982 PDT [DEBUG] wire - http-outgoing-1 << "Content-Length: 0[\r][\n]" 2013/08/05 11:44:08:982 PDT [DEBUG] wire - http-outgoing-1 << "[\r][\n]" 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << HTTP/1.1 400 Bad Request 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << Cache-Control: private 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << Server: Microsoft-IIS/7.5 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << Set-Cookie: exchangecookie=bbe9d2eb198e4c17a014b4be12f59a48; expires=Tue, 05-Aug-2014 18:44:08 GMT; path=/; HttpOnly 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << X-AspNet-Version: 2.0.50727 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << X-Powered-By: ASP.NET 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << Date: Mon, 05 Aug 2013 18:44:08 GMT 2013/08/05 11:44:08:982 PDT [DEBUG] headers - http-outgoing-1 << Content-Length: 0 2013/08/05 11:44:08:982 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Response received 2013/08/05 11:44:08:982 PDT [DEBUG] MainClientExec - [exchange: 1] Response received HTTP/1.1 400 Bad Request 2013/08/05 11:44:08:983 PDT [DEBUG] ResponseProcessCookies - Cookie accepted: "[version: 0][name: exchangecookie][value: bbe9d2eb198e4c17a014b4be12f59a48][domain: mc-ex4-1-sfm.s2x.uncrap.local][path: /][expiry: Tue Aug 05 11:44:08 PDT 2014]". 2013/08/05 11:44:08:983 PDT [DEBUG] MainClientExec - Authentication succeeded 2013/08/05 11:44:08:983 PDT [DEBUG] TargetAuthenticationStrategy - Caching 'basic' auth scheme for https://mc-ex4-1-sfm.s2x.uncrap.local:443 2013/08/05 11:44:08:985 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] Input ready 2013/08/05 11:44:08:985 PDT [DEBUG] MainClientExec - [exchange: 1] Consume content 2013/08/05 11:44:08:985 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: 0 bytes read 2013/08/05 11:44:08:985 PDT [DEBUG] MainClientExec - [exchange: 1] Connection can be kept alive indefinitely 2013/08/05 11:44:08:986 PDT [DEBUG] MainClientExec - [exchange: 1] Response processed 2013/08/05 11:44:08:986 PDT [DEBUG] InternalHttpAsyncClient - [exchange: 1] releasing connection 2013/08/05 11:44:08:986 PDT [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-1 10.0.115.37:47997<->10.224.203.221:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: Remove attribute http.nio.exchange-handler 2013/08/05 11:44:08:986 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection [id: http-outgoing-1][route: {s}-> https://mc-ex4-1-sfm.s2x.uncrap.local:443] can be kept alive indefinitely 2013/08/05 11:44:08:986 PDT [DEBUG] PoolingNHttpClientConnectionManager - Connection released: [id: http-outgoing-1][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20] 2013/08/05 11:44:11:358 PDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1 [ACTIVE] [content length: 0; pos: 0; completed: true] javax.xml.stream.XMLStreamException: ParseError at [row,col]:[1,1] Message: Premature end of file. at com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.next(XMLStreamReaderImpl.java:598) at com.sun.xml.internal.stream.XMLEventReaderImpl.nextEvent(XMLEventReaderImpl.java:83) at salesforce.microsoft.exchange.webservices.data.EwsXmlReader.read(EwsXmlReader.java:173) at salesforce.microsoft.exchange.webservices.data.EwsServiceXmlReader.read(EwsServiceXmlReader.java:22) at salesforce.microsoft.exchange.webservices.data.EwsXmlReader.read(EwsXmlReader.java:196) at salesforce.microsoft.exchange.webservices.data.EwsServiceXmlReader.read(EwsServiceXmlReader.java:22) at salesforce.microsoft.exchange.webservices.data.EwsXmlReader.internalReadElement(EwsXmlReader.java:111) at salesforce.microsoft.exchange.webservices.data.EwsXmlReader.readStartElement(EwsXmlReader.java:620) at salesforce.microsoft.exchange.webservices.data.EwsServiceXmlReader.readStartElement(EwsServiceXmlReader.java:22) at salesforce.microsoft.exchange.webservices.data.ServiceRequestBase.readResponse(ServiceRequestBase.java:523) at sync.s2x.nio.commands.CommandFuture.get(CommandFuture.java:40) at test.exchange.TestCreateItem.main(TestCreateItem.java:91) javax.xml.stream.XMLStreamException: ParseError at [row,col]:[1,1] Message: Premature end of file. at com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.next(XMLStreamReaderImpl.java:598) at com.sun.xml.internal.stream.XMLEventReaderImpl.nextEvent(XMLEventReaderImpl.java:83) at salesforce.microsoft.exchange.webservices.data.EwsXmlReader.read(EwsXmlReader.java:173) at salesforce.microsoft.exchange.webservices.data.EwsServiceXmlReader.read(EwsServiceXmlReader.java:22) at salesforce.microsoft.exchange.webservices.data.ServiceRequestBase.readSoapFault(ServiceRequestBase.java:744) at sync.s2x.nio.commands.CommandFuture.get(CommandFuture.java:46) at test.exchange.TestCreateItem.main(TestCreateItem.java:91) Exception in thread "main" java.lang.NullPointerException at sync.s2x.nio.commands.CommandFuture.get(CommandFuture.java:47) at test.exchange.TestCreateItem.main(TestCreateItem.java:91) On Mon, Aug 5, 2013 at 11:54 AM, Oleg Kalnichevski wrote: > On Mon, 2013-08-05 at 11:47 -0700, Alex Oscherov wrote: > > Oleg, > > > > here is my complete log. My simple test program crashes since it can't > > process unexpected message from the server but HTTP communications is > > finished by then > > > > > > Alex > > > > Apparently the attachments got stripped away by the ASF mail server or > some intermediate hops. > > Try using http://pastebin.com/ or a similar service. > > Oleg > > > > > > > On Mon, Aug 5, 2013 at 11:28 AM, Oleg Kalnichevski > > wrote: > > On Mon, 2013-08-05 at 10:59 -0700, Alex Oscherov wrote: > > > I have a problem making http async client working with > > Exchange server > > > through IIS 7.5. Everything works fine as long as requests > > are small > > > but as soon as size of requests increases communication > > fails with the > > > HTTP 400 response from the server. > > > > > > > > > Analysing log (attached) I observe following behaviour from > > the HTTP > > > async client : > > > > > > 1. on line 2013/08/05 10:30:42:497 PDT [DEBUG] client starts > > sending > > > request to the server > > > > > > 2. on line 2013/08/05 10:30:42:515 PDT client while sending > > request > > > not finished receives authentication challenge from server > > > > > > 3. on line 2013/08/05 10:30:42:552 PDT client sends to the > > server new > > > authenticated request but instead of starting to send body > > of the > > > request from the beginning it just sends body of the request > > from the > > > point where it was interrupted first time. > > > > > > > > > As a result server can't process request and sends back HTTP > > 400. > > > > > > I am not an experienced http async client library user so it > > is quite > > > possible that I am doing something wrong. > > > > > > > > > Any advice or recommendation will be highly appreciated and > > any > > > additional information if it is needed could be provided. > > > > > > > > > > > > Alex > > > > Please please attach a complete log of the session. > > > > Oleg > > > > > > > > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: > > httpclient-users-unsubscribe@hc.apache.org > > For additional commands, e-mail: > > httpclient-users-help@hc.apache.org > > > > > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org > > For additional commands, e-mail: httpclient-users-help@hc.apache.org > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org > For additional commands, e-mail: httpclient-users-help@hc.apache.org > > --047d7b414aa4502c2e04e338fdc7--