anycable / anycable-rails

AnyCable for Ruby on Rails applications
https://anycable.io
MIT License
495 stars 35 forks source link

Issue with anycable-rpc crashing on start `terminate called after throwing an instance of 'std::logic_error'` #184

Closed AndrwM closed 1 year ago

AndrwM commented 1 year ago

Tell us about your environment

Ruby version: 2.7.7

Rails version: 6.0.6

anycable gem version: 1.3.0

anycable-rails gem version: 1.3.7

grpc gem version: 1.54.2

What did you do?

We run a k8s cluster and are using the helmchart to run anycable-go (this seems fine) but we’re using kustomize to configure our anycable rpc server and we’re seeing an error that we haven't been able to find any mention to in any anycable docs, issues, or discussions. Worth noting we are running Alpine.

Here's our configuration

# kubernetes/kustomize/components/anycable-rpc/deployment.yaml
apiVersion: apps/v1
kind: Deployment
metadata:
  name: anycable-rpc
  labels:
    app.kubernetes.io/component: anycable-rpc
spec:
  progressDeadlineSeconds: 600
  replicas: 1
  revisionHistoryLimit: 10
  selector:
    matchLabels:
      app.kubernetes.io/component: anycable-rpc
  strategy:
    type: RollingUpdate
    rollingUpdate:
      maxUnavailable: 1
      maxSurge: 0
  template:
    metadata:
      labels:
        app.kubernetes.io/component: anycable-rpc
    spec:
      containers:
        - name: anycable-rpc
          image: ########################################
          imagePullPolicy: IfNotPresent
          command:
            - /bin/bash
            - -c
          args:
            - /kubernetes_init bundle exec anycable --rpc-host 0.0.0.0:50051 --log-level debug --debug
          env:
            - name: ANYCABLE_RPC_DEBUG
              value: "1"
      dnsPolicy: ClusterFirst
      restartPolicy: Always
      schedulerName: default-scheduler
      securityContext: {}
      terminationGracePeriodSeconds: 30
# kubernetes/kustomize/components/anycable-rpc/kustomization.yaml
apiVersion: kustomize.config.k8s.io/v1beta1
kind: Kustomization

resources:
- deployment.yaml
- service.yaml
# kubernetes/kustomize/components/anycable-rpc/service.yaml
apiVersion: v1
kind: Service
metadata:
  name: anycable-rpc
  labels:
    app.kubernetes.io/component: anycable-rpc
spec:
  selector:
    app.kubernetes.io/component: anycable-rpc
  type: ClusterIP
  ports:
    - port: 50051
      targetPort: 50051
      protocol: TCP
# kustomize/environments/development/#########/web-ingress.yaml
apiVersion: networking.k8s.io/v1
kind: Ingress
metadata:
  name: ingress-web
  annotations:
    alb.ingress.kubernetes.io/certificate-arn: #################################
    alb.ingress.kubernetes.io/load-balancer-attributes: access_logs.s3.enabled=true,access_logs.s3.bucket=elb-application-logs-dev,access_logs.s3.prefix=log
    alb.ingress.kubernetes.io/actions.anycable-go-anycable-go: '[{"HTTP": 8080}]'
    external-dns.alpha.kubernetes.io/hostname: #################,###################
    cert-manager.io/cluster-issuer: "letsencrypt"
    kubernetes.io/tls-acme: "true"
