search

anycable / anycable-go

AnyCable real-time server
https://anycable.io
MIT License
377 stars 65 forks source link

Intermittent GoAway Error with ENHANCE_YOUR_CALM Code in AnyCable-Go 1.4.8 Despite Functional Setup #204

Closed jnstq closed 7 months ago

jnstq commented 7 months ago

Tell us about your environment

AnyCable-Go version: 1.4.8-f9dd29c

AnyCable gem version: 1.4.4

What did you do?

I have this docker-compose setup.

services:
  web:
    build: .
    restart: always
    depends_on:
      - db
      - redis
    env_file:
      - docker-compose.env
    labels:
      - "traefik.enable=true"
      - "traefik.http.routers.web.entrypoints=web"
      - "traefik.http.routers.web.rule=Host(`example.com`)"

  cable:
    build: .
    restart: always
    depends_on:
      - db
      - redis
    environment:
      - ANYCABLE_DEPLOYMENT=true
      - ANYCABLE_PORT=3331
      - ANYCABLE_HOST=0.0.0.0
      - ANYCABLE_RPC_HOST=0.0.0.0:50051
      - ANYCABLE_METRICS_LOG=true
    env_file:
      - docker-compose.env
    labels:
      - "traefik.enable=true"
      - "traefik.http.routers.cable.entrypoints=web"
      - "traefik.http.routers.cable.rule=Host(`example.com`)") && PathPrefix(`/cable`)"
      - "traefik.http.services.cable.loadbalancer.server.port=3331"

  redis:
    image: redis:7.2
    restart: always
    command: ["redis-server", "--maxmemory", "250mb", "--maxmemory-policy", "noeviction"]
    volumes:
      - "redis_data:/data"

  db:
    image: postgres:16.2
    restart: always
    volumes:
      - "db_data:/var/lib/postgresql/data"
    env_file:
      - docker-compose.env

  traefik:
    image: traefik:v2.9
    container_name: traefik
    command:
      - "--api.insecure=true"
      - "--providers.docker=true"
      - "--providers.docker.exposedbydefault=false"
      - "--entrypoints.web.address=:80"
    ports:
      - "80:80"
      - "8080:8080"
    volumes:
      - "/var/run/docker.sock:/var/run/docker.sock:ro"

volumes:
  redis_data:
  db_data:

What did you expect to happen?

It runs any errors.

What actually happened?

I see this error in the log output, but everything seems to work. Can I just ignore it?

