bug#54458: 27.2; erc-dcc-get: Re-entering top level after C stack overflow

["J.P." <jp@neverwas.me>]

[-- Attachment #1: Type: text/plain, Size: 4789 bytes --]

Hi Mattias (and Eli),

Mattias Engdegård <mattiase@acm.org> writes:

> 27 mars 2022 kl. 22.54 skrev Mattias Engdegård <mattiase@acm.org>:
>
>> Not sure where this happens but it looks like it might be erc-dcc-send-filter.
>
> Presumably we should add a note to the documentation of process filter
> functions that they shouldn't be used to send more data to the process. (Not
> sure what to recommend, an idle timer maybe?)

As you highlighted up thread, inhibited sends appeal to
`wait_reading_process_output' to try and shake something loose. I agree
such occasions seem likeliest to trigger "unexpected" filter nesting.

As far as best practices go, I'm not sure how a successful
request-response dialog can happen without participants being able to
react in a timely fashion. If the main worry is stack growth, then
perhaps scheduling something on the event loop with a timer (as you say)
makes the most sense.

I actually tried that (via `run-at-time') in the tinkering detailed
below but still managed to incur "error running timer" messages that
referred to "excessive variable binding." Should I have used something
in the "idle" department instead?

The approach that seemed to "work" mimics the one relied on by ERC's
main client filter, which takes pains to ensure overlapping calls merely
stash the input and bail (via `erc-server-processing-p'). Perhaps a
synchronization primitive especially suited to process filters would
make more sense? (No idea.)

> I'm not going to fix this because I don't know ERC very well and wouldn't be
> able to test it sufficiently, but our ERC maintainers do and can!

You're very generous, and your expertise is much appreciated. (But as
Eli says, "hopefully".)


                              . . .

Hi Fernando,

I've managed to trigger behavior (somewhat) resembling what you've
described. It's quite possible, even likely, that this is total baloney,
but please humor me anyway this one round (unless you spot something
totally egregious, that is). The basic "hypothesis" seems to comport
with Mattias's analysis. It posits that the peer you're connecting to is
misbehaving and engaged in some combination of:

 1. not reading frequently enough amid sends

 2. being too stingy with its read buffer

I'd be great if you could confirm this suspicion by checking if the
"window" portion of the TCP ACK segments containing actual payloads go
to zero after a spell. This can be done with tcpdump or wireshark. A
well behaved peer respecting the protocol should normally have nonzero
windows throughout.

On the client side (Emacs master this time), here is what I observe
after following the steps enumerated further down: There appears to be
another buffer of around 64KB that needs filling before I (the receiver)
encounter the error, which in my case is a "variable binding depth
exceeds max-specpdl-size" message along with an unresponsive UI. For me,
this happens without fail at around 800MB after the TCP window goes to 0
(at around 100MB). Strangely, increasing the value of `max-specpdl-size'
doesn't change things perceptively.

Anyway, the file-writing operation continues for around 200MB and
eventually peters out. But the connection only dies after the sender
closes it normally (having sent everything). The IRC connection of
course PINGs out and is severed by the IRC server. The Emacs receiver
process eventually recovers responsiveness (if you wait long enough).

These are the steps I followed. They require two emacs -Q instances, a
server, and the attached script:

 1. connect to the server and make sure the sender can /whois the
    receiver (have them join the same #chan if necessary)
 
 2. start the script:

    python ./script.py ./some_large_file.bin misbehave
 
 3. on the sender:

    /msg RecvNick ^ADCC SEND some_large_file.bin 2130706433 9899 1234567890^A

    where 1234567890 is the size of the file in bytes and ^A is an
    actual control char
 
 4. on the receiver:

    /dcc get SendNick some_large_file.bin

As mentioned earlier, I've attached a crude experiment (patch) that just
records whether we're currently sending (so receipts can be skipped when
the flag is set). I used the process plist for now, but erc-dcc does
keep a global context-state object called `erc-dcc-entry-data', which I
suppose may be more fitting. The idea is to roll with the punches from a
pathological peer but also (of course) interoperate correctly with an
obedient, protocol-abiding one.

Normal sender
- Sends 1405135128 bytes
- Sees 343051 reports

Aberrant sender
- Sends 1405135128 bytes
- Ignores 238662 + unknown reports

Let me know if anything needs clarifying. And thanks for your patience!


[-- Attachment #2: serve.py --]
[-- Type: application/octet-stream, Size: 2199 bytes --]

"""Hostile DCC-SEND endpoint

Usage: python this_script.py ./blob.bin [active_flag]

With ``active_flag``, don't wait for read receipts before sending the
next hunk.

"""
import sys
import socket
import asyncio

from pathlib import Path


class OnConnect:
    def __init__(self, file, no_recv=False):
        self.file = Path(file)
        self.skip = bool(no_recv)
        print(f"Sending {file!r} ({self.file.stat().st_size} bytes)")
        print("Firehose mode:", "on" if self.skip else "off")

    async def read(self) -> int:
        data = await self.reader.read(1024)
        dlen = len(data)
        print("." if dlen == 4 else f"[{dlen}]", end="", flush=True)
        return dlen

    async def handle(self):
        sent = received = 0
        print(f"Connection from {self.writer.get_extra_info('peername')!r}")

        with self.file.open("rb") as f:
            while chunk := f.read(32768):
                self.writer.write(chunk)
                await self.writer.drain()
                sent += len(chunk)
                if self.skip:
                    continue
                received += await self.read()

            try:
                while g := await asyncio.wait_for(self.read(), timeout=1):
                    received += g
            except asyncio.TimeoutError:
                pass
            print("\nSent %d bytes" % sent)
            print("Saw %d reports" % (received // 4))
            self.writer.close()
            await self.writer.wait_closed()

    def __call__(self, reader, writer):
        self.reader = reader
        self.writer = writer
        return self.handle()


async def main(handler: OnConnect):
    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, True)
    sock.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 128)
    sock.bind(("127.0.0.1", 9899))
    server = await asyncio.start_server(handler, sock=sock)
    print(f"Serving on {server.sockets[0].getsockname()}")

    async with server:
        await server.serve_forever()


if __name__ == "__main__":
    try:
        asyncio.run(main(OnConnect(*sys.argv[1:])))
    except KeyboardInterrupt:
        print()

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0001-EXPERIMENT-regulate-ACK-updates-in-erc-dcc-get-filte.patch --]
[-- Type: text/x-patch, Size: 1123 bytes --]

From 7f9a7fe1a1ea9208841a4ec600ec25e1a464b71d Mon Sep 17 00:00:00 2001
From: "F. Jason Park" <jp@neverwas.me>
Date: Mon, 28 Mar 2022 02:24:43 -0700
Subject: [PATCH] [EXPERIMENT] regulate ACK updates in erc-dcc-get-filter

* lisp/erc/erc-dcc.el (erc-dcc-get-filter): Don't bother sending a
"received so far" receipt if another attempt is in progress.
---
 lisp/erc/erc-dcc.el | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/lisp/erc/erc-dcc.el b/lisp/erc/erc-dcc.el
index cc4143bfa2..aaac2277bf 100644
--- a/lisp/erc/erc-dcc.el
+++ b/lisp/erc/erc-dcc.el
@@ -986,9 +986,10 @@ erc-dcc-get-filter
          'dcc-get-file-too-long
          ?f (file-name-nondirectory (buffer-name)))
         (delete-process proc))
-       (t
-        (process-send-string
-         proc (erc-pack-int received-bytes)))))))
+       ((not (process-get proc :sending))
+        (process-put proc :sending t) ; should maybe use `erc-dcc-entry-data'
+        (process-send-string proc (erc-pack-int received-bytes))
+        (process-put proc :sending nil))))))
 
 
 (defun erc-dcc-get-sentinel (proc _event)
-- 
2.35.1