element-hq / element-android

A Matrix collaboration client for Android.
https://element.io/
Apache License 2.0
3.31k stars 704 forks source link

NTFY Endpoint Registration Fails within an Airgapped Environment #8228

Open kieranlane opened 1 year ago

kieranlane commented 1 year ago

Steps to reproduce

Steps to reproduce

Issue History so far:

Initial Query

Hi šŸ‘‹ I'm trying to confirm the process for setting up NTFY within an airgapped environment with the app. I think I'm almost there. I believe the issue is with having the NTFY push gateway registering within the app. (Details within thread)

Setup is as follows: (Note all using wildcard certs issued by CA on Server1 - Android app has CA.pem installed)

I believe the issue is that there are still no registered push gateways listed within the Element app. (Advanced Settings -> Notification Targets says No registered push gateways) Going to Notifications -> Troubleshoot Notifications I get the following:

image

FYI Running the trouble-shooter and immediately going to the home screen (so it's no longer the active app) causes the Test Push to fail. (NTFY doesn't receive any notification / etc.)

NTFY application is happily connected to the created topic (and a test one, which does correctly receive notifications)

image

Troubleshooting with @MatMaul

Check ntfy.example.com DNS record is visible from Server 1?

Server 1 is the DNS server, and pings to ntfy.example.com work successfully (it actually also self-hosts an NTFY web client so can be sure it's working from Server 1)

Initially trying to troubleshoot in the on-prem support, was told "It is the responsibility of Matrix clients to register "pushers" with their homeserver. The pusher contains the URL to the push GW to use" - So I guess I could try registering a pusher using the api manually, see what comes back

Check if synapse log is returning 500 when registering the pusher.

2023-03-06 13:36:10,415 - synapse.access.http.8008 - 460 - INFO - GET-30693 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 30.003sec/0.001sec (0.000sec, 0.001sec) (0.000sec/0.000sec/0) 230B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s52_2887_2_35_69_1_15_24_0 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:36:11,305 - synapse.access.http.8008 - 460 - INFO - GET-30695 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 30.002sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 230B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=online&timeout=30000&since=s52_2887_2_35_69_1_15_24_0 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:36:12,130 - synapse.storage.databases.main.event_push_actions - 1305 - INFO - rotate_notifs-4053 - Rotating notifications
2023-03-06 13:36:12,132 - synapse.storage.databases.main.event_push_actions - 1528 - INFO - rotate_notifs-4053 - Rotating notifications up to: 52
2023-03-06 13:36:12,134 - synapse.storage.databases.main.event_push_actions - 1627 - INFO - rotate_notifs-4053 - Rotating notifications, handling 0 rows
2023-03-06 13:36:12,138 - synapse.storage.databases.main.event_push_actions - 1720 - INFO - rotate_notifs-4053 - Rotating notifications, deleted 0 push actions
2023-03-06 13:36:12,188 - synapse.handlers.presence - 791 - INFO - persist_presence_changes-2026 - Persisting 2 unpersisted presence updates
2023-03-06 13:36:12,212 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-4053 - Dropped 0 items from caches

Those are the logs (I triggered the troubleshooter at 13:36) - I guess the synapse.storage.databases.main.event_push_actions are the things related to the registration? I'm not seeing anything immediately obvious as to why it fails šŸ¤”

Troubleshooter is not triggering pusher registration. Switch back and forth the notification service and check the logs. Expecting to see processed request with a path matching registering a pusher.

Sure will also clear the cache / storage of both NTFY and Element apps and try from the beginning for good measure

2023-03-06 13:52:08,024 - synapse.handlers.auth - 995 - INFO - POST-30991 - Logging in user @phone:example.com on device BEEIKQOZUK
2023-03-06 13:52:08,025 - synapse.access.http.8008 - 460 - INFO - GET-30985 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 15.699sec/0.003sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 280B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s52_2919_2_35_69_1_15_24_0 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:52:08,033 - synapse.access.http.8008 - 460 - INFO - POST-30991 - 192.168.0.3 - 8008 - {None} Processed request: 0.332sec/0.001sec (0.312sec, 0.000sec) (0.003sec/0.010sec/5) 216B 200 "POST /_matrix/client/r0/login HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,055 - synapse.access.http.8008 - 460 - INFO - POST-30992 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 0.012sec/0.000sec (0.001sec, 0.001sec) (0.005sec/0.004sec/3) 1807B 200 "POST /_matrix/client/r0/keys/query HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:52:08,392 - synapse.access.http.8008 - 460 - INFO - GET-30994 - 192.168.0.3 - 8008 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 78B 200 "GET /_matrix/client/r0/login HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,760 - synapse.handlers.e2e_keys - 614 - INFO - POST-30995 - Updating device_keys for device 'BEEIKQOZUK' for user @phone:example.com at 1678110728760
2023-03-06 13:52:08,762 - synapse.access.http.8008 - 460 - INFO - GET-30996 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.005sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "GET /_matrix/client/r0/thirdparty/protocols HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,777 - synapse.access.http.8008 - 460 - INFO - GET-30993 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 0.723sec/0.004sec (0.000sec, 0.003sec) (0.000sec/0.000sec/0) 280B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s52_2919_2_35_69_1_15_25_0 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:52:08,783 - synapse.access.http.8008 - 460 - INFO - GET-30997 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.005sec/0.003sec (0.004sec, 0.000sec) (0.001sec/0.001sec/1) 14B 200 "GET /_matrix/client/r0/pushers HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,786 - synapse.access.http.8008 - 460 - INFO - POST-30995 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.025sec/0.006sec (0.004sec, 0.002sec) (0.003sec/0.012sec/5) 47B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,788 - synapse.access.http.8008 - 460 - INFO - GET-30998 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.001sec/0.005sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 656B 200 "GET /_matrix/client/r0/capabilities HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,814 - synapse.access.http.8008 - 460 - INFO - GET-31000 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.001sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 27B 200 "GET /_matrix/media/r0/config HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,820 - synapse.handlers.e2e_keys - 686 - INFO - POST-31001 - Adding one_time_keys dict_keys(['signed_curve25519:AAAABQ', 'signed_curve25519:AAAABA', 'signed_curve25519:AAAAAw', 'signed_curve25519:AAAAAg', 'signed_curve25519:AAAAAQ']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110728820
2023-03-06 13:52:08,831 - synapse.access.http.8008 - 460 - INFO - POST-31001 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.011sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.006sec/3) 47B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,837 - synapse.access.http.8008 - 460 - INFO - GET-31002 - 192.168.0.3 - 8008 - {None} Processed request: 0.000sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 808B 200 "GET /_matrix/client/versions HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,929 - synapse.handlers.e2e_keys - 686 - INFO - POST-31003 - Adding one_time_keys dict_keys(['signed_curve25519:AAAACQ', 'signed_curve25519:AAAACA', 'signed_curve25519:AAAABw', 'signed_curve25519:AAAABg', 'signed_curve25519:AAAACg']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110728929
2023-03-06 13:52:08,939 - synapse.access.http.8008 - 460 - INFO - POST-31003 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.010sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.005sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:08,945 - synapse.access.http.8008 - 460 - INFO - GET-31004 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.004sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.001sec/2) 472B 200 "GET /_matrix/client/r0/devices HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,044 - synapse.access.http.8008 - 460 - INFO - POST-31005 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 0.005sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.002sec/3) 2298B 200 "POST /_matrix/client/r0/keys/query HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:52:09,065 - synapse.handlers.e2e_keys - 686 - INFO - POST-31006 - Adding one_time_keys dict_keys(['signed_curve25519:AAAADQ', 'signed_curve25519:AAAADA', 'signed_curve25519:AAAACw', 'signed_curve25519:AAAADw', 'signed_curve25519:AAAADg']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729065
2023-03-06 13:52:09,073 - synapse.access.http.8008 - 460 - INFO - POST-31006 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.001sec, 0.001sec) (0.001sec/0.005sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,113 - synapse.handlers.e2e_keys - 686 - INFO - POST-31008 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAEQ', 'signed_curve25519:AAAAEA', 'signed_curve25519:AAAAFA', 'signed_curve25519:AAAAEw', 'signed_curve25519:AAAAEg']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729113
2023-03-06 13:52:09,113 - synapse.access.http.8008 - 460 - INFO - GET-31007 - 192.168.0.3 - 8008 - {None} Processed request: 0.000sec/0.002sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 808B 200 "GET /_matrix/client/versions HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,122 - synapse.access.http.8008 - 460 - INFO - POST-31008 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.009sec/0.001sec (0.002sec, 0.000sec) (0.002sec/0.004sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,149 - synapse.handlers.e2e_keys - 686 - INFO - POST-31009 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAFQ', 'signed_curve25519:AAAAGQ', 'signed_curve25519:AAAAGA', 'signed_curve25519:AAAAFw', 'signed_curve25519:AAAAFg']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729149
2023-03-06 13:52:09,162 - synapse.access.http.8008 - 460 - INFO - POST-31009 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.013sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.009sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,165 - synapse.access.http.8008 - 460 - INFO - POST-31010 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.004sec, 0.001sec) (0.002sec/0.001sec/1) 17B 200 "POST /_matrix/client/r0/user/@phone:example.com/filter HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,251 - synapse.access.http.8008 - 460 - INFO - GET-31011 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.003sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.001sec/2) 23B 200 "GET /_matrix/client/r0/profile/@phone:example.com HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,261 - synapse.handlers.e2e_keys - 686 - INFO - POST-31012 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAHg', 'signed_curve25519:AAAAHQ', 'signed_curve25519:AAAAHA', 'signed_curve25519:AAAAGw', 'signed_curve25519:AAAAGg']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729261
2023-03-06 13:52:09,269 - synapse.access.http.8008 - 460 - INFO - POST-31012 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.005sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,358 - synapse.handlers.e2e_keys - 686 - INFO - POST-31013 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAHw', 'signed_curve25519:AAAAIw', 'signed_curve25519:AAAAIg', 'signed_curve25519:AAAAIQ', 'signed_curve25519:AAAAIA']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729358
2023-03-06 13:52:09,366 - synapse.access.http.8008 - 460 - INFO - POST-31013 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.004sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,436 - synapse.handlers.e2e_keys - 686 - INFO - POST-31014 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAJw', 'signed_curve25519:AAAAJg', 'signed_curve25519:AAAAJQ', 'signed_curve25519:AAAAJA', 'signed_curve25519:AAAAKA']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729436
2023-03-06 13:52:09,445 - synapse.access.http.8008 - 460 - INFO - POST-31014 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.009sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.005sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,504 - synapse.handlers.e2e_keys - 686 - INFO - POST-31016 - Adding one_time_keys dict_keys(['signed_curve25519:AAAAKw', 'signed_curve25519:AAAAKg', 'signed_curve25519:AAAALQ', 'signed_curve25519:AAAALA', 'signed_curve25519:AAAAKQ']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729504
2023-03-06 13:52:09,515 - synapse.access.http.8008 - 460 - INFO - POST-31016 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.011sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.006sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,560 - synapse.handlers.e2e_keys - 686 - INFO - POST-31017 - Adding one_time_keys dict_keys(['signed_curve25519:AAAALw', 'signed_curve25519:AAAALg', 'signed_curve25519:AAAAMg', 'signed_curve25519:AAAAMQ', 'signed_curve25519:AAAAMA']) for device 'BEEIKQOZUK' for user '@phone:example.com' at 1678110729560
2023-03-06 13:52:09,572 - synapse.access.http.8008 - 460 - INFO - POST-31017 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.012sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.006sec/3) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,582 - synapse.access.http.8008 - 460 - INFO - GET-31015 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.112sec/0.001sec (0.029sec, 0.000sec) (0.016sec/0.055sec/40) 19580B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=offline&timeout=0 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [20 dbevts]
2023-03-06 13:52:09,657 - synapse.access.http.8008 - 460 - INFO - GET-31018 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.003sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.001sec/2) 310B 200 "GET /_matrix/client/unstable/room_keys/version HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,860 - synapse.access.http.8008 - 460 - INFO - GET-31020 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.003sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.001sec/2) 472B 200 "GET /_matrix/client/r0/devices HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:09,879 - synapse.access.http.8008 - 460 - INFO - POST-31021 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.005sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.003sec/3) 2798B 200 "POST /_matrix/client/r0/keys/query HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,029 - synapse.access.http.8008 - 460 - INFO - PUT-31022 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.005sec/3) 2B 200 "PUT /_matrix/client/r0/sendToDevice/m.room_key_request/31f4235c-ddd0-43f1-a62e-787e18026101 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,075 - synapse.access.http.8008 - 460 - INFO - PUT-31023 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.008sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.004sec/3) 2B 200 "PUT /_matrix/client/r0/sendToDevice/m.room_key_request/c9038f8a-e608-406c-885e-ca5a9e2d680b HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,132 - synapse.access.http.8008 - 460 - INFO - GET-31024 - 192.168.0.3 - 8008 - {None} Processed request: 0.000sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 808B 200 "GET /_matrix/client/versions HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,149 - synapse.access.http.8008 - 460 - INFO - GET-30999 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 1.349sec/0.002sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 382B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s52_2919_2_35_69_1_15_26_0 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 13:52:10,156 - synapse.access.http.8008 - 460 - INFO - GET-31025 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.017sec/0.001sec (0.004sec, 0.000sec) (0.002sec/0.006sec/5) 1256B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=online&timeout=0&since=s52_2919_2_35_69_1_15_26_0 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,177 - synapse.access.http.8008 - 460 - INFO - POST-31027 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.005sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.003sec/3) 2798B 200 "POST /_matrix/client/r0/keys/query HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:10,217 - synapse.access.http.8008 - 460 - INFO - GET-31028 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.005sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.002sec/1) 192B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=online&timeout=0&since=s52_2920_2_35_69_1_17_26_0 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 13:52:12,131 - synapse.storage.databases.main.event_push_actions - 1305 - INFO - rotate_notifs-4085 - Rotating notifications
2023-03-06 13:52:12,132 - synapse.storage.databases.main.event_push_actions - 1528 - INFO - rotate_notifs-4085 - Rotating notifications up to: 52
2023-03-06 13:52:12,133 - synapse.storage.databases.main.event_push_actions - 1627 - INFO - rotate_notifs-4085 - Rotating notifications, handling 0 rows
2023-03-06 13:52:12,137 - synapse.storage.databases.main.event_push_actions - 1720 - INFO - rotate_notifs-4085 - Rotating notifications, deleted 0 push actions
2023-03-06 13:52:12,188 - synapse.handlers.presence - 791 - INFO - persist_presence_changes-2042 - Persisting 2 unpersisted presence updates
2023-03-06 13:52:12,212 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-4085 - Dropped 0 items from caches
2023-03-06 13:52:12,312 - synapse.storage.databases.main.metrics - 475 - INFO - generate_user_daily_visits-409 - Calling _generate_user_daily_visits
2023-03-06 13:52:13,838 - synapse.access.http.8008 - 460 - INFO - GET-31030 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/2) 472B 200 "GET /_matrix/client/r0/devices HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]