cable-1        | 2024/03/28 11:17:49 ERROR: [transport] Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII "too_many_pings".
cable-1        | D 2024-03-28T11:17:49.381Z context=grpc disconnected from 127.0.0.1:50051
cable-1        | D 2024-03-28T11:17:49.382Z context=grpc connected to 127.0.0.1:50051
redis-1        | 1:C 28 Mar 2024 11:15:48.532 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis-1        | 1:C 28 Mar 2024 11:15:48.532 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis-1        | 1:C 28 Mar 2024 11:15:48.532 * Redis version=7.2.4, bits=64, commit=00000000, modified=0, pid=1, just started
redis-1        | 1:C 28 Mar 2024 11:15:48.532 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
redis-1        | 1:M 28 Mar 2024 11:15:48.533 * monotonic clock: POSIX clock_gettime
redis-1        | 1:M 28 Mar 2024 11:15:48.533 * Running mode=standalone, port=6379.
redis-1        | 1:M 28 Mar 2024 11:15:48.534 * Server initialized
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * Loading RDB produced by version 7.2.4
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * RDB age 5 seconds
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * RDB memory usage when created 1.33 Mb
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * Done loading RDB, keys loaded: 40, keys expired: 0.
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * DB loaded from disk: 0.002 seconds
redis-1        | 1:M 28 Mar 2024 11:15:48.535 * Ready to accept connections tcp
db-1           | 2024-03-28 11:15:48.558 UTC [1] LOG:  starting PostgreSQL 16.2 (Debian 16.2-1.pgdg120+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
db-1           | 2024-03-28 11:15:48.558 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db-1           | 2024-03-28 11:15:48.558 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db-1           | 2024-03-28 11:15:48.560 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db-1           | 2024-03-28 11:15:48.565 UTC [30] LOG:  database system was shut down at 2024-03-28 11:15:43 UTC
db-1           | 2024-03-28 11:15:48.570 UTC [1] LOG:  database system is ready to accept connections
traefik        | time="2024-03-28T11:15:48Z" level=info msg="Configuration loaded from flags."
web-1          | [7] Puma starting in cluster mode...
web-1          | [7] * Puma version: 6.4.0 (ruby 3.3.0-p0) ("The Eagle of Durango")
web-1          | [7] *  Min threads: 5
web-1          | [7] *  Max threads: 5
web-1          | [7] *  Environment: production
web-1          | [7] *   Master PID: 7
web-1          | [7] *      Workers: 2
web-1          | [7] *     Restarts: (✔) hot (✖) phased
web-1          | [7] * Preloading application
cable-1        | Anyway Config was loaded before Rails. Activating Anyway Config Rails plugins now.
cable-1        | NOTE: Already loaded configs were provisioned without Rails-specific sources.
cable-1        | Starting AnyCable RPC server (pid: 7)
web-1          | [7] * Listening on http://0.0.0.0:3000
web-1          | [7] Use Ctrl-C to stop
cable-1        | AnyCable version: 1.4.4 (proto_version: v1)
cable-1        | Serving Rails application from ./config/anycable.rb
cable-1        | gRPC version: 1.62.0
cable-1        | handling /anycable.RPC/Connect with #<Method: AnyCable::GRPC::Handler#connect(request, call) /usr/local/bundle/ruby/3.3.0/gems/anycable-core-1.4.4/lib/anycable/grpc/handler.rb:12>
cable-1        | handling /anycable.RPC/Command with #<Method: AnyCable::GRPC::Handler#command(request, call) /usr/local/bundle/ruby/3.3.0/gems/anycable-core-1.4.4/lib/anycable/grpc/handler.rb:20>
cable-1        | handling /anycable.RPC/Disconnect with #<Method: AnyCable::GRPC::Handler#disconnect(request, call) /usr/local/bundle/ruby/3.3.0/gems/anycable-core-1.4.4/lib/anycable/grpc/handler.rb:16>
cable-1        | handling /grpc.health.v1.Health/Check with #<Method: Grpc::Health::Checker#check(req, _call) /usr/local/bundle/ruby/3.3.0/gems/grpc-1.62.0-x86_64-linux/src/ruby/pb/grpc/health/checker.rb:34>
cable-1        | handling /grpc.health.v1.Health/Watch with #<Method: Grpc::Health::Checker(Grpc::Health::V1::Health::Service)#watch(*) /usr/local/bundle/ruby/3.3.0/gems/grpc-1.62.0-x86_64-linux/src/ruby/lib/grpc/generic/service.rb:99>
cable-1        | Broadcasting Redis channel: __anycable__
web-1          | [7] - Worker 0 (PID: 12) booted in 0.0s, phase: 0
cable-1        | RPC server is starting...
web-1          | [7] - Worker 1 (PID: 19) booted in 0.0s, phase: 0
cable-1        | RPC server is listening on 0.0.0.0:50051 (workers_num: 30)
cable-1        | Started command: anycable-go (pid: 53)
cable-1        | D 2024-03-28T11:15:54.640Z context=main 🔧 🔧 🔧 Debug mode is on 🔧 🔧 🔧
cable-1        | I 2024-03-28T11:15:54.640Z context=main Starting AnyCable 1.4.8-f9dd29c (pid: 53, open file limit: 1048576, gomaxprocs: 4)
cable-1        | I 2024-03-28T11:15:54.641Z context=main Anonymized telemetry is on. Learn more: https://docs.anycable.io/anycable-go/telemetry
cable-1        | I 2024-03-28T11:15:54.641Z context=main Using no-op (legacy) broker
cable-1        | D 2024-03-28T11:15:54.641Z context=disconnector Calls rate: 10ms         
cable-1        | I 2024-03-28T11:15:54.642Z context=rpc RPC controller initialized: 0.0.0.0:50051 (concurrency: 28, impl: grpc, enable_tls: false, proto_versions: v1)
cable-1        | I 2024-03-28T11:15:54.643Z context=main Handle WebSocket connections at http://0.0.0.0:3331/cable
cable-1        | I 2024-03-28T11:15:54.643Z context=main Handle health requests at http://0.0.0.0:3331/health
cable-1        | D 2024-03-28T11:15:54.642Z context=grpc connected to 127.0.0.1:50051
cable-1        | I 2024-03-28T11:15:54.643Z context=broadcast provider=redis Subscribed to Redis channel: __anycable__
cable-1        | 
cable-1        | D 2024-03-28T11:15:54.644Z context=main Go pools initialized (remote commands: 256)
cable-1        | D 2024-03-28T11:15:54.644Z context=http Starting WebSocket server at http://0.0.0.0:3331
cable-1        | I 2024-03-28T11:15:54.644Z context=metrics Log metrics every 15s    
worker-1       | 2024-03-28T11:15:54.659Z pid=1 tid=bbt INFO: Booted Rails 7.1.3 application in production environment
worker-1       | 2024-03-28T11:15:54.660Z pid=1 tid=bbt INFO: Running in ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux]
worker-1       | 2024-03-28T11:15:54.660Z pid=1 tid=bbt INFO: See LICENSE and the LGPL-3.0 for licensing details.
worker-1       | 2024-03-28T11:15:54.660Z pid=1 tid=bbt INFO: Upgrade to Sidekiq Pro for more features and support: https://sidekiq.org
worker-1       | 2024-03-28T11:15:54.660Z pid=1 tid=bbt INFO: Sidekiq 7.2.0 connecting to Redis with options {:size=>10, :pool_name=>"internal", :url=>"redis://redis:6379"}
worker-1       | 2024-03-28T11:15:54.663Z pid=1 tid=bbt INFO: Sidekiq 7.2.0 connecting to Redis with options {:size=>12, :pool_name=>"default", :url=>"redis://redis:6379"}
cable-1        | D 2024-03-28T11:15:59.274Z sid=vNL--Xe8R6z4FS5s5DBwG WebSocket session established
cable-1        | deadline is 1969-12-31 23:59:59 +0000; (now=2024-03-28 11:15:59 +0000)
cable-1        | schedule another job
cable-1        | D 2024-03-28T11:15:59.280Z context=rpc sid=vNL--Xe8R6z4FS5s5DBwG Authenticate response: status:SUCCESS identifiers:"{\"current_user\":\"84b18bf53411779098df01e9cddb4eff\"}" transmissions:"{\"type\":\"welcome\",\"sid\":\"vNL--Xe8R6z4FS5s5DBwG\"}" env:<cstate:<key:"__ltags__" value:"[\"ActionCable\",\"84b18bf53411779098df01e9cddb4eff\"]" > > 
cable-1        | D 2024-03-28T11:15:59.280Z context=hub sid=vNL--Xe8R6z4FS5s5DBwG Registered with identifiers: {"current_user":"84b18bf53411779098df01e9cddb4eff"}
cable-1        | D 2024-03-28T11:15:59.299Z context=node sid=vNL--Xe8R6z4FS5s5DBwG Incoming message: &{subscribe {"channel":"ScheduleChannel","id":1} <nil> {0 map[]}}
cable-1        | deadline is 1969-12-31 23:59:59 +0000; (now=2024-03-28 11:15:59 +0000)
...
cable-1        | 2024/03/28 11:17:49 ERROR: [transport] Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII "too_many_pings".
cable-1        | D 2024-03-28T11:17:49.381Z context=grpc disconnected from 127.0.0.1:50051
cable-1        | D 2024-03-28T11:17:49.382Z context=grpc connected to 127.0.0.1:50051
palkan commented 7 months ago

I see this error in the log output, but everything seems to work. Can I just ignore it?

Yeah, feel free to ignore it. Go gRPC client automatically adjust its settings over time to match the server keepalive configuration, it's not a problem (and it's been there forever but stayed unnoticed because grpc-go reported it with the info level; and now it's changed).

We're updating the internal server settings to match the client's one in v1.5 (which is coming very soon), so this log line should disappear.