search

facebook / proxygen

A collection of C++ HTTP libraries including an easy to use HTTP server.
Other
8.16k stars 1.5k forks source link

HTTP2 WINDOW_UPDATE #448

Closed SteveSelva closed 1 year ago

SteveSelva commented 1 year ago

I have set my Proxy Server's initial window size as 65536. While updating the window size using WINDOW_UPDATE frame, its causing some error.

Proxy Server Logs Snippet

I20230605 19:51:23.090782 1144 HTTP2Codec.cpp:49] creating downstream HTTP/2 codec I20230605 19:51:23.090782 1144 HTTPSessionAcceptor.cpp:94] Created new h2 session for peer 127.0.0.1:50822 I20230605 19:51:23.090782 1144 ServerAcceptor.cpp:299] New Connection has been Added to Connection Manager I20230605 19:51:23.090782 1144 HTTP2Codec.cpp:1683] downstream generating 5 settings I20230605 19:51:23.091784 1144 FlowControlFilter.cpp:56] Incrementing default conn-level recv window by 1 I20230605 19:51:23.091784 1144 HTTP2Codec.cpp:1727] generating window update for stream=0: Processed 1 bytes I20230605 19:51:23.091784 1144 HTTPSession.cpp:2899] proto=http/2, UA=, downstream=127.0.0.1:50822, 127.0.0.1:5555=local: resuming reads I20230605 19:51:23.091784 1144 HTTPSession.cpp:2217] proto=http/2, UA=, downstream=127.0.0.1:50822, 127.0.0.1:5555=local writing 52, activeWrites=1 cork:0 timestampTx:0 timestampAck:0 I20230605 19:51:23.092803 1144 HTTP2Codec.cpp:798] parsing SETTINGS frame for stream=0 length=30 I20230605 19:51:23.092803 1144 HTTPSession.cpp:1440] proto=http/2, UA=, downstream=127.0.0.1:50822, 127.0.0.1:5555=local got new maximum number of concurrent txns we can initiate: 1000 I20230605 19:51:23.092803 1144 HTTPSession.cpp:1433] proto=http/2, UA=, downstream=127.0.0.1:50822, 127.0.0.1:5555=local got send window size adjustment. new=6291456 I20230605 19:51:23.092803 1144 HTTP2Codec.cpp:1718] downstream generating settings ack I20230605 19:51:23.093824 1144 HTTP2Codec.cpp:1009] parsing WINDOW_UPDATE frame for stream=0 length=4 I20230605 19:51:23.093824 1144 FlowControlFilter.cpp:120] Remote side ack'd 15663105 bytes, sendWindow=15728640 I20230605 19:51:23.093824 1144 HTTP2Codec.cpp:390] parsing HEADERS frame for stream=1 length=438 I20230605 19:51:23.093824 1144 HTTPSession.cpp:690] processing new msg streamID=1 proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:50822, 127.0.0.1:5555=local I20230605 19:51:23.094871 1144 HTTP2PriorityQueue.cpp:512] Adding id=1 with parent=0 and weight=256 I20230605 19:51:23.094871 1144 HTTPSession.cpp:839] processing ingress headers complete for proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:50822, 127.0.0.1:5555=local, streamID=1

Logs File Link : Proxy_Server_Logs.txt

I am testing this Proxy Server with Tomcat.

Tomcat Logs

05-Jun-2023 19:50:45.793 FINE [https-openssl-apr-0.0.0.0-443-exec-6] org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_NOW] reported while processing request org.apache.coyote.CloseNowException: org.apache.coyote.http2.StreamException: Timeout waiting for client to increase flow control window to permit stream data to be written at org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:1034) at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71) at org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:230) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:389) at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:449) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:87) at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:750) Caused by: org.apache.coyote.http2.StreamException: Timeout waiting for client to increase flow control window to permit stream data to be written at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:260) at org.apache.coyote.http2.Stream.reserveWindowSize(Stream.java:235) at org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:982) at org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java:912) at org.apache.coyote.http2.Http2OutputBuffer.doWrite(Http2OutputBuffer.java:59) at org.apache.coyote.Response.doWrite(Response.java:615) at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:340) at org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.java:784) at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:299) at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:252) at org.apache.catalina.connector.Response.finishResponse(Response.java:445) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:391) at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:426) ... 7 more 05-Jun-2023 19:50:45.793 FINE [https-openssl-apr-0.0.0.0-443-exec-4] org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit, Connection [352], SocketState [CLOSED] 05-Jun-2023 19:50:45.793 FINE [https-openssl-apr-0.0.0.0-443-exec-6] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@408625f6:2514261437248], Status in: [OPEN_READ], State out: [CLOSED]

