sub close request for missing client

[jangowu]

Hello, there is a occasional problem that i use durable subscriptions.
The ClientID and Channel used by this client will never work
until the stan server is restarted or change one of them(ClientID,Channel).

The problem is as follows:

the go client prints
”stan: unknown clientID“

the stan server prints
"sub close request for missing client".

software informations:

nats server version: 2.2.6
stan server version: 0.22.0
nats go client version: github.com/nats-io/nats.go v1.13.0
stan go client version: github.com/nats-io/stan.go v0.10.2

the nats server configuration file

 nats.conf: |
    pid_file: "/var/run/nats/nats.pid"
    http: 8222
    cluster {
      port: 6222
      routes [
        nats://nats-0.nats-mgmt.nats.svc.cluster.local:6222
        nats://nats-1.nats-mgmt.nats.svc.cluster.local:6222
        nats://nats-2.nats-mgmt.nats.svc.cluster.local:6222
      ]
      tls: {
        ca_file: /etc/nats-routes-tls-certs/ca.crt
        cert_file: /etc/nats-routes-tls-certs/tls.crt
        key_file: /etc/nats-routes-tls-certs/tls.key
      }
      connect_retries: 10
    }
    tls: {
    verify:   true
    ca_file: /etc/nats-server-tls-certs/ca.crt
    cert_file: /etc/nats-server-tls-certs/tls.crt
    key_file: /etc/nats-server-tls-certs/tls.key
    }
    leafnodes {
      port: 7422
      tls: {
        verify:   true
        ca_file: /etc/nats-server-tls-certs/ca.crt
        cert_file: /etc/nats-server-tls-certs/tls.crt
        key_file: /etc/nats-server-tls-certs/tls.key
      },
    }

the stan server configuration file

  stan.conf: |
    http: 8222

    streaming {
      id: test-cluster
      store: file
      dir: /data/stan/store
      ft_group_name: "cloud-cluster"
      file_options {
          buffer_size: 32mb
          slice_max_bytes: 512mb
          parallel_recovery: 64
      }
      nats_server_url: "nats://nats.nats.svc:4222"
      partitioning: true
      replace_durable: true
      store_limits {
          channels: {
           cloud.>: {}
          }
          max_channels: 0
          max_msgs: 0
          max_bytes: 256gb
          max_age: 168h
          max_subs: 0
      }
      tls: {
      verify:   true
      client_cert: "/etc/nats-client-tls-certs/tls.crt"
      client_key: "/etc/nats-client-tls-certs/tls.key"
      client_ca: "/etc/nats-client-tls-certs/ca.crt"

     }
    }

The go client arguments:

clientID: system-client-123
Channel: cloud.system.channel.1234.files
durableName: stan.DurableName("my-durable")

The stan server logs:

[1] 2022/02/08 07:15:33.620592 [INF] STREAM: Channel "cloud.system.channel.1234.files" has been created
[1] 2022/02/08 07:16:36.344782 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 07:17:02.161002 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 07:17:45.221130 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 07:21:37.676233 [INF] STREAM: Channel "cloud.system.channel123.files" has been created
[1] 2022/02/08 08:25:42.036405 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:25:44.012622 [ERR] STREAM: [Client:system-client-123] sub close request for missing inbox _INBOX.FvMNRCapuTupwo4z5bXT6q
[1] 2022/02/08 08:25:47.684652 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:25:51.283992 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:25:52.307378 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:25:53.067049 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:25:55.068352 [ERR] STREAM: [Client:system-client-123] sub close request for missing inbox _INBOX.JfB6D587aKDfylQRA8hfdU
[1] 2022/02/08 08:26:04.266840 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:26:08.718376 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:26:10.054393 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:26:11.012525 [ERR] STREAM: [Client:system-client-123] sub close request for missing client
[1] 2022/02/08 08:27:10.317308 [INF] STREAM: Channel "cloud.system.channel1234.files" has been created
[1] 2022/02/08 08:28:23.754350 [INF] STREAM: Channel "cloud.system.channel.12345.files" has been created
[1] 2022/02/08 08:32:21.282055 [ERR] STREAM: [Client:system-client-123] sub close request for missing client

[kozlovic]

@jangowu You reported this issue in the past, but unfortunately, I still don't have more information on how to reproduce this. Few questions:

• You wrote the Go client writes: stan: unknown clientID: what API call raises this?
• Have you tried restarting your application, instead of restarting the server?
• I see this at the top of the log excerpt: Channel "cloud.system.channel.1234.files" has been created, but then later on I see Channel "cloud.system.channel1234.files" has been created, which is not the same (a . is missing). Is it that you have changed the channel names for the report and this is a typo? Should they have been the same? If they are supposed to be the same, how come the same channel gets created twice?

In the past I had ask you if you could provide steps to reproduce, or at least more details on how your application is written: how you connect (including options to the connect), do you setup a connection lost handler, if so what do you do in there, etc...
The server is running in FT mode, was there failover happening before the issue started to occur? Is the state properly shared between the FT servers? That is, is the directory /data/stan/store the same and available to all nodes that run the NATS Streaming server? (Remember, with FT the datastore is shared between nodes, think SAN or NFS, etc..).

I am trying to get as much information as possible to be able to reproduce the issue.

[jangowu]

@jangowu You reported this issue in the past, but unfortunately, I still don't have more information on how to reproduce this. Few questions:

• You wrote the Go client writes: stan: unknown clientID: what API call raises this?
• Have you tried restarting your application, instead of restarting the server?
• I see this at the top of the log excerpt: Channel "cloud.system.channel.1234.files" has been created, but then later on I see Channel "cloud.system.channel1234.files" has been created, which is not the same (a . is missing). Is it that you have changed the channel names for the report and this is a typo? Should they have been the same? If they are supposed to be the same, how come the same channel gets created twice?

In the past I had ask you if you could provide steps to reproduce, or at least more details on how your application is written: how you connect (including options to the connect), do you setup a connection lost handler, if so what do you do in there, etc... The server is running in FT mode, was there failover happening before the issue started to occur? Is the state properly shared between the FT servers? That is, is the directory /data/stan/store the same and available to all nodes that run the NATS Streaming server? (Remember, with FT the datastore is shared between nodes, think SAN or NFS, etc..).

I am trying to get as much information as possible to be able to reproduce the issue.

I am sorry,I can't provide the replay step because it very haphazard and rare.

• use stan 'Subscribe(subject string, cb MsgHandler, opts ...SubscriptionOption) (Subscription, error)' raises stan: unknown clientID

• The client cannot be restored when I restart my applications.
  The test found that recovery could only be achieved by restarting the stan server and modifying the client Channel name.

• I know the difference. this is my test. the client use same clientID . the client Channel use Channel "cloud.system.channel.1234.files" raises stan: unknown clientID error. but i change the client Channel to Channel "cloud.system.channel1234.files" and it can work.

• My stan server is three nodes but all mounted on the same NFS storage.and there was no reelection and restart when the problem arose.
  My application will exit if the subscription fails,It's not going to reconnect.

[kozlovic]

@jangowu I have merged a fix for what I believe was causing the issue you observed. It was difficult to find and with original code I had to put delays and have a specific sequence of events to be able to reproduce. With the changes in the PR, I believe that the issue should not happen again. Please upgrade at your convenience and let me know if the issue is still present. Thank you for your patience.

[jangowu]

Thank you for fixing it so quickly.Best wishes.