OpenJDK (JDK 11) behavior discussion for HttpClient

[Asha Sunagar]

Yes Daniel, I see the same issue with JDK 17 too. I executed the code thrice, so log shows 3 prefaces.

-----Original Message-----
From: Daniel Fuchs <daniel.fuchs at oracle.com> 
Sent: Friday, September 15, 2023 6:21 PM
To: Asha Sunagar <Asha.Sunagar at ibm.com>; net-dev at openjdk.org
Cc: Syed Moinudeen1 <smoinud1 at in.ibm.com>; Rajesh Gudikoti <ragudiko at in.ibm.com>; Suman Mitra <summitra at in.ibm.com>; Shruthi Shruthi1 <Shruthi.Shruthi1 at ibm.com>
Subject: [EXTERNAL] Re: OpenJDK (JDK 11) behavior discussion for HttpClient

Hi Asha,

Thanks for the report. Do you see the same issue when using a more recent version of the JDK (e.g.: 17)?

I'm not quite sure why your log show 3 prefaces. Are you sending three requests? The ones starting with 95 looks strange.

It looks as if it start with the posted data - as Daniel Jelińsky already suggested.

best regards

-- daniel

On 15/09/2023 10:26, Asha Sunagar wrote:
> Hello Team,
> 
> 
> We are facing invalid preface issue when we send POST request using 
> HttpClient. We overcame this issue using workaround mentioned in 
> openjdk issue 
> <https://bugs.openjdk.org/browse/JDK-8198947 >. The workaround was to use a blank request before making post request.
> 
> Based on our below observations, the Preface String is different in 
> Failure & Success case,
> 
> 
> The Preface String for
> 1.1) Post Request without blank request --> we get GOAWAY Exception 
> (Failure case)
> 
> Preface String: [80, 82, 73, 32, 42, 32, 72, 84, 84, 80, 47, 50, 46, 
> 48, 13, 10, 13, 10, 83, 77, 13, 10, 13, 10]
> 
> Preface String: [95, 70, 73, 82, 83, 84, 95, 80, 79, 83, 84, 95, 80, 
> 77, 68, 73, 78, 72, 95, 80, 82, 73, 32, 42]
> 
> Preface String: [95, 70, 73, 82, 83, 84, 95, 80, 79, 83, 84, 95, 80, 
> 77, 68, 73, 78, 72, 95, 80, 82, 73, 32, 42]
> 
> 1.2) Workaround case with a blank request (Success Case)
> 
> Preface String: [80, 82, 73, 32, 42, 32, 72, 84, 84, 80, 47, 50, 46, 
> 48, 13, 10, 13, 10, 83, 77, 13, 10, 13, 10]
> 
> Preface String: [80, 82, 73, 32, 42, 32, 72, 84, 84, 80, 47, 50, 46, 
> 48, 13, 10, 13, 10, 83, 77, 13, 10, 13, 10]
> 
> Preface String: [80, 82, 73, 32, 42, 32, 72, 84, 84, 80, 47, 50, 46, 
> 48, 13, 10, 13, 10, 83, 77, 13, 10, 13, 10]
> 
> 2) LOGS
> 2.1) Post Request without blank request :We get the error  "an error 
> occurred processing a frame": Failed to complete the connection 
> preface from Liberty server and GOAWAY Exception.
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 
> com.ibm.ws.http.channel.h2internal.FrameReadProcessor        3
> checkConnectionPreface: processNextFrame-:  stream: 0 frame type: 
> Magic Preface  direction: READ_IN H2InboundLink hc: 101118290
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 
> com.ibm.ws.http.channel.h2internal.FrameReadProcessor        3
> checkConnectionPreface: Preface String: [95, 70, 73, 82, 83, 84, 95, 
> 80, 79, 83, 84, 95, 80, 77, 68, 73, 78, 72, 95, 80, 82, 73, 32, 42]
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 SystemOut                                                    
> O PMDINH, FrameReadProcessor CHECKPOINT 2, throw new ProtocolException 
> --- Connection preface/magic was invalid
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 SystemOut                                                    
> O PMDINH, FrameReadProcessor CHECKPOINT 3, throw new ProtocolException 
> --- Cconnection preface
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 
> com.ibm.ws.http.channel.h2internal.H2InboundLink             3
> processRead: an error occurred processing a frame: Failed to complete 
> the connection preface
> 
> [9/7/23, 15:41:10:595 IST] 00000058 id=00000000 
> com.ibm.ws.http.channel.h2internal.H2InboundLink             3
> close(vc,e): :linkstatus: is: INIT :close: H2InboundLink hc: 
> 101118290exception: 
> com.ibm.ws.http.channel.h2internal.exceptions.ProtocolException: 
> Failed to complete the connection preface
> 
> 2.2) Workaround case with a blank request
> 
> [9/7/23, 15:54:21:528 IST] 0000005a id=00000000 
> com.ibm.ws.http.channel.h2internal.FrameReadProcessor        3
> checkConnectionPreface: processNextFrame-:  stream: 0 frame type: 
> Magic Preface  direction: READ_IN H2InboundLink hc: 551136004
> 
> [9/7/23, 15:54:21:528 IST] 0000005a id=00000000 
> com.ibm.ws.http.channel.h2internal.FrameReadProcessor        3
> checkConnectionPreface: Preface String: [80, 82, 73, 32, 42, 32, 72, 
> 84, 84, 80, 47, 50, 46, 48, 13, 10, 13, 10, 83, 77, 13, 10, 13, 10]
> 
> [9/7/23, 15:54:21:528 IST] 0000005a id=00000000 
> com.ibm.ws.http.channel.h2internal.H2InboundLink             3 
> createNewInboundLink entry: stream-id: 0
> 
> [9/7/23, 15:54:21:528 IST] 0000005a id=00000000 
> com.ibm.ws.http.channel.internal.inbound.HttpInboundLink
> 
> Please let us to know whether it is an expected behavior or an issue?  
> Or is there a way to handle such scenarios?
> 
> Thanks & Regards,
> 
> Asha H Sunagar
> 
> IGA - JTC | Global Business Services – IBM
> 
> Phone: +91 8884256034
> 
> Email : asha.sunagar at ibm.com <mailto:asha.sunagar at ibm.com>
>