Realtime dropping connection intermittently

[awalias]

Running the test script in supabase-js https://github.com/supabase/supabase/blob/master/libraries/supabase-js/test/integration/testRealtime.js

I get intermittent Network timeout. Still waiting... and REALTIME DISCONNECTED errors

When I inspect the server logs, there are a couple of errors logged:

127.0.0.1 - - [25/Feb/2020:17:26:17 +0000] "POST /messages HTTP/1.1" 201 - "" ""
17:26:18.082 [info] "realtime:public"
17:26:18.082 [info] "realtime:public:messages"
17:26:18.083 [info] "realtime:public:messages:channel_id=eq.1"
17:26:18.085 [error] GenServer #PID<0.2564.0> terminating
** (ArgumentError) argument error
    :erlang.bit_size(nil)
    (realtime) anonymous fn/3 in Realtime.Replication.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/replication.ex:237: anonymous fn/3 in Realtime.Replication.notify_subscribers/1
    (elixir) lib/enum.ex:1948: Enum."-reduce/3-lists^foldl/2-0-"/3
    (realtime) lib/realtime/replication.ex:217: Realtime.Replication.notify_subscribers/1
Last message: {:epgsql, #PID<0.2565.0>, {:x_log_data, 23616408, 23616408, <<67, 0, 0, 0, 0, 0, 1, 104, 91, 104, 0, 0, 0, 0, 1, 104, 91, 152, 0, 2, 66, 104, 141, 229, 100, 110>>}}

and

17:26:18.151 [info] CONNECTED TO RealtimeWeb.UserSocket in 178µs
  Transport: :websocket
  Serializer: Phoenix.Socket.V1.JSONSerializer
  Connect Info: %{}
  Parameters: %{"vsn" => "1.0.0"}
17:26:18.153 [error] GenServer #PID<0.2569.0> terminating
** (KeyError) key :record not found in: %Realtime.Adapters.Changes.DeletedRecord{columns: [%Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "id", type: "int8", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "inserted_at", type: "timestamp", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "updated_at", type: "timestamp", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "data", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "message", type: "text", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "user_id", type: "int8", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "channel_id", type: "int8", type_modifier: 4294967295}], commit_timestamp: ~U[2020-02-25 17:26:18Z], old_record: %{"channel_id" => "1", "data" => nil, "id" => "23", "inserted_at" => "2020-02-25 17:26:18.071593", "message" => "delete test", "updated_at" => "2020-02-25 17:26:18.071593", "user_id" => "1"}, schema: "public", table: "messages", type: "DELETE"}
    (realtime) lib/realtime/replication.ex:237: anonymous fn/3 in Realtime.Replication.notify_subscribers/1
    (elixir) lib/enum.ex:1948: Enum."-reduce/3-lists^foldl/2-0-"/3
    (realtime) lib/realtime/replication.ex:217: Realtime.Replication.notify_subscribers/1
    (realtime) lib/realtime/replication.ex:82: Realtime.Replication.process_message/2
    (realtime) lib/realtime/replication.ex:54: 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.2570.0>, {:x_log_data, 23616632, 23616632, <<67, 0, 0, 0, 0, 0, 1, 104, 92, 72, 0, 0, 0, 0, 1, 104, 92, 120, 0, 2, 66, 104, 141, 229, 243, 123>>}}

not sure if these are responsible but probably worth cleaning up anyway

[kiwicopple]

Dubugged these a bit
I think the culprit is this line.

As DELETE transactions don't have change.record to enumerate over (unless the user has set REPLICA IDENTITY FULL in postgres). It does have the "old_record" though (i think), so we might be able to enumerate over that instead

[kiwicopple]

Looks good. The patch for the other issue just a matter of wrapping this block with an if change.record

The reason why (i think) is that this function is getting called when the replication starts, and there are no actual changes in the transaction.

Let's test your changes for now though. Do you need me to push to docker hub?

[awalias]

last remaining thing to fix is 04:33:14.166 [error] GenServer #PID<0.2513.0> terminating ** (KeyError) key :record not found in: %Realtime.Adapters.Changes.DeletedRecord{columns: [%Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "id", type: "int8", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "inserted_at", type: "timestamp", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "updated_at", type: "timestamp", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "data", type: "jsonb", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "message", type: "text", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "user_id", type: "int8", type_modifier: 4294967295}, %Realtime.Decoder.Messages.Relation.Column{flags: [:key], name: "channel_id", type: "int8", type_modifier: 4294967295}], commit_timestamp: ~U[2020-03-16 04:33:14Z], old_record: %{"channel_id" => "1", "data" => nil, "id" => "50", "inserted_at" => "2020-03-16 04:33:14.144909", "message" => "delete test", "updated_at" => "2020-03-16 04:33:14.144909", "user_id" => "1"}, schema: "public", table: "messages", type: "DELETE"}

[awalias]

oh sorry just saw you already posted the fix above, will make the change now, I tested the previous fix and it works well

[awalias]

fixed in 0.7.2