Elixir: Package {"hexpm", "connection"} not prefetched

[pehbehbeh]

Our dependabot-script running on GitLab stopped working for Hex dependencies today. We are running an up-to-date version 0.133.2 of dependabot. Here are the relevant parts from the log:

Parsing dependencies information
/builds/xxx/dependabot/vendor/ruby/2.6.0/gems/dependabot-common-0.133.2/lib/dependabot/shared_helpers.rb:118:in `rescue in run_helper_subprocess': ** (ArgumentError) argument error (Dependabot::SharedHelpers::HelperSubprocessFailed)
:erlang.binary_to_term("\n10:07:57.467 [error] GenServer Hex.Registry.Server terminating\n
** (Mix.Error) Package {\"hexpm\", \"connection\"} not prefetched, please report this issue\n
...
(stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3\nLast message (from #PID<0.535.0>): {:outer_checksum, \"hexpm\", \"connection\", \"1.1.0\"}\nState: %{closing_fun: nil, ets: nil, fetched: #MapSet<[]>, path: nil, pending: #MapSet<[]>, waiting: %{}}\nClient #PID<0.535.0> is alive\n\n
...
(stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3\n\n10:07:57.487 [error] Task #PID<0.540.0> started from :hex_fetcher terminating\n** (stop) exited in: GenServer.call(Hex.Registry.Server, {:outer_checksum, \"hexpm\", \"jason\", \"1.2.2\"}, 60000)\n
** (EXIT) an exception was raised:\n        
** (Mix.Error) Package {\"hexpm\", \"connection\"} not prefetched, please report this issue\n 
...
(stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3\nFunction: #Function<7.1407416/0 in Hex.SCM.prefetch/1>\n    Args: []\n\n10:07:57.487 [error] Task #PID<0.542.0> started from :hex_fetcher terminating\n** (stop) exited in: GenServer.call(Hex.Registry.Server, {:outer_checksum, \"hexpm\", \"scrivener_ecto\", \"2.7.0\"}, 60000)\n
** (EXIT) an exception was raised:\n        
** (Mix.Error) Package {\"hexpm\", \"connection\"} not prefetched, please report this issue\n 
...
(stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3\nFunction: #Function<7.1407416/0 in Hex.SCM.prefetch/1>\n    Args: []\n\n10:07:57.487 [error] Task #PID<0.548.0> started from :hex_fetcher terminating\n** (stop) exited in: GenServer.call(Hex.Registry.Server, {:outer_checksum, \"hexpm\", \"oban\", \"2.4.3\"}, 60000)\n
** (EXIT) an exception was raised:\n        
** (Mix.Error) Package {\"hexpm\", \"connection\"} not prefetched, please report this issue\n 
...

Is this a problem on our end or with dependabot?

[feelepxyz]

@pehbehbeh not seen that issue on the hosted version of dependabot. We can't provide much support for self-hosted runners as it's almost impossible to debug what might be going wrong 😕

This issue might be related elixir-lang/elixir#9374

[pehbehbeh]

@feelepxyz Thanks for the reply! I just tested it again and we do not have the error anymore... ¯\_(ツ)_/¯

[roelandvanbatenburg]

I noted a bug report on hex: hexpm/hex#889

We are running into this issue too.

I just ran a failed job a few more times and the 6th time it succeeded. Beside the error above I also got another message:

/builds/eRNtTTew/0/Enrise/dependabot/vendor/ruby/2.7.0/gems/dependabot-common-0.156.4/lib/dependabot/shared_helpers.rb:123:in `rescue in run_helper_subprocess': ** (ArgumentError) argument error (Dependabot::SharedHelpers::HelperSubprocessFailed)
    :erlang.binary_to_term(<<10, 48, 57, 58, 52, 52, 58, 53, 48, 46, 51, 54, 55, 32, 91, 101, 114, 114, 111, 114, 93, 32, 71, 101, 110, 83, 101, 114, 118, 101, 114, 32, 72, 101, 120, 46, 82, 101, 103, 105, 115, 116, 114, 121, 46, 83, 101, 114, 118, 101, ...>>)
    /opt/hex/lib/run.exs:11: DependencyHelper.main/0
    (elixir 1.11.4) lib/code.ex:931: Code.require_file/2
    (mix 1.11.4) lib/mix/tasks/run.ex:146: Mix.Tasks.Run.run/5
	from /builds/eRNtTTew/0/Enrise/dependabot/vendor/ruby/2.7.0/gems/dependabot-common-0.156.4/lib/dependabot/shared_helpers.rb:73:in `run_helper_subprocess'
	from /builds/eRNtTTew/0/Enrise/dependabot/vendor/ruby/2.7.0/gems/dependabot-hex-0.156.4/lib/dependabot/hex/update_checker/version_resolver.rb:54:in `run_elixir_update_checker'
	from /builds/eRNtTTew/0/Enrise/dependabot/vendor/ruby/2.7.0/gems/dependabot-hex-0.156.4/lib/dependabot/hex/update_checker/version_resolver.rb:41:in `block (2 levels) in fetch_latest_resolvable_version'

[jurre]

That other error seems unrelated 🤔 it appears we're getting some unexpected content when trying to convert from binary data.

Unfortunately these issues are really hard to debug as I've not been able to find a way to reproduce them 😞, @roelandvanbatenburg do you have a (test) project I could use to try to replicate this on by any chance?

[roelandvanbatenburg]

This is a private repository. I'll see if I can create a way to replicate this and then let you know.

[baseballlover723]

@jurre
I also ran into this issue in our private repo, and I had it reproducible a while ago (though I can't reproduce it anymore for some inexplicable reason). I think that the prefetching might be a red herring. I noticed that while I was debugging it, that it still outputs the correct version, so I think it might just be STDOUT / STDERR noise that is causing the output to not be parsed correctly (and then fail). If this is the case, then it could be fixed by using a stricter STDOUT format that can handle additional text or by skipping STDOUT all together and using something like a http endpoint for transferring info.

Another thing I noticed is that there are 3 layers of runtimes, a top level Ruby layer, which is the bulk of it, an Elixir layer that is charge of figuring out dependency stuff, and then a final Elixir layer inside of the target project, that is used to generate lock files and whatnot (see https://github.com/dependabot/dependabot-core/blob/dd1fba76003434639209627676febc595787ba7c/hex/helpers/lib/run.exs for the middle Elixir layer). Dependabot currently communicates from the inner Elixir layer to the outer Elixir layer, by taking a value, converting it to binary, outputting the binary to STDOUT, then in the outer Elixir layer, it reads the STDOUT from the command it ran, converts it from a binary to an Elixir value, and then uses that Elixir value. An issue with this, is that if there is other output from the script, such as a warning or non fatal error or something, then the parsing gets messed up, since the bytes on STDOUT will no longer deserialize into an Elixir value. I think that the outer Elixir layer is probably unnecessary and could probably be done in the Ruby layer, which would make debugging easier, and it hopefully being more resilient.

[jurre]

I think that the outer Elixir layer is probably unnecessary and could probably be done in the Ruby layer, which would make debugging easier, and it hopefully being more resilient.

Yep, I noticed this as well when I last looked into it, alternatively we could stop shelling out in the outer elixir layer and directly call the inner layer using method calls, I don't think there's a reason to shell out really.

Unfortunately I likely won't have time to dig into this any time soon but would definitely be able to help review a PR if you're up for it?

[baseballlover723]

Unfortunately, I'll also not have the time to look at this during the week, might be able to squeeze it on a weekend though, but certainly not worth waiting on, if you find the time to work on it. If I start working on it, I'll push up a branch / let you know.

[pehbehbeh]

We started to see this issue again. Any updates on this?