Liveview doesn't update in production but does locally

[Nev]

Hello everyone,

Sorry if there’s something obvious that I can’t see, but I’m stuck on a bug that I don’t understand.

When a user bids on my Phoenix Liveview action page, the amount does not update… But only in production! And only since this morning!

Locally, with precisely the same code, I can’t reproduce the bug. And since I was on vacation last week, there have been no new commits on master for 11 days, during which four auctions went well without the bug appearing.

The only lead I found: in the FlyCtl logs, we don’t see (unlike the local logs) when the bid is correctly inserted and when LiveView receives the data. (See end of logs in italics)

FlyCtl logs (bug)

[info] Create bid with auction_id: 7e05e61e-5dff-4a0d-9937-1c9356f5a603, registration_id: 3dd3a9b2-9917-415b-a9e3-df40045f0953, amount: 195000

[debug] Locating aggregate process for MyApp.Auctions.Aggregates.Auction with UUID “7e05e61e-5dff-4a0d-9937-1c9356f5a603”
[debug] MyApp.Auctions.Aggregates.Auction7e05e61e-5dff-4a0d-9937-1c9356f5a603@5 executing command: %MyApp.Auctions.Commands.OutbidAuction{amount: 195000, auction_id: “7e05e61e-5dff-4a0d-9937-1c9356f5a603”, registration_id: “3dd3a9b2-9917-415b-a9e3-df40045f0953”}

[debug] Listener received notification on channel “events” with payload: “7e05e61e-5dff-4a0d-9937-1c9356f5a603,1049,6,6”
[debug] Listener received notification on channel “events” with payload: “$all,0,4377,4377”

[debug] Appended 1 event(s) to stream “7e05e61e-5dff-4a0d-9937-1c9356f5a603”

[debug] MyApp.Auctions.Aggregates.Auction7e05e61e-5dff-4a0d-9937-1c9356f5a603@6 received events: [%Commanded.EventStore.RecordedEvent{causation_id: “e3c8f9ec-1f27-4540-a160-10b60ebe6acc”, correlation_id: “7c406e66-77a2-4f9a-8588-c4c0e62fe1e7”, created_at: ~U[2022-08-08 12:37:43.257026Z], data: %MyApp.Auctions.Events.AuctionOutbid{amount: 195000, auction_id: “7e05e61e-5dff-4a0d-9937-1c9356f5a603”, created_at: “2022-08-08T12:37:43.246951Z”, new_end_date: nil, postponed_version: nil, registration_id: “3dd3a9b2-9917-415b-a9e3-df40045f0953”}, event_id: “f6065a6f-8836-4623-8d18-6d803e12a3a2”, event_number: 6, event_type: “Elixir.MyApp.Auctions.Events.AuctionOutbid”, metadata: %{}, stream_id: “7e05e61e-5dff-4a0d-9937-1c9356f5a603”, stream_version: 6}]

[debug] Subscription “Auctions.Projectors.Auction”@“$all” received 1 event(s)

[debug] QUERY OK source=“bids” db=6.9ms queue=0.1ms idle=1222.2ms

Local logs (correct)

[info] Create bid with auction_id: a509f165-6a6d-44d1-9234-bc4e8639bc06, registration_id: cade691f-ce06-4268-9769-d88d81ea06e2, amount: 250000

[debug] Locating aggregate process for MyApp.Auctions.Aggregates.Auction with UUID “a509f165-6a6d-44d1-9234-bc4e8639bc06”

[debug] MyApp.Auctions.Aggregates.Auctiona509f165-6a6d-44d1-9234-bc4e8639bc06@10 executing command: %MyApp.Auctions.Commands.OutbidAuction{amount: 250000, auction_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, registration_id: “cade691f-ce06-4268-9769-d88d81ea06e2”}

[debug] Appended 1 event(s) to stream “a509f165-6a6d-44d1-9234-bc4e8639bc06”

[debug] Listener received notification on channel “events” with payload: “a509f165-6a6d-44d1-9234-bc4e8639bc06,2,11,11”

[debug] Listener received notification on channel “events” with payload: “$all,0,13,13”

