nats.net: The client is not able to reconnect to the server

Description

When using the dotnet nats client library (with SetUserCredentialHandlers) and a nats server, using the accounts authentication mechanism with the full nats resolver, the dotnet client is not able to reconnect with the system account upon server restart.

nats-server: 2.4.0 nats.net: 0.12.0.0

Reproduction

Prerequisite : docker

  1. Download NatsClientTest.zip
  2. Extract
  3. Check the docker-compose file to have an idea of what will happen next
  4. Run docker-compose up
  5. In another terminal, run docker-compose restart server

Expected result

  • The server restart
  • The dotnet client reconnects
  • The nats-box tools reconnects

Actual result

  • The server restart
  • The dotnet client does not reconnect because of an Authorization Violation (signature not verified)
  • The nats-box tools reconnects

Other tests have demonstrated that the client is also not able to connect by recreating a new connection. Restarting the dotnet client process allows it to reconnect successfully.

Full compose log:

docker-compose up
Starting natsclienttest_server_1 ... done
Starting natsclienttest_client_1 ... done
Starting natsclienttest_tools_1  ... done
Attaching to natsclienttest_server_1, natsclienttest_client_1, natsclienttest_tools_1
server_1  | [1] 2021/09/07 13:58:40.538425 [INF] Starting nats-server
server_1  | [1] 2021/09/07 13:58:40.538466 [INF]   Version:  2.4.0
server_1  | [1] 2021/09/07 13:58:40.538468 [INF]   Git:      [e49eb66]
server_1  | [1] 2021/09/07 13:58:40.538471 [DBG]   Go build: go1.16.7
server_1  | [1] 2021/09/07 13:58:40.538478 [INF]   Name:     test-server
server_1  | [1] 2021/09/07 13:58:40.538483 [INF]   ID:       NBH6PFXIJUC5K76UXUDBJPMOTWFNSAHGEJ6MM6YNY6VUPSNHQO6ZJUYA
server_1  | [1] 2021/09/07 13:58:40.538493 [INF] Using configuration file: /config/nats-server.conf
server_1  | [1] 2021/09/07 13:58:40.538495 [INF] Trusted Operators
server_1  | [1] 2021/09/07 13:58:40.538497 [INF]   System  : ""
server_1  | [1] 2021/09/07 13:58:40.538499 [INF]   Operator: "tank"
server_1  | [1] 2021/09/07 13:58:40.538516 [INF]   Issued  : 2021-09-07 13:32:43 +0000 UTC
server_1  | [1] 2021/09/07 13:58:40.538520 [INF]   Expires : 1970-01-01 00:00:00 +0000 UTC
server_1  | [1] 2021/09/07 13:58:40.539158 [INF] Managing all jwt in exclusive directory /nsc/accounts-server
server_1  | [1] 2021/09/07 13:58:40.539374 [INF] Starting http monitor on 0.0.0.0:8222
server_1  | [1] 2021/09/07 13:58:40.539457 [INF] Listening for websocket clients on ws://0.0.0.0:443
server_1  | [1] 2021/09/07 13:58:40.539465 [WRN] Websocket not configured with TLS. DO NOT USE IN PRODUCTION!
server_1  | [1] 2021/09/07 13:58:40.539471 [DBG] Get non local IPs for "0.0.0.0"
server_1  | [1] 2021/09/07 13:58:40.539622 [DBG]   ip=172.21.0.2
server_1  | [1] 2021/09/07 13:58:40.539669 [INF] Listening for leafnode connections on 0.0.0.0:7422
server_1  | [1] 2021/09/07 13:58:40.539677 [DBG] Get non local IPs for "0.0.0.0"
server_1  | [1] 2021/09/07 13:58:40.539796 [DBG]   ip=172.21.0.2
server_1  | [1] 2021/09/07 13:58:40.539992 [INF] Listening for MQTT clients on mqtt://0.0.0.0:1883
server_1  | [1] 2021/09/07 13:58:40.540022 [INF] Listening for client connections on 0.0.0.0:4222
server_1  | [1] 2021/09/07 13:58:40.540034 [DBG] Get non local IPs for "0.0.0.0"
server_1  | [1] 2021/09/07 13:58:40.540173 [DBG]   ip=172.21.0.2
server_1  | [1] 2021/09/07 13:58:40.540191 [INF] Server is ready
server_1  | [1] 2021/09/07 13:58:41.170481 [DBG] 172.21.0.4:58226 - cid:4 - Client connection created
server_1  | [1] 2021/09/07 13:58:41.171226 [TRC] 172.21.0.4:58226 - cid:4 - <<- [CONNECT {"verbose":false,"pedantic":false,"jwt":"eyJ0eXAiOiJKV1QiLCJhbGciOiJlZDI1NTE5LW5rZXkifQ.eyJqdGkiOiJMVDZFRk5BRktXT0FTQUE1U1VIVEEyWjdVVFE2WE1VWFBYRkc0UFIyN0RRNDJUMzVZWDJBIiwiaWF0IjoxNjMxMDIxNTIyLCJpc3MiOiJBQUZOWjdVR0FCVDNNRTZHRUY0Q1NYTlk2S1VWNkxTR1dWWjNDNTVMSExVQUtRMldFNFFCRUJVNiIsIm5hbWUiOiJzeXMiLCJzdWIiOiJVQTRWVUFDWldXNDRLMlFGM1dHQlhKVkFZTkE0RVFJQkdFWTIyWUlMUFZUNldaUEZVRUtSQk1HNiIsIm5hdHMiOnsicHViIjp7fSwic3ViIjp7fSwic3VicyI6LTEsImRhdGEiOi0xLCJwYXlsb2FkIjotMSwiaXNzdWVyX2FjY291bnQiOiJBQlBZV0lBRzQzUEhTQVJOVFNYN0Y0NzZSV1BGMkxZREcyTkNPT1FMSjNNWFYzUU9FN1NXQkxaTiIsInR5cGUiOiJ1c2VyIiwidmVyc2lvbiI6Mn19.4BeBwF8Jtc-tYeCcviN0JlexapLaIUiatuubaWriUK4ANoLjvxIY05rAg96AdmqaQr5eB0DdLyciZfskOG7wDA","sig":"c809DYmMAP_5c40--I5sZd_2biK57WXAdSf13Pz_Eb_D3MzE7eBiqEWTRFaUFDfrV_B8zdOEBhFLE4gMy4M1BQ","tls_required":false,"name":"NATS CLI Version 20210429","lang":"go","version":"1.11.0","protocol":1,"echo":true,"headers":true,"no_responders":true}]
server_1  | [1] 2021/09/07 13:58:41.172072 [DBG] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - Authenticated JWT: Client "UA4VUACZWW44K2QF3WGBXJVAYNA4EQIBGEY22YILPVT6WZPFUEKRBMG6" (claim-name: "sys", claim-tags: []) signed with "AAFNZ7UGABT3ME6GEF4CSXNY6KUV6LSGWVZ3C55LHLUAKQ2WE4QBEBU6" by Account "ABPYWIAG43PHSARNTSX7F476RWPF2LYDG2NCOOQLJ3MXV3QOE7SWBLZN" (claim-name: "SYS", claim-tags: []) signed with "OC3S2QS2NFINTDQA2DOTD46HM6KSMCR3PA6MCSKB3XMP35ECIM4KDPGR"
server_1  | [1] 2021/09/07 13:58:41.172084 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [PING]
server_1  | [1] 2021/09/07 13:58:41.172092 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - ->> [PONG]
server_1  | [1] 2021/09/07 13:58:41.172282 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [SUB ">"  1]
server_1  | [1] 2021/09/07 13:58:41.172316 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [PING]
server_1  | [1] 2021/09/07 13:58:41.172322 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - ->> [PONG]
tools_1   | 13:58:41 Subscribing on ">"
client_1  | Connecting to 'nats://server:4222'
server_1  | [1] 2021/09/07 13:58:41.335397 [DBG] 172.21.0.3:44186 - cid:5 - Client connection created
server_1  | [1] 2021/09/07 13:58:41.366139 [TRC] 172.21.0.3:44186 - cid:5 - <<- [CONNECT {"verbose":true,"pedantic":false,"user":"","pass":"[REDACTED]","ssl_required":false,"name":"the-client","auth_token":"","lang":".NET","version":"0.12.0.0","protocol":1,"jwt":"eyJ0eXAiOiJKV1QiLCJhbGciOiJlZDI1NTE5LW5rZXkifQ.eyJqdGkiOiJMVDZFRk5BRktXT0FTQUE1U1VIVEEyWjdVVFE2WE1VWFBYRkc0UFIyN0RRNDJUMzVZWDJBIiwiaWF0IjoxNjMxMDIxNTIyLCJpc3MiOiJBQUZOWjdVR0FCVDNNRTZHRUY0Q1NYTlk2S1VWNkxTR1dWWjNDNTVMSExVQUtRMldFNFFCRUJVNiIsIm5hbWUiOiJzeXMiLCJzdWIiOiJVQTRWVUFDWldXNDRLMlFGM1dHQlhKVkFZTkE0RVFJQkdFWTIyWUlMUFZUNldaUEZVRUtSQk1HNiIsIm5hdHMiOnsicHViIjp7fSwic3ViIjp7fSwic3VicyI6LTEsImRhdGEiOi0xLCJwYXlsb2FkIjotMSwiaXNzdWVyX2FjY291bnQiOiJBQlBZV0lBRzQzUEhTQVJOVFNYN0Y0NzZSV1BGMkxZREcyTkNPT1FMSjNNWFYzUU9FN1NXQkxaTiIsInR5cGUiOiJ1c2VyIiwidmVyc2lvbiI6Mn19.4BeBwF8Jtc-tYeCcviN0JlexapLaIUiatuubaWriUK4ANoLjvxIY05rAg96AdmqaQr5eB0DdLyciZfskOG7wDA","nkey":"","sig":"r5NBHdKvk7GQ6zI/ujKY0j3iL6yg2qRdjUau0lcL//IpBFCXljoYaCzwl4qFeQcXPX/O/H20Hh4CG0byQ8QICw==","echo":true,"headers":true,"no_responders":true}]
server_1  | [1] 2021/09/07 13:58:41.366889 [DBG] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - Authenticated JWT: Client "UA4VUACZWW44K2QF3WGBXJVAYNA4EQIBGEY22YILPVT6WZPFUEKRBMG6" (claim-name: "sys", claim-tags: []) signed with "AAFNZ7UGABT3ME6GEF4CSXNY6KUV6LSGWVZ3C55LHLUAKQ2WE4QBEBU6" by Account "ABPYWIAG43PHSARNTSX7F476RWPF2LYDG2NCOOQLJ3MXV3QOE7SWBLZN" (claim-name: "SYS", claim-tags: []) signed with "OC3S2QS2NFINTDQA2DOTD46HM6KSMCR3PA6MCSKB3XMP35ECIM4KDPGR"
server_1  | [1] 2021/09/07 13:58:41.366910 [TRC] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - ->> [OK]
server_1  | [1] 2021/09/07 13:58:41.366917 [TRC] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - <<- [PING]
server_1  | [1] 2021/09/07 13:58:41.366920 [TRC] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - ->> [PONG]
client_1  | Connected.
server_1  | [1] 2021/09/07 13:58:43.368912 [DBG] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - Client Ping Timer
server_1  | [1] 2021/09/07 13:58:43.369019 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - ->> [PING]
server_1  | [1] 2021/09/07 13:58:43.369650 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [PONG]
server_1  | [1] 2021/09/07 13:58:43.557522 [DBG] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - Client Ping Timer
server_1  | [1] 2021/09/07 13:58:43.557681 [TRC] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - ->> [PING]
server_1  | [1] 2021/09/07 13:58:46.786270 [DBG] Trapped "terminated" signal
server_1  | [1] 2021/09/07 13:58:46.786389 [INF] Initiating Shutdown...
tools_1   | 13:58:46 Disconnected due to: EOF, will attempt reconnect
server_1  | [1] 2021/09/07 13:58:46.786541 [DBG] 172.21.0.3:44186 - cid:5 - "v0.12.0.0:.NET:the-client" - Client connection closed: Server Shutdown
server_1  | [1] 2021/09/07 13:58:46.786548 [DBG] MQTT accept loop exiting..
server_1  | [1] 2021/09/07 13:58:46.786556 [DBG] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - Client connection closed: Server Shutdown
server_1  | [1] 2021/09/07 13:58:46.786568 [DBG] SYSTEM - System connection closed: Client Closed
server_1  | [1] 2021/09/07 13:58:46.786546 [DBG] Client accept loop exiting..
server_1  | [1] 2021/09/07 13:58:46.786582 [TRC] 172.21.0.4:58226 - cid:4 - "v1.11.0:go:NATS CLI Version 20210429" - <-> [DELSUB 1]
server_1  | [1] 2021/09/07 13:58:46.786616 [DBG] Leafnode accept loop exiting..
server_1  | [1] 2021/09/07 13:58:46.786666 [INF] Server Exiting..
client_1  | Disconnected.
natsclienttest_server_1 exited with code 1
server_1  | [1] 2021/09/07 13:58:48.860430 [DBG] 172.21.0.3:44222 - cid:4 - Client connection created
server_1  | [1] 2021/09/07 13:58:48.863692 [TRC] 172.21.0.3:44222 - cid:4 - <<- [CONNECT {"verbose":true,"pedantic":false,"user":"","pass":"[REDACTED]","ssl_required":false,"name":"the-client","auth_token":"","lang":".NET","version":"0.12.0.0","protocol":1,"jwt":"eyJ0eXAiOiJKV1QiLCJhbGciOiJlZDI1NTE5LW5rZXkifQ.eyJqdGkiOiJMVDZFRk5BRktXT0FTQUE1U1VIVEEyWjdVVFE2WE1VWFBYRkc0UFIyN0RRNDJUMzVZWDJBIiwiaWF0IjoxNjMxMDIxNTIyLCJpc3MiOiJBQUZOWjdVR0FCVDNNRTZHRUY0Q1NYTlk2S1VWNkxTR1dWWjNDNTVMSExVQUtRMldFNFFCRUJVNiIsIm5hbWUiOiJzeXMiLCJzdWIiOiJVQTRWVUFDWldXNDRLMlFGM1dHQlhKVkFZTkE0RVFJQkdFWTIyWUlMUFZUNldaUEZVRUtSQk1HNiIsIm5hdHMiOnsicHViIjp7fSwic3ViIjp7fSwic3VicyI6LTEsImRhdGEiOi0xLCJwYXlsb2FkIjotMSwiaXNzdWVyX2FjY291bnQiOiJBQlBZV0lBRzQzUEhTQVJOVFNYN0Y0NzZSV1BGMkxZREcyTkNPT1FMSjNNWFYzUU9FN1NXQkxaTiIsInR5cGUiOiJ1c2VyIiwidmVyc2lvbiI6Mn19.4BeBwF8Jtc-tYeCcviN0JlexapLaIUiatuubaWriUK4ANoLjvxIY05rAg96AdmqaQr5eB0DdLyciZfskOG7wDA","nkey":"","sig":"CZXznW+0vR14p0b2WmyOfugiSOBbsjhFDqQN8wFIaiMaQwOIftnGnGsa0PMGr3FLoIY/KGTgsjjBMAkaEkmNBg==","echo":true,"headers":true,"no_responders":true}]
server_1  | [1] 2021/09/07 13:58:48.866156 [DBG] 172.21.0.3:44222 - cid:4 - "v0.12.0.0:.NET:the-client" - Signature not verified
server_1  | [1] 2021/09/07 13:58:48.866192 [ERR] 172.21.0.3:44222 - cid:4 - "v0.12.0.0:.NET:the-client" - authentication error
server_1  | [1] 2021/09/07 13:58:48.866251 [TRC] 172.21.0.3:44222 - cid:4 - "v0.12.0.0:.NET:the-client" - ->> [-ERR Authorization Violation]
server_1  | [1] 2021/09/07 13:58:48.866324 [DBG] 172.21.0.3:44222 - cid:4 - "v0.12.0.0:.NET:the-client" - Client connection closed: Authentication Failure
server_1  | [1] 2021/09/07 13:58:48.870153 [DBG] 172.21.0.4:58266 - cid:5 - Client connection created
server_1  | [1] 2021/09/07 13:58:48.873199 [TRC] 172.21.0.4:58266 - cid:5 - <<- [CONNECT {"verbose":false,"pedantic":false,"jwt":"eyJ0eXAiOiJKV1QiLCJhbGciOiJlZDI1NTE5LW5rZXkifQ.eyJqdGkiOiJMVDZFRk5BRktXT0FTQUE1U1VIVEEyWjdVVFE2WE1VWFBYRkc0UFIyN0RRNDJUMzVZWDJBIiwiaWF0IjoxNjMxMDIxNTIyLCJpc3MiOiJBQUZOWjdVR0FCVDNNRTZHRUY0Q1NYTlk2S1VWNkxTR1dWWjNDNTVMSExVQUtRMldFNFFCRUJVNiIsIm5hbWUiOiJzeXMiLCJzdWIiOiJVQTRWVUFDWldXNDRLMlFGM1dHQlhKVkFZTkE0RVFJQkdFWTIyWUlMUFZUNldaUEZVRUtSQk1HNiIsIm5hdHMiOnsicHViIjp7fSwic3ViIjp7fSwic3VicyI6LTEsImRhdGEiOi0xLCJwYXlsb2FkIjotMSwiaXNzdWVyX2FjY291bnQiOiJBQlBZV0lBRzQzUEhTQVJOVFNYN0Y0NzZSV1BGMkxZREcyTkNPT1FMSjNNWFYzUU9FN1NXQkxaTiIsInR5cGUiOiJ1c2VyIiwidmVyc2lvbiI6Mn19.4BeBwF8Jtc-tYeCcviN0JlexapLaIUiatuubaWriUK4ANoLjvxIY05rAg96AdmqaQr5eB0DdLyciZfskOG7wDA","sig":"B0N7CUZ4pZQ2vF4Sf_8uIJeVEyqcTL_hBcIJrLDC7AO4TQZTfiyCjsZdRDAaqssCPgJr94XksjIp6FWm3hVjDw","tls_required":false,"name":"NATS CLI Version 20210429","lang":"go","version":"1.11.0","protocol":1,"echo":true,"headers":true,"no_responders":true}]
server_1  | [1] 2021/09/07 13:58:48.876439 [DBG] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - Authenticated JWT: Client "UA4VUACZWW44K2QF3WGBXJVAYNA4EQIBGEY22YILPVT6WZPFUEKRBMG6" (claim-name: "sys", claim-tags: []) signed with "AAFNZ7UGABT3ME6GEF4CSXNY6KUV6LSGWVZ3C55LHLUAKQ2WE4QBEBU6" by Account "ABPYWIAG43PHSARNTSX7F476RWPF2LYDG2NCOOQLJ3MXV3QOE7SWBLZN" (claim-name: "SYS", claim-tags: []) signed with "OC3S2QS2NFINTDQA2DOTD46HM6KSMCR3PA6MCSKB3XMP35ECIM4KDPGR"
server_1  | [1] 2021/09/07 13:58:48.876508 [TRC] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [PING]
server_1  | [1] 2021/09/07 13:58:48.876527 [TRC] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - ->> [PONG]
server_1  | [1] 2021/09/07 13:58:48.877486 [TRC] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [SUB ">"  1]
server_1  | [1] 2021/09/07 13:58:48.877553 [TRC] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - <<- [PING]
server_1  | [1] 2021/09/07 13:58:48.877571 [TRC] 172.21.0.4:58266 - cid:5 - "v1.11.0:go:NATS CLI Version 20210429" - ->> [PONG]
tools_1   | 13:58:48 Reconnected [nats://server:4222]
ser

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 21 (2 by maintainers)

Most upvoted comments

@mullerch , thank you so much for the provided test and detail in this issue. Much appreciated! We’ll take a look.