OpenJDK (JDK 11) behavior discussion for HttpClient

[Daniel Fuchs]

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>
>