KeyError key record not found

[supabase]

KeyError key record not found

[w3b6x9]

@relferreira Realtime RLS no longer returns unchanged_toast. You'll have to set REPLICA IDENTITY to FULL If you would like the unchanged column(s) outputted. Please see #223 for more context.

[kwakwaversal]

Just as a gentle reminder, the latest docker image for supabase/realtime still has this bug. I tracked it down to this issue and rebuilt from the latest code in the repo using the provided Dockerfile and it has resolved.

[w3b6x9]

@relferreira thanks for confirming! we'll look into this

[relferreira]

@w3b6x9 I don't know if it helps, but this table has 2 json columns

[fracek]

The problem seems to be in the channel notifier

realtime/server/lib/realtime/subscribers_notification.ex

Lines 63 to 69 in f830e3e

	Enum.each change.record, fn {k, v} ->
	if v != nil do
	eq = table_topic <> ":" <> k <> "=eq." <> v
	Logger.info inspect(eq)
	RealtimeWeb.RealtimeChannel.handle_realtime_transaction(eq, change)
	end
	end

You can see the definition of NewRecord, UpdateRecord and DeleteRecord are slightly different in that NewRecord has a record field, same for UpdateRecord. When we delete a record there is no new record but only an old_record.

realtime/server/lib/adapters/changes.ex

Lines 5 to 12 in f830e3e

	defmodule Realtime.Adapters.Changes do
	defmodule(Transaction, do: defstruct([:changes, :commit_timestamp]))
	defmodule(NewRecord, do: defstruct([:type, :record, :schema, :table, :columns, :commit_timestamp]))
	defmodule(UpdatedRecord, do: defstruct([:type, :old_record, :record, :schema, :table, :columns, :commit_timestamp]))
	defmodule(DeletedRecord, do: defstruct([:type, :old_record, :schema, :table, :columns, :commit_timestamp]))
	defmodule(TruncatedRelation, do: defstruct([:type, :schema, :table, :commit_timestamp]))
	end

I can fix this quickly to send all types of changes to the channel.

How did you trigger the deletion?

[kiwicopple]

same for UpdateRecord

Note that UpdateRecord will only receive the old value in some cases:

[OPTIONAL] If you want to recieve the old record (previous values) on UDPATE and DELETE, you can set the REPLICA IDENTITY to FULL like this: ALTER TABLE your_table REPLICA IDENTITY FULL;. This has to be set for each table unfortunately.

Logger.info inspect(eq)

We should change this to a debug rather than info

How did you trigger the deletion?

@awalias did you have a repo you're testing on? Othewise I can mock it up into the Next.js example for testing

[awalias]

sorry, this was on a user's box so I don't have the delete details

[awalias]

hotfixed with 2ece7b1 I'm guessing it will need further work to cover the cases you mentioned above?

[kiwicopple]

That's perfect @awalias - should work for UPDATE too

[awalias]

getting a different error now:

2020-06-05 17:18:44.270 [info] Running RealtimeWeb.Endpoint with cowboy 2.6.3 at :::4000 (http)
2020-06-05 17:18:44.270 [info] Access RealtimeWeb.Endpoint at http://localhost:4000
2020-06-05 17:18:44.330 [info] "realtime:public"
2020-06-05 17:18:44.330 [info] "realtime:public:dashboard"
2020-06-05 17:18:44.330 [info] "realtime:public:dashboard:id=eq.<REDACTED>"
2020-06-05 17:18:44.331 [info] "realtime:public:dashboard:name=eq.Saver.nu"
2020-06-05 17:18:44.332 [error] GenServer Realtime.SubscribersNotification terminating
** (ArgumentError) argument error
    :erlang.bit_size(:unchanged_toast)
    (realtime) anonymous fn/3 in Realtime.SubscribersNotification.notify_subscribers/1
    (elixir) lib/enum.ex:789: anonymous fn/3 in Enum.each/2
    (stdlib) maps.erl:232: :maps.fold_1/3
    (elixir) lib/enum.ex:1964: Enum.each/2
    (realtime) lib/realtime/subscribers_notification.ex:64: anonymous fn/3 in Realtime.SubscribersNotification.notify_subscribers/1
    (elixir) lib/enum.ex:1948: Enum."-reduce/3-lists^foldl/2-0-"/3
    (realtime) lib/realtime/subscribers_notification.ex:44: Realtime.SubscribersNotification.notify_subscribers/1
