Explain race condition in assert_receive to user when it happens (#5204)

When using assert_receive, it is possible for the following sequence of
events:
1. `after` timeout triggers, indicating messages was not received
2. Process receive messages
3. `Process.info(self(), :messages) is called and gets message
`assert_receive` was waiting for.

Previously, `assert_receive` would not check the output
`Process.info(self, :messages)` for the expected pattern, so it would
print a confusing error message that said "No message matching <pattern>
after <timeout>ms", but then show a matching message in the "Process
mailbox" section.  Now, for this special race-condition, a long-form
explanation that the message is being delivered at or near the timeout
is being printed, along with how this could impact production and how to
fix it if it only impacts tests.

2 files changed, 44 insertions, 4 deletions

diff --git a/lib/ex_unit/lib/ex_unit/assertions.ex b/lib/ex_unit/lib/ex_unit/assertions.ex
index f08b53efc..2e9bde94c 100644
--- a/lib/ex_unit/lib/ex_unit/assertions.ex
+++ b/lib/ex_unit/lib/ex_unit/assertions.ex
@@ -403,9 +403,25 @@ defmodule ExUnit.Assertions do
             {received, unquote(vars)}
         after
           timeout ->
-            failure_message = unquote(failure_message) || "No message matching #{unquote(binary)} after #{timeout}ms."
+            {:messages, messages} = Process.info(self(), :messages)
+
+            failure_message = if Enum.any?(messages, fn message -> match?(unquote(pattern), message) end) do
+              "No message matching #{unquote(binary)} after #{timeout}ms, " <>
+              "but a matching message appeared before reading the mailbox for this error message, " <>
+              "which indicates the message is being delivered a few milliseconds after the current timeout or in the same " <>
+              "millisecond, but the timeout triggers before the sending process runs.\n" <>
+              "\n" <>
+              "If your system has time constraints that depend on this timeout, " <>
+              "this failure indicates you are at the edge of timing out in production; however, " <>
+              "if the timeout can safely be increased for this test, you can increase it two ways:\n" <>
+              "1. Increase the timeout to this one `assert_receive`.\n" <>
+              "2. Increase the default timeout to all `assert_receive`: In `config/test.exs` add `config :ex_unit, assert_receive_timeout: <new_timeout>`"
+            else
+              unquote(failure_message) || "No message matching #{unquote(binary)} after #{timeout}ms."
+            end
+
             flunk(failure_message <> ExUnit.Assertions.__pins__(unquote(pins))
-                          <> ExUnit.Assertions.__mailbox__(self()))
+                          <> ExUnit.Assertions.__mailbox__(messages))
         end
 
       received
@@ -416,8 +432,7 @@ defmodule ExUnit.Assertions do
   @max_mailbox_length 10
 
   @doc false
-  def __mailbox__(pid) do
-    {:messages, messages} = Process.info(pid, :messages)
+  def __mailbox__(messages) do
     length = length(messages)
     mailbox =
       messages
diff --git a/lib/ex_unit/test/ex_unit/assertions_test.exs b/lib/ex_unit/test/ex_unit/assertions_test.exs
index d72b55d71..8d91c7837 100644
--- a/lib/ex_unit/test/ex_unit/assertions_test.exs
+++ b/lib/ex_unit/test/ex_unit/assertions_test.exs
@@ -158,6 +158,31 @@ defmodule ExUnit.AssertionsTest do
     :hello = assert_receive :hello
   end
 
+  test "assert receive with message in mailbox after timeout, but before reading mailbox tells user to increase timeout" do
+    parent = self()
+    # this is testing a race condition, so it's not guaranteed this works under all loads of the system
+    timeout = 100
+    spawn fn -> Process.send_after parent, :hello, timeout end
+
+    try do
+      assert_receive :hello, timeout
+    rescue
+      error in [ExUnit.AssertionError] ->
+        "No message matching :hello after 100ms, " <>
+        "but a matching message appeared before reading the mailbox for this error message, " <>
+        "which indicates the message is being delivered a few milliseconds after the current timeout or in the same " <>
+        "millisecond, but the timeout triggers before the sending process runs.\n" <>
+        "\n" <>
+        "If your system has time constraints that depend on this timeout, " <>
+        "this failure indicates you are at the edge of timing out in production; however, " <>
+        "if the timeout can safely be increased for this test, you can increase it two ways:\n" <>
+        "1. Increase the timeout to this one `assert_receive`.\n" <>
+        "2. Increase the default timeout to all `assert_receive`: In `config/test.exs` add `config :ex_unit, assert_receive_timeout: <new_timeout>`\n" <>
+        "Process mailbox:\n" <>
+        "  :hello" = error.message
+    end
+  end
+
   test "assert received does not wait" do
     send self(), :hello
     :hello = assert_received :hello