In browser I got HTTP Status as '(failed) net::ERR_HTTP2_PROTOCOL_ERROR. Image Link : Browser Response Image

Help me fix this issue.

jbeshay commented 1 year ago

So your setup is client -> proxygen -> tomcat.

The link to the server logs is not working but what the part of the log you included shows that proxygen generated a window update frame and sent that to tomcat (I20230605 19:51:23.091784), then it received and processed a window update from tomcat (I20230605 19:51:23.093824).

The tomcat error refers to not receiving a window update from proxygen. The data in the logs is not enough to figure out what the state is but you could collect a pcap trace and look further into the contents of each of the window updates.

SteveSelva commented 1 year ago

Yeah my setup is Browser(Client) -> Proxygen -> Tomcat.

Note: Every Trace/Log is for request URL : https://testenv.com/tomcat.svg

Updated Logs ProxyServer-Logs.txt Tomcat-Logs.txt

I have set an initial Window size of 65536. For any request and server, if the response size is greater than the window size(65536), then I am getting a "(failed) net::ERR_HTTP2_PROTOCOL_ERROR" in the browser's request status column in Network Tab.

Recorded the Transaction from Server(Tomcat) Side since Proxygen is acting as ProxyServer in the Client(Browser) Side. ProxyServer_Traffic.pcap Keys.log

There is a WINDOW_UPDATE frame sent from Tomcat and its the last packet sent from Tomcat and an incomplete Acknowledgement message is returned from the Client(Proxygen) side.

jbeshay commented 1 year ago

I don't think the error is when a window_update frame is sent from tomcat - at least not based upon the logs you've shared.

The tomcat log says:

Timeout waiting for client to increase flow control window to permit stream data to be written

Before the connection ends, the proxygen log says:

I20230605 19:51:23.224630  1144 FlowControlFilter.cpp:73] processed 8 toAck_=32767 bytes, will ack=0
...
I20230605 19:51:28.248910  1144 HTTPSession.cpp:1502] Transaction timeout for streamID=1
I20230605 19:51:28.249825  1144 HTTPTransaction.cpp:719] ingress timeout on proto=http/2, local=192.168.1.101:50825, 192.168.1.10:443=upstream, streamID=

The proxygen flow controller has not yet decided to send a window_update because the flow control window is still open (less than half of it is used). However, tomcat seems to be expecting a window_update anyway. Without further details on the flow control state, this looks like a tomcat http/2 bug.

SteveSelva commented 1 year ago

But I have tested this with many websites, and for every request when the response is greater than the initial window size(65536), the response is not completely sent.

Images of Request and Response Status Without Proxy-Tomcat With Proxy-Tomcat With Proxy-Youtube With Proxy-Facebook

In these requests, for every response which has size greater than the initial window size(65536), the response is not sent properly, causing an HTTP2_PROTOCOL_ERROR to be thrown.

jbeshay commented 1 year ago