Last message (from #PID<0.2578.0>): {:notify, %Realtime.Adapters.Changes.Transaction{changes: [%Realtime.Adapters.Changes.UpdatedRecord{columns: [%Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "id", type: "uuid", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "name", type: "text", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "products", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "sources", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{<REDACTED>}
2020-06-05 17:18:44.334 [error] GenServer #PID<0.2578.0> terminating
** (stop) exited in: GenServer.call(Realtime.SubscribersNotification, {:notify, %Realtime.Adapters.Changes.Transaction{changes: [%Realtime.Adapters.Changes.UpdatedRecord{columns: [%Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "id", type: "uuid", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "name", type: "text", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "products", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [], name: "sources", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{<REDACTED>)
    ** (EXIT) an exception was raised:
        ** (ArgumentError) argument error
            :erlang.bit_size(:unchanged_toast)
            (realtime) anonymous fn/3 in Realtime.SubscribersNotification.notify_subscribers/1
            (elixir) lib/enum.ex:789: anonymous fn/3 in Enum.each/2
            (stdlib) maps.erl:232: :maps.fold_1/3
            (elixir) lib/enum.ex:1964: Enum.each/2
            (realtime) lib/realtime/subscribers_notification.ex:64: anonymous fn/3 in Realtime.SubscribersNotification.notify_subscribers/1
            (elixir) lib/enum.ex:1948: Enum."-reduce/3-lists^foldl/2-0-"/3
            (realtime) lib/realtime/subscribers_notification.ex:44: Realtime.SubscribersNotification.notify_subscribers/1
    (elixir) lib/gen_server.ex:1009: GenServer.call/3
    (realtime) lib/realtime/replication.ex:84: Realtime.Replication.process_message/2
    (realtime) lib/realtime/replication.ex:56: Realtime.Replication.handle_info/2
    (stdlib) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:epgsql, #PID<0.2579.0>, {:x_log_data, 110555416, 110555416, <<67, 0, 0, 0, 0, 0, 6, 150, 240, 232, 0, 0, 0, 0, 6, 150, 241, 24, 0, 2, 74, 12, 113, 75, 65, 82>>}}

[fracek]

I can't reproduce this. I tried to delete and update rows manually using psql and the process does not crash.

[kiwicopple]

Last message: {:epgsql, #PID<0.2579.0>, {:x_log_data, 110555416, 110555416, <<67, 0, 0, 0, 0, 0, 6, 150, 240, 232, 0, 0, 0, 0, 6, 150, 241, 24, 0, 2, 74, 12, 113, 75, 65, 82>>}}

We might be able to run this through one of the tests scripts to replicate. I'm a bit tied up but can get to this later tonight or early tmr

edit: not sure this is the correct way to replicate. I created a test but it looks like a red herring - the error above is failing on Realtime.SubscribersNotification.notify_subscribers my test is failing in the genserver (likely because I'm not feeding in the correct data or to the correct genserver)

This is the error

Will have to think of another way to replicated

[kiwicopple]

@awalias can you let us know where you are finding these errors? On the customer boxes? Are they definitely on the latest commit?

[kiwicopple]

OK found the cause of the error:

%{
    "id" => "17ce1beb-f4ed-4d6c-a1e0", 
    "name" => "Saver.nu",
    "products" => :unchanged_toast, 
    "showEUR" => "t", 
    "sources" => "[{\"id\": \"c5e37367-39d7-4182-9459\", \"name\": \"redacted\"}}]"
}

Fails on this:

if v != nil do
    eq = table_topic <> ":" <> k <> "=eq." <> v
    RealtimeWeb.RealtimeChannel.handle_realtime_transaction(eq, change)
end

The cause must be sources which is a stringified array "[{\"id\": \"c5e37367-39d7-4182-9459\", \"name\": \"redacted\"}}]", and then it cant send out the notify to the RealtimeChannel

@fracek's suggested improvements would solve this (we wouldn't do an equality check on an array) - table_topic <> ":" <> k <> "=eq." <> v

For now we will have to patch/avoid these sort of strings. Checking the best ways now. @fracek any suggestion?

[kiwicopple]

actually "products" => :unchanged_toast, is the culprit. Fixing

[kiwicopple]

@awalias this is fixed. I don't know the release process that you're using for KPS. Should I bump it ? https://github.com/supabase/realtime#releases

[kiwicopple]

Reopening until this is patched & deployed

[awalias]

thanks guys for getting to the bottom of this

I will bump and release tonight

[awalias]

shipping

[kiwicopple]

Interesting. thanks for the follow up @kwakwaversal - not sure why it isn't yet shipped to docker

[relferreira]

Hello, I'm seen this error in the SaaS Supabase:

[w3b6x9]

@relferreira thanks for reporting your error. Were you listening to row level changes (e.g. teams:id=eq.taua) when this error occurred?

[relferreira]

Hello @w3b6x9, yes:

const mySubscription = supabase
          .from(`teams:id=eq.${team}`)
          .on('UPDATE', payload => {
            console.log('Change received!', payload);
            // setTeamInfo(payload.new);
          })
          .subscribe();

[w3b6x9]

@relferreira alright so you can circumvent this issue by either setting your teams table's replica identity to FULL (ALTER TABLE teams REPLICA IDENTITY FULL;) or simply ignore it since there are no changes.

[relferreira]

Hello @w3b6x9,
It's been a long time, but thank you for the response.

I think that in the latest release, the unchanged_toast is not returning anymore. It is a bug, or was something planned?

Thanks in advance.