Fixes in DTPHandler.use_sendfile and Epoll.poll

stat1c-void commented 1 year ago

Hi!

Thanks for your awesome work on pyftpdlib!

Here are two fixes, quite important in some cases, gathered from our production experience.

1. DTPHandler.use_sendfile

In one rare case in our environment pyftpdlib went into an infinite traceback printing loop.

May be a rare thing, I suspect it was mainly because of our environment: filesystem is a NAS-backed NFS, so things happen. Basically, it went something like this from my understanding:

event loop tries to close a connection
it then tries to close opened file, but fails to do so
during error handling and logging, calls get_repr_info() -> use_sendfile() -> fileno()
fileno() raises ValueError, which is not caught, and overall the event is not processed
same event tries to get processed the next tick of event loop, with similar result

This was happening many times per second. I'm going to attach a relevant traceback.

2. Epoll.poll

In some cases I observed infinite hanging of a connection thread. Basically, in some cases Epoll.poll() gets called with timeout = 0, but it causes it to call self._poller.poll(-1). At the same time there are no more events on the socket. The timeout idler should have triggered, but the thread (we use threaded server) is stuck on poll(-1).

I guess zero timeout comes from _Scheduler.poll when the top-most task is overdue:

return max(0, self._tasks[0].timeout - now)

Here is a pystack snapshot from our production env:

Traceback for thread 30 (python) [] (most recent call last):
    (Python) File "/usr/local/lib/python3.10/threading.py", line 973, in _bootstrap
        self._bootstrap_inner()
      Arguments:
        self: <Thread at 0x7f0c68e16440>
    (Python) File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
        self.run()
      Arguments:
        self: <Thread at 0x7f0c68e16440>
    (Python) File "/usr/local/lib/python3.10/threading.py", line 953, in run
        self._target(*self._args, **self._kwargs)
      Arguments:
        self: <Thread at 0x7f0c68e16440>
    (Python) File "/usr/src/app/.venv/lib/python3.10/site-packages/pyftpdlib/servers.py", line 402, in _loop
        poll(timeout=soonest_timeout)
      Arguments:
        handler: <OVFXHandler at 0x7f0c6a23d5a0>
        self: <ThreadedFTPServer at 0x7f0c6a312170>
      Locals:
        poll_timeout: 1
        soonest_timeout: 0
        sched_poll: <method at 0x7f0c67f27500>
        poll: <method at 0x7f0c67f25b40>
        ioloop: <Epoll at 0x7f0c6961bd30>
    (Python) File "/usr/src/app/.venv/lib/python3.10/site-packages/pyftpdlib/ioloop.py", line 521, in poll
        events = self._poller.poll(timeout or -1)  # -1 waits indefinitely
      Arguments:
        timeout: 0
        self: <Epoll at 0x7f0c6961bd30>

stat1c-void commented 1 year ago

The mentioned traceback: loki-logs-export.txt

codecov[bot] commented 1 year ago

Codecov Report

Attention: 1 lines in your changes are missing coverage. Please review.

Comparison is base (ec1f095) 69.78% compared to head (2224586) 70.06%. Report is 7 commits behind head on master.

:exclamation: Current head 2224586 differs from pull request most recent head 068e989. Consider uploading reports for the commit 068e989 to get more accurate results

Additional details and impacted files

```diff @@ Coverage Diff @@ ## master #607 +/- ## ========================================== + Coverage 69.78% 70.06% +0.28% ========================================== Files 9 9 Lines 3617 3621 +4 ========================================== + Hits 2524 2537 +13 + Misses 1093 1084 -9 ``` | [Files](https://app.codecov.io/gh/giampaolo/pyftpdlib/pull/607?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Giampaolo+Rodola) | Coverage Δ | | |---|---|---| | [pyftpdlib/ioloop.py](https://app.codecov.io/gh/giampaolo/pyftpdlib/pull/607?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Giampaolo+Rodola#diff-cHlmdHBkbGliL2lvbG9vcC5weQ==) | `89.79% <100.00%> (+0.28%)` | :arrow_up: | | [pyftpdlib/handlers.py](https://app.codecov.io/gh/giampaolo/pyftpdlib/pull/607?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Giampaolo+Rodola#diff-cHlmdHBkbGliL2hhbmRsZXJzLnB5) | `70.94% <0.00%> (+0.40%)` | :arrow_up: | ... and [1 file with indirect coverage changes](https://app.codecov.io/gh/giampaolo/pyftpdlib/pull/607/indirect-changes?src=pr&el=tree-more&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Giampaolo+Rodola)

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

stat1c-void commented 1 year ago

Sure, updated the PR :+1:

giampaolo / pyftpdlib