Thats the logs from the point of first login -- most is just registering the new device etc. -- nothing matching /_matrix/client/v3/pushers/set though So I guess that means the server isn't seeing such a request come in? Checking manually going to https://synapse.example.com/_matrix/client/v3/pushers/set works at least from Server 1 / 2 and the phone.

Can access that from all - actually tried again to double check and get the following:

2023-03-06 14:04:02,970 - synapse.access.http.8008 - 460 - INFO - GET-31229 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 0.002sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.001sec/1) 14B 200 "GET /_matrix/client/r0/pushers HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 14:04:06,938 - synapse.access.http.8008 - 460 - INFO - GET-31220 - 192.168.0.3 - 8008 - {@phone:example.com} Processed request: 30.002sec/0.000sec (0.000sec, 0.001sec) (0.000sec/0.000sec/0) 230B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=online&timeout=30000&since=s52_2938_2_35_69_1_20_26_0 HTTP/1.1" "Element dbg/1.5.28-dev (Google Pixel 6; Android 13; TQ1A.230205.002; Flavour GooglePlay; MatrixAndroidSdk2 1.5.28)" [0 dbevts]
2023-03-06 14:04:07,539 - synapse.access.http.8008 - 460 - INFO - GET-31222 - 192.168.0.2 - 8008 - {@computer:example.com} Processed request: 30.002sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 230B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s52_2938_2_35_69_1_20_26_0 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/110.0" [0 dbevts]
2023-03-06 14:04:12,130 - synapse.storage.databases.main.event_push_actions - 1305 - INFO - rotate_notifs-4109 - Rotating notifications
2023-03-06 14:04:12,131 - synapse.storage.databases.main.event_push_actions - 1528 - INFO - rotate_notifs-4109 - Rotating notifications up to: 52
2023-03-06 14:04:12,133 - synapse.storage.databases.main.event_push_actions - 1627 - INFO - rotate_notifs-4109 - Rotating notifications, handling 0 rows
2023-03-06 14:04:12,137 - synapse.storage.databases.main.event_push_actions - 1720 - INFO - rotate_notifs-4109 - Rotating notifications, deleted 0 push actions
2023-03-06 14:04:12,188 - synapse.handlers.presence - 791 - INFO - persist_presence_changes-2054 - Persisting 2 unpersisted presence updates
2023-03-06 14:04:12,212 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-4109 - Dropped 0 items from caches

