Testclient bailing with Received: Authentication timeout

[Heidistein]

I have setup (perhaps correct) the notify_push service. The clients are (seemingly) not recieving the 'notification'. However the test_client bails (instantly) with a timeout...

Found push server at wss://nextcloud.beetjevreemd.nl/push/ws
Received: Authentication timeout
Error: 
  0: IO error: CloseNotify alert received
  1: CloseNotify alert received

Location:
  test_client/src/main.rs:39

 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
  1: color_eyre::config::EyreHook::into_eyre_hook::{{closure}}::h9efefbf195760dbe
     at <unknown source file>:<unknown line>
  2: test_client::main::hbfaff217f5a6f51d
     at <unknown source file>:<unknown line>
  3: std::sys_common::backtrace::__rust_begin_short_backtrace::hd2d2d38788a19c55
     at <unknown source file>:<unknown line>
  4: main<unknown>
     at <unknown source file>:<unknown line>

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.

real	0m2,533s
user	0m0,005s
sys	0m0,011s

[icewind1991]

Is there anything in the output of the push server? (use occ notify_push:log debug to enable more logging)

[Heidistein]

apr 14 15:49:38 cecco.platypusnet.org notify_push[25746]: [2021-04-14 15:49:38.070947 +02:00] INFO [notify_push] src/lib.rs:194: Set log level to notify_push=debug
apr 14 15:49:45 cecco.platypusnet.org notify_push[25746]: [2021-04-14 15:49:45.720629 +02:00] DEBUG [notify_push] src/lib.rs:239: new websocket connection from Some(2a02:58:c9:fe07::100)
apr 14 15:49:45 cecco.platypusnet.org notify_push[25746]: [2021-04-14 15:49:45.733407 +02:00] DEBUG [notify_push::nc] src/nc.rs:27: Verifying credentials for dexter

After this nothing. If I set the level to trace I see the credentionals arriving, and the daemon making a connection to the nextcloud-server.

[trassl]

I also noticed an "Authentication timeout" and for me it actually was an authentication timeout. The hardcoded 1s is not sufficient for my setup.

--- a/src/connection.rs
+++ b/src/connection.rs
@@ -44,7 +44,7 @@ impl ActiveConnections {
 
 pub async fn handle_user_socket(mut ws: WebSocket, app: Arc<App>, forwarded_for: Vec<IpAddr>) {
     let user_id = match timeout(
-        Duration::from_secs(1),
+        Duration::from_secs(15),
         socket_auth(&mut ws, forwarded_for, &app),
     )
     .await

[Heidistein]

Ah, that explains. Yes 1 second is a tad fast for my setup as well. I have difficulty compiling the testclient, so i cannot test it so far

[icewind1991]

I've increased the timeout in master, you can find new server binaries fresh from CI at https://github.com/nextcloud/notify_push/actions/runs/755868422 and put the correct one in notify_push/bin/...

[Heidistein]

Hmmm, is that 15 perhaps miliseconds? Hitting the exact same error

Found push server at wss://nextcloud.beetjevreemd.nl/push/ws
Received: Authentication timeout
Error: 
   0: IO error: CloseNotify alert received
   1: CloseNotify alert received

Location:
   test_client/src/main.rs:39

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.

real	0m2,728s
user	0m0,006s
sys	0m0,007s

[gawelfr]

Hello,

Same problem here.

• Nextcloud 21.0.2
• notify_push 0.1.7

$ ./occ notify_push:self-test
✓ redis is configured
✓ push server is receiving redis messages
✓ push server can load mount info from database
✓ push server can connect to the Nextcloud server
✓ push server is a trusted proxy
✓ push server is running the same version as the app

Using test_client from #issuecomment-821208900

$ RUST_BACKTRACE=1 ./test_client https://cloud.openwebzone.fr <USERNAME> '<PASSWORD>'
Found push server at wss://cloud.openwebzone.fr/push/ws
Received: Authentication timeout
Error: 
   0: IO error: CloseNotify alert received
   1: CloseNotify alert received

Location:
   test_client/src/main.rs:39

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                 ⋮ 1 frame hidden ⋮                               
   2: test_client::main::hbfaff217f5a6f51d
      at <unknown source file>:<unknown line>
   3: std::sys_common::backtrace::__rust_begin_short_backtrace::hd2d2d38788a19c55
      at <unknown source file>:<unknown line>
   4: main<unknown>
      at <unknown source file>:<unknown line>

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
Run with RUST_BACKTRACE=full to include source snippets.

And nothing special in debug logs :

cloud_app      | 172.22.0.7 - gawel [22/May/2021:12:18:12 +0200] "GET /ocs/v2.php/cloud/capabilities HTTP/1.0" 200 5581 "-" "ureq/2.1.0"
cloud_push     | [2021-05-22 12:18:13.975093 +02:00] DEBUG [notify_push] src/lib.rs:239: new websocket connection from Some(109.190.202.171)
cloud_push     | [2021-05-22 12:18:13.983654 +02:00] DEBUG [notify_push::nc] src/nc.rs:27: Verifying credentials for gawel
cloud_app      | 172.22.0.12 - gawel [22/May/2021:12:18:13 +0200] "GET /index.php/apps/notify_push/uid HTTP/1.1" 200 1551 "-" "-"

Let me know if you need more information.