[debug] MyApp.Auctions.Aggregates.Auctiona509f165-6a6d-44d1-9234-bc4e8639bc06@11 received events: [%Commanded.EventStore.RecordedEvent{causation_id: “14b1de91-fc21-4c42-97f6-f0cd9a65eaf2”, correlation_id: “73ed1d75-f8e8-475a-82c0-7d78660ad12e”, created_at: ~U[2022-08-08 12:44:33.623684Z], data: %MyApp.Auctions.Events.AuctionOutbid{amount: 250000, auction_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, created_at: “2022-08-08T12:44:33.622888Z”, new_end_date: nil, postponed_version: nil, registration_id: “cade691f-ce06-4268-9769-d88d81ea06e2”}, event_id: “65e1043e-70d3-496c-b172-4f70582bdddf”, event_number: 11, event_type: “Elixir.MyApp.Auctions.Events.AuctionOutbid”, metadata: %{}, stream_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, stream_version: 11}]

[debug] Subscription “Auctions.Projectors.Auction”@“$all” received 1 event(s)

[debug] Subscription “Auctions.Projectors.Auction”@“$all” is enqueueing 1 event(s)
[debug] MyApp.Auctions.Projectors.Auction received events: [%Commanded.EventStore.RecordedEvent{causation_id: “14b1de91-fc21-4c42-97f6-f0cd9a65eaf2”, correlation_id: “73ed1d75-f8e8-475a-82c0-7d78660ad12e”, created_at: ~U[2022-08-08 12:44:33.623684Z], data: %MyApp.Auctions.Events.AuctionOutbid{amount: 250000, auction_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, created_at: “2022-08-08T12:44:33.622888Z”, new_end_date: nil, postponed_version: nil, registration_id: “cade691f-ce06-4268-9769-d88d81ea06e2”}, event_id: “65e1043e-70d3-496c-b172-4f70582bdddf”, event_number: 13, event_type: “Elixir.MyApp.Auctions.Events.AuctionOutbid”, metadata: %{}, stream_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, stream_version: 11}]
[debug] QUERY OK db=0.1ms idle=1197.3ms
begin []
[debug] QUERY OK source=“projection_versions” db=0.2ms
SELECT p0.“projection_name”, p0.“last_seen_event_number”, p0.“inserted_at”, p0.“updated_at” FROM “projection_versions” AS p0 WHERE (p0.“projection_name” = $1) [“Auctions.Projectors.Auction”]
[debug] QUERY OK db=0.2ms
UPDATE “projection_versions” SET “last_seen_event_number” = $1, “updated_at” = $2 WHERE “projection_name” = $3 [13, ~N[2022-08-08 12:44:33.641920], “Auctions.Projectors.Auction”]
[debug] QUERY OK db=0.3ms
INSERT INTO “bids” (“amount”,“created_at”,“is_retained”,“registration_id”,“inserted_at”,“updated_at”,“id”) VALUES ($1,$2,$3,$4,$5,$6,$7) [250000, ~U[2022-08-08 12:44:33.622888Z], false, <<202, 222, 105, 31, 206, 6, 66, 104, 151, 105, 216, 141, 129, 234, 6, 226>>, ~U[2022-08-08 12:44:33.642349Z], ~U[2022-08-08 12:44:33.642349Z], <<201, 169, 47, 87, 199, 25, 69, 99, 144, 233, 238, 176, 171, 198, 104, 93>>]
[debug] QUERY OK source=“auctions” db=0.3ms
UPDATE “auctions” AS a0 SET “best_bid_id” = $1 WHERE (a0.“id” = $2) [<<201, 169, 47, 87, 199, 25, 69, 99, 144, 233, 238, 176, 171, 198, 104, 93>>, <<165, 9, 241, 101, 106, 109, 68, 209, 146, 52, 188, 78, 134, 57, 188, 6>>]
[debug] QUERY OK db=0.7ms
commit []
[info] Notify with topic_id: “a509f165-6a6d-44d1-9234-bc4e8639bc06”, event: [:auction, :outbid]
[debug] MyApp.Auctions.Projectors.Auction confirming receipt of event #13
[debug] LiveView received [:auction, :outbid]

But the requests/responses in the websocket look identicals and corrects:

Prod websocket

