On Wed, 2018-07-25 at 01:11 +0000, [email protected] wrote: > How would you suggest we address this bug?
By kindly asking Jersey developers to fix it. > Right now it looks like if you use jersey (and possibly other > libraries as well) with httpcomponent it does not work properly with > both gzip and chunked encoding. > Can you help me understand why the client can not assume the > connection is safe for re-use if it does not read until the end? Why > is that a requirement? > If the closing chunk does not get consumed and the connection get re- used for another message exchange, on the next exchange the client gets garbage from the previous exchange instead of a valid response message. Oleg > Thanks for your help on this. > > > Can you help me understand why it is some imp > > On 7/24/18, 12:19 AM, "Oleg Kalnichevski" <[email protected]> wrote: > > On Mon, 2018-07-23 at 17:21 +0000, [email protected] wrote: > > Oleg, > > > > The data is properly formatted, and there is a closing chunk. > On > > further investigation it turns out that the problem is a > combination > > of both gzip and chunk encoding turned on. > > The gzip decoder knows exactly how many bytes it needs and > pulls > > exactly that number (at least our jersey version of it seems > to) -- > > so we never get to the closing block. Jersey then sends a close > to > > the file which causes it to close for real. Which is very much > not > > what we want. > > > > The question is whether it is legitimate for a client to send > close > > to a http connection using chunks without having read all the > way to > > the end. I would argue that it is. > > > > It is legitimate but if the consumer stops reading from the > content > stream without reading until the end of the stream the client > cannot > assume the connection to be safe for re-use. > > Oleg > > > > > On 7/20/18, 1:02 AM, "Oleg Kalnichevski" <[email protected]> > wrote: > > > > On Thu, 2018-07-19 at 01:07 +0000, [email protected] > wrote: > > > I am seeing a problem where ConnectionHolder.close() is > getting > > > called before ConnectionHolder.release() is called. This > > results in > > > immediately closing the connection even though we want to > keep > > it > > > around. > > > > > > This happens only with chunked responses. What appears to > > happen is > > > that jersey reads the last chunk with data and then > closes the > > > connection – which ultimately gets sent to > > ConnectionHolder.close(). > > > Since eof has not yet been found (we don’t seem to get > to the > > > nextChunk() call that reads the 0 chunk), it means the > > underlying > > > connection gets closed. > > > > > > > This issue has been reported and looked into on more than > one > > occasion. > > HttpClient behavior is correct. It is not safe to re-use a > > connection > > with a chunk coded response message whose data stream has > not > > been > > terminated by a closing chunk. > > > > Oleg > > > > > > > If I change this code > > > > > > @Override > > > public void close() throws IOException { > > > releaseConnection(false); > > > } > > > > > > To simply this: > > > > > > @Override > > > public void close() throws IOException { > > > releaseConnection(reusable); > > > } > > > > > > I no longer have the connection getting immediately > dropped. > > (This > > > does break a unit test, though). > > > > > > Here is some sample log output at debug level with the > problem: > > > > > > > > > tokenstatus 2018-07-17 21:12:46,282 +0000 DEBUG 117161 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > HTTP/1.1 > > > 200 OK > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Server: > > > nginx/1.13.10 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Date: > > > Tue, 17 Jul 2018 21:12:46 GMT > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Content- > > > Type: application/json;charset=UTF-8 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > > Transfer-Encoding: chunked > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > > Connection: keep-alive > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > RequestId: 16073adf3336513470aff4bcc23005d6 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > CorrelationId: f1f6c4cb-9f09-42a6-b5ce-8544592bd50b > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > Content-Type-Options: nosniff > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << x- > > wily- > > > info: Clear guid=AA169DAC0ADB81C5151380A28398C79E > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << x- > > wily- > > > servlet: Encrypt1 > > > > > > hR/KG2GOR16aRfvv3/q1AY6IOmaQiRHSVfF4o38i8Nb6NeyR36CyvkJdrtOXs+Q6i7zEX > > > > > > S+Izr9EdU/xAf5ZhxHw0ow/QkacutvAiuKKILiB5+OqdEgjMxWr7r3IdRDJNdPklBSMvG > > > lPzS6DStuVPPHYlVqYfLeF5wTGvWuAivcjp7Io/wzYPActeNQCNkRr > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Cache- > > > Control: private, must-revalidate, max-age=3600 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Expires: > > > Wed, 18 Jul 2018 09:12:45 GMT > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Content- > > > Encoding: gzip > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] MainClientExec [] - > Connection can > > be > > > kept alive indefinitely > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "a[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > > "[0x3][0x0][0xc1]/[0xd7][0x14]U[\r][0x0][0x0][\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "0[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] > DefaultManagedHttpClientConnection > > [] - > > > http-outgoing-5: Close connection > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] MainClientExec [] - > Connection > > discarded > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] > PoolingHttpClientConnectionManager > > [] - > > > Connection released: [id: 5][route: {s}->https://kamaji.a > uth.ap > > i.np.a > > > c.playstation.net:443][total kept alive: 0; route > allocated: 3 > > of > > > 500; total allocated: 3 of 1000] > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "[read] I/O > > > error: Socket is closed" > > > > > > And here is log output with the problem solved: > > > > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > HTTP/1.1 200 > > > OK > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Server: > > > nginx/1.13.10 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > Date: > > Thu, > > > 19 Jul 2018 00:32:19 GMT > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Content- > > > Type: application/json;charset=UTF-8 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Transfer- > > > Encoding: chunked > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Connection: > > > keep-alive > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > RequestId: > > > 49e6b565d40253cfc320547931f80a50 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > > CorrelationId: 9031d94b-133e-495b-aa99-39a5ffff7c65 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > Content- > > > Type-Options: nosniff > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > x- > > wily-info: > > > Clear guid=AFF3AC6D0ADB813826D1845C71D1DA71 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > x- > > wily- > > > servlet: Encrypt1 > > > > > > hR/KG2GOR16aRfvv3/q1AcDfNQfBP1AWkr5Dck/nEoqU5/Ft5cGKgUaFVMBigeSiwiPcI > > > > > > oX+2ikKbgkrgUodlPY7ogzMDnags9JMk3ktv98z33D2MCUqLopn132Nh2CW5UibmV9ShP > > > jWXFiphiHtL5GZ7ugYXVvCWt5z0kf7Dg55aD9Tou8pNiwZ0gzxvG5+ > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > Cache- > > > Control: private, must-revalidate, max-age=3600 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Expires: > > > Thu, 19 Jul 2018 12:31:30 GMT > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Content- > > > Encoding: gzip > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] MainClientExec [] - Connection > can be > > kept > > > alive indefinitely > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 31 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 139 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 8 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 0 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 6 return: 6 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 512 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 512 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 62 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "a[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > > > "[0x3][0x0][0x8][0x8a][0xc3][0xb8]6[\r][0x0][0x0][\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "0[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 10 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] MainClientExec [] - Connection > Holder; > > > releaseConnection; reusable: true > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > PoolingHttpClientConnectionManager [] - > > > Connection [id: 13][route: {s}->https://kamaji.auth.api.n > p.ac.p > > laysta > > > tion.net:443] can be kept alive indefinitely > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > DefaultManagedHttpClientConnection [] - > > http- > > > outgoing-13: set socket timeout to 0 > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > PoolingHttpClientConnectionManager [] - > > > Connection released: [id: 13][route: {s}->https://kamaji. > auth.a > > pi.np. > > > ac.playstation.net:443][total kept alive: 11; route > allocated: > > 11 of > > > 500; total allocated: 11 of 1000] > > > > > > Note that I added some extra debug statements to get a > better > > idea of > > > the problem. In particular I added debug statements to > > > EofSensorInputStream.read() > > > > > > > ----------------------------------------------------------- > ------ > > ---- > > To unsubscribe, e-mail: [email protected] > > For additional commands, e-mail: [email protected] > > > > > > > > > > ------------------------------------------------------------- > -------- > > To unsubscribe, e-mail: [email protected] > > For additional commands, e-mail: [email protected] > > > > ----------------------------------------------------------------- > ---- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