spec:
  tls:
    - secretName: kajabi-products-server-tls
      hosts:
        - ###############################
        - ###############################
        - ###############################
        - ###############################
  rules:
    - http:
        paths:
          - path: /cable
            pathType: ImplementationSpecific
            backend:
              service:
                name: anycable-go-anycable-go
                port:
                  name: use-annotation
          - path: /*
            pathType: ImplementationSpecific
            backend:
              service:
                name: web-active
                port:
                  name: use-annotation
# Gemfile
gem "anycable-rails", "~> 1.3.7"
gem "grpc", "~> 1.54.0", platforms: :ruby
# ...
# config/environments/production.rb
  config.after_initialize do
    if AnyCable::Rails.enabled?
      config.action_cable.allowed_request_origins = ENV.fetch("ACTION_CABLE_ALLOWED_REQUEST_ORIGINS", "https://#{AppConfig.primary_host}").split(",").map(&:strip)
      config.action_cable.url = ActionCable.server.config.url = ENV.fetch("CABLE_URL", "wss://#{AppConfig.primary_host}/cable")
    end
  end

What did you expect to happen?

anycable-rpc should start without creshing

What actually happened?

(1) anycable-rpc is crashing with an output of:

[2023-05-18T14:40:46.143948 #1]  INFO -- : Starting AnyCable RPC server (pid: 1)
[2023-05-18T14:40:46.144503 #1]  INFO -- : AnyCable version: 1.3.0 (proto_version: v1)
[2023-05-18T14:40:46.144592 #1]  INFO -- : Serving Rails application from ./config/environment.rb
[2023-05-18T14:40:46.144690 #1]  INFO -- : gRPC version: 1.54.2
terminate called after throwing an instance of 'std::logic_error'
  what():  basic_string::_S_construct null not valid

(2) We see a websocket connection in the frontend:

Andrew McIntee Screencap 2023-05-18 at 11 42 46@2x

(3) We're seeing logs of

[2023-05-18 15:22:40.219] ERROR -- Looks like you're trying to connect to Rails Action Cable server, not an AnyCable one.
Please make sure your client is configured to connect to AnyCable server.

(4) We're seeing Rails logs from the ActionCable channels indicating that a subscription has occurred success

I, [2023-05-18T15:23:41.075535 #19]  INFO -- : [format:json {"message":"ApplicationCable::Connection::Connect","current_user_id":149}
I, [2023-05-18T15:42:33.259872 #19]  INFO -- : [format:json] {"message":"Admin::Themes::ThemeSettings::LastUpdateChannel::Subscribed","current_user_id":149,"theme_id":"534"}

(5) Within the Rails console we are seeing that AnyCable is enabled

irb(main):012:0> AnyCable::Rails.enabled?
=> true

irb(main):018:0> AnyCable.config
=> #<AnyCable::Config:0x00000000003e1750 config_name="anycable" env_prefix="ANYCABLE" values={:presets=>[],
  :broadcast_adapter=>"redis",
  :redis_url=>"##########################",
  :redis_sentinels=>nil,
  :redis_channel=>"__anycable__",
  :redis_tls_verify=>false,
  :redis_tls_client_cert_path=>nil,
  :redis_tls_client_key_path=>nil,
  :nats_servers=>["nats://localhost:4222"],
  :nats_channel=>"__anycable__",
  :nats_dont_randomize_servers=>false,
  :nats_options=>{},
  :http_broadcast_url=>"http://localhost:8090/_broadcast",
  :http_broadcast_secret=>nil,
  :log_file=>nil,
  :log_level=>"debug",
  :debug=>false,
  :http_health_port=>nil,
  :http_health_path=>"/health",
  :version_check_enabled=>true,
  :sid_header_enabled=>true,
  :rpc_host=>"0.0.0.0:50051",
  :rpc_pool_size=>30,
  :rpc_max_waiting_requests=>20,
  :rpc_poll_period=>1,
  :rpc_pool_keep_alive=>0.25,
  :rpc_server_args=>{},
  :rpc_max_connection_age=>300,
  :log_grpc=>true,
  :access_logs_disabled=>true,
  :persistent_session_enabled=>false,
  :embedded=>false
  }>

We're unable to find additional logging or information on the anycable-rpc issue and we're hopeful someone in the community may know where to look. 🤝 🙏 Thanks for your time.

palkan commented 1 year ago

Looks like you're trying to connect to Rails Action Cable server

This line indicates that your clients try to connect to the built-in Action Cable server; can you show the contents of the "Headers" tabs from the browser console? What is the URL?

How do you configure the client? Do you use the action_cable_meta_tag to inject the URL into an HTML or maybe you provide an explicit URL value to the createConsumer function?

sdhull commented 1 year ago

It looks like we misconfigured ingress. Previously we had cargo-culted pathType: ImplementationSpecific and for port name: use-annotation but when we swapped this for pathType: Exact and for port number: 8080, we were able to see traffic in the logs of anycable-go pod!!

I think you can close this, sorry for the noise and thank you so much for the responses ❤️