search

zwilias / elm-json

Install, upgrade and uninstall Elm dependencies
MIT License
183 stars 9 forks source link

`elm-json install --yes ...` sporadically gets stuck on macOS 11 and 10.15 #50

Open cho-m opened 1 year ago

cho-m commented 1 year ago

In Homebrew, we have seen commands like elm-json install elm/browser@1 --yes sporadically get stuck on macOS 11 (Big Sur) and 10.15 (Catalina). Haven't tried older macOS. So far, we haven't seen it fail on macOS 12 (Monterey) or 13 (Ventura)

Originally this issue was seen while building unisonlang (https://github.com/Homebrew/homebrew-core/pull/105842) which runs elm-json (https://github.com/unisonweb/unison-local-ui/blob/release/M4e/scripts/ui-core.js#L6). At that time, I was able to find the problematic command was elm-json but it stalled without any meaningful output.

I have tried debugging further in https://github.com/Homebrew/homebrew-core/pull/117735 and was able to reproduce issue with TRACE logging (https://github.com/Homebrew/homebrew-core/actions/runs/3656429004/jobs/6190012945#step:6:5028)

Logs for elm-json -v -v -v install --yes elm/browser@1 ``` 2022-12-10T00:05:01.927259Z DEBUG elm_json::package::retriever: Fetching versions since 0 2022-12-10T00:05:01.928234Z DEBUG agent_thread{id=0}: isahc::agent: agent took 578.5µs to start up 2022-12-10T00:05:01.928746Z TRACE agent_thread{id=0}:poll_messages:handle_message{Execute(Easy { handle: 0x15c00d600, handler: RequestHandler })}: isahc::agent: received message from agent handle 2022-12-10T00:05:02.059321Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=false writable=true 2022-12-10T00:05:02.090323Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.142090Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.192596Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.193501Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8095 bytes of data 2022-12-10T00:05:02.193731Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8136 bytes of data 2022-12-10T00:05:02.193884Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.212297Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.251924Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.252292Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 56 bytes of data 2022-12-10T00:05:02.252418Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4096 bytes of data 2022-12-10T00:05:02.252491Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8192 bytes of data 2022-12-10T00:05:02.252588Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4016 bytes of data 2022-12-10T00:05:02.252706Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:02.252975Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4176 bytes of data 2022-12-10T00:05:02.253048Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8192 bytes of data 2022-12-10T00:05:02.256888Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:02.256976Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12192 bytes of data 2022-12-10T00:05:03.267341Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:03.267712Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4192 bytes of data 2022-12-10T00:05:03.267822Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8192 bytes of data 2022-12-10T00:05:03.267900Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 3984 bytes of data 2022-12-10T00:05:03.268203Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4208 bytes of data 2022-12-10T00:05:03.268274Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 8192 bytes of data 2022-12-10T00:05:03.273271Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:03.273376Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12160 bytes of data 2022-12-10T00:05:04.283848Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:04.284273Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4224 bytes of data 2022-12-10T00:05:04.284389Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12152 bytes of data 2022-12-10T00:05:04.284705Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:04.284816Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:04.285081Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4232 bytes of data 2022-12-10T00:05:04.285153Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12144 bytes of data 2022-12-10T00:05:04.288938Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:04.289009Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12144 bytes of data 2022-12-10T00:05:05.294020Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:05.294442Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:05.294799Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4240 bytes of data 2022-12-10T00:05:05.294875Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12136 bytes of data 2022-12-10T00:05:05.294983Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:05.295258Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:05.295358Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:05.295650Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4248 bytes of data 2022-12-10T00:05:05.311961Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:05.312053Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16375 bytes of data 2022-12-10T00:05:06.322475Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:06.322906Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:06.323259Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:06.323374Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:06.323654Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:06.323752Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:06.324025Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4257 bytes of data 2022-12-10T00:05:06.324102Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12118 bytes of data 2022-12-10T00:05:06.340603Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:06.340700Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12118 bytes of data 2022-12-10T00:05:07.351131Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:07.351550Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:07.351899Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:07.352003Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:07.352275Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:07.352379Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:07.352650Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4266 bytes of data 2022-12-10T00:05:07.352729Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12110 bytes of data 2022-12-10T00:05:07.369231Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:07.369331Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12110 bytes of data 2022-12-10T00:05:08.379818Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:08.380231Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:08.380582Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 4274 bytes of data 2022-12-10T00:05:08.380657Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12102 bytes of data 2022-12-10T00:05:08.380764Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:08.381042Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 12474 bytes of data 2022-12-10T00:05:08.381115Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 3901 bytes of data 2022-12-10T00:05:08.397752Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:08.397836Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 3901 bytes of data 2022-12-10T00:05:09.398642Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:09.399109Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:09.399462Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:09.399577Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:09.399870Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:09.399967Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:09.400240Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 16384 bytes of data 2022-12-10T00:05:09.400340Z TRACE agent_thread{id=0}: isahc::agent: socket event socket=11 readable=true writable=false 2022-12-10T00:05:09.400492Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 6278 bytes of data 2022-12-10T00:05:09.416539Z TRACE agent_thread{id=0}:poll_messages:handle_message{UnpauseWrite(0)}: isahc::agent: received message from agent handle 2022-12-10T00:05:09.416623Z TRACE send{method=GET uri=https://package.elm-lang.org/all-packages/since/0}:handler{id=0}:write: isahc::handler: received 6278 bytes of data ```

After the final line, it appears to be stuck and only stops when I force fail with a timeout. Otherwise, it appears to remain stuck indefinitely. This caused Homebrew CI to block for about 1 day until manually cancelled.

Had tried both pre-built binary fetched via npm and a locally built copy of elm-json.

tsukimizake commented 1 year ago

Seems like isahc is stuck while polling. Probably the same as #54, so I think #55 may fix it too.