To double-check, you are using this sample code (https://github.com/facebook/proxygen/blob/main/proxygen/httpserver/samples/proxy/ProxyServer.cpp) on Windows. Is that correct?

Have you made any changes to this code?

SteveSelva commented 1 year ago

Yeah, I am using that sample code (https://github.com/facebook/proxygen/blob/main/proxygen/httpserver/samples/proxy/ProxyServer.cpp) on Windows.

And I have made changes too.

jbeshay commented 1 year ago

I have not been able to reproduce the issue with the sample ProxyServer.cpp code on Linux. What is the Chrome config you are using? What are the code changes you made to the sample?

SteveSelva commented 1 year ago

I have configured Proxygen to work as a HTTPS Proxy Server . I have not configured anything in Chrome. I have made changes in HTTPServerAcceptor, RequestHandlerFactory, RequestHandler. And implemented fizz::server::CertManager and used my CertManager in Proxygen.

Complete Logs: Logs.zip contains ProxyServer-Logs.txt Tomcat-Logs.txt Downstream-Trace.pcapng (Apply Display filter as "tcp.port == 5555") Downstream-Key.log Upstream-Trace.pcapng (Apply Display filter as "tcp.port == 443") Upstream-Key.log

SteveSelva commented 1 year ago

From my analysis of the ProxyServer logs, I doubt that this may cause timeout.

FlowControlFilter.cpp

bool FlowControlFilter::ingressBytesProcessed(folly::IOBufQueue& writeBuf,
                                              uint32_t delta) {
  toAck_ += delta;
  bool willAck =
      (toAck_ > 0 && uint32_t(toAck_) > recvWindow_.getCapacity() / 2);
  VLOG(4) << "processed " << delta << " toAck_=" << toAck_
          << " bytes, will ack=" << willAck;
  if (willAck) {
    CHECK(recvWindow_.free(toAck_));
    call_->generateWindowUpdate(writeBuf, 0, toAck_);
    toAck_ = 0;
    return true;
  }
  return false;
}

In this function, they are verifying that whether the total bytes to be acknowledged(toAck) is greater than half the size of initial window (65535/2 = 32767.5). And if toAck is greater than that value, Proxygen is acknowledging that it has received toAck bytes, or else its reading till toAck met that condition.

In Tomcat's case, one time it acknowledged when it reached toAck = 32768. But the other time the toAck = 32767 and it is waiting for more data to receive. But there is no data read (reason maybe upstream server waiting for ACKnowledgement or data has been sent completely). So its reaching timeout(5 seconds) causing error thereby, sending RST_STREAM frame.

Acknowledge is sent when toAck>32767.5

I20230607 15:44:52.380589  4348 AsyncSocket.cpp:2989] this=00000190344D7910, AsyncSocket::handleRead() got 9 bytes
I20230607 15:44:52.381572  4348 HTTPSessionBase.cpp:141] proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream Dequeued 9 bytes of ingress. Ingress buffer uses 0 of 65536 bytes.
I20230607 15:44:52.381572  4348 FlowControlFilter.cpp:73] processed 9 toAck_=32768 bytes, will ack=1
I20230607 15:44:52.381572  4348 HTTP2Codec.cpp:1727] generating window update for stream=0: Processed 32768 bytes
I20230607 15:44:52.381572  4348 ProxyHandler.cpp:194] Forwarding 9 body bytes to client
I20230607 15:44:52.381572  4348 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=9
I20230607 15:44:52.381572  4348 HTTPSession.cpp:2217] proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream writing 13, activeWrites=1 cork:0 timestampTx:0 timestampAck:0

Acknowledge is not sent when toAck<32767.5

I20230607 15:44:52.405705  4348 AsyncSocket.cpp:2989] this=00000190344D7910, AsyncSocket::handleRead() got 8 bytes
I20230607 15:44:52.405705  4348 HTTPSessionBase.cpp:141] proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream Dequeued 8 bytes of ingress. Ingress buffer uses 0 of 65536 bytes.
I20230607 15:44:52.405705  4348 FlowControlFilter.cpp:73] processed 8 toAck_=32767 bytes, will ack=0
I20230607 15:44:52.406672  4348 ProxyHandler.cpp:194] Forwarding 8 body bytes to client
I20230607 15:44:52.406672  4348 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=8
I20230607 15:44:52.406672  4348 HTTPSession.cpp:2110] proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local egressing txnID=1 allowed=65536
I20230607 15:44:52.406672  4348 HTTPTransaction.cpp:1276] Sending 8 bytes of body. eom=no send_window is 6225921 / 6291456 trailers=no proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local, streamID=1
I20230607 15:44:52.406672  4348 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=-8
I20230607 15:44:52.406672  4348 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=-8
I20230607 15:44:52.406672  4348 HTTPSession.cpp:2217] proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local writing 17, activeWrites=1 cork:0 timestampTx:0 timestampAck:0
I20230607 15:44:57.342180  4348 HTTPSession.cpp:1502] Transaction timeout for streamID=1
I20230607 15:44:57.342180  4348 HTTPTransaction.cpp:719] ingress timeout on proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream, streamID=1
I20230607 15:44:57.343133  4348 HTTPTransaction.cpp:1444] pauseIngress request proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream, streamID=1
I20230607 15:44:57.343133  4348 HTTPSession.cpp:1460] proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream pausing streamID=1, liveTransactions_ was 1
I20230607 15:44:57.343133  4348 HTTPTransaction.cpp:551] Marking ingress complete on proto=http/2, local=192.168.1.101:52772, 192.168.1.10:443=upstream, streamID=1
E20230607 15:44:57.343133  4348 ProxyHandler.cpp:214] Server error: what="ingress timeout, streamID=1", direction=0, proxygenError=Timeout, codecStatusCode=-1, httpStatusCode=0
I20230607 15:44:57.343133  4348 HTTPTransaction.cpp:551] Marking ingress complete on proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local, streamID=1
I20230607 15:44:57.343133  4348 HTTPTransaction.cpp:558] Marking egress complete on proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local, streamID=1
I20230607 15:44:57.343133  4348 HTTPTransaction.cpp:1389] aborting transaction proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local, streamID=1
I20230607 15:44:57.344092  4348 HTTPSession.cpp:1747] proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local sending abort for streamID=1
I20230607 15:44:57.344092  4348 HTTP2Codec.cpp:1526] sending RST_STREAM for stream=1 with code=INTERNAL_ERROR
I20230607 15:44:57.344092  4348 HTTPTransaction.cpp:150] destroying transaction proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:52769, 127.0.0.1:5555=local, streamID=1
I20230607 15:44:57.344092  4348 ProxyHandler.cpp:232] Request Completed

