Weird behavior in a test case

nhpip

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

7 comments

#testing #unit-testing #type-checking #types #test

0 1080 7

2022-08-11 00:08:04 UTC

Showing Posts 7 to 1

Show Best Posts
Show All (oldest first)
Show All (newest first)

nhpip

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

Post #7

al2o3cr

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

Post #6

nhpip

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

Post #5

al2o3cr

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…

Post #4

nhpip

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

Post #3

nhpip

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

Post #2

nhpip

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.

Post #1

— All posts loaded —