It's doing /_matrix/client/r0/pushers not /_matrix/client/v3/pushers, but it's an actual request in that direct so probably closer to what you were expecting to see

Went on a tangent here about NTFY server version / apk package name which were ultimately ruled out as potential issues in the process

Rageshake Issue / Logcat tests

Thanks for all the help on this so far!! I've gone through and done a test and filtered the logs from Synapse, NTFY and the logcat to between 19:22pm -> 19.23pm (where I ran through all the steps). I'm collating everything within https://github.com/matrix-org/element-android-rageshakes/issues/50380 šŸ¤ž There's something in there that explains what's going on. Also going to dig around with the Admin API to list the pushers etc. to see if there's anything at all listed for the user.

I'm hoping the above has enough information within to help figure out what's going wrong with the registration. I manually merged all the logs into a combined log ordered chronologically -> https://github.com/matrix-org/element-android-rageshakes/files/10902597/combined\_and\_ordered.log

Troubleshooting with @bmarty

Disable / enable notification to force a set pusher request? (via Enable notification for this session)

I filtered the logcat based on the package name - hopefully thats okay. logcat.log

so for referenceI adb shell'd on. Then did logcat | grep im.vector.app

No pusher registration request.

Perhaps I was too hasty ending the logcat? logcat2.log

That one I doublechecked it appeared in NTFY afterwards too - which it did, and left a little longer after. Process followed is:

