Skip to content

Network specs hang: 75 ruby/spec files killed by the clock on rbgo and not on MRI (Net::FTP 39, Net::HTTP 27, Socket 8, Timeout 1) #916

Open

Description

@tannevaled

Measuring rbgo against MRI 4.0.7 over library/net-ftp — both engines, same corpus, same shim — 39 of 56 spec files have to be killed by the clock on rbgo, and none on MRI:

56 file(s): control 459 passing, treatment 17 passing, -442
library/net-ftp/put_spec.rb              39   0   -39  KILLED on timeout, the treatment
library/net-ftp/get_spec.rb              35   0   -35  KILLED on timeout, the treatment
library/net-ftp/login_spec.rb            29   0   -29  KILLED on timeout, the treatment
library/net-ftp/putbinaryfile_spec.rb    23   0   -23  KILLED on timeout, the treatment
…  (39 rows, all "the treatment")

MRI passes 459 examples in those files. rbgo passes 17. The missing 442 are not failing assertions — the process does not come back.

⛔ This was being reported as "unimplemented"

Until #915, specdelta discarded the killed flag at a parse boundary, so a killed engine fell through to ran == false and the report said DID NOT RUN on the treatment. Every earlier sweep therefore listed these 39 files as "rbgo cannot load them" — i.e. as a missing Net::FTP — when Net::FTP loads fine and hangs. Those are opposite findings and they call for opposite work.

With the fix in place and a 20-second per-file budget on a quiet machine (1-minute load 4), the verdict is unambiguous: a spec file that normally returns in under a second is still running after 20 s, 39 times over.

Why the short timeout is the better instrument here

The first re-measurement used 300 s and was still running after 77 minutes with nothing printed. For a hang-or-absent question a short budget is strictly better: 20 s is already ~100× a normal file's work, so anything that exceeds it is a hang by any definition, and the answer arrives in minutes instead of hours.

Where to start