[“8”,“10”,“lv:auction-live”,“event”,{“type”:“click”,“event”:“bid_confirmed”,“value”:{“value”:“”}}]
[“8”,“10”,“lv:auction-live”,“phx_reply”,{“response”:{“diff”:{“0”:{“3”:{“1”:{“0”:{“1”:{“1”:{“0”:“08/08/2022 à 12:00”}},“6”:{“0”:{“1”:{“0”:{“1”:{“1”:{“d”:[[" phx-click=“fast_bid”“,” phx-value-amount=“280000”“,{“0”:” class=“inline-flex cursor-pointer rounded-md shadow-sm w-full”“,“1”:{“0”:”“,“1”:”“,“2”:” class=[some CSS],“3”:{“0”:“5 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click=“fast_bid”“,” phx-value-amount=“285000”“,{“0”:” class=[some CSS], “3”:{“0”:“10 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click=“fast_bid”“,” phx-value-amount=“290000”“,{“0”:” class=[some CSS],“3”:{“0”:“15 000 €”,“s”:0},“s”:1},“s”:2}]],“p”:{“0”:[“\n +\n “,”\n “],“1”:[”\n <button”,“”," type=“button”“,”>\n “,”\n \n “],“2”:[”<span",“>\n “,”\n\n”]}}}},“1”:{“1”:{“7”:{“1”:{“2”:" class=[some CSS],“8”:{“1”:{“0”:{“0”:“”,“1”:" class=[some CSS],“2”:" data-phx-link-state=“push”“,“3”:” href=[A link],“8”:{“s”:[“”]}}}}}}},“status”:“ok”}]

Local websocket

[“8”,“10”,“lv:auction-live”,“event”,{“type”:“click”,“event”:“bid_confirmed”,“value”:{“value”:“”}}]
[“8”,“10”,“lv:auction-live”,“phx_reply”,{“response”:{“diff”:{“0”:{“3”:{“1”:{“0”:{“1”:{“1”:{“0”:“08/08/2022 à 12:00”}},“6”:{“0”:{“1”:{“0”:{“1”:{“1”:{“d”:[[" phx-click=“fast_bid”“,” phx-value-amount=“270000”“,{“0”:” class=[some CSS],“3”:{“0”:“5 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click=“fast_bid”“,” phx-value-amount=“275000”“,{“0”:” class=[some CSS],“1”:{“0”:“”,“1”:“”,“2”:" class=[some CSS]“,“3”:{“0”:“10 000 €”,“s”:0},“s”:1},“s”:2}],[” phx-click=“fast_bid”“,” phx-value-amount=“280000”“,{“0”:” class=[some CSS]““,“1”:{“0”:”“,“1”:”“,“2”:” class=[some CSS],“3”:{“0”:“15 000 €”,“s”:0},“s”:1},“s”:2}]],“p”:{“0”:[“\n +\n “,”\n “],“1”:[”\n <button”,“”,” type=“button”“,”>\n “,”\n \n “],“2”:[”<span",“>\n “,”\n\n”]}}}},“1”:{“1”:{“7”:{“1”:{“2”:" class=[some CSS],“8”:{“1”:{“0”:{“0”:“”,“1”:" class=[some CSS],“2”:" data-phx-link-state=“push”“,“3”:” href=[A link],“8”:{“s”:[“”]}}}}}}},“status”:“ok”}]

To summarize :
→ Liveview no longer updates an element of my page in production
→ Other LiveView elements refresh correctly (especially the timer on the same page, which refreshes every second)
→ Without new commits or recent PR (the bug was reported this morning, the last master release was 11 days ago)
→ Restarting a deploy did not change anything
→ FlyCtl and local logs do not match
→ Prod and local WebSocket request/response does match

Next test:
I will try to revert to an earlier version. See if that fixes the problem, although I don’t understand why it only appears today.

Versions :
Elixir 1.13 ; Phoenix 1.6.6 ; LiveView 0.17.10 ; Erlang 24.0.2.

Is there something obvious that I’m not seeing? Are there any tests/leads I could follow? Can Fly.io impact how Liveview behaves?

Thanks for any leads you can give me!

PS : I also posted this message on the Elixir forum.

[tj1]

Sounds like the javascript is not loading correctly. Can you check the developer console for errors?

[Nev]

Hi !

I don’t see anything that seems related to LiveView. Should I look at something in particular in the debugger?

[tj1]

1. Go to network tab in dev console.
2. Refresh
3. Click on the active websocket.
4. In there, there should be a request/response area.
5. See if clicking on the non-updating element is sending the appropriate request/response.

[Nev]

Everything seems correct (amounts and variables are correct) and identical between local/prod…

On local :

[“8”,“10”,“lv:auction-live”,“event”,{“type”:“click”,“event”:“bid_confirmed”,“value”:{“value”:“”}}]
[“8”,“10”,“lv:auction-live”,“phx_reply”,{“response”:{“diff”:{“0”:{“3”:{“1”:{“0”:{“1”:{“1”:{“0”:“08/08/2022 à 12:00”}},“6”:{“0”:{“1”:{“0”:{“1”:{“1”:{“d”:[[" phx-click="fast_bid"“,” phx-value-amount="270000"“,{“0”:” class=[some CSS],“3”:{“0”:“5 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click="fast_bid"“,” phx-value-amount="275000"“,{“0”:” class=[some CSS],“1”:{“0”:“”,“1”:“”,“2”:" class=[some CSS]“,“3”:{“0”:“10 000 €”,“s”:0},“s”:1},“s”:2}],[” phx-click="fast_bid"“,” phx-value-amount="280000"“,{“0”:” class=[some CSS]"“,“1”:{“0”:”“,“1”:”“,“2”:” class=[some CSS],“3”:{“0”:“15 000 €”,“s”:0},“s”:1},“s”:2}]],“p”:{“0”:[“\n +\n “,”\n “],“1”:[”\n <button”,“”," type="button"“,”>\n “,”\n \n “],“2”:[”<span",“>\n “,”\n\n”]}}}},“1”:{“1”:{“7”:{“1”:{“2”:" class=[some CSS],“8”:{“1”:{“0”:{“0”:“”,“1”:" class=[some CSS],“2”:" data-phx-link-state="push"“,“3”:” href=[A link],“8”:{“s”:[“”]}}}}}}},“status”:“ok”}]

On prod :

[“8”,“10”,“lv:auction-live”,“event”,{“type”:“click”,“event”:“bid_confirmed”,“value”:{“value”:“”}}]
[“8”,“10”,“lv:auction-live”,“phx_reply”,{“response”:{“diff”:{“0”:{“3”:{“1”:{“0”:{“1”:{“1”:{“0”:“08/08/2022 à 12:00”}},“6”:{“0”:{“1”:{“0”:{“1”:{“1”:{“d”:[[" phx-click="fast_bid"“,” phx-value-amount="280000"“,{“0”:” class="inline-flex cursor-pointer rounded-md shadow-sm w-full"“,“1”:{“0”:”“,“1”:”“,“2”:” class=[some CSS],“3”:{“0”:“5 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click="fast_bid"“,” phx-value-amount="285000"“,{“0”:” class=[some CSS], “3”:{“0”:“10 000 €”,“s”:0},“s”:1},“s”:2}],[" phx-click="fast_bid"“,” phx-value-amount="290000"“,{“0”:” class=[some CSS],“3”:{“0”:“15 000 €”,“s”:0},“s”:1},“s”:2}]],“p”:{“0”:[“\n +\n “,”\n “],“1”:[”\n <button”,“”," type="button"“,”>\n “,”\n \n “],“2”:[”<span",“>\n “,”\n\n”]}}}},“1”:{“1”:{“7”:{“1”:{“2”:" class=[some CSS],“8”:{“1”:{“0”:{“0”:“”,“1”:" class=[some CSS],“2”:" data-phx-link-state="push"“,“3”:” href=[A link],“8”:{“s”:[“”]}}}}}}},“status”:“ok”}]

[tj1]

Wow, ok. Well, then it looks like it must be an issue with the enqueuing?

This isn’t being run on production anymore. What / how is that being called?

[debug] Subscription “Auctions.Projectors.Auction”@“$all” is enqueueing 1 event(s)

Of course, this doesn’t make any sense unless the update is happening without the liveview…since the liveview is returning the thing that you expect? Definitely confusing.

[Nev]

Thanks again for your help.

This is what the module in question looks like, I’m going to do some tests, but I admit that I don’t really master this part of the code because it was written by a former employee.

Auctions.Projectors.Auction

defmodule MyApp.Auctions.Projectors.Auction do
  use Commanded.Projections.Ecto,
    application: MyApp.Auctions.Application,
    repo: MyApp.Repo,
    name: "Auctions.Projectors.Auction",
    consistency: :strong

  require Logger

  alias MyApp.Auctions
  alias MyApp.Auctions.Events.{AuctionOutbid, AuctionStarted, AuctionEnded}

  alias MyApp.Auctions.Jobs.EndAuction, as: EndAuctionJob
  alias MyApp.Auctions.{Auction, Bid}

  alias Ecto.Multi

  alias MyApp.Mailer.{
    AuctionOutbidAgentEmail,
    AuctionOutbidBidderEmail,
    AuctionOutbidParticipantsEmail,
    AuctionStartedAgentEmail,
    AuctionStartedUserEmail,
    AuctionEndedUserEmail,
    AuctionEndedAgentEmail
  }

  project(%AuctionStarted{auction_id: auction_id, end_date: end_date}, fn multi ->
    Logger.info(
      "#{__MODULE__}: %AuctionStarted{auction_id: #{auction_id}, end_date: #{end_date}}"
    )

    multi
    |> update_auction(auction_id, status: :started, end_date: end_date)
    |> Oban.insert(
      :auction_started_user_email,
      AuctionStartedUserEmail.new(%{auction_id: auction_id})
    )
    |> Oban.insert(
      :auction_started_agent_email,
      AuctionStartedAgentEmail.new(%{auction_id: auction_id})
    )
    |> Oban.insert(
      :end_auction_job,
      EndAuctionJob.new(%{id: auction_id, postponed_version: 0}, scheduled_at: end_date)
    )
  end)

  project(%AuctionEnded{auction_id: auction_id}, fn multi ->
    multi
    |> update_auction(auction_id, status: :completed)
    |> Oban.insert(
      :auction_ended_agent_email,
      AuctionEndedAgentEmail.new(%{auction_id: auction_id})
    )
    |> Oban.insert(
      :auction_ended_user_email,
      AuctionEndedUserEmail.new(%{auction_id: auction_id})
    )
  end)

  project(%AuctionOutbid{} = auction_outbid, fn multi ->
    multi
    |> Multi.insert(:bid, %Bid{
      amount: auction_outbid.amount,
      registration_id: auction_outbid.registration_id,
      new_end_date: ensure_utc_date_time(auction_outbid.new_end_date),
      created_at: ensure_utc_date_time(auction_outbid.created_at)
    })
    |> Multi.run(:auction, fn repo, %{bid: bid} ->
      end_date_update =
        if is_nil(auction_outbid.new_end_date) do
          []
        else
          [end_date: ensure_utc_date_time(auction_outbid.new_end_date)]
        end

      update_auction(repo, auction_outbid.auction_id, [best_bid_id: bid.id] ++ end_date_update)
    end)
    |> Multi.run(:auction_outbid_emails, fn _repo, %{bid: bid} ->
      %{bid_id: bid.id}
      |> AuctionOutbidBidderEmail.new()
      |> Oban.insert()

      %{bid_id: bid.id}
      |> AuctionOutbidAgentEmail.new()
      |> Oban.insert()

      %{bid_id: bid.id}
      |> AuctionOutbidParticipantsEmail.new()
      |> Oban.insert()
    end)
    |> maybe_insert_end_auction_job(auction_outbid)
  end)

  def after_update(%AuctionOutbid{auction_id: auction_id}, _metadata, _changes) do
    Auctions.notify(:ok, auction_id, [:auction, :outbid])
    :ok
  end

  def after_update(_event, _metadata, _changes), do: :ok

  defp update_auction(%Multi{} = multi, auction_id, changes) do
    Multi.update_all(multi, :auction, auction_query(auction_id), set: changes)
  end

  defp update_auction(repo, auction_id, changes) do
    repo.update_all(auction_query(auction_id), set: changes)
    |> case do
      {1, nil} -> {:ok, 1}
      error -> error
    end
  end

  defp auction_query(auction_id) do
    from(a in Auction, where: a.id == ^auction_id)
  end

  defp maybe_insert_end_auction_job(multi, auction_outbid) do
    if auction_outbid.new_end_date do
      Oban.insert(
        multi,
        :end_auction_job,
        EndAuctionJob.new(
          %{id: auction_outbid.auction_id, postponed_version: auction_outbid.postponed_version},
          scheduled_at: ensure_utc_date_time(auction_outbid.new_end_date)
        )
      )
    else
      multi
    end
  end

  defp ensure_utc_date_time(nil), do: nil
  defp ensure_utc_date_time(%DateTime{} = datetime), do: datetime

  defp ensure_utc_date_time(ison_datetime) when is_binary(ison_datetime) do
    {:ok, datetime, 0} = DateTime.from_iso8601(ison_datetime)
    datetime
  end
end

Also, if the problem comes from this code, I don’t understand why it would act differently in the production environment vs in local/beta environment (which works correctly). Apart from the mailer, perhaps?

Also, I tried to revert far enough back to a time when I’m sure the bug didn’t exist… Without success. The bug was still present. This confirms that it’s not a recent commit / PR that is the cause…