Sometimes anycable sends responce data twice.

[dmgrinko1]

I mentioned that from time to time anycable sends data response twice, which can brokes frontend logic.
Im using IOS client, same problem with my Postman client. Nothing special in logs, looks like it broadcast once.
Anycable log

[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] RPC Command: <AnyCable::CommandMessage: command: "subscribe", identifier: "{"channel":"NotificationChannel"}", connection_identifiers: "{"non_session_user":"Z2lkOi8vYW55Y2FibGUvVXNlci8xMjg5Mj9pZD0xMjg5MiZlbWFpbCZ1c2VybmFtZT1UZXN0X3VzZXJfMiZjcmVhdGVkX2F0PTIwMjItMDktMTQrMTIlM0ExMSUzQTI2K1VUQyZ1cGRhdGVkX2F0PTIwMjItMTEtMDMrMTElM0EwMyUzQTU2K1VUQyZsb2NrZWQ9ZmFsc2UmYXZhdGFyPW5hcndoYWwmY3VzdG9tX2F2YXRhcj1CODUwRkEyMi05MzAxLTRFMUQtQjRDQS1CMzREMzJBQzk2MTYucG5nJnVzZXJzX2F3YXJkc19jb3VudD0xMyZ1c2VyX2RlY29yYXRpb25zX2NvdW50PTEmZnJpZW5kX3JlbGF0aW9uc19jb3VudD0zJnNlYXJjaGFibGU9dHJ1ZSZzdG9yaWVzX2NvdW50PTImc3RhdHVzPW9mZmxpbmUmcGhvbmVfbnVtYmVyPSUyQjExMTExMTExMTEyJmlzX2RlbGV0ZWQ9ZmFsc2U","uuid":"UhAiivkvbtQVIxHWwpjmvw"}", data: "", env: <AnyCable::Env: url: "http://localhost:8080/cable?token=db190784c14a3fe27afcf8a2bb51ec8a", headers: {"REMOTE_ADDR"=>"127.0.0.1", "cookie"=>""}, cstate: {}, istate: {}>>
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] NotificationChannel is transmitting the subscription confirmation
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] RPC Command: <AnyCable::CommandMessage: command: "message", identifier: "{"channel":"NotificationChannel"}", connection_identifiers: "{"non_session_user":"Z2lkOi8vYW55Y2FibGUvVXNlci8xMjg5Mj9pZD0xMjg5MiZlbWFpbCZ1c2VybmFtZT1UZXN0X3VzZXJfMiZjcmVhdGVkX2F0PTIwMjItMDktMTQrMTIlM0ExMSUzQTI2K1VUQyZ1cGRhdGVkX2F0PTIwMjItMTEtMDMrMTElM0EwMyUzQTU2K1VUQyZsb2NrZWQ9ZmFsc2UmYXZhdGFyPW5hcndoYWwmY3VzdG9tX2F2YXRhcj1CODUwRkEyMi05MzAxLTRFMUQtQjRDQS1CMzREMzJBQzk2MTYucG5nJnVzZXJzX2F3YXJkc19jb3VudD0xMyZ1c2VyX2RlY29yYXRpb25zX2NvdW50PTEmZnJpZW5kX3JlbGF0aW9uc19jb3VudD0zJnNlYXJjaGFibGU9dHJ1ZSZzdG9yaWVzX2NvdW50PTImc3RhdHVzPW9mZmxpbmUmcGhvbmVfbnVtYmVyPSUyQjExMTExMTExMTEyJmlzX2RlbGV0ZWQ9ZmFsc2U","uuid":"UhAiivkvbtQVIxHWwpjmvw"}", data: "{"action":"send_initial_data"}", env: <AnyCable::Env: url: "http://localhost:8080/cable?token=db190784c14a3fe27afcf8a2bb51ec8a", headers: {"REMOTE_ADDR"=>"127.0.0.1", "cookie"=>""}, cstate: {}, istate: {"room"=>"12892"}>>
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] NotificationChannel#send_initial_data