How to fix this?

SteveSelva commented 1 year ago

I tried to send acknowledge by changing the code,

bool willAck =
      (toAck_ > 0 && uint32_t(toAck_) >= recvWindow_.getCapacity() / 2);

And this made Proxygen to acknowledge but still timeout occurs even after acknowledged.

I20230608 10:51:49.900946  2776 AsyncSSLSocket.cpp:1511] AsyncSSLSocket::performRead() this=000001D49C9B7990, buf=000001D49C9CB1B0, buflen=4000
I20230608 10:51:49.900946  2776 AsyncSocket.cpp:2989] this=000001D49C9B7990, AsyncSocket::handleRead() got 8 bytes
I20230608 10:51:49.900946  2776 HTTPSessionBase.cpp:141] proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream Dequeued 8 bytes of ingress. Ingress buffer uses 0 of 65536 bytes.
I20230608 10:51:49.900946  2776 FlowControlFilter.cpp:73] processed 8 toAck_=32767 bytes, will ack=1
I20230608 10:51:49.900946  2776 HTTP2Codec.cpp:1727] generating window update for stream=0: Processed 32767 bytes
I20230608 10:51:49.900946  2776 ProxyHandler.cpp:194] Forwarding 8 body bytes to client
I20230608 10:51:49.900946  2776 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=8
I20230608 10:51:49.900946  2776 HTTPSession.cpp:2217] proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream writing 13, activeWrites=1 cork:0 timestampTx:0 timestampAck:0
I20230608 10:51:49.900946  2776 HTTPSession.cpp:2110] proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:61839, 127.0.0.1:5555=local egressing txnID=1 allowed=65536
I20230608 10:51:49.900946  2776 HTTPTransaction.cpp:1276] Sending 8 bytes of body. eom=no send_window is 6225921 / 6291456 trailers=no proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:61839, 127.0.0.1:5555=local, streamID=1
I20230608 10:51:49.900946  2776 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=-8
I20230608 10:51:49.900946  2776 HTTPSessionBase.cpp:152] notifyEgressBodyBuffered pwsd=-8
I20230608 10:51:49.900946  2776 HTTPSession.cpp:2217] proto=http/2, UA=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36, downstream=127.0.0.1:61839, 127.0.0.1:5555=local writing 17, activeWrites=1 cork:0 timestampTx:0 timestampAck:0
I20230608 10:51:57.409485  2776 HTTPSession.cpp:1502] Transaction timeout for streamID=1
I20230608 10:51:57.413897  2776 HTTPTransaction.cpp:719] ingress timeout on proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream, streamID=1
I20230608 10:51:57.413897  2776 HTTPTransaction.cpp:1444] pauseIngress request proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream, streamID=1
I20230608 10:51:57.413897  2776 HTTPSession.cpp:1460] proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream pausing streamID=1, liveTransactions_ was 1
I20230608 10:51:57.415365  2776 HTTPTransaction.cpp:551] Marking ingress complete on proto=http/2, local=192.168.1.101:61842, 192.168.1.10:443=upstream, streamID=1
E20230608 10:51:57.415365  2776 ProxyHandler.cpp:214] Server error: what="ingress timeout, streamID=1", direction=0, proxygenError=Timeout, codecStatusCode=-1, httpStatusCode=0
SteveSelva commented 1 year ago

