[ReverseProxyPlugin] Fails to process request when response is too big

[atsakiridis]

Describe the bug
I try the reverse proxy example from README.md by starting proxy.py with (hopefully) appropriate flags (check below for invocation) and send simple requests using curl. For some reason proxy sporadically fails and times out after ~10 secs and client isn't receiving the response body. This happens around 20% of the times; the rest of them it's working fine.

To Reproduce

1. Run proxy.py as python -m proxy --disable-http-proxy --enable-web-server --plugins proxy.plugin.ReverseProxyPlugin --hostname 127.0.0.1
2. Use the curl example found in README.md curl -v http://127.0.0.1:8899/get. When reproducible I get:

$ curl -v http://127.0.0.1:8899/get
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8899 (#0)
> GET /get HTTP/1.1
> Host: 127.0.0.1:8899
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Mon, 10 Feb 2020 18:01:15 GMT
< Content-Type: application/json
< Content-Length: 250
< Connection: keep-alive
< Server: gunicorn/19.9.0
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Credentials: true
< 
* transfer closed with 250 bytes remaining to read
* Closing connection 0
curl: (18) transfer closed with 250 bytes remaining to read

3. The proxy.py output is:

$ python -m proxy --disable-http-proxy --enable-web-server --plugins proxy.plugin.ReverseProxyPlugin --hostname 127.0.0.1
2020-02-10 20:00:55,637 - pid:49866 [I] load_plugins:525 - Loaded plugin proxy.http.server.HttpWebServerPlugin
2020-02-10 20:00:55,637 - pid:49866 [I] load_plugins:525 - Loaded plugin proxy.plugin.ReverseProxyPlugin
2020-02-10 20:00:55,637 - pid:49866 [I] listen:63 - Listening on 127.0.0.1:8899
2020-02-10 20:00:55,652 - pid:49866 [I] start_workers:84 - Started 8 workers
2020-02-10 20:01:09,716 - pid:49870 [I] access_log:232 - 127.0.0.1:49854 - GET /get - 10381.46 ms
2020-02-10 20:01:25,265 - pid:49870 [I] access_log:232 - 127.0.0.1:49917 - GET /get - 10297.06 ms
2020-02-10 20:01:36,078 - pid:49867 [I] access_log:232 - 127.0.0.1:50003 - GET /get - 277.89 ms

Notice the first 2 requests timing out at ~10 seconds and the 3rd going through fine.

Expected behavior
Was expecting to handle all requests without issues.

Version information

• OS: MacOS Catalina (10.15.2 (19C57))
• Browser: N/A (using curl, but same happens for postman)
• Device: MacBook Pro Mid 2015
• proxy.py Version: v2.1.2, also tried latest from develop and results are the same

Additional context
Happy to help by debugging further & providing a patch for this (if indeed an issue), just need some pointers on where to look :)

Screenshots
N/A

[abhinavsingh]

Hi @atsakiridis thank you for reporting this.

We'll need to dig into it further, but ~10 seconds is coming from default timeout. Looks like occasionally proxy.py is unable to detect if/when a response has finished. So it is most likely just waiting for timeout before tearing down the connection.

[atsakiridis-test]

Thanks for the insights @abhinavsingh. I will try to do some more digging in handler thread where receiving from upstream and sending back to client

[abhinavsingh]

Thank you. I am currently traveling. I'll be able to get back to it in 2 weeks time. In meantime, feel free to share your findings, I can proceed on-top of that.

…

On Sat, Feb 15, 2020, 1:08 AM atsakiridis-test ***@***.***> wrote: Thanks for the insights @abhinavsingh <https://github.com/abhinavsingh>. I will try to do some more digging in handler thread where receiving from upstream and sending back to client — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#292?email_source=notifications&email_token=AAA6Y4OMBH2TKVL3ERNJLPTRC6WKRA5CNFSM4KSTE5D2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEL3FWLY#issuecomment-586570543>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAA6Y4JDZADEQXTRMIXTTTTRC6WKRANCNFSM4KSTE5DQ> .

[atsakiridis]

@abhinavsingh I think the culprit is here. If the full response isn't returned in the first call to conn.recv(), then the connection with upstream is closed. Hence the rest of the response is never conveyed to the proxy to be queued to client connection and handled as writable.

Does this make sense?

[abhinavsingh]

@atsakiridis That totally makes sense to me.

I wrote this plugin mostly to demonstrate reverse proxy capabilities, definitely didn't thought about big enough responses requiring multiple recv.

[atsakiridis]