To cover all bases, (and attempt to have a complete logcat that's not lightyears long) - I setup aosp on a old pixel 2xl (so hopefully as little other things going on in the bg as possible unlike personal phone) and did a run through from scratch. Below is that logcat. I didn't filter on application name or anything and I followed these steps:

logcat.log

ToggleNotificationsForCurrentSessionUseCase: push notif is enabled, deleting any account data and updating pusher but the current code does not seem to register a pusher if it does not exist yet.

Change Notification method and select again ntfy to force a refresh of the pusher.

That's how I was previously changing when troubleshooting with MatMaul - but can give it try like that and send over the logcat - see if it throws up anything different / useful. Just to confirm: the problem is that the HS does not notify the Push gateway, right?

Erm I'm not sure on the specifics, possibly, the only concrete error message I have is the troubleshoot flow stating that "Failed to register endpoint token to homeserver: Unknown Error"

I can at least confirm from this https://unifiedpush.org/users/troubleshooting/ that the issue isn't with the distributor (i.e. NTFY) as I successfully receive a Unified Push notification using the UP-example app

This error is displayed when there is no pushers registered on the HS. I guess the troubleshoot Quick fix has no effect?

Clicking the 'Reset Notification Method' button that appears - just presents the change notification method prompt. Clicking NTFY again and re-running tests has the same error unfortunately

Confirmation of Synapse -> NTFY -> Phone flow works via Client-Server API

So fairly sure now that the Home Server and NTFY are working OK and it's something the app isn't doing right.

Using the ClientServer API I have registered a new pusher with this cURL command:

curl -H "Content-Type: application/json" -H "Authorization: Bearer syt_bm90aWZ5_iAMjqfxqmvKzBeaAdJME_054oG2" -d '{"app_display_name":"Mat Rix","app_id":"com.example.app.ios","append":false,"data":{"format":"event_id_only","url":"https://ntfy.example.com/_matrix/push/v1/notify"},"device_display_name":"iPhone 9","kind":"http","lang":"en","pushkey":"https://ntfy.example.com/example"}' --insecure -X POST https://synapse.example.com/_matrix/client/v3/pushers/set

I then have sent a message from computer user to notify user. NTFY receives the notification, and publishes to https://ntfy.example.com/example (the push key). I have manually subscribed to the ntfy.example.com/example topic and receive on the phone the json notification string

This method above obviously doesn't use UnifiedPush ?format?, so what I get on the phone is the raw notification json, but as far as the overall flow... registering a pusher to the homeserver, the homeserver pushing successfully to the gateway, and the gateway sending to a device it works.

Patch file sent for more detailed logs on custom built apk

We miss some log when this error occurs. Apply patch for more logs

Logs attached! I will also make a proper issue on the android github and collate all these threads / msgs

logcat4.log

Outcome

What did you expect?

Phone to successfully register endpoint token with homeserver so that notifications are served successfully to the phone when the application isn't in focus via NTFY.

What happened instead?

No notification is ever received by the phone due to the failure to successfully register the pusher with synapse.

Your phone model

Pixel 6 & Pixel 2 XL

Operating system version

Android 13

Application version and app store

1.5.28-dev [40105280] (G-448374fc) feature/bma/certList 448374fc (both with and without Patch applied

Homeserver

On-Premise Installer 02.01 (Believe thats Synapse version 1.72.0)

Will you send logs?

Yes

Are you willing to provide a PR?

Yes

Outcome

Outcome

What did you expect?

Phone to successfully register endpoint token with homeserver so that notifications are served successfully to the phone when the application isn't in focus via NTFY.

What happened instead?

No notification is ever received by the phone due to the failure to successfully register the pusher with synapse.

kieranlane commented 1 year ago

For reference this is the rageshake logs: https://github.com/matrix-org/element-android-rageshakes/issues/50380

Most recent logs following patch: logcat4.log

Morhonda commented 1 year ago

Hi @bmarty,

could you have a look at this issue today? It would be great if we could offer the client a fix until Monday because I am meeting the client on Monday in person. Thanks. I appreciate your work on this issue.

Best wishes,

Moritz

bmarty commented 1 year ago

@kieranlane I cannot find the words Fail to setPusher in the file logcat4.log.

We suspect the Worker AddPusherWorker to never start wecause is has a constraint to start only when network is available.

Other Workers have this constraint, and so can fail:

What can be done to try to unblock quickly is to remove the Network constraint, at least to check that this is the source of the issue you are trying to fix. Here is a patch with this: noNetworkConstraintOnAddPusherWorker.patch

For long term solution, more work would be necessary to fix all the identified issue.

kieranlane commented 1 year ago

Thanks @bmarty, I've tested this on three devices (Pixel 6 / 2 * Pixel 2XLs) and the fix works, the endpoint is now successfully registered. However there does appear to be a quirk to the notifications actually coming in:

Presumably this is a an caused by possibly the things that can fail, most likely ("initial sync request, if the first one fails because of network error."and "background sync when a Push is received")

I can confirm attempting to send an attachment just sits 'Waiting' forever, as expect.

kieranlane commented 1 year ago

@bmarty - just adding that another airgapped customer has now run into this, specifically with media not being sent via the app within their airgapped environment. (Believe that is likely due to the Network constraint) - perhaps this issue should be renamed to be more generalised now the source of the problem has been identified?

Perhaps something like Network Constraint: On Add Pusher Worker - breaks core functionality within Airgapped environments

p1gp1g commented 11 months ago

By default, android uses these endpoints to check connectivity :

You can set your DNS and a webserver to respond 204 to one of these (HTTP) request, then your devices will work like there is network and element will work properly

bmarty commented 11 months ago

Thanks @p1gp1g , on our side we had identified and tested:

So maybe worth also testing https://www.google.com/generate_204

CC @giomfo @simaddis