anycable-go

 INFO 2022-11-03T11:20:31.605Z context=main Starting AnyCable 1.2.1 (pid: 81592, open file limit: 10240, gomaxprocs: 8)
 INFO 2022-11-03T11:20:31.606Z context=rpc RPC controller initialized: localhost:50051 (concurrency: 28, enable_tls: false, proto_versions: v1)
 INFO 2022-11-03T11:20:31.606Z context=main Handle WebSocket connections at http://localhost:8080/cable
 INFO 2022-11-03T11:20:31.607Z context=main Handle health connections at http://localhost:8080/health
 INFO 2022-11-03T11:20:31.612Z context=pubsub Subscribed to Redis channel: __anycable__

Development log

[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] NotificationChannel is transmitting the subscription confirmation
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] RPC Command: <AnyCable::CommandMessage: command: "message", identifier: "{"channel":"NotificationChannel"}", connection_identifiers: "{"non_session_user":"Z2lkOi8vYW55Y2FibGUvVXNlci8xMjg5Mj9pZD0xMjg5MiZlbWFpbCZ1c2VybmFtZT1UZXN0X3VzZXJfMiZjcmVhdGVkX2F0PTIwMjItMDktMTQrMTIlM0ExMSUzQTI2K1VUQyZ1cGRhdGVkX2F0PTIwMjItMTEtMDMrMTElM0EwMyUzQTU2K1VUQyZsb2NrZWQ9ZmFsc2UmYXZhdGFyPW5hcndoYWwmY3VzdG9tX2F2YXRhcj1CODUwRkEyMi05MzAxLTRFMUQtQjRDQS1CMzREMzJBQzk2MTYucG5nJnVzZXJzX2F3YXJkc19jb3VudD0xMyZ1c2VyX2RlY29yYXRpb25zX2NvdW50PTEmZnJpZW5kX3JlbGF0aW9uc19jb3VudD0zJnNlYXJjaGFibGU9dHJ1ZSZzdG9yaWVzX2NvdW50PTImc3RhdHVzPW9mZmxpbmUmcGhvbmVfbnVtYmVyPSUyQjExMTExMTExMTEyJmlzX2RlbGV0ZWQ9ZmFsc2U","uuid":"UhAiivkvbtQVIxHWwpjmvw"}", data: "{"action":"send_initial_data"}", env: <AnyCable::Env: url: "http://localhost:8080/cable?token=db190784c14a3fe27afcf8a2bb51ec8a", headers: {"REMOTE_ADDR"=>"127.0.0.1", "cookie"=>""}, cstate: {}, istate: {"room"=>"12892"}>>
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] NotificationChannel#send_initial_data
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-]   News Load (0.4ms)  SELECT "news".* FROM "news" WHERE "news"."user_id" = $1  [["user_id", 12892]]
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-]    (0.4ms)  SELECT COUNT(*) FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read" = $2 AND "notifications"."notification_type" = $3  [["user_id", 12892], ["read", false], ["notification_type", "creation_liked"]]
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-]    (0.3ms)  SELECT COUNT(*) FROM "notifications" WHERE "notifications"."user_id" = $1 AND "notifications"."read" = $2 AND "notifications"."notification_type" = $3  [["user_id", 12892], ["read", false], ["notification_type", "friend_request"]]
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-]   Group Load (0.5ms)  SELECT "groups".* FROM "groups" INNER JOIN "group_members" ON "group_members"."group_id" = "groups"."id" INNER JOIN "message_receivers" ON "message_receivers"."group_member_id" = "group_members"."id" WHERE "group_members"."user_id" = $1 AND "message_receivers"."is_viewed" = $2  [["user_id", 12892], ["is_viewed", false]]
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-]    (0.6ms)  SELECT COUNT(*) FROM "group_invites" WHERE "group_invites"."is_viewed" = $1 AND "group_invites"."invitee_id" = $2 AND "group_invites"."accepted" = $3 AND "group_invites"."rejected" = $4  [["is_viewed", false], ["invitee_id", 12892], ["accepted", false], ["rejected", false]]
[AnyCable sid=Z-Iip2EyNsp6QydgXQp4-] [ActionCable] Broadcasting to notification:12892: {:payload=>{:sent_at=>"2022-11-03T11:04:26.728+0000", :new_content_from_friends=>52, :new_content_user_scenario=>8, :new_content_shared_with_me=>0, :new_content_present=>true, :likes_notifications=>0, :friends_notifications=>0, :chats_notifications=>0, :invites_notifications=>0, :unread_notificat...

notification_channel.rb

class NotificationChannel < ApplicationCable::Channel
  state_attr_accessor :room

  def subscribed
    self.room = non_session_user.id
    stream_for room
    return unless room

    update_user_status(:online)
  end

  def unsubscribed
    return unless room

    update_user_status(:offline)
  end

  def send_initial_data
    ::Websocket::Counters::SendInitialData.perform(non_session_user)
  end

screenshot client

[palkan]

Could you please try to run anycable-go with debug logs (anycable-go -debug)? That should help us to identify the problem. RPC command is called once, right?

So, the duplication could be at the pub/sub level or somewhere else.

Which app do you use for tests, btw?

I would suggest trying ACLI as well (to make sure this is not a client-side problem).

[dmgrinko1]

Yes, sure. Heres a code. But again, it happens from time to time. Sometimes it broadcast ones as expected

module Websocket
  module Counters
    class SendInitialData < ContextBase
      include NewsPresent

      def initialize(user)
        @user = user
      end

      def perform
        ::WebsocketNotifications::Notification.new(NotificationChannel).notify(
          user, new_content_from_friends: 'test new content')
      end

and notify method

     module WebsocketNotifications
 class Notification
   def initialize(channel)
     @channel = channel
   end

   def notify(recipient, data)
     @channel.broadcast_to(recipient.id, payload: payload.merge(data))
   end

   def payload
     { sent_at: ::Formatters.time_with_miliseconds(Time.zone.now) }
   end
 end
end

One options is to drop a debugger at ActionCable.server.broadcast and see why it's called twice (if it is).
I`ve double checked, it 100% called once

def notify(recipient, data)
  @channel.broadcast_to(recipient.id, payload: payload.merge(data))
end

[palkan]

Let's try one more thing: subscribe to Redis via redis-cli and check whether you receive messages twice:

$ redis-cli 

> SUBSCRIBE __anycable__

// wait for messages

[dmgrinko1]

Yep, I receive it twice

1) "message"
2) "__anycable__"
3) "{\"stream\":\"notification:12919\",\"data\":\"{\\\"payload\\\":{\\\"new_content_from_friends\\\":123}}\"}"
1) "message"
2) "__anycable__"
3) "{\"stream\":\"notification:12919\",\"data\":\"{\\\"payload\\\":{\\\"new_content_from_friends\\\":123}}\"}"

What is actually interesting, if I change anything in method which returns double response and send request again (been already subscribed) then I receive response once.
I`m just adding for example 'p' here. And run action 'send_initial_data' again

def send_initial_data
    p 'test'
    ::Websocket::Counters::SendInitialData.perform(non_session_user)
  end

Then I receive once

1) "message"
2) "__anycable__"
3) "{\"stream\":\"notification:12919\",\"data\":\"{\\\"payload\\\":{\\\"new_content_from_friends\\\":123}}\"}"

[palkan]

if I change anything in method which returns double response and send request again (been already subscribed) then I receive response once.

Hm, looks like something related to code reloading 🤔

Could you try setting eager_load = true and cache_classes = false in the app settings and check again?

Btw, do you use AnyCable::Rails.extend_adapter!? Maybe, it's called twice

[dmgrinko1]

Yep. Looks like it was called twice AnyCable::Rails.extend_adapter!. Fixed. Thank you for helping a lot.