GoulvenClech

Liveview doesn’t update an element in production but does locally

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 Flyio forum.

7 comments

/phoenix #liveview #deploy #flyio

0 1126 7

2022-08-10 14:45:47 UTC

First 7 of 7 Posts

tcoopman

It looks like your projection doesn’t receive the event in production?

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

I would look into why that is the case first.

Post #1

evadne

How many nodes have you deployed?

Post #2

GoulvenClech

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?

Finally, 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…

Post #3

GoulvenClech

Sorry for my lack of experience, but how can I get this information easily?

Post #4

evadne

To see the specific VM status, run fly status --all to get a list of VMs

See if you have more than one

Post #5

tcoopman

It’s a bit hard with the limited amount of code available, but it looks like the projection and in particular project(%AuctionOutbid{} = auction_outbid... is responsible for updating the auction amount?

So my guess would be that the projection doesn’t run and that’s the reason your ui doesn’t update (because the read model of the auction is not really updated)

Now why it doesn’t run, that’s hard to see with the amount of code. I would guess a business logic error somewhere?
The last line of the log in production doesn’t seem to appear locally:
[debug] QUERY OK source=“bids” db=6.9ms queue=0.1ms idle=1222.2ms

Can you find out where that comes from, and why it’s printed?

Post #6