rust-payjoin
rust-payjoin copied to clipboard
payjoin
V2 Integration test has unhandled relay error when closing the connection
This error does not affect the test and is simply logged at the final stages of the test. While this does not affect reliability of the test I think it is helpful to document this error.
2025-05-13T17:49:46.254400Z ERROR ohttp_relay::bootstrap::connect: server io error: Transport endpoint is not
connected (os error 107)
if it were just logged as warn I think that would make me less concerned in the place it does crop up in ci logs. Is that an appropriate change tho?
Here is the relevant debug log. It seems like while the connection is established with the relay it seems to not pool the idle connection the first time and this is the only difference between the error and expected behavior I can see.
2025-05-14T17:01:00.336260Z DEBUG hyper_util::client::legacy::connect::http: connecting to [::1]:35331
2025-05-14T17:01:00.336384Z DEBUG hyper_util::client::legacy::connect::http: connected to [::1]:35331
2025-05-14T17:01:00.339229Z DEBUG payjoin_directory: serve_payjoin_directory: ["", "health"]
2025-05-14T17:01:00.339415Z DEBUG hyper_util::client::legacy::pool: pooling idle connection for ("https", loc
alhost:35331)
2025-05-14T17:01:00.350320Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="localhost"
2025-05-14T17:01:00.350698Z DEBUG hyper_util::client::legacy::connect::http: connecting to [::1]:33893
2025-05-14T17:01:00.350833Z DEBUG hyper_util::client::legacy::connect::http: connected to [::1]:33893
2025-05-14T17:01:00.353385Z DEBUG payjoin_directory: serve_payjoin_directory: ["", ".well-known", "ohttp-gate
way"]
2025-05-14T17:01:00.394068Z DEBUG hyper_util::client::legacy::pool: pooling idle connection for ("https", loc
alhost:35331)
...
2025-05-14T17:01:00.417463Z DEBUG hyper_util::client::legacy::pool: reuse idle connection for ("http", localh
ost:33893)
2025-05-14T17:01:00.418881Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="localhost"
2025-05-14T17:01:00.419168Z ERROR ohttp_relay::bootstrap::connect: server io error: Transport endpoint is not
connected (os error 107)
2025-05-14T17:01:00.419526Z DEBUG serve_ohttp_relay{req=Request { method: POST, uri: /https://localhost:35331
/, version: HTTP/1.1, headers: {"content-type": "message/ohttp-req", "accept": "*/*", "host": "localhost:3389
3", "content-length": "8192"}, body: Body(Streaming) } config=RelayConfig { default_gateway: GatewayUri { sch
eme: "https", authority: localhost:35331 }, client: HttpClient(Client), prober: Prober { gateways: RwLock { d
ata: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https", authority: localhost:35331 }: Kno
wn(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 } })}, by_expiry: [
HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, key: GatewayUri { scheme: "https", au
thority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800s, http_2xx: 604800s, http_4xx: 6048
00s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer: 0ns, timedout: 0ns, default: 5s },
client: HttpClient(Client) } }}:handle_ohttp_relay{req=Request { method: POST, uri: /https://localhost:35331
/, version: HTTP/1.1, headers: {"content-type": "message/ohttp-req", "accept": "*/*", "host": "localhost:3389
3", "content-length": "8192"}, body: Body(Streaming) } config=RelayConfig { default_gateway: GatewayUri { sch
eme: "https", authority: localhost:35331 }, client: HttpClient(Client), prober: Prober { gateways: RwLock { d
ata: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https", authority: localhost:35331 }: Kno
wn(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 } })}, by_expiry: [
HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, key: GatewayUri { scheme: "https", au
thority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800s, http_2xx: 604800s, http_4xx: 6048
00s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer: 0ns, timedout: 0ns, default: 5s },
client: HttpClient(Client) } } gateway=GatewayUri { scheme: "https", authority: localhost:35331 }}:forward_r
equest{req=Request { method: POST, uri: https://localhost:35331/.well-known/ohttp-gateway, version: HTTP/1.1,
headers: {"content-type": "message/ohttp-req", "content-length": "8192"}, body: BoxBody } config=RelayConfig
{ default_gateway: GatewayUri { scheme: "https", authority: localhost:35331 }, client: HttpClient(Client), p
rober: Prober { gateways: RwLock { data: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https
", authority: localhost:35331 }: Known(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv
_nsec: 171152227 } })}, by_expiry: [HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, k
ey: GatewayUri { scheme: "https", authority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800
s, http_2xx: 604800s, http_4xx: 604800s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer
: 0ns, timedout: 0ns, default: 5s }, client: HttpClient(Client) } }}: hyper_util::client::legacy::connect::ht
tp: connecting to [::1]:35331
And here is another set of logs later on with the expected behavior after I assume the connection has been setup.
Note that there is no endpoint not connected error here.
2025-05-14T17:01:00.426577Z DEBUG payjoin_directory::db: Failed to fetch content initially
2025-05-14T17:01:02.429553Z DEBUG hyper_util::client::legacy::pool: pooling idle connection for ("https", loc
alhost:35331)
2025-05-14T17:01:02.429748Z DEBUG hyper_util::client::legacy::pool: pooling idle connection for ("http", loca
lhost:33893)
2025-05-14T17:01:02.461782Z DEBUG hyper_util::client::legacy::pool: reuse idle connection for ("http", localh
ost:33893)
2025-05-14T17:01:02.462201Z DEBUG serve_ohttp_relay{req=Request { method: POST, uri: /https://localhost:35331
/, version: HTTP/1.1, headers: {"content-type": "message/ohttp-req", "accept": "*/*", "host": "localhost:3389
3", "content-length": "8192"}, body: Body(Streaming) } config=RelayConfig { default_gateway: GatewayUri { sch
eme: "https", authority: localhost:35331 }, client: HttpClient(Client), prober: Prober { gateways: RwLock { d
ata: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https", authority: localhost:35331 }: Kno
wn(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 } })}, by_expiry: [
HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, key: GatewayUri { scheme: "https", au
thority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800s, http_2xx: 604800s, http_4xx: 6048
00s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer: 0ns, timedout: 0ns, default: 5s },
client: HttpClient(Client) } }}:handle_ohttp_relay{req=Request { method: POST, uri: /https://localhost:35331
/, version: HTTP/1.1, headers: {"content-type": "message/ohttp-req", "accept": "*/*", "host": "localhost:3389
3", "content-length": "8192"}, body: Body(Streaming) } config=RelayConfig { default_gateway: GatewayUri { sch
eme: "https", authority: localhost:35331 }, client: HttpClient(Client), prober: Prober { gateways: RwLock { d
ata: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https", authority: localhost:35331 }: Kno
wn(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 } })}, by_expiry: [
HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, key: GatewayUri { scheme: "https", au
thority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800s, http_2xx: 604800s, http_4xx: 6048
00s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer: 0ns, timedout: 0ns, default: 5s },
client: HttpClient(Client) } } gateway=GatewayUri { scheme: "https", authority: localhost:35331 }}:forward_r
equest{req=Request { method: POST, uri: https://localhost:35331/.well-known/ohttp-gateway, version: HTTP/1.1,
headers: {"content-type": "message/ohttp-req", "content-length": "8192"}, body: BoxBody } config=RelayConfig
{ default_gateway: GatewayUri { scheme: "https", authority: localhost:35331 }, client: HttpClient(Client), p
rober: Prober { gateways: RwLock { data: KnownGateways { capacity: 1000, by_url: {GatewayUri { scheme: "https
", authority: localhost:35331 }: Known(Policy { bip77_allowed: true, expires: Instant { tv_sec: 946338945, tv
_nsec: 171152227 } })}, by_expiry: [HeapEntry { expires: Instant { tv_sec: 946338945, tv_nsec: 171152227 }, k
ey: GatewayUri { scheme: "https", authority: localhost:35331 } }] } }, ttl_config: TTLConfig { opt_in: 604800
s, http_2xx: 604800s, http_4xx: 604800s, http_504_gateway_timeout: 0ns, http_5xx: 5s, dns: 0ns, reset_by_peer
: 0ns, timedout: 0ns, default: 5s }, client: HttpClient(Client) } }}: hyper_util::client::legacy::pool: reuse
idle connection for ("https", localhost:35331)
2025-05-14T17:01:02.462781Z DEBUG payjoin_directory: serve_payjoin_directory: ["", ".well-known", "ohttp-gate
way"]
2025-05-14T17:01:02.464685Z DEBUG payjoin_directory: handle_v2: ["", "WKTSS9ED8LD5G"]
Is that an appropriate change tho?
I'm actually not sure what place in our code we could change the log status for this, I think it is occurring in the reqwest::Client code IIUC