Addressing errors spawning off of elixir upgrade from 1.6.6 to 1.10.4

Questions / Help
1

I upgraded from elixir 1.6.6 to 1.10.4. Before the upgrade all tests were passing. Now I have about 10 tests failing. At some point the application is shutdown which inevitably makes the rest of the tests fail. The shutdown is caused by this error:

16:11:29.767 [error] GenServer Verk.ScheduleManager terminating
** (UndefinedFunctionError) function Redix.command/2 is undefined or private
    (redix 0.7.1) Redix.command(#PID<0.6698.0>, ["EVALSHA", "2f42b81434c4ff28b1b82414f7e76b67a1d6e933", 1, "schedule", 1612473089])
    (verk 1.4.1) lib/verk/schedule_manager.ex:59: Verk.ScheduleManager.handle_info/3
    (stdlib 3.12.1) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.12.1) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.12.1) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: :fetch_scheduled
State: %Verk.ScheduleManager.State{redis: #PID<0.6698.0>}

16:11:29.768 [warn]  Pausing all queues. Max timeout: 30000

16:11:29.769 [error] GenServer #PID<0.6873.0> terminating
** (stop) exited in: GenServer.call(:"whatever-volcano.workers_manager", :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir 1.10.4) lib/gen_server.ex:1013: GenServer.call/3
    (verk 1.4.1) lib/verk/manager.ex:45: Verk.Manager.pause/1
    (verk 1.4.1) lib/verk/queues_drainer.ex:60: anonymous fn/3 in Verk.QueuesDrainer.do_terminate/1
    (elixir 1.10.4) lib/enum.ex:2111: Enum."-reduce/3-lists^foldl/2-0-"/3
    (verk 1.4.1) lib/verk/queues_drainer.ex:59: Verk.QueuesDrainer.do_terminate/1
    (stdlib 3.12.1) gen_server.erl:673: :gen_server.try_terminate/3
    (stdlib 3.12.1) gen_server.erl:858: :gen_server.terminate/10
    (stdlib 3.12.1) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:EXIT, #PID<0.6693.0>, :shutdown}
State: 30000

16:54:08.847 [error] Failed to fetch a job. Reason: 1

I understand the error:
** (UndefinedFunctionError) function Redix.command/2 is undefined or private
is telling me that I’m passing in 2 arguments instead of 3 to Redix.command function.
This is what’s being passed in:
Redix.command(#PID<0.6698.0>, ["EVALSHA", "2f42b81434c4ff28b1b82414f7e76b67a1d6e933", 1, "schedule", 1612473089])
Which appears congruent with what’s laid out in redix docs example:
Redix.command(conn, ["SET", "mykey", "foo"])

Also like I said, this was working before elixir upgrade so I’m at a loss as to why I’m suddenly having problems with Redix.

Any help would be greatly appreciated! Thanks ahead of time.

2

Quick check: does this behavior persist if you remove the _build directory and/or force a recompile?

I haven’t encountered this specific issue before, but I’ve definitely seen other compiler weirdness that went away with a clean slate.

3

I removed the _build directory, recompiled with the same result.

I want to note that if I pry into one of the failing tests the following is repeatedly logged out:

18:03:57.124 [error] Failed to fetch a job. Reason: 1
18:03:57.919 [error] Failed to fetch a job. Reason: 1
18:03:58.379 [error] Failed to fetch a job. Reason: 1

In that same pry, I can run:

Redix.command(Verk.Redis, ["SADD", "key", "Line 1"])
{:ok, 1}
4

Are you running ElixirLS in any chance at the same time? I often see competing compilation between my command and ElixirLS. When it happened, I quit vscode, remove .elixir-ls, deps, and _build directory and then recompile everything.

1 Like
5

Thanks for the reply! I tried removing the _build and deps directories and recompiling… no luck. Still getting the same errors. I am not using ElixirLS.

6

Did you try creating a new, smaller test, that only issues the command you tried in iex?

7

As the usual deprecation cycle is 2 minor versions, you skipped straight 2 of them.

Try to upgrade in smaller steps instead.

8

I reset to development removed deps, _build and recompiled and updated my elixir version from 1.6.6 to 1.7.0 (the next stable version) and reran tests getting almost identical error as seen on 1.10.4.

15:59:51.854 [error] GenServer :"default.queue_manager" terminating
** (UndefinedFunctionError) function Redix.command/2 is undefined or private
    (redix) Redix.command(#PID<0.5666.0>, ["EVALSHA", "3586a7b1fcc76092670c0eb971b87c2287e4bb20", 2, "queue:default", "inprogress:default:1", 100])
    (verk) lib/verk/queue_manager.ex:112: Verk.QueueManager.handle_call/3
    (stdlib) gen_server.erl:661: :gen_server.try_handle_call/4
    (stdlib) gen_server.erl:690: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message (from :"default.workers_manager"): {:dequeue, 100}
State: %Verk.QueueManager.State{node_id: "1", queue_name: :default, redis: #PID<0.5666.0>}
Client :"default.workers_manager" is alive

    (stdlib) gen.erl:167: :gen.do_call/4
    (elixir) lib/gen_server.ex:921: GenServer.call/3
    (verk) lib/verk/queue_manager.ex:42: Verk.QueueManager.dequeue/3
    (verk) lib/verk/workers_manager.ex:147: Verk.WorkersManager.handle_info/2
    (stdlib) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

15:59:51.855 [error] Manager terminating, reason: {{:undef, [{Redix, :command, [#PID<0.5666.0>, ["EVALSHA", "3586a7b1fcc76092670c0eb971b87c2287e4bb20", 2, "queue:default", "inprogress:default:1", 100]], []}, {Verk.QueueManager, :handle_call, 3, [file: 'lib/verk/queue_manager.ex', line: 112]}, {:gen_server, :try_handle_call, 4, [file: 'gen_server.erl', line: 661]}, {:gen_server, :handle_msg, 6, [file: 'gen_server.erl', line: 690]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}, {GenServer, :call, [:"default.queue_manager", {:dequeue, 100}, 5000]}}

15:59:51.859 [warn]  Pausing all queues. Max timeout: 30000

15:59:51.866 [error] GenServer #PID<0.5830.0> terminating
** (ArgumentError) argument error
    (stdlib) :ets.match_object(:verk_manager, :_)
    (stdlib) ets.erl:763: :ets.tab2list/1
    (verk) lib/verk/queues_drainer.ex:59: Verk.QueuesDrainer.do_terminate/1
    (stdlib) gen_server.erl:673: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:858: :gen_server.terminate/10
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:EXIT, #PID<0.5652.0>, :shutdown}
State: 30000
9

I should also note that each test file passes when run individually. But when running the test suite using mix test all the over half the tests fail.

10

Likely not what you want to hear but I suggest you start a brand new project and gradually add your deps and part of the code to it until it fails. You’ll identify the faulty bit. At that point you could publish it on GitHub and post a link so we all could take a look.

Another blind guess from my side would be an outdated dependency. That’s where I’d look first now if I were you.

Since tests are acting that weird now, did you try upgrading ex_unit in your project?

11

Are you using any mocking libraries or similar tools that fiddle with modules at runtime? The behavior you’re describing sounds like something (maybe in test setup?) is manipulating the definition of Redix.command and not cleaning up after itself.

1 Like
12 
17:15:20.079 [error] GenServer Verk.ScheduleManager terminating
** (UndefinedFunctionError) function Redix.command/2 is undefined or private
    (redix 0.7.1) Redix.command(#PID<0.466.0>, ["EVALSHA", "2f42b81434c4ff28b1b82414f7e76b67a1d6e933", 1, "retry", 1612995320])

Which is occurring in Verk source code here: Verk Schedule Manager L:60

So for some reason, it appears that, Redix is not available in Verk at this point.

However, Redix is used earlier in the ScheduleManager here: Verk ScheduleManager L:32

For context my app.ex file is below:

defmodule MyApp.App do
  require Lager
  @moduledoc """
  Main application entrypoint
  """
  use Application

  def start(_type, _args) do
    import Supervisor.Spec
    tree = [
      supervisor(MyApp.Repo, []),
      supervisor(Verk.Supervisor, [])
    ]
    opts = [name: MyApp.Sup, strategy: :one_for_one]
    result = Supervisor.start_link(tree, opts)

  end
end
13

Modules do not usually “become unavailable” during normal execution of an Elixir program, so something must be causing that behavior. For example, meck dynamically recompiles modules to implement mocking/stubbing. Are there any similar tools in use in your test suite to mock out Redix?

14

Yes, we use Mock which has meck as a dependency. Do you have any suggestions to avoid this behavior?

15

I see two possibilities for why this is happening:

  • a test that mocks Redix doesn’t tear down the mock cleanly; the next piece of code to try to call Redix.command gets the error
  • a test that mocks Redix is reconfiguring modules exactly at the moment the Verk.QueueManager tries to interact with Redis

You may want to consider if Verk.Supervisor and the associated machinery should be running during tests, especially tests where Redix is being replaced dynamically. I’ve mostly used Oban, which recommends running tests with job dispatching disabled.

4 Likes