Weird behavior in a test case

nhpip · August 10, 2022, 10:11pm

Hello,

I’ve been given the task to upgrade our product from OTP R22 / Elixir 1.11 to OTP R25 / Elixir 1.13.4 (hoping for 1.14). There is a test-case that works fine on 1.11 that is failing in 1.13.

This is the code, as is the test literally blocks and does nothing.

  rando_info = users.rando

  users = %{users | rando: %{rando_info | sign_pair: sign_pair, public_key: public_key, key_version: 1}}
 
  # Make export request
  request_payload =
    %{user_id: users.admin.user_id,
      type: "export",
      device_id: users.admin.device.id,
      data: %{until: NaiveDateTime.to_iso8601(NaiveDateTime.add(NaiveDateTime.utc_now, 900)),
              users: [%{user_id: users.admin.user_id, key_version: users.admin.key_version},
                      %{user_id: users.approver1.user_id, key_version: users.approver1.key_version},
                      %{user_id: users.approver2.user_id, key_version: users.approver2.key_version},
                      %{user_id: users.rando.user_id, key_version: 1}]},
      timestamp: NaiveDateTime.to_iso8601(NaiveDateTime.utc_now),
      expiration: NaiveDateTime.to_iso8601(NaiveDateTime.add(NaiveDateTime.utc_now, 900)),
      protocol_version: 1} |> Poison.encode!()

If I remove one line from the list of users:

  %{user_id: users.admin.user_id,
    type: "export",
    device_id: users.admin.device.id,
    data: %{until: NaiveDateTime.to_iso8601(NaiveDateTime.add(NaiveDateTime.utc_now, 900)),
            users: [%{user_id: users.admin.user_id, key_version: users.admin.key_version},
                    %{user_id: users.approver1.user_id, key_version: users.approver1.key_version},
                    %{user_id: users.approver2.user_id, key_version: users.approver2.key_version}]},
    timestamp: NaiveDateTime.to_iso8601(NaiveDateTime.utc_now),
    expiration: NaiveDateTime.to_iso8601(NaiveDateTime.add(NaiveDateTime.utc_now, 900)),
    protocol_version: 1} |> Poison.encode!()

I get a bunch of errors like:

warning: incompatible types:

    %{rando: var1} !~ %{rando: var2}

in expression:

    # test/api/export_test.exs:364
    users.rando

where "users" was given the type %{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: %

I can get the test to work by updating the users map via access methods:

rando_info = users.rando

rando_info = Map.replace(rando_info, :sign_pair, sign_pair)
             |> Map.replace(:public_key, public_key)
             |> Map.replace(:key_version, 1)

users = %{users | rando: rando_info}

users is a map like:

%{
  admin: %{
    account_version: 0,
    claim_return: %{...},
    ...
  },
  approver1: %{
    account_version: 0,
    claim_return: %{...},
    ...
  },
  approver2: %{
    account_version: 0,
    claim_return: %{...},
    ...
  },
  rando: %{
    account_version: 0,
    claim_return: %{...},
    ...      
  }
}

I just found it odd that’s all

Thanks

nhpip · August 10, 2022, 10:50pm

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.

nhpip · August 10, 2022, 11:51pm

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

nhpip · August 10, 2022, 11:59pm

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]}
 ]}

al2o3cr · August 11, 2022, 12:00am

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…

nhpip · August 11, 2022, 12:01am

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

al2o3cr · August 11, 2022, 12:06am

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:

github.com/elixir-lang/elixir

Compilation hangs when trying to compile a particular map-related code

opened 09:30AM - 22 Feb 22 UTC

closed 08:55PM - 01 Mar 22 UTC

mat-hek

### Precheck ### Environment * Elixir & Erlang/OTP versions (elixir --vers…ion): ``` Erlang/OTP 24 [erts-12.2.1] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [jit] [dtrace] Elixir 1.13.3 (compiled with Erlang/OTP 24) ``` **This seems not to happen on 1.12** * Operating system: Mac OS 11.6 ### Current behavior Trying to compile the following code makes the compilation hang and use 70-100% of a CPU core ```elixir defmodule A do def fun(x, y) do key_var = y %{^key_var => _value} = x key_var2 = y %{^key_var2 => _value2} = x y.z end end ``` Replacing `y.z` with ```elixir key_var3 = y %{^key_var3 => _value3} = x ``` gives the same effect ### Expected behavior I believe this should compile normally ;)

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

nhpip · August 11, 2022, 12:08am

all the type errors:

github.com

nhpip/stuff/blob/master/test_case_map_type_warnings.txt

Erlang/OTP 25 [erts-13.0.1] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [jit:ns]

warning: incompatible types:

    %{rando: var1} !~ %{rando: var2}

in expression:

    # test/api/export_test.exs:365
    users.rando

where "users" was given the type %{rando: %{sign_pair: var13, public_key: var14, key_version: integer(), user_id: var15, user_id: var15, user_id: var15, user_id: var15, 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: %{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()}, rando: var18, rando: var19, 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()}, rando: var20, 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: %{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: %{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: %{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()}, rando: var21, optional(dynamic()) => dynamic()} in:

    # test/api/export_test.exs:325
    users = %{
      users
      | rando: %{rando_info | sign_pair: sign_pair, public_key: public_key, key_version: 1}
    }

where "users" was given the type %{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()}, optional(dynamic()) => dynamic()} (due to calling var.field) in:

This file has been truncated. show original