Cool. Let me do some research on how to best accommodate this functionality based on underlying architecture and we can discuss alternatives.

By way, I also noticed in reverse_proxy.py that the connection to upstream is always cleartext so was thinking to add support for https, if that's what's used in the proxy pass url. If that makes sense for the project/community I could come up with a new enhancement issue on this and contribute a PR, so let me know.

[abhinavsingh]

+1 to everything you suggested. Few thoughts: 1) I have run into similar needs/use-case on another thread. Not exactly related to reverse proxy plugin, but related to asynchronously read/write from an upstream server. 2) Base problem I see, when asynchronous read/writes are needed from an upstream server, plugin authors must handle asynchronous read/write within plugin. 3) `proxy.py` core can help. By allowing plugin authors to register new file descriptors for read/write events. Then, core can simply callback plugin method when file descriptor is ready for read/writes, allowing for really clean code in plugins. 4) `proxy.py` core already exposes such (file descriptor registration) functionality. It is currently not exposed to plugins but should be possible with little effort (I feel). 4) Totally agree on HTTPS use-case. Thank you ------------------------------------------------------ Abhinav Singh, https://abhinavsingh.com ------------------------------------------------------

…

On Mon, Feb 17, 2020 at 12:09 AM Antonis Tsakiridis < ***@***.***> wrote: Cool. Let me do some research on how to best accommodate this functionality based on underlying architecture and we can discuss alternatives. By way, I also noticed in reverse_proxy.py that the connection to upstream is always cleartext so was thinking to add support for https, if that's what's used in the proxy pass url. If that makes sense for the project/community I could come up with a new enhancement issue on this and contribute a PR, so let me know. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#292?email_source=notifications&email_token=AAA6Y4JC3PCZYLZ5INBAQILRDGB7TA5CNFSM4KSTE5D2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEL4OVZA#issuecomment-586738404>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAA6Y4N34M6MXHNM52NTUHDRDGB7TANCNFSM4KSTE5DQ> .

[atsakiridis]

Thanks for the insights 👍 let me do some digging there and I'll circle back with potential solutions. Let me also open up an issue for the https use case

[atsakiridis]

@abhinavsingh been doing some research on the codebase so let me share some ideas before I jump into coding to make sure we are on the same page. What we can do is:

• Provide register fd functionality in HttpWebServerPlugin, that will allow any web server plugin like ReverseProxyPlugin to dynamically register fds for read/write operations (we could pass a reference to HttpWebServerPlugin in HttpWebServerBasePlugin so that all web server plugins can access it to facilitate that registration). This roughly means that in HttpWebServerPlugin we'll need to: introduce a method like add_descriptor(), provide buffering and storage for the fd(s)
• I see HttpWebServerPlugin already communicates fds to HttpProtocolHandler through get_descriptors() (even if right now it's always returning empty) so we seem to be covered in that respect already by just updating this to return the new fds we'll be introducing.
• Once the fd is added, then the handler thread will be woken if there's data to read/write there. We'll have to add implementation to HttpWebServerPlugin's write_to_descriptors() and read_from_descriptors()
• Each time we get a response chunk from upstream in read_from_descriptors() we can add it in the client queue so that it finds its way back to the browser (similar to what used to happen inside the reverse proxy plugin code)

Let me know if I'm missing something or something is off :)

[atsakiridis]

@abhinavsingh fyi I have forked the repo and started modeling a solution, so let me get back to you when I have news.

[abhinavsingh]

👍👍👍🙂

…

On Sun, Mar 8, 2020, 12:15 AM Antonis Tsakiridis ***@***.***> wrote: @abhinavsingh <https://github.com/abhinavsingh> fyi I have forked the repo and started modeling a solution, so let me get back to you when I have news. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#292?email_source=notifications&email_token=AAA6Y4KIRXAJ24ZK4UNREK3RGKI3PA5CNFSM4KSTE5D2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEOECRWI#issuecomment-596125913>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAA6Y4PUP6PQNG3SHDBIPALRGKI3PANCNFSM4KSTE5DQ> .

[atsakiridis]

@abhinavsingh I created a draft PR for this that seems to be fixing the issue. I plan to iterate more on it to clean it up and test more comprehensively. Still would be nice if you can have a look and see if there are any gaps there or things that could be improved

[abhinavsingh]

Hi @atsakiridis Thanks for the patience. These have been tough times with all the traveling involved. Good news, I am back at a stable place and will soon jump back onto your PR. Really appreciate it. 👍

[atsakiridis]

No worries, the times are tough for everybody. Looking forward to it

[widy28]

hi, @atsakiridis @abhinavsingh
How to solve it? i use plugin - [ProxyPoolPlugin], same problem happened.
i try change the method tunnel and debug:

    def tunnel(self, request: HttpParser) -> None:
        """Send to upstream proxy, receive from upstream proxy, queue back to client."""
        assert self.conn
        self.conn.send(request.build())
        import time
        start = time.time()
        response = b''
        size = 1024     # or DEFAULT_BUFFER_SIZE
        while True:
            tmp_response = self.conn.recv(size, socket.MSG_WAITALL)
            end = time.time()
            print("recv: ", len(tmp_response), end-start)
            response += tmp_response
            if len(tmp_response) < size:
                print('no response')
                break
        self.client.queue(memoryview(response))

the debug info for 3 times:

recv:  1024   0.3232271671295166
recv:  1024   0.32412099838256836
recv:  1024   0.3241739273071289
recv:  1024   0.3242011070251465
recv:  1024   0.32442688941955566
recv:  1024   0.32448720932006836
recv:  1024   0.32462000846862793
recv:  1024   0.3246500492095947
recv:  955     5.3378589153289795
no response
----------------
recv:  1024   0.2523069381713867
recv:  1024   0.25275087356567383
recv:  1024   0.2530839443206787
recv:  1024   0.25316786766052246
recv:  1024   0.25522589683532715
recv:  1024   0.2556018829345703
recv:  1024   0.25581884384155273
recv:  1024   0.25587010383605957
recv:  1024   0.2559080123901367
recv:  1024   0.25606203079223633
recv:  91        5.367153882980347
no response
----------------
recv:  1024   0.021346092224121094
recv:  1024   0.021461963653564453
recv:  1024   0.022738218307495117
recv:  1024   0.022825002670288086
recv:  1024   0.02287006378173828
recv:  1024   0.023881912231445312
recv:  1024   0.024350881576538086
recv:  1024   0.024409055709838867
recv:  1024   0.024569034576416016
recv:  1024   0.024621963500976562
recv:  61       5.021462917327881

the last time if if len(tmp_response) < size, the interval is 5s every time, i don't know why.
so i hope someone help, thanks.

[abhinavsingh]

@widy28

I think this approach can work with few modifications.

1. Inspect the Content-Length response header and bail out of while loop once expected amount of response has been received.
2. If you want, you can also try queuing the response by calling self.client.queue(memoryview(buffer)) as you receive chunks from upstream
3. Answer to why 5 seconds probably lie in response headers or upstream server behavior (which might be dropping the connection after 5 seconds idle time).

@abhinavsingh been doing some research on the codebase so let me share some ideas before I jump into coding to make sure we are on the same page. What we can do is:

• Provide register fd functionality in HttpWebServerPlugin, that will allow any web server plugin like ReverseProxyPlugin to dynamically register fds for read/write operations (we could pass a reference to HttpWebServerPlugin in HttpWebServerBasePlugin so that all web server plugins can access it to facilitate that registration). This roughly means that in HttpWebServerPlugin we'll need to: introduce a method like add_descriptor(), provide buffering and storage for the fd(s)
• I see HttpWebServerPlugin already communicates fds to HttpProtocolHandler through get_descriptors() (even if right now it's always returning empty) so we seem to be covered in that respect already by just updating this to return the new fds we'll be introducing.
• Once the fd is added, then the handler thread will be woken if there's data to read/write there. We'll have to add implementation to HttpWebServerPlugin's write_to_descriptors() and read_from_descriptors()
• Each time we get a response chunk from upstream in read_from_descriptors() we can add it in the client queue so that it finds its way back to the browser (similar to what used to happen inside the reverse proxy plugin code)

Let me know if I'm missing something or something is off :)

@atsakiridis This approach is the long term fix we want to go towards. As your research figured, most of the nut-bolts do exist but we need to tie them together. Yep, allowing plugins to register fds with a callback is the missing link in the chain. Did you get a chance to make progress towards it?

Thank you folks!!!

[widy28]

@widy28

I think this approach can work with few modifications.

1. Inspect the Content-Length response header and bail out of while loop once expected amount of response has been received.
2. If you want, you can also try queuing the response by calling self.client.queue(memoryview(buffer)) as you receive chunks from upstream
3. Answer to why 5 seconds probably lie in response headers or upstream server behavior (which might be dropping the connection after 5 seconds idle time).

@abhinavsingh been doing some research on the codebase so let me share some ideas before I jump into coding to make sure we are on the same page. What we can do is:

• Provide register fd functionality in HttpWebServerPlugin, that will allow any web server plugin like ReverseProxyPlugin to dynamically register fds for read/write operations (we could pass a reference to HttpWebServerPlugin in HttpWebServerBasePlugin so that all web server plugins can access it to facilitate that registration). This roughly means that in HttpWebServerPlugin we'll need to: introduce a method like add_descriptor(), provide buffering and storage for the fd(s)
• I see HttpWebServerPlugin already communicates fds to HttpProtocolHandler through get_descriptors() (even if right now it's always returning empty) so we seem to be covered in that respect already by just updating this to return the new fds we'll be introducing.
• Once the fd is added, then the handler thread will be woken if there's data to read/write there. We'll have to add implementation to HttpWebServerPlugin's write_to_descriptors() and read_from_descriptors()
• Each time we get a response chunk from upstream in read_from_descriptors() we can add it in the client queue so that it finds its way back to the browser (similar to what used to happen inside the reverse proxy plugin code)

Let me know if I'm missing something or something is off :)

@atsakiridis This approach is the long term fix we want to go towards. As your research figured, most of the nut-bolts do exist but we need to tie them together. Yep, allowing plugins to register fds with a callback is the missing link in the chain. Did you get a chance to make progress towards it?

Thank you folks!!!

Thank you for your reply. I have inspect the Content-Length response header, the problem is solved.

[abhinavsingh]

@anthonykgross @widy28 Probably related, now there is a plugin ModifyChunkResponsePlugin which demonstrate handling of chunked encoded responses. See #387 and related docs.

[abhinavsingh]

Marking this as a feature request instead of bug. At this point, to fix this issue in a non-blocking fashion require re-thinking plugin interface to expose event loop.

[atsakiridis]

Hey @abhinavsingh, things are pretty crazy here so didn't get a chance to reply, sorry.

@atsakiridis This approach is the long term fix we want to go towards. As your research figured, most of the nut-bolts do exist but we need to tie them together. Yep, allowing plugins to register fds with a callback is the missing link in the chain. Did you get a chance to make progress towards it?

So yeah as I mentioned above I came up with a PR some months back that hooks on existing facilities to provide the (hopefully) needed functionality (I did some tests and the issue is no longer reproducible). Notice though it's not final yet, so was looking for your feedback on the PR to see if we need more adjustments but now I see it's closed, so wondering what happened :)

[abhinavsingh]

@atsakiridis Agreed. Your PR #303 is a good start. However, I found it very specific to ReverseProxyPlugin problems. Specifically, it addresses exposing event loop from WebServer components. But over time, I realize exposing core event loop is a good idea not just for web server plugins but even for proxy server plugins. Example, proxy pool plugin can benefit from it #359

I closed the PR last week (left a comment on it) in view of:

1. PR was sent on March 4th, but I couldn't get back to it earlier due to Covid and travel plans.
2. Finally, I did revisit it 2 weeks back, but due to reasons explained above, I decided to close that PR for now.

I still want to get it addressed though. However, let's take a step at a time, instead of checking in a solution which only addresses ReverseProxyPlugin. Comments on that PR are reflective of what I wrote # TODO: Check how much is common between self and HttpProxyPlugin and consider extracting into HttpProtocolHandlerPlugin. These core changes will likely impact everything including (http core handler, web server core, proxy server core, various plugins, etc)

Wdyt?

[atsakiridis]

I see your point @abhinavsingh, it's just too bad we couldn't sync at that time to agree on needed changes and get them out the door. Anyway, let me know if you have a plan to adapt this in a way that makes more general sense for the project and I'll be happy to help.

Best regards

[jevy-wangfei]

Experienced similar problem for large data, only part of data could be received using ReverseProxyPlugin.
Current resolved by:

            conn.send(build_url)
            data = bytearray()
            while True:
                package = conn.recv(DEFAULT_BUFFER_SIZE)
                if len(package) < 1: 
                    break
                else:
                    data.extend(package)
            self.client.queue(memoryview(data))

[abhinavsingh]

@jevy-wangfei @atsakiridis @widy28 Necessary support to proceed here has landed. Now plugins can too register for socket descriptor and read/write async. Proxy pool plugin has already been updated to use the same, see here #645

ReverseProxyPlugin comes from http server plugin (not proxy), but the core is common and workflow will remain the same. I'll also update the ReserveProxyPlugin sometime to use async read/write.

That should automatically solve several issues that we have experienced till now. Thanks for your patience and for being persistent :)

[abhinavsingh]

@jevy-wangfei @atsakiridis @widy28

PTAL at #675

Thank you for your patience.