Weird behavior in a test case

Edit to add that there is a nif that logs a message a few seconds after start. That doesn’t happen in the hang case. But the nif shouldn’t be involved with this test.

Hmmmmm…this is the vm

===============================================================================================================================================================================
 cs@localhost                                                              23:50:08
 Load:  cpu         4               Memory:  total      151543    binary      13437
        procs     480                        processes   74055    code        26980
        runq        0                        atom         1256    ets         15130

Pid            Name or Initial Func                                              Time     Reds   Memory     MsgQ Current Function
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
<8485.966.0>   erlang:apply/2                                                     '-'201520000  4720584        0 'Elixir.Module.Types.Unify':'subtype?'/3
<8485.1424.0>  etop_txt:init/1                                                    '-'    18420   426576        0 etop:update/1
<8485.713.0>   'Elixir.DBConnection.ConnectionPool':init/1                        '-'     6321    11984        0 gen_server:loop/7
<8485.963.0>   cowboy_clear:connection_process/4                                  '-'     3333    42344        0 cowboy_http:loop/1

the bad pid stacktrace

iex(cs@localhost)11> Process.info(pid, :current_stacktrace)
{:current_stacktrace,
 [
   {Module.Types.Unify, :subtype?, 3,
    [file: 'lib/module/types/unify.ex', line: 581]},
   {Enum, :any_list, 2, [file: 'lib/enum.ex', line: 3973]},
   {Enum, :all_list, 2, [file: 'lib/enum.ex', line: 3947]},
   {Enum, :reject_list, 2, [file: 'lib/enum.ex', line: 4150]},
   {Enum, :reject_list, 2, [file: 'lib/enum.ex', line: 4153]},
   {Module.Types.Unify, :unique_super_types, 2,
    [file: 'lib/module/types/unify.ex', line: 671]},
   {Module.Types.Unify, :to_union, 2,
    [file: 'lib/module/types/unify.ex', line: 651]},
   {Module.Types.Expr, :of_expr, 4,
    [file: 'lib/module/types/expr.ex', line: 83]},
   {Module.Types.Of, :"-map_pairs/4-fun-0-", 4,
    [file: 'lib/module/types/of.ex', line: 75]},
   {Module.Types.Helpers, :do_map_reduce_ok, 3,
    [file: 'lib/module/types/helpers.ex', line: 93]},
   {Module.Types.Of, :closed_map, 4, [file: 'lib/module/types/of.ex', line: 67]},
   {Module.Types.Of, :"-map_pairs/4-fun-0-", 4,
    [file: 'lib/module/types/of.ex', line: 75]},
   {Module.Types.Helpers, :do_map_reduce_ok, 3,
    [file: 'lib/module/types/helpers.ex', line: 93]},
   {Module.Types.Of, :closed_map, 4, [file: 'lib/module/types/of.ex', line: 67]},
   {Module.Types.Helpers, :do_map_reduce_ok, 3,
    [file: 'lib/module/types/helpers.ex', line: 93]},
   {Module.Types.Expr, :of_expr, 4,
    [file: 'lib/module/types/expr.ex', line: 375]},
   {Module.Types.Expr, :of_expr, 4,
    [file: 'lib/module/types/expr.ex', line: 140]},
   {Module.Types.Helpers, :do_map_reduce_ok, 3,
    [file: 'lib/module/types/helpers.ex', line: 93]},
   {Module.Types.Expr, :of_expr, 4,
    [file: 'lib/module/types/expr.ex', line: 209]},
   {Module.Types.Helpers, :do_map_reduce_ok, 3,
    [file: 'lib/module/types/helpers.ex', line: 93]}
 ]}

Can you post the full output of one of those? The example given cuts off after showing some odd repetitions (formatted for readability):

%{
  rando: %{
    user_id: var13,
    user_id: var13,
    user_id: var13,
    user_id: var13,
    sign_pair: var14,
    public_key: var15,
    key_version: integer(),
    optional(dynamic()) => dynamic()
  },
  rando: var16,
  rando: var17,
  admin: %{
    user_id: var5,
    key_version: var6,
    user_id: var5,
    device: %{
      id: var7,
      id: var7,
      optional(dynamic()) => dynamic()
    },
    user_id: var5,
    sign_pair: %{
      public: var8,
      secret: var9,
      optional(dynamic()) => dynamic()
    },
    key_version: var6,
    key_version: var6,
    device: %{
      id: var7,
      id: var7,
      optional(dynamic()) => dynamic()
    },
    user_id: var5,
    sign_pair: %{
      public: var8,
      secret: var9,
      optional(dynamic()) => dynamic()
    },
    optional(dynamic()) => dynamic()
  },
  admin: %{
    user_id: var5,
    key_version: var6,
    user_id: var5,
    device: %
... cuts off here...

The message is coming from the :unable_unify formatter in the type-hinting system but that module already existed in 1.11, so something must have changed.

Can you clarify “blocks” here? Does the test time out? I don’t see anything in the code you posted that could do that…

blocks as in…dead…but I connected another vm to the test-case vm…see above

That stack trace was super-helpful - the most recent change to Module.Types.Unify was a fix for this issue which sounds very much like what you’re experiencing:

https://github.com/elixir-lang/elixir/issues/11658

This seems promising since:

• it’s related to type-hinting in code that uses maps
• it produces a hang
• the bug wasn’t in 1.12 or prior

all the type errors:
https://github.com/nhpip/stuff/blob/master/test_case_map_type_warnings.txt