doesn't work over single SSH reverse-forward port

[steveej]

what i did

1. locally, run rperf -s -d

2. connect to a remote via SSH while setting up a reverse-port forwarding to rperf's default port:

   ssh $REMOTE -R 127.0.0.1:5199:127.0.0.1:5199
   

3. on the remote, run rperf -c 127.0.0.1

4. observe it fail (see all the logs)

---

client log

$ rperf -c 127.0.0.1 -d
[2024-04-05T10:15:34Z DEBUG rperf] registering SIGINT handler...
[2024-04-05T10:15:34Z DEBUG rperf] connecting to server...
[2024-04-05T10:15:34Z DEBUG rperf::stream::tcp::receiver] using OS assignment for IPv4 TCP ports
[2024-04-05T10:15:34Z DEBUG rperf::stream::tcp::receiver] using OS assignment for IPv6 TCP ports
[2024-04-05T10:15:34Z DEBUG rperf::stream::udp::receiver] using OS assignment for IPv4 UDP ports
[2024-04-05T10:15:34Z DEBUG rperf::stream::udp::receiver] using OS assignment for IPv6 UDP ports
[2024-04-05T10:15:34Z DEBUG rperf::utils::cpu_affinity] enumerated CPU cores: [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95]
[2024-04-05T10:15:34Z DEBUG rperf::utils::cpu_affinity] not applying CPU core affinity
[2024-04-05T10:15:34Z DEBUG rperf::protocol::messaging] preparing TCP upload config...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::messaging] preparing TCP download config...
[2024-04-05T10:15:34Z INFO  rperf::client] connecting to server at 127.0.0.1:5199...
[2024-04-05T10:15:34Z INFO  rperf::client] connected to server
[2024-04-05T10:15:34Z DEBUG rperf::client] running in forward-mode: server will be receiving data
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] sending message of length 172, Object {"family": String("tcp"), "kind": String("configuration"), "length": Number(32768), "receive_buffer": Number(0), "role": String("download"), "streams": Number(1), "test_id": Array [Number(108), Number(25), Number(198), Number(168), Number(186), Number(122), Number(65), Number(153), Number(144), Number(67), Number(89), Number(88), Number(42), Number(211), Number(201), Number(16)]}, to 127.0.0.1:5199...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] awaiting length-value from 127.0.0.1:5199...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] received length-spec of 41 from 127.0.0.1:5199
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] awaiting payload from 127.0.0.1:5199...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] received Object {"kind": String("connect"), "stream_ports": Array [Number(43503)]} from 127.0.0.1:5199
[2024-04-05T10:15:34Z INFO  rperf::client] preparing for TCP test with 1 streams...
[2024-04-05T10:15:34Z DEBUG rperf::client] preparing TCP-sender for stream 0...
[2024-04-05T10:15:34Z INFO  rperf::client] informing server that testing can begin...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] sending message of length 16, Object {"kind": String("begin")}, to 127.0.0.1:5199...
[2024-04-05T10:15:34Z DEBUG rperf::client] spawning stream-threads
[2024-04-05T10:15:34Z INFO  rperf::client] beginning execution of stream 0...
[2024-04-05T10:15:34Z DEBUG rperf::protocol::communication] awaiting length-value from 127.0.0.1:5199...
[2024-04-05T10:15:34Z DEBUG rperf::utils::cpu_affinity] CPU affinity is not configured; not doing anything
[2024-04-05T10:15:34Z DEBUG rperf::client] beginning test-interval for stream 0
[2024-04-05T10:15:34Z DEBUG rperf::stream::tcp::sender] preparing to connect TCP stream 0...
[2024-04-05T10:15:34Z ERROR rperf::client] unable to process stream: unable to connect stream 0: Connection refused (os error 111)
----------
Failure in client stream | stream: 0
[2024-04-05T10:15:34Z WARN  rperf::client] stream 0 failed
[2024-04-05T10:15:34Z INFO  rperf::client] giving the server a few seconds to report results...
[2024-04-05T10:15:37Z DEBUG rperf::protocol::communication] received length-spec of 50 from 127.0.0.1:5199
[2024-04-05T10:15:37Z DEBUG rperf::protocol::communication] awaiting payload from 127.0.0.1:5199...
[2024-04-05T10:15:37Z DEBUG rperf::protocol::communication] received Object {"kind": String("failed"), "origin": String("server"), "stream_idx": Number(0)} from 127.0.0.1:5199
[2024-04-05T10:15:37Z WARN  rperf::client] server reported failure with stream 0
[2024-04-05T10:15:37Z DEBUG rperf::protocol::communication] sending message of length 14, Object {"kind": String("end")}, to 127.0.0.1:5199...
[2024-04-05T10:15:37Z DEBUG rperf::client] stopping any still-in-progress streams
[2024-04-05T10:15:37Z DEBUG rperf::client] waiting for all streams to end
[2024-04-05T10:15:37Z DEBUG rperf::client] displaying test results
==========
TCP send result over 0.00s | streams: 1
stream-average bytes per second: 0.000 | megabits/second: 0.000
total bytes: 0 | per second: 0.000 | megabits/second: 0.000
==========
TCP receive result over 0.00s | streams: 1
stream-average bytes per second: 0.000 | megabits/second: 0.000
total bytes: 0 | per second: 0.000 | megabits/second: 0.000
TESTING DID NOT COMPLETE SUCCESSFULLY

nmap sees the port as open on the client

$ nix run nixpkgs#nmap -- 127.0.0.1 -p5199
Starting Nmap 7.94 ( https://nmap.org ) at 2024-04-05 10:14 UTC
Nmap scan report for localhost (127.0.0.1)
Host is up (0.00023s latency).

PORT     STATE SERVICE
5199/tcp open  unknown

Nmap done: 1 IP address (1 host up) scanned in 0.03 seconds

server log

[2024-04-05T10:15:34Z INFO  rperf::server] connection from 127.0.0.1:60504
[2024-04-05T10:15:34Z INFO  rperf::server] [127.0.0.1:60504] running in forward-mode: server will be receiving data
[2024-04-05T10:15:34Z INFO  rperf::server] [127.0.0.1:60504] preparing for TCP test with 1 streams...
[2024-04-05T10:15:34Z INFO  rperf::server] [127.0.0.1:60504] beginning execution of stream 0...
[2024-04-05T10:15:37Z ERROR rperf::server] [127.0.0.1:60504] unable to process stream: TCP listening for stream 0 timed out
[2024-04-05T10:15:37Z INFO  rperf::server] [127.0.0.1:60504] end of testing signaled
[2024-04-05T10:15:37Z INFO  rperf::server] 127.0.0.1:60504 disconnected

[flan]

Hey, Stefan.

The conflict here is likely that the implementation of rperf uses separate ports for each connection that carries data.

The forwarded port is sufficient for the control-session, but from your example, the server indicated that the port 43503 was to be used for data.

This can be constrained with the --tcp-port-pool or --udp-port-pool (or IPv6 variant) options, which may be necessary for your use-case.

Per-port forwarding or prioritisation is not an uncommon thing in environments where rperf is used, so using multiple ports (which also removes some process-level latenct) allows us to get a better idea of whether there are potential problems in production contexts.