@afrind @jbeshay Can you guys help me fix this please?

jbeshay commented 1 year ago

It's not easy to tell what's going on from the logs without your changes. The ProxyServer sample is written as a forward proxy but based upon the traces you shared, it looks like you have modified it to work as a reverse proxy.

SteveSelva commented 1 year ago

No, it's not working as a Reverse Proxy, I have configured it as a HTTPS Proxy.

And I have changed only at the configuration level and didn't change any code in codec or protocol handling level.

jbeshay commented 1 year ago

Using the downstream pcap + keys you shared, the first HTTP message I see is the HTTP/2 GET.

Could you share a downstream pcap trace with the keys between the client and the proxy server? It'd be helpful to see the HTTP messages for setting up the connection to the proxy.

Alternatively, are you able to run this over HTTP instead of HTTPS. Do you get the same timeout?

SteveSelva commented 1 year ago

Based on the Logs from Tomcat, its sure that WINDOW_UPDATE message is not being received in Upstream so the window is empty.

08-Jun-2023 22:44:10.245 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders 101 bytes
08-Jun-2023 22:44:10.245 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.245 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [57343]
08-Jun-2023 22:44:10.245 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [57343]
08-Jun-2023 22:44:10.245 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-100]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [49151]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [49151]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-120]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [40959]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [40959]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-140]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [32767]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [32767]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-160]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [24575]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [24575]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-180]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [16383]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [16383]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-200]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8192] to [8191]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8192] to [8191]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8192], EndOfStream [false]
08-Jun-2023 22:44:10.263 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-220]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [0], Stream [1], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [1], reduce flow control window by [8191] to [0]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [0], Stream [0], reduce flow control window by [8191] to [0]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.writeBody Connection [0], Stream [1], Data length [8191], EndOfStream [false]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection [0], Stream [0], Frame type [DATA] resulted in new overhead count of [-240]
08-Jun-2023 22:44:10.280 FINE [https-openssl-apr-0.0.0.0-443-exec-3] org.apache.coyote.http2.WindowAllocationManager.waitForStream Connection [0], Stream [1], Waiting for Stream flow control window (blocking) with timeout [20000]

But a WINDOW_UPDATE frame is sent to Upstream. Upstream Trace

SteveSelva commented 1 year ago

I have configured Proxygen to work as a HTTPS Proxy Server . I have not configured anything in Chrome. I have made changes in HTTPServerAcceptor, RequestHandlerFactory, RequestHandler. And implemented fizz::server::CertManager and used my CertManager in Proxygen.

Complete Logs: Logs.zip contains ProxyServer-Logs.txt Tomcat-Logs.txt Downstream-Trace.pcapng (Apply Display filter as "tcp.port == 5555") Downstream-Key.log Upstream-Trace.pcapng (Apply Display filter as "tcp.port == 443") Upstream-Key.log

This file contains both Upstream and Downstream pcap trace with keys.

jbeshay commented 1 year ago

I am still unable to reproduce your exact same scenario with the vanilla sample code. The logs you shared from the proxy server show that it is receiving a GET /tomcat.svg from the client. If this is being used a fwd proxy, I would have assumed a CONNECT or a GET with a full URL.

I20230607 15:44:52.226044  4348 ProxyHandler.cpp:164] Forwarding client request: /tomcat.svg to server

The ProxyHandler in the vanilla sample code and configuration does not handle this so I am not able to reproduce the behavior you are seeing.

To be able to help you further, Please try to reproduce the issue with the vanilla code or share a minimal change and specific steps to reproduce the issue you're facing.

SteveSelva commented 1 year ago

I think my code changes caused the issue due to resetting transaction in ProxyHandler. I apologize for the confusion. Thanks for your support.