The daemon times out fetching some feeds that answer at once from anywhere else #112

New Issue

rays · 2026-10-02T12:36:32-07:00

rays commented

2026-10-02 12:36:32 -07:00

Since the 30 s feed timeout (#108) went out on 2026-10-02, matthew-garrett (https://mjg59.dreamwidth.org/data/rss) times out on every try in the daemon: feed_error error_type=timeout at 13:48, 16:56, 17:57, 18:59 UTC, each fetch span exactly 30.0 s (trace 4d7448382e236cee5598e921f8bfbad7). In the first scan after the deploy it took 18.6 s and succeeded (d56e4df581f512bbc0115026e484ba54); pluralistic.net took the full 30 s in that scan and 0.4 s in a later one.

The same requests are fast everywhere else, tried at 19:30:

curl from Tower: 0.3 s (pluralistic 1.2 s), any of plain, compressed, HTTP/1.1, HTTP/2.
wget from a container on content_default, ipx's network: fine.
ipx's own client in a fresh process inside the iPX container (ipx --local add, throwaway SQLite): 1-2 s, three times.
curl replaying the daemon's conditional request (If-Modified-Since: Mon, 06 Jul 2026 09:03:04 GMT, no ETag): 304 in 0.14 s.

So it is the long-running daemon, not the site, the network or the request. Before the timeout the same feed took 60-67 s and ended in 504s (#108), so it was this all along rather than Dreamwidth being down. Unconfirmed guess: a pooled connection (reqwest keeps them, HTTP/2 multiplexed) that has gone stale to some hosts; the prefetch tasks (#104) share the one client. Next step: log or trace connection reuse for the fetch, or try pool_idle_timeout / http1-only for feed fetches and watch whether the timeouts stop.

Query: {container="iPX"} |= ""ev":"feed_error"" | json | error_type="timeout"

Since the 30 s feed timeout (#108) went out on 2026-10-02, matthew-garrett (https://mjg59.dreamwidth.org/data/rss) times out on every try in the daemon: feed_error error_type=timeout at 13:48, 16:56, 17:57, 18:59 UTC, each fetch span exactly 30.0 s (trace 4d7448382e236cee5598e921f8bfbad7). In the first scan after the deploy it took 18.6 s and succeeded (d56e4df581f512bbc0115026e484ba54); pluralistic.net took the full 30 s in that scan and 0.4 s in a later one. The same requests are fast everywhere else, tried at 19:30: - curl from Tower: 0.3 s (pluralistic 1.2 s), any of plain, compressed, HTTP/1.1, HTTP/2. - wget from a container on content_default, ipx's network: fine. - ipx's own client in a fresh process inside the iPX container (ipx --local add, throwaway SQLite): 1-2 s, three times. - curl replaying the daemon's conditional request (If-Modified-Since: Mon, 06 Jul 2026 09:03:04 GMT, no ETag): 304 in 0.14 s. So it is the long-running daemon, not the site, the network or the request. Before the timeout the same feed took 60-67 s and ended in 504s (#108), so it was this all along rather than Dreamwidth being down. Unconfirmed guess: a pooled connection (reqwest keeps them, HTTP/2 multiplexed) that has gone stale to some hosts; the prefetch tasks (#104) share the one client. Next step: log or trace connection reuse for the fetch, or try pool_idle_timeout / http1-only for feed fetches and watch whether the timeouts stop. Query: {container="iPX"} |= "\"ev\":\"feed_error\"" | json | error_type="timeout"

rays added the bug label 2026-10-02 12:36:32 -07:00

rays commented

2026-10-04 13:13:08 -07:00

From the production check on 2026-10-04: no feed has timed out since 2026-10-02 21:02 UTC (matthew-garrett, 14 minutes after the 20:47 deploy restarted the daemon). pluralistic's last timeout was 2026-10-02 13:49. That is about 41 hours of daemon uptime without one, less a host-wide log gap from 2026-10-03 20:16 to 2026-10-04 13:40 and a reboot at 14:32. Fits a stale-connection cause that comes and goes rather than a fixed per-host failure; worth keeping open and watching. Query: sum by (feed) (count_over_time({container="iPX"} |= ""ev":"feed_error"" | json | error_type="timeout" [7d]))

From the production check on 2026-10-04: no feed has timed out since 2026-10-02 21:02 UTC (matthew-garrett, 14 minutes after the 20:47 deploy restarted the daemon). pluralistic's last timeout was 2026-10-02 13:49. That is about 41 hours of daemon uptime without one, less a host-wide log gap from 2026-10-03 20:16 to 2026-10-04 13:40 and a reboot at 14:32. Fits a stale-connection cause that comes and goes rather than a fixed per-host failure; worth keeping open and watching. Query: sum by (feed) (count_over_time({container="iPX"} |= "\"ev\":\"feed_error\"" | json | error_type="timeout" [7d]))

rays commented

2026-10-04 13:14:49 -07:00

Looked into it again on 2026-10-04. I think this is Dreamwidth, not the daemon, and nothing in ipx needs changing.

The stale-pooled-connection guess cannot hold. reqwest drops a connection after 90 s idle (pool_idle_timeout, the default, reqwest 0.13.5 async_impl/client.rs:302), and these feeds are fetched about once an hour, so every fetch opens a new connection. Nothing is old enough to go stale.
A fresh daemon failed the same way. The 21:02 timeout on 2026-10-02 (trace 94d9346e21230e81771bfbdf72ce4233) came 15 minutes after the 20:47 deploy, which also built a new feed client (#115).
Dreamwidth's own front end answers 504 Gateway Timeout. Before #108 the slow fetches ended in 504s after 60-67 s, and the last failure, 2026-10-03 01:09 (trace abdf7138c48a79759739efc89040b76b), was a 504 after 10.2 s. A 504 means the request reached Dreamwidth and its gateway gave up waiting on its own backend.
The fast tries from curl and fresh processes were all at 19:30 on 2026-10-02; nothing was tried from outside while a daemon fetch was failing. So it looks like Dreamwidth's backend being slow on and off, not something only the daemon sees.

From 2026-09-29 to 2026-10-02 there were 31 mjg59 fetches over 3 s. Since then there has been one (the 504 above), and pluralistic.net has not timed out since 2026-10-02 13:49. The 30 s timeout (#108) and the backoff for failing feeds (#99) already keep this from holding up a scan.

Closing. Reopen if a feed keeps timing out in the daemon while curl from Tower gets it quickly at the same moment.

Query: {resource.deployment.environment.name="production"} >> {name="fetch" && span.url="https://mjg59.dreamwidth.org/data/rss" && duration > 3s}

Looked into it again on 2026-10-04. I think this is Dreamwidth, not the daemon, and nothing in ipx needs changing. - The stale-pooled-connection guess cannot hold. reqwest drops a connection after 90 s idle (pool_idle_timeout, the default, reqwest 0.13.5 async_impl/client.rs:302), and these feeds are fetched about once an hour, so every fetch opens a new connection. Nothing is old enough to go stale. - A fresh daemon failed the same way. The 21:02 timeout on 2026-10-02 (trace 94d9346e21230e81771bfbdf72ce4233) came 15 minutes after the 20:47 deploy, which also built a new feed client (#115). - Dreamwidth's own front end answers 504 Gateway Timeout. Before #108 the slow fetches ended in 504s after 60-67 s, and the last failure, 2026-10-03 01:09 (trace abdf7138c48a79759739efc89040b76b), was a 504 after 10.2 s. A 504 means the request reached Dreamwidth and its gateway gave up waiting on its own backend. - The fast tries from curl and fresh processes were all at 19:30 on 2026-10-02; nothing was tried from outside while a daemon fetch was failing. So it looks like Dreamwidth's backend being slow on and off, not something only the daemon sees. From 2026-09-29 to 2026-10-02 there were 31 mjg59 fetches over 3 s. Since then there has been one (the 504 above), and pluralistic.net has not timed out since 2026-10-02 13:49. The 30 s timeout (#108) and the backoff for failing feeds (#99) already keep this from holding up a scan. Closing. Reopen if a feed keeps timing out in the daemon while curl from Tower gets it quickly at the same moment. Query: {resource.deployment.environment.name="production"} >> {name="fetch" && span.url="https://mjg59.dreamwidth.org/data/rss" && duration > 3s}

rays closed this issue

2026-10-04 13:14:49 -07:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: rays/ipx#112