These specs stand up a local FTP server (ruby/spec's SpecFTPServer) and connect to it, so the suspects are the accept/read path and whatever bounds it — note that Timeout.timeout currently never fires (#803), so anything relying on it for a deadline has none. #895 (TestUDPSocketLoopback can hang) is the same family.

This is the largest single block in the whole non-core/language measurement: 442 examples, more than bigdecimal (180), matrix (233) and date (132) combined.

Measured on c604cce1ba0b, darwin/arm64, corpus SPEC_SHA=87b1631992bd00cf0c4934474766d54dad088191, control /opt/homebrew/opt/ruby@4.0/bin/ruby.

🤖 Generated with Claude Code

Activity

  1. tannevaled commented on Nov 10, 2026

    @tannevaled
    ContributorAuthor

    It is not only FTP: 75 spec files hang, across four stdlib areas

    Re-measuring the rest of the network modules with the same instrument — 20 s per file, both engines, quiet machine — extends the list well past Net::FTP:

    area files killed on rbgo examples MRI passes in them
    library/net-ftp 39 442
    library/net-http 27 ~75
    library/socket 8 0
    library/timeout 1 6
    total 75
    library/net-http/http/post_spec.rb            7   0   -7  KILLED on timeout, the treatment
    library/net-http/http/request_get_spec.rb     5   0   -5  KILLED on timeout, the treatment
    …
    library/socket/tcpserver/accept_spec.rb       0   0   +0  KILLED on timeout, the treatment
    library/socket/unixserver/accept_spec.rb      0   0   +0  KILLED on timeout, the treatment
    

    Three things worth separating:

    The socket rows cost 0 examples and are still a defect. MRI passes nothing in those eight files either (they are guarded), so they do not widen the parity gap — but rbgo hangs where MRI returns, and tcpserver/accept, unixserver/accept, basicsocket/recv, socket/recvfrom, tcp_server_loop, udp_server_loop are exactly the accept/read path. That is the same path #895 reports hanging from the Go side, now with eight ruby/spec files naming it.

    One file hangs on BOTH engines — library/net-http/http/start_spec.rb, KILLED on timeout, both engines. That one is the spec wanting a network, not an rbgo defect, and it is listed here so it is not counted as one.

    I had dismissed the socket rows. Earlier in this measurement I wrote that the eight library/socket rows were "0 for MRI too, so not parity gaps" — true about the count, and wrong about the cause: they were being reported as DID NOT RUN on the treatment (absent) when they are hangs. That misreading is exactly what #915 fixed, and it is why the correction is written here rather than left out.

    So of the 152 files the rollup counted as producing no result on rbgo, 75 are hangs and the rest are genuine absences (Coverage 53 examples, StringScanner#scan_integer/#scan_byte/#peek_byte 27, four CGI escape files 19, WeakRef 9, two BigDecimal files 8, and a handful of singles).

    Same corpus and engine as the issue above: c604cce1ba0b, darwin/arm64, SPEC_SHA=87b1631992bd00cf0c4934474766d54dad088191, control MRI 4.0.7.

    🤖 Generated with Claude Code

  2. changed the title [-]Net::FTP: 39 of 56 spec files hang — 442 examples MRI passes, and the harness was calling it unimplemented[/-] [+]Network specs hang: 75 ruby/spec files killed by the clock on rbgo and not on MRI (Net::FTP 39, Net::HTTP 27, Socket 8, Timeout 1)[/+] on Nov 10, 2026
  3. tannevaled commented on Nov 10, 2026

    @tannevaled
    ContributorAuthor

    Located: a blocking socket read with no deadline, in Go

    Ran library/net-ftp/login_spec.rb under rbgo and sent the process SIGQUIT after 15 s, so the Go runtime printed every goroutine's stack. The main goroutine is in [IO wait]:

    goroutine 1 gp=0x178e3a5e21e0 m=nil [IO wait]:
    internal/poll.(*pollDesc).waitRead(...)
    internal/poll.(*FD).Read(...)
    net.(*netFD).Read(...)
    net.(*conn).Read(...)
    bufio.(*Reader).fill(...)
    bufio.(*Reader).ReadString(...)
    …/internal/vm.(*ftpObj).reader.func1()          net_ftp_bind.go:123
    github.com/go-ruby-net-ftp/net-ftp.GetMultiline(…)   reply.go:71
    …/internal/vm.(*ftpObj).getResp(…)               net_ftp_bind.go:147
    …/internal/vm.(*VM).ftpConnect(…)                net_ftp.go:186
    …/internal/vm.(*VM).registerFTPMethods.func3(…)  net_ftp.go:240
    

    It is waiting for the server's greeting line and will wait for ever.

    ⛔ This rules out the fix I was about to build

    #803 (Timeout.timeout never times out) looked like the root cause, and a deadline checked in the bytecode loop would have been the natural repair. It would not have touched this. The process is not executing Ruby instructions — it is parked in a Go read(2), where no interpreter-level check ever runs. Two plausible causes, and the stack says which.

    The actual defect

    $ grep -n "read_timeout\|open_timeout\|SetDeadline\|Dial" internal/vm/net_ftp.go internal/vm/net_ftp_bind.go
    internal/vm/net_ftp.go:178       conn, err := net.Dial("tcp", net.JoinHostPort(host, strconv.Itoa(port)))
    internal/vm/net_ftp_bind.go:277  conn, err := net.Dial("tcp", net.JoinHostPort(host, strconv.Itoa(port)))
    

    net.Dial with no timeout, and no SetReadDeadline anywhere in the binding. MRI's Net::FTP carries open_timeout and read_timeout and bounds both; rbgo's carries neither, so a server that accepts the connection and then says nothing holds the interpreter for ever.

    That is also why this is a security defect and not only a conformance one: an unbounded read on a socket the peer controls is a denial of service that needs no exploit, just silence.

    Shape of the repair

    1. net.DialTimeout driven by open_timeout (MRI's default is 60 s), raising Net::OpenTimeout.
    2. SetReadDeadline before each read, driven by read_timeout, raising Net::ReadTimeout.
    3. open_timeout/read_timeout and their writers exposed on the Ruby object, as MRI has them.

    Probe used: a 60-line Go program that starts the engine, waits, sends SIGQUIT and prints the dump — the goroutine stack is what turns "it hangs" into a file and a line.

    🤖 Generated with Claude Code

  4. tannevaled commented on Nov 11, 2026

    @tannevaled
    ContributorAuthor

    Root cause: a Ruby Thread makes no progress in a native blocking call while another thread is in one

    Reduced to 25 lines, with no FTP, no mspec and no fixture. A TCPServer#accept in one thread and a client in the main thread:

    srv = TCPServer.new("127.0.0.1", 0)
    t = Thread.new do
      mark "THREAD: started"
      sock = srv.accept
      mark "THREAD: accept RETURNED"
      sock.write("220 mini ready\r\n")
    end
    sleep 0.3
    mark "MAIN: thread status=#{t.status.inspect}"
    Net::FTP.new("127.0.0.1", port: srv.addr[1], read_timeout: 2)   # or 5
     0.002s THREAD: started
     0.304s MAIN: thread status="sleep"          ← parked in accept
     2.307s MAIN: connect failed Net::ReadTimeout
     2.308s THREAD: accept RETURNED              ← 1 ms after the client gave up
    

    accept is not stuck. It is blocked until the main thread leaves its native read.

    The control that makes it a mechanism rather than a coincidence

    Change only the client's read_timeout and the accept moves with it:

    client read_timeout client fails at accept returns at
    2 s 2.307 s 2.308 s
    5 s 5.307 s 5.307 s

    The server thread is ready the whole time — the TCP handshake completes on the listen backlog, which is why the client proceeds to wait for a greeting at all. accept simply cannot complete while another Ruby thread sits inside a blocking Go call.

    Why this is the whole of #916

    Every library/net-ftp spec stands up NetFTPSpecs::DummyFTP in the same process and then connects to it. Client and server are two Ruby threads in one VM, so:

    • without a read deadline (rbgo before Net::FTP: bound the connect and every read, as MRI does #921) the main thread never leaves its native read, accept never returns, and the process deadlocks — 39 of 56 files killed by the clock, and none under MRI;
    • with a read deadline, every exchange costs one full timeout before the server can answer, which is why the specs still fail rather than pass.

    So #921 (bounding the read) was necessary to make this observable, and is not the repair. The repair is here.

    What it is not

    • Not SO_OOBINLINE (#922): adding that constant left the sweep byte-identical, because the fixture's thread never reaches the line that reads it. I announced it as the cause and the measurement refuted it.
    • Not Net::FTP#connect versus the constructor, and not an ivar read inside the thread block: both were bisected out (variants B and D), each failing identically.
    • Not a scheduling fairness question. The thread runs — THREAD: started prints immediately. It is specifically the native blocking call that does not overlap.

    Scope beyond FTP

    Any Ruby program that serves itself in one process is affected: a spec fixture that stands up a server, a test that binds a socket and connects to it, an embedder running a listener beside its own client. library/socket's eight accept/recv files were also killed by the clock in the same sweep, which fits.

    Measured on darwin/arm64, engine built from ftp-bound-reads + socket-so-oobinline, corpus SPEC_SHA=87b1631992bd00cf0c4934474766d54dad088191.

    🤖 Generated with Claude Code

  5. tannevaled commented on Nov 13, 2026

    @tannevaled
    ContributorAuthor

    A second cause, in the harness path: Net::FTP.default_passive does not exist

    The GVL fix (#924) is necessary and proved on a minimal reproduction, and it did
    not move these specs. Looking for what else is in the path turned up a
    concrete, mechanism-level gap that is not about threads at all.

    library/net-ftp/spec_helper.rb, which every one of the 56 files requires,
    opens with:

    if defined?(Net::FTP.default_passive)
      Net::FTP.default_passive = false
    end

    rbgo has no Net::FTP.default_passive, so the guard is skipped in silence
    and the whole suite runs against a connection rbgo keeps in passive mode.
    Checked two independent ways:

    $ grep -rn default_passive internal/vm/      # exit 1, nothing
    $ rbgo -e 'require "net/ftp"
               p defined?(Net::FTP.default_passive)
               p Net::FTP.new.passive'
    nil
    true
    

    MRI, with the helper applied, gives false there. The fixture server
    (library/net-ftp/fixtures/server.rb) implements port and eprt and has no
    pasv method at all
    — it is written for active mode only. So rbgo sends
    PASV, the server's handle_request falls through to self.send(:pasv), and
    the rescue turns it into a reply the client then reports:

    451 Exception: undefined method 'pasv' for an instance of NetFTPSpecs::DummyFTP
    

    library/net-ftp/initialize_spec.rb asserts the same contract directly:
    passive is nil on an allocated instance and false after initialize,
    with passive: true / passive: false in the options Hash overriding it.

    ⛔ What this does NOT establish

    That it explains the 39 files killed by the clock. It explains failures. Of
    the two files run so far under the current build, both complete rather than
    hang — acct_spec.rb (6 fail / 2 error, all undefined method 'acct') and
    getbinaryfile_spec.rb (3 pass / 7 fail / 11 error, carrying the pasv line
    above). No hanging file has been isolated yet, and the timing work that would
    classify them is deferred: this machine is carrying a 1-minute load average
    between 23 and 86, and a per-file timeout measured under that cannot tell a hang
    from a slow file.

    ⛔ Fixing this FIRST would probably make the measurement worse

    Implementing default_passive moves these specs into active mode, and in
    active mode the client opens the listening socket and the server connects to it
    — which in rbgo is internal/vm/net_ftp_bind.go:409 and :419, an Accept and
    a Dial that still hold the GVL. They are entries 1 and 2 of the backlog
    #924 seeds. That is the exact shape #916 is about: one process, two threads,
    the server returning from Accept and then parking on a lock the client holds.

    So the order matters, and it is the opposite of the obvious one:

    1. release the GVL on the data connection (:409, :419, :485, :504),
    2. then add Net::FTP.default_passive / default_passive= and make
      new.passive honour it,
    3. then re-measure, on a quiet machine.

    Doing 2 before 1 would turn today's fast errors into fresh hangs and read as a
    regression.

  6. tannevaled commented on Nov 13, 2026

    @tannevaled
    ContributorAuthor

    Reopened — GitHub closed this on a sentence that said the opposite

    #924 merged and GitHub closed this issue automatically. It should not have: the
    pull request body said, under a heading reading "Two limits I am not going to
    bury"
    :

    1. This does not fix #916. The library/net-ftp specs are byte-identical
    after the change: still 39 killed by the clock, still 459/17, still −442.

    The closing-keyword parser reads fix #916 and does not read the does not in
    front of it. A sentence written specifically to prevent a false impression
    produced the strongest possible false impression: a closed issue.

    Nothing has changed about the state of this issue. The GVL release is
    necessary and proved on a minimal reproduction (accept 5.307 s → 0.305 s), and
    the specs did not move. The next steps are the ones in the comment above:
    release the GVL on the Net::FTP data connection (internal/vm/net_ftp_bind.go
    lines 409, 419, 485, 504 — now the seeded backlog of the gate #924 added), then
    add Net::FTP.default_passive, then re-measure on an unloaded machine.

    ⛔ Note for future bodies in this repository: to mention an issue without
    closing it, there is no safe way to put a closing keyword next to its number —
    not negated, not quoted, not inside a heading. Write "this does not close
    #916" with the number escaped, or simply say "the measurement did not move"
    and reference the issue once, with Refs.

  7. tannevaled commented on Nov 13, 2026

    @tannevaled
    ContributorAuthor

    Measured: +75 examples, all of it default_passive, none of it the GVL

    An A/B over all 56 library/net-ftp files, same corpus, same harness, 30 s per
    file, both binaries provenance-checked by specdelta (it refuses to attribute a
    run to a binary whose work tree has moved):

    engine passing delta
    main (209fa06) 256 —
    + the data-connection GVL release (deaafc8) 256 +0
    + Net::FTP.default_passive (f90469a) 331 +75

    9 files moved. No example went from passing to failing.

    ⛔ The GVL work contributed nothing measurable here

    That is the honest reading of row 2, and it is a result about my own change.
    Releasing the GVL on the data connection is still right — it is the mechanism
    behind the deadlock, proved by dose-response on a minimal reproduction — but in
    this sweep it moves no example at all. Everything measured here is the
    default_passive accessor, plus the related fix in the same commit (ftpInit
    returned before reading the options Hash when the host was nil, so
    Net::FTP.new(nil, passive: true) dropped every option).

    ⛔ And this sweep does not reproduce the 39 kills — on EITHER engine

    specdelta prints KILLED on timeout for a file the clock stopped. There is
    not one such row in any of these runs, including the control.
    So this says
    nothing about whether the hangs are fixed: a sweep where the control does not
    hang cannot show a fix for hanging. The 39-kill figure came from a different
    sweep configuration — notably parallel JOBS, which is where the contention
    that produces the deadlock actually arises. Reproducing it needs that
    configuration, not this one.

    The two "WENT RED" rows are not a loss

    They are one shared example counted in two files
    (put_spec.rb, putbinaryfile_spec.rb), and the labels move error → fail:

    • before: Net::FTPTempError: 451 Exception: undefined method 'pasv' — it died
      at PASV before any transfer happened;
    • after: expected [] to == ["This is an", " example f", …].

    It now reaches the transfer and exposes a real gap:
    putbinaryfile / put with a block does not yield the transmitted blocks.
    That is worth its own issue; it was simply unreachable before.

    ⚠ The MRI oracle on this machine is not usable yet

    A first attempt used MRI 4.0.6 (net-ftp 0.3.9) as the control. It scored 0
    passing on all 56 files
    — an instrument that says nothing, not a result, so
    none of its deltas are quoted here. The likely cause is that the corpus's
    spec_helper.rb has been overwritten by the rbgo shim. Worth fixing separately:
    a working MRI oracle at the corpus's own version would settle questions that
    rbgo-vs-rbgo cannot.

  8. tannevaled commented on Nov 13, 2026

    @tannevaled
    ContributorAuthor

    ⛔ Correction: the GVL release is what fixed this module, and my earlier comment said the opposite

    Earlier today I wrote here that "the GVL work contributed nothing measurable".
    That was wrong, and wrong for a reason worth naming: my control already
    contained the treatment.
    I compared main against my branch, and main had
    already merged #924. A control that carries the change cannot show its effect.

    With a binary built at 84aee38 — #921 merged, #924 not yet — the dated
    sweep reproduces exactly:

    56 file(s): control 459 passing, treatment 17 passing, -442
    39 × KILLED on timeout, the treatment
    

    459 / 17 / −442 / 39 killed: the same four numbers this repository's README
    records. So the oracle and the harness agree with a measurement taken
    independently, and the comparison below is trustworthy.

    The attribution, one change at a time

    All against MRI 4.0.6 (net-ftp 0.3.9), same corpus, 30 s per file:

    engine passing files killed by the clock
    #921 alone (84aee38) 17 39
    + #924, the GVL release on the control connection 256 0
    + #927, the GVL release on the data connection 256 0
    + #928, default_passive and the nil-host options 331 0
    MRI 4.0.6 459 0

    #924 removed all 39 hangs and took the module from 17 to 256 passing: +239.
    That is the single largest movement in this issue, and it is exactly what the
    dose-response reproduction predicted (accept 2 s → 2.308 s, 5 s → 5.307 s,
    ioBlock → 0.305 s).

    What my earlier comment measured correctly was the data connection (#927),
    which really does add 0 here — the spec fixtures exercise the control
    connection. It was the headline that was wrong.

    Where the remaining kills are, with a working control

    Sweeping the other three modules this issue names, MRI against rbgo:

    module this issue recorded measured today
    library/net-http/http/ 27 27
    library/socket/ 8 8
    library/timeout/ 1 1
    library/net-ftp/ 39 0

    36 files killed under rbgo, 0 under MRI, 1 under both. The three remaining
    modules reproduce to the file, so the symptom is intact and precisely located —
    and the names say what it is: tcpserver/accept_spec, unixserver/accept_spec,
    tcp_server_loop_spec, udp_server_loop_spec, recv/send/recvfrom, plus all
    27 of net-http/http/. Every one is the "a program that serves itself" shape.

    The gate added in #924 already names the next candidates in its seeded backlog:
    net_imap_bind.go ×2, net_smtp_bind.go, httprb.go, hanami_bind.go — all
    still holding the GVL across a blocking call.

    Note on the oracle

    None of this was measurable until the reference interpreter was repaired: the
    MRI on this machine starts without RubyGems on its load path, so net/ftp and
    friends raise LoadError and every file scores a clean 0 — which a sweep
    reports as a result. #930 adds cmd/mriref and the check that it is working is
    the 459 above.

  9. tannevaled commented on Nov 13, 2026

    @tannevaled
    ContributorAuthor

    75 hangs → 9, and the two halves had nothing to do with each other

    module this issue recorded now by what
    library/net-ftp 39 0 #924 — the GVL release on the control connection
    library/net-http 27 0 #932 — open with a block must close
    library/socket 8 8 —
    library/timeout 1 1 —

    That is the thing worth taking away from this issue: one symptom, two
    unrelated causes.
    Half the files hung because a blocking socket call held the
    emulated GVL, and the other half because TCPSocket.open { … } never closed the
    socket, so a peer waited for an EOF that never came. Neither fix touches the
    other's files — which is exactly why #924 looked like it "did nothing" when I
    first measured it against the HTTP specs.

    The net-http half, in one line

    library/net-http/http/fixtures/http_server.rb serves one client at a time and
    shuts down by writing an unterminated "CLOSE" inside
    TCPSocket.open(ip, port) { … }, then joining the server thread. With the
    socket left open the server's gets never returns, the accept loop never comes
    back round, and the join never completes. All 27 files end there.

    ⛔ It is not the GVL, which is what I went looking for. A goroutine dump of
    a hung get_spec.rb puts the server thread correctly inside ioBlock with
    the GVL released, and the main thread in threadJoin.

    Measured

    library/net-http + library/socket + library/timeout, 321 files, MRI 4.0.6
    as the control, 30 s per file:

    killed under rbgo passing
    before #932 36 243
    after 9 274

    And a detail no single-engine sweep could have shown:
    net-http/http/start_spec.rb is now killed on the control — MRI hangs on
    it and rbgo passes 12. Without a working oracle I would have counted that file
    as an rbgo failure.

    What is left

    Nine files, all one shape: library/socket's accept / recv / send /
    recvfrom / tcp_server_loop / udp_server_loop / connect_nonblock, plus
    library/timeout. That is the family #924's gate already watches, and its
    seeded backlog still names net_imap_bind.go ×2, net_smtp_bind.go,
    httprb.go and hanami_bind.go as holding the GVL across a blocking call.

    None of this was measurable until the reference interpreter was repaired
    (#930): it had been scoring a clean 0 on every file, which a sweep reports as a
    result.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions