Setting up rocketchat with Gotify

githubdeb commented 3 years ago

Hi Immanuel,

I try to setup gotify to work with rocketchat. Cam you help me? I am a beginner in this area.

I have installed rockectchat and used my gotify gateway for push notifications like this: https://push.mydomain.com/my_app_token I have created users to use gotify with username and passsword. I have installed Gotify.apk on two android phones and successfully logged in to my gotify server(https://push.mydomain.com I was expecting to see a notification on Gotify when I use rocketchat and the other user is logged in but with the app closed. However, I do not see anything. Can you please explain me where I'm wrong and how should I solve this problem step by step? Thank you. Luke

immanuelfodor commented 3 years ago

I suspect the issue here could be the missing bridge/Apprise config where you assign each Gotify user their respective Rocketchat user app tokens. If I understand correctly, you have e.g. 2 RC users, created 2 Gotify users for them, but nothing about the bridge. Have you set it up with the necessary config? Have you configured RC to use the bridge as push notification service?

githubdeb commented 3 years ago

I set up RC to use push notifications and added in the Gateway https://push.mydomain.com
I was successful getting the users token as well as the the veriLongToken from the mongodb
I have a problem while building the docker-compose image. It always breaks at cryptography.

Collecting cryptography Downloading cryptography-3.4.7.tar.gz (546 kB) Installing build dependencies: started Installing build dependencies: finished with status 'error' ERROR: Command errored out with exit status 1: command: /usr/local/bin/python /tmp/pip-standalone-pip-cguicstq/env_pip__.zip/pip install --ignore-installed --no-user --prefix /tmp/pip-build-env-zgoi60jl/overlay --no-warn-script-location --no-binary :none: --only-binary :none: -i https://pypi.org/simple -- 'setuptools>=40.6.0' wheel 'cffi>=1.12; platform_python_implementation != '"'"'PyPy'"'"'' 'setuptools-rust>=0.11.4' cwd: None Complete output (124 lines): Collecting setuptools>=40.6.0 Downloading setuptools-56.2.0-py3-none-any.whl (785 kB) Collecting wheel Downloading wheel-0.36.2-py2.py3-none-any.whl (35 kB) Collecting cffi>=1.12 Downloading cffi-1.14.5.tar.gz (475 kB) Collecting setuptools-rust>=0.11.4 Downloading setuptools_rust-0.12.1-py3-none-any.whl (22 kB) Collecting pycparser Downloading pycparser-2.20-py2.py3-none-any.whl (112 kB) Collecting semantic-version>=2.6.0 Downloading semantic_version-2.8.5-py2.py3-none-any.whl (15 kB) Collecting toml>=0.9.0 Downloading toml-0.10.2-py2.py3-none-any.whl (16 kB) Building wheels for collected packages: cffi Building wheel for cffi (setup.py): started Building wheel for cffi (setup.py): finished with status 'error' ERROR: Command errored out with exit status 1: command: /usr/local/bin/python -u -c 'import io, os, sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/setup.py'"'"'; file__='"'"'/tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/setup.py'"'"';f = getattr(tokenize, '"'"'open'"'"', open)(file) if os.path.exists(file) else io.StringIO('"'"'from setuptools import setup; setup()'"'"');code = f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, file, '"'"'exec'"'"'))' bdist_wheel -d /tmp/pip-wheel-yplq_93z cwd: /tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/ Complete output (45 lines):

immanuelfodor commented 3 years ago

Well, it seems the new Alpine Python image doesn't contain the necessary deps anymore to build the cryptography package, so I added them manually. Now the build is working again.

githubdeb commented 3 years ago

I set up RC to use push notifications and added in the Gateway https://push.mydomain.com
I was successful getting the users token as well as the the veriLongToken from the mongodb
I have a problem while building the docker-compose image. It always breaks at cryptography.

Collecting cryptography Downloading cryptography-3.4.7.tar.gz (546 kB) Installing build dependencies: started Installing build dependencies: finished with status 'error' ERROR: Command errored out with exit status 1: command: /usr/local/bin/python /tmp/pip-standalone-pip-cguicstq/env_pip__.zip/pip install --ignore-installed --no-user --prefix /tmp/pip-build-env-zgoi60jl/overlay --no-warn-script-location --no-binary :none: --only-binary :none: -i https://pypi.org/simple -- 'setuptools>=40.6.0' wheel 'cffi>=1.12; platform_python_implementation != '"'"'PyPy'"'"'' 'setuptools-rust>=0.11.4' cwd: None Complete output (124 lines): Collecting setuptools>=40.6.0 Downloading setuptools-56.2.0-py3-none-any.whl (785 kB) Collecting wheel Downloading wheel-0.36.2-py2.py3-none-any.whl (35 kB) Collecting cffi>=1.12 Downloading cffi-1.14.5.tar.gz (475 kB) Collecting setuptools-rust>=0.11.4 Downloading setuptools_rust-0.12.1-py3-none-any.whl (22 kB) Collecting pycparser Downloading pycparser-2.20-py2.py3-none-any.whl (112 kB) Collecting semantic-version>=2.6.0 Downloading semantic_version-2.8.5-py2.py3-none-any.whl (15 kB) Collecting toml>=0.9.0 Downloading toml-0.10.2-py2.py3-none-any.whl (16 kB) Building wheels for collected packages: cffi Building wheel for cffi (setup.py): started Building wheel for cffi (setup.py): finished with status 'error' ERROR: Command errored out with exit status 1: command: /usr/local/bin/python -u -c 'import io, os, sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/setup.py'"'"'; file__='"'"'/tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/setup.py'"'"';f = getattr(tokenize, '"'"'open'"'"', open)(file) if os.path.exists(file) else io.StringIO('"'"'from setuptools import setup; setup()'"'"');code = f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, file, '"'"'exec'"'"'))' bdist_wheel -d /tmp/pip-wheel-yplq_93z cwd: /tmp/pip-install-c1oxxxo1/cffi_4853e645eb1d4bac8db678e3af71ca7f/ Complete output (45 lines):

githubdeb commented 3 years ago

Hi Immanuel,

I was able to build the push gateway. I tested it with the curl and I got an error first time and success after that. All my machines are on the same server(Rocketchat, Push gateway, Gotify) In Rocketchat I went to the admin/Push page and added http://my-ip-address:10088 In the Push gateway config file I added gotiffys://my-gotify-push-server/random-app-token-for-rocketchat Both Gotify and Rocketchat runs secure behind a SSL proxy in my Nginx server. In Rocketchat I created two accounts for testing. In Gotify I have a Rocketchat application with the random-token and I created two users. For simplicity the users names are identical with the ones in Rocketchat I have also installed Gotify android client on two cellphones and successfully logged in to the Gotify server(https://my-gotify-push-server).

I have several questions:

Do I have to have a Nginx file behind a proxy for the Push gateway that runs on port 10088? If yes, do I need to secure it ?(use https for it)?
How can I debug the configuration once everything is in place? At this moment I have all the pieces running. However, I do not get any notifications in Gotify apk client.
Are there any wrong steps in what I described above?

Thank you. Luke

immanuelfodor commented 3 years ago

You seem to follow the recommended network topology fine: https://github.com/immanuelfodor/rocketchat-push-gateway#network-topology with your reverse proxy being Nginx. No need to configure anything in Nginx for the bridge.

You can set the log level to debug here then restart the service to see more logs: https://github.com/immanuelfodor/rocketchat-push-gateway/blob/master/docker-compose.yml#L11

Whenever you change the apprise config file, don't forget to rebuild the image, it doesn't use volumes, so the config is added in build time.

In the Push gateway config file I added gotiffys://my-gotify-push-server/random-app-token-for-rocketchat

The protocol seems to be incorrect, it should be just gotify, without double ff and without s.

If you run RC or Gotify server in docker, too, then I feel something could be with the host names as well. Localhost in Docker means the container itself, so you should use the service names to let them communicate with each other through the docker network bridge if using one compose file for all services or just the default bridge. The Docker host's LAN IP address could also work as hostname for second solution option. You could also run the three services with host network, then everything could communicate through localhost but must run on different ports, however, this one feels a bit hacky.

githubdeb commented 3 years ago

Hi Immanuel,

I corrected the error, but still not working. I think I know the cause, but don't know how to solve it. To test the RC app I created two users: one is denis and second is ana. In the apprise-config.yml I configured Ana's Gotify server with the corresponding token from Gotify and did the same for Denis. However, in mongo, when I run db.getCollection("_raix_push_app_tokens").find({userId:"RanD0m-UsERid"}, {_id:0, token:1}); for Ana, I do not get any king of token. I was expected to get the very-Long-Token. I did get one very-Long-Token but only when I used Denis account. Is the very-long-Token valid for both users or is custom for each user? If it is custom for each user, how do I get one for Ana?

Thank you.

immanuelfodor commented 3 years ago

You need to login at least once with the Ana user in the mobile app. The first mobile login seems to trigger the push token generation :)

githubdeb commented 3 years ago

Hi Immanuel,

I'm still debugging the configuration. I got the erros below while testing. Are these errors normal? Especially the Python error? If not what do you suggest?

rc-push-gw | [2021-05-12 03:50:58 +0000] [1] [INFO] Starting gunicorn 20.1.0 rc-push-gw | [2021-05-12 03:50:58 +0000] [1] [INFO] Listening at: http://0.0.0.0:5000 (1) rc-push-gw | [2021-05-12 03:50:58 +0000] [1] [INFO] Using worker: sync rc-push-gw | [2021-05-12 03:50:58 +0000] [8] [INFO] Booting worker with pid: 8 rc-push-gw | [2021-05-12 03:50:58 +0000] [9] [INFO] Booting worker with pid: 9 rc-push-gw | [2021-05-13 13:53:13 +0000] [8] [INFO] New notification received rc-push-gw | [2021-05-13 13:53:13 +0000] [8] [ERROR] Unexpected error during notification processing rc-push-gw | [2021-05-13 13:53:13 +0000] [8] [ERROR] Traceback (most recent call last): rc-push-gw | File "/usr/src/app/push.py", line 33, in push_send rc-push-gw | token = request.json['token'] rc-push-gw | TypeError: 'NoneType' object is not subscriptable rc-push-gw | rc-push-gw | [2021-05-13 13:53:13 +0000] [8] [ERROR] Could not forward the notification rc-push-gw | [2021-05-13 13:53:13 +0000] [8] [INFO] None rc-push-gw | 172.19.0.1 - - [13/May/2021:13:53:13 +0000] "POST /push/error/send HTTP/1.1" 200 5 "-" "curl/7.68.0" rc-push-gw | [2021-05-13 13:53:36 +0000] [9] [INFO] New notification received rc-push-gw | [2021-05-13 13:53:36 +0000] [9] [INFO] Forwarded the received notification, tag=push-gw-admin rc-push-gw | 172.19.0.1 - - [13/May/2021:13:53:36 +0000] "POST /push/success/send HTTP/1.1" 200 7 "-" "curl/7.68.0"

Thank you.

githubdeb commented 3 years ago

Hi Immanuel

Can you please confirm of not the following for me?

In Rocketchat I went to the admin/Push page and added http://localhost:10088 (This is the push gateway) ?
In apprise-config.yml
- gotifys://my-gotify-server/my-rocketchat-token ( I use gotifys because my gotify server is secured)
  - tag: push-gw-admin
- gotifys://my-gotify-server/my-rocketchat-token-for-user1
  - tag: my-very-long-token-for-user1-from-rocketchat-mongodb
- gotifys://my-gotify-server/my-rocketchat-token-for-user1
  - tag: my-very-long-token-for-user1-from-rocketchat-mongodb The source https://github.com/caronc/apprise/wiki/Notify_gotify mention that hostname is "The Rocket.Chat server you're sending your notification to." This confuses me as it is different than what you said in your apprise-config.yml Which one is the correct setting?

Thank you.

githubdeb commented 3 years ago

Hi Immanuel,

I am a step closer to make it work. I was successful in sending notifications from the push gateway to the Gotify server. However, I still have to work on Rocketchat that does not send push notifications to the push gateway. In the Rocketchat push settings I added: http://localhost:10088 Do I need anything else to set up? Thank you.

immanuelfodor commented 3 years ago

Sorry that I could not reply earlier, I didn't have time at the weekend and I have a fulltime job to do otherwise 😃

Were you able to send a "fake" push through the gateway and Gotify server to the mobile clients with curl? So that part works all right? This could mean that only the RC server and the gateway connection are having problems.

Do you still get the following error in the logs?

rc-push-gw | File "/usr/src/app/push.py", line 33, in push_send
rc-push-gw | token = request.json['token']
rc-push-gw | TypeError: 'NoneType' object is not subscriptable

The source https://github.com/caronc/apprise/wiki/Notify_gotify mention that hostname is "The Rocket.Chat server you're sending your notification to." This confuses me as it is different than what you said in your apprise-config.yml Which one is the correct setting?

This is a clear mistake in the Gotify wiki, probably a copy paste error. They ment a Gotify server, not RC.

immanuelfodor commented 3 years ago

gotifys://my-gotify-server/my-rocketchat-token-for-user1 tag: my-very-long-token-for-user1-from-rocketchat-mongodb gotifys://my-gotify-server/my-rocketchat-token-for-user1 tag: my-very-long-token-for-user1-from-rocketchat-mongodb

Here is also a copypaste error? The two user1 configs should likely be one user1 and user2

githubdeb commented 3 years ago

Hi Immanuel,

Yes. I understand. Fell free to answer when you can. I try to figure this out first and after that to move to automate the whole process.

See in the picture below the config of my apprise-config.yml

Notice that I have the names of the Gotify users and the veRY-LOng-Token separted by a coma. WhenI only have the veRY-LOng-Token without Gotify user names, I do not receive any push notification in Gotify.

Yes I can send push notifications from gateway to Gotify users. I used this command curl -X POST \ http://localhost:10088/push/success/send \ -H 'Content-Type: application/json' \ -d '{ "token": "cAmmTtMCQ9-Fv-q5ye6uDQ:APA91bGpCgX1t6pzMTHIVvgwj4AEPab8SrulfXE8DZbqdsGr5w6nh6UJv3I7IbSSibKuE1gLDc7xpnaom2ek8sR4EpmyZXCLpAVUD2cWcKEZtR5SficMcs8l0Q8b62k", "options": { "title": "Test message", "text": "Hello World! It Works" } }' After using the command I get a push notification for user "denis" without quotes in my Gotify client android app.
You are correct, I still get that error that you mentioned. See the logs below. The first part shows the success in sending the push to Gotify. The second part shows the fail.

Indeed now the only left part is to be able to push notifications from Rocketchat to the gateway. What do you suggest?

Thank you.

immanuelfodor commented 3 years ago

This is great progress!

Do you send a test push from the RC admin? My best guess is that it doesn't include any payload as there is a completely empty POST shown on the log screenshot.

Have you tried it in a context where one of the users should get a real notification? Maybe try it in a chat room where the related users are added but the others don't have the web client open, just you, so RC should send a real push notification for them.

immanuelfodor commented 3 years ago

It's also interesting that the log screenshot only contains the 'curl' user agent, and the error is at the /push/error/send route with form data. RC sends JSON data, not form data. There is one example for an error in the readme, as it uses form data (-F flag):

# should produce an error later in the logs
curl -X POST \
  http://localhost:10088/push/error/send \
  -F foo=bar

So this is intended not to work, but the JSON example with the valid payload is working:

# should be forwarded successfully
curl -X POST \
  http://localhost:10088/push/success/send \
  -H 'Content-Type: application/json' \
  -d '{
    "token": "push-gw-admin",
    "options": {
        "title": "Test message",
        "text": "Hello World!"
    }
}'

Hence, the above log screenshot are not from RC, I think, they wouldn't modify their user agent to curl (would they?) and would only send JSON payload that also works wit curl, so it should with RC, too.

githubdeb commented 3 years ago

This is great progress!

Do you send a test push from the RC admin? My best guess is that it doesn't include any payload as there is a completely empty POST shown on the log screenshot.

Have you tried it in a context where one of the users should get a real notification? Maybe try it in a chat room where the related users are added but the others don't have the web client open, just you, so RC should send a real push notification for them.

No, I do not send a test push from the RC admin.

I have created two users: denis and babe in RC.
I have created the same users in Gotify, each user with the RC application.
I installed RC on android on two phones. On one phone I have the denis account and on another phone I have the babe account.
The two accounts(denis and babe) communicate well using RC. However, they do not get push notifications in Gotify. Maybe I'm wrong, but I was expected that when denis send a message in RC to babe, Gotify on babe's phone should show a push notification.

Thanks

immanuelfodor commented 3 years ago

The two accounts(denis and babe) communicate well using RC. However, they do not get push notifications in Gotify. Maybe I'm wrong, but I was expected that when denis send a message in RC to babe, Gotify on babe's phone should show a push notification.

This is true but one of them should not be logged in on the web interface, just via phone. RC doesn't send the push if it can deliver the message via web. Maybe to save an FCM cloud push request.

githubdeb commented 3 years ago

It's also interesting that the log screenshot only contains the 'curl' user agent, and the error is at the /push/error/send route with form data. RC sends JSON data, not form data. There is one example for an error in the readme, as it uses form data (-F flag):
# should produce an error later in the logs
curl -X POST \
  http://localhost:10088/push/error/send \
  -F foo=bar
So this is intended not to work, but the JSON example with the valid payload is working:
# should be forwarded successfully
curl -X POST \
  http://localhost:10088/push/success/send \
  -H 'Content-Type: application/json' \
  -d '{
    "token": "push-gw-admin",
    "options": {
        "title": "Test message",
        "text": "Hello World!"
    }
}'
Hence, the above log screenshot are not from RC, I think, they wouldn't modify their user agent to curl (would they?) and would only send JSON payload that also works wit curl, so it should with RC, too.

You are right. The logs I posted are not from the RC. They are from using the test curl syntax from your post.

My main issue is that it seems that RC does not communicate with the push gateway. In my push settings I have http://localhost:10088 I need a way to make sure that my RC somehow reaches this gateway address. Do you have any idea on how to do this?

Thank you.

immanuelfodor commented 3 years ago

I think they shouldn't even use the phone at the same time. RC is clever, it saves the push if it thinks the user can see it right away in the app or on the web 😃

immanuelfodor commented 3 years ago

Do you run RC in docker on the same host, too? What is the compose file you are using with RC, if yes?

githubdeb commented 3 years ago

The two accounts(denis and babe) communicate well using RC. However, they do not get push notifications in Gotify. Maybe I'm wrong, but I was expected that when denis send a message in RC to babe, Gotify on babe's phone should show a push notification.

This is true but one of them should not be logged in on the web interface, just via phone. RC doesn't send the push if it can deliver the message via web. Maybe to save an FCM cloud push request.

None of them are logged in the web interface. Both accounts are only on Android RC.

githubdeb commented 3 years ago

Do you run RC in docker on the same host, too? What is the compose file you are using with RC, if yes?

I run RC on the same host but not in Docker.

immanuelfodor commented 3 years ago

Hmm, what I feel is that somehow the http://localhost:10088/ URL is not being resolved to the Docker container. Could you please try using the IP address of the VM/machine that hosts the bridge? E.g., http://192.168.1.22:10088

githubdeb commented 3 years ago

I tried and the result is the same Look at the logs below. It seems that for some reason Rocketchat does not communicate with the gateway.

immanuelfodor commented 3 years ago

This is evidence that RC sends out the push, but do you have the logs from Docker for the exact same push, or can you generate one? Send a push in RC and screenshot both the RC and the related gateway logs. Are there any logs in the bridge related to it, or the bridge doesn't receive any communication from RC? I'm trying to rule out either a network error (not the bridge's fault) or a changed payload scheme (the bridge needs to be updated), this is why I'm asking this to narrow down where the error is.

githubdeb commented 3 years ago

Here you are: The message I sent is from user babe to user denis. The text sent is "Hello there" sent at 17:45 I do not think is something related to the network because I can do telnet to rocketchat server and push-gateway and it works well.

push-gateway logs blow. As you can see there is nothing there.

Rockectchat logs

I20210522-17:45:14.251(0) API ➔ debug GET: /api/info I20210522-17:45:14.254(0) API ➔ debug Success { statusCode: 200, body: { version: '3.14.0', success: true } } 
I20210522-17:45:14.475(0) Meteor ➔ publish null -> userId: null, arguments: [] 
I20210522-17:45:14.894(0) API ➔ debug POST: /api/v1/login I20210522-17:45:15.741(0) Meteor ➔ publish null -> userId: Fuv9nzrYzGCkMJXMk, arguments: [] 
I20210522-17:45:16.228(0) API ➔ debug GET: /api/v1/roles.list? I20210522-17:45:16.242(0) API ➔ debug Success {   statusCode: 200,   body: {     roles: [       [Object], [Object],       [Object], [Object],       [Object], [Object],       [Object], [Object],       [Object], [Object],       [Object]     ],     success: true   } } 
I20210522-17:45:16.407(0) API ➔ debug GET: /api/v1/users.presence?ids=abzTtbRcebN5Wgxer%2CL9PrQDZEEfrRshpDk%2CFuv9nzrYzGCkMJXMk 
I20210522-17:45:16.412(0) API ➔ debug GET: /api/v1/commands.list? 
I20210522-17:45:16.417(0) API ➔ debug Success {   statusCode: 200,   body: {     commands: [       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object], [Object], [Object],       [Object]     ],     offset: 0,     count: 25,     total: 25,     success: true   } } 
I20210522-17:45:16.420(0) API ➔ debug POST: /api/v1/push.token 
I20210522-17:45:16.431(0) Push ➔ debug Got push token from app: {   id: 'YcNsxZ85GCZBjqmzj',   token: {     gcm: 'fWvLySQ0RJaoM1g1KEKwxz:APA91bFoq8jop_HfDk-RFbkIs-BDIvWcBggLU0ScNlk1iZpXes3LjwSwZ9_0Dkq3RwNdAxtsV0CHJ9VzsfRlRh-CgUFNaml0oasYk-J6hKScbwBvkttCjOxoqOzBydg5JBOM_IUSt-Ye'   },   appName: 'chat.rocket.android',   userId: 'Fuv9nzrYzGCkMJXMk' } 
I20210522-17:45:16.435(0) API ➔ debug POST: /api/v1/method.call/license:getModules 
I20210522-17:45:16.439(0) API ➔ debug Success {   statusCode: 200,   body: { message: '{"msg":"result","result":[]}', success: true } } I20210522-17:45:16.445(0) API ➔ debug Success {   statusCode: 200,   body: { users: [ [Object], [Object] ], full: false, success: true } } 
I20210522-17:45:16.458(0) Push ➔ debug updated {   _id: '6MG9HcsbzW4DDtWJK',   token: {     gcm: 'fWvLySQ0RJaoM1g1KEKwxz:APA91bFoq8jop_HfDk-RFbkIs-BDIvWcBggLU0ScNlk1iZpXes3LjwSwZ9_0Dkq3RwNdAxtsV0CHJ9VzsfRlRh-CgUFNaml0oasYk-J6hKScbwBvkttCjOxoqOzBydg5JBOM_IUSt-Ye'   },   appName: 'chat.rocket.android',   userId: 'Fuv9nzrYzGCkMJXMk',   enabled: true,   createdAt: 2021-05-12T03:31:19.705Z,   updatedAt: 2021-05-21T22:51:03.991Z } 
I20210522-17:45:16.462(0) API ➔ debug Success {   statusCode: 200,   body: {     result: {       _id: '6MG9HcsbzW4DDtWJK',       token: [Object],       appName: 'chat.rocket.android',       userId: 'Fuv9nzrYzGCkMJXMk',       enabled: true,       createdAt: 2021-05-12T03:31:19.705Z,       updatedAt: 2021-05-21T22:51:03.991Z     },     success: true   } } 
I20210522-17:45:16.534(0) API ➔ debug GET: /api/v1/permissions.listAll?updatedSince=2021-05-04T18%3A59%3A22.133Z 
I20210522-17:45:16.624(0) API ➔ debug Success { statusCode: 200, body: { update: [], remove: [], success: true } } 
I20210522-17:45:16.714(0) API ➔ debug GET: /api/v1/emoji-custom.list? I20210522-17:45:16.719(0) API ➔ debug GET: /api/v1/subscriptions.get?updatedSince=2021-05-22T00%3A41%3A43.983Z I20210522-17:45:16.722(0) Meteor ➔ method subscriptions/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: [{}] I20210522-17:45:16.725(0) API ➔ debug GET: /api/v1/rooms.get?updatedSince=2021-05-22T00%3A41%3A43.983Z 
I20210522-17:45:16.728(0) Meteor ➔ method rooms/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: [{}] I20210522-17:45:16.736(0) API ➔ debug Success {   statusCode: 200,   body: { emojis: { update: [], remove: [] }, success: true } } I20210522-17:45:16.739(0) API ➔ debug Success {   statusCode: 200,   body: { update: [ [Object] ], remove: [], success: true } } I20210522-17:45:16.747(0) API ➔ debug Success {   statusCode: 200,   body: { update: [ [Object] ], remove: [], success: true } } 
I20210522-17:45:16.891(0) API ➔ debug GET: /api/v1/chat.syncMessages?roomId=Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer&lastUpdate=2021-05-22T00%3A34%3A22.068Z I20210522-17:45:16.905(0) Meteor ➔ method messages/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer",{"lastUpdate":"2021-05-22T00:34:22.068Z"}] I20210522-17:45:16.909(0) Meteor ➔ method canAccessRoom -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer","Fuv9nzrYzGCkMJXMk"] I20210522-17:45:16.930(0) API ➔ debug Success {   statusCode: 200,   body: { result: { updated: [Array], deleted: [] }, success: true } } 
I20210522-17:45:17.316(0) API ➔ debug GET: /api/v1/users.info?userId=abzTtbRcebN5Wgxer I20210522-17:45:17.329(0) API ➔ debug Success {   statusCode: 200,   body: {     user: {       _id: 'abzTtbRcebN5Wgxer',       type: 'user',       status: 'offline',       active: true,       name: 'Denis',       username: 'denis',       statusText: '',       utcOffset: -5     },     success: true   } } 
I20210522-17:45:17.467(0) API ➔ debug POST: /api/v1/subscriptions.read I20210522-17:45:17.470(0) Meteor ➔ method readMessages -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer"] I20210522-17:45:17.479(0) API ➔ debug Success { statusCode: 200, body: { success: true } } I20210522-17:45:26.898(0) API ➔ debug POST: /api/v1/chat.sendMessage I20210522-17:45:26.935(0) API ➔ debug Success {   statusCode: 200,   body: {     message: {       _id: 'hsTDaIHNfWVgYDOAi',       rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',       msg: 'Hello there',       ts: 2021-05-22T17:45:26.903Z,       u: [Object],       urls: [],       mentions: [],       channels: [],       _updatedAt: 2021-05-22T17:45:26.929Z     },     success: true   } } I20210522-17:45:26.950(0) Integrations ➔ Outgoing WebHook.debug Execute Trigger: sendMessage I20210522-17:45:26.954(0) Integrations ➔ Outgoing WebHook.debug Got the event arguments for the event: sendMessage {   event: 'sendMessage',   message: {     _id: 'hsTDaIHNfWVgYDOAi',     rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',     msg: 'Hello there',     ts: 2021-05-22T17:45:26.903Z,     u: { _id: 'Fuv9nzrYzGCkMJXMk', username: 'babe', name: undefined },     urls: [],     mentions: [],     channels: [],     _updatedAt: 2021-05-22T17:45:26.929Z   },   room: {     _id: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',     t: 'd',     usernames: [ 'babe', 'denis' ],     usersCount: 2,     msgs: 46,     ts: 2021-05-12T03:53:47.868Z,     uids: [ 'Fuv9nzrYzGCkMJXMk', 'abzTtbRcebN5Wgxer' ],     _updatedAt: 2021-05-22T02:14:11.202Z,     lastMessage: {       _id: 'EzihPPuQZ7xrgKQM1',       rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',       msg: 'Another test',       ts: 2021-05-22T02:14:11.170Z,       u: [Object],       urls: [],       mentions: [],       channels: [],       _updatedAt: 2021-05-22T02:14:11.187Z     },     lm: 2021-05-22T02:14:11.170Z,     jitsiTimeout: 2021-05-14T22:06:23.580Z   } } 
I20210522-17:45:26.957(0) Integrations ➔ Outgoing WebHook.debug Starting search for triggers for the room: Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer I20210522-17:45:26.963(0) Integrations ➔ Outgoing WebHook.debug Found 0 to iterate over and see if the match the event. I20210522-17:45:27.780(0) Push ➔ debug Sending notification {   createdAt: 2021-05-22T17:45:27.775Z,   createdBy: '<SERVER>',   sent: false,   sending: 0,   from: 'push',   title: 'babe',   text: 'Hello there',   userId: 'abzTtbRcebN5Wgxer',   payload: {     host: 'https://chat.mystockphotos.eu/',     messageId: 'hsTDaIHNfWVgYDOAi',     notificationType: 'message',     rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',     sender: { _id: 'Fuv9nzrYzGCkMJXMk', username: 'babe' },     senderName: 'babe',     type: 'd'   },   badge: 1,   sound: 'default',   notId: 62867164,   apn: { category: 'MESSAGE' },   gcm: {     image: 'https://chat.mystockphotos.eu/images/logo/android-chrome-192x192.png',     style: 'inbox'   } } 
I20210522-17:45:27.781(0) Push ➔ debug send message "babe" to userId abzTtbRcebN5Wgxer I20210522-17:45:27.833(0) Push ➔ debug send to token {   gcm: 'cAmmTtMCQ9-Fv-q5ye6uDQ:APA91bGpCgX1t6pzMTHIVvgwj4AEPab8SrulfXE8DZbqdsGr5w6nh6UJv3I7IbSSibKuE1gLDc7xpnaom2ek8sR4EpmyZXCLpAVUD2cWcKEZtR5SficMcs8l0Q8b62kON6qxswbnG64Y' } I20210522-17:45:27.841(0) Push ➔ debug send to token {   gcm: 'cAmmTtMCQ9-Fv-q5ye6uDQ:APA91bGpCgX1t6pzMTHIVvgwj4AEPab8SrulfXE8DZbqdsGr5w6nh6UJv3I7IbSSibKuE1gLDc7xpnaom2ek8sR4EpmyZXCLpAVUD2cWcKEZtR5SficMcs8l0Q8b62kON6qxswbnG64Y' } I20210522-17:45:27.842(0) Push ➔ debug Sent message "babe" to 0 ios apps 1 android apps 
I20210522-17:45:27.849(0) Push ➔ debug GUIDE: The "appTokensCollection" - No APN clients have registered on the server yet... 
I20210522-17:45:28.942(0) API ➔ debug POST: /api/v1/subscriptions.read I20210522-17:45:28.946(0) Meteor ➔ method readMessages -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer"] I20210522-17:45:28.953(0) API ➔ debug Success { statusCode: 200, body: { success: true } } 
I20210522-17:46:00.779(0) SyncedCron ➔ info Starting "Generate download files for user data". 
I20210522-17:46:00.788(0) SyncedCron ➔ info Finished "Generate download files for user data".

System logs:

May 22 17:39:01 friend CRON[3119]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
May 22 17:39:02 friend systemd[1]: Starting Clean php session files...
May 22 17:39:02 friend systemd[1]: phpsessionclean.service: Succeeded.
May 22 17:39:02 friend systemd[1]: Finished Clean php session files.
May 22 17:43:20 friend rocketchat[1402]: Exception while invoking method saveSettings Error: TOTP Required [totp-required]
May 22 17:43:20 friend rocketchat[1402]:     at checkCodeForUser (app/2fa/server/code/index.ts:186:9)
May 22 17:43:20 friend rocketchat[1402]:     at MethodInvocation.<anonymous> (app/2fa/server/twoFactorRequired.ts:31:4)
May 22 17:43:20 friend rocketchat[1402]:     at MethodInvocation.methodsMap.<computed> (app/lib/server/lib/debug.js:76:34)
May 22 17:43:20 friend rocketchat[1402]:     at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)
May 22 17:43:20 friend rocketchat[1402]:     at packages/ddp-server/livedata_server.js:1689:15
May 22 17:43:20 friend rocketchat[1402]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
May 22 17:43:20 friend rocketchat[1402]:     at packages/ddp-server/livedata_server.js:1687:36
May 22 17:43:20 friend rocketchat[1402]:     at new Promise (<anonymous>)
May 22 17:43:20 friend rocketchat[1402]:     at Server.applyAsync (packages/ddp-server/livedata_server.js:1686:12)
May 22 17:43:20 friend rocketchat[1402]:     at Server.apply (packages/ddp-server/livedata_server.js:1625:26)
May 22 17:43:20 friend rocketchat[1402]:     at Server.call (packages/ddp-server/livedata_server.js:1607:17)
May 22 17:43:20 friend rocketchat[1402]:     at Object.post (app/api/server/v1/misc.js:263:26)
May 22 17:43:20 friend rocketchat[1402]:     at app/api/server/api.js:394:82
May 22 17:43:20 friend rocketchat[1402]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
May 22 17:43:20 friend rocketchat[1402]:     at Object._internalRouteActionHandler [as action] (app/api/server/api.js:394:39)
May 22 17:43:20 friend rocketchat[1402]:     at Route.share.Route.Route._callEndpoint (packages/nimble_restivus/lib/route.coffee:150:32)
May 22 17:43:20 friend rocketchat[1402]:     at packages/nimble_restivus/lib/route.coffee:59:33
May 22 17:43:20 friend rocketchat[1402]:     at packages/simple_json-routes.js:98:9
May 22 17:43:20 friend rocketchat[1402]:  => awaited here:
May 22 17:43:20 friend rocketchat[1402]:     at Promise.await (/opt/Rocket.Chat/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:60:12)
May 22 17:43:20 friend rocketchat[1402]:     at Server.apply (packages/ddp-server/livedata_server.js:1638:22)
May 22 17:43:20 friend rocketchat[1402]:     at Server.call (packages/ddp-server/livedata_server.js:1607:17)
May 22 17:43:20 friend rocketchat[1402]:     at Object.post (app/api/server/v1/misc.js:263:26)
May 22 17:43:20 friend rocketchat[1402]:     at app/api/server/api.js:394:82
May 22 17:43:20 friend rocketchat[1402]:     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
May 22 17:43:20 friend rocketchat[1402]:     at Object._internalRouteActionHandler [as action] (app/api/server/api.js:394:39)
May 22 17:43:20 friend rocketchat[1402]:     at Route.share.Route.Route._callEndpoint (packages/nimble_restivus/lib/route.coffee:150:32)
May 22 17:43:20 friend rocketchat[1402]:     at packages/nimble_restivus/lib/route.coffee:59:33
May 22 17:43:20 friend rocketchat[1402]:     at packages/simple_json-routes.js:98:9
May 22 17:43:26 friend rocketchat[1402]: API âž” debug POST: /api/v1/method.call/private-settings%3Aget
May 22 17:43:26 friend rocketchat[1402]: Meteor âž” method private-settings/get -> userId: L9PrQDZEEfrRshpDk, arguments: [{}]
May 22 17:43:26 friend rocketchat[1402]: API âž” debug Success {
May 22 17:43:26 friend rocketchat[1402]:   statusCode: 200,
May 22 17:43:26 friend rocketchat[1402]:   body: {
May 22 17:43:26 friend rocketchat[1402]:     message: '{"msg":"result","id":"28","result":{"update":[{"_id":"Log_Level","_updatedAt":{"$date":1621705406297},"autocomplete":true,"blocked":false,"createdAt":{"$date":1620154728577},"enterprise":false,"group":"Logs","hidden":false,"i18nDescription":"Log_Level_Description","i18nLabel":"Log_Level","packageValue":"0","public":true,"requiredOnWizard":false,"secret":false,"sorter":0,"ts":{"$date":1620154728579},"type":"select","value":"2","valueSource":"packageValue","values":[{"key":"0","i18nLabel":"0_Errors_Only"},{"key":"1","i18nLabel":"1_Errors_and_Information"},{"key":"2","i18nLabel":"2_Erros_Information_and_Debug"}]}],"remove":[]}}',
May 22 17:43:26 friend rocketchat[1402]:     success: true
May 22 17:43:26 friend rocketchat[1402]:   }
May 22 17:43:26 friend rocketchat[1402]: }
May 22 17:43:31 friend rocketchat[1402]: API âž” debug GET: /api/v1/stdout.queue
May 22 17:43:31 friend rocketchat[1402]: API âž” debug Success {
May 22 17:43:31 friend rocketchat[1402]:   statusCode: 200,
May 22 17:43:31 friend rocketchat[1402]:   body: {
May 22 17:43:31 friend rocketchat[1402]:     queue: [
May 22 17:43:31 friend rocketchat[1402]:       [Object], [Object], [Object],
May 22 17:43:31 friend rocketchat[1402]: message repeated 8 times: [       [Object], [Object], [Object],]
May 22 17:43:31 friend rocketchat[1402]:       [Object], [Object], [Object]
May 22 17:43:31 friend rocketchat[1402]:     ],
May 22 17:43:31 friend rocketchat[1402]:     success: true
May 22 17:43:31 friend rocketchat[1402]:   }
May 22 17:43:31 friend rocketchat[1402]: }
May 22 17:44:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:44:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:45:14 friend rocketchat[1402]: API âž” debug GET: /api/v1/settings.public?query={%22_id%22:{%22$in%22:[%22Accounts_AllowEmailChange%22,%22Accounts_AllowPasswordChange%22,%22Accounts_AllowRealNameChange%22,%22Accounts_AllowUserAvatarChange%22,%22Accounts_AllowUserProfileChange%22,%22Accounts_AllowUserStatusMessageChange%22,%22Accounts_AllowUsernameChange%22,%22Accounts_AvatarBlockUnauthenticatedAccess%22,%22Accounts_CustomFields%22,%22Accounts_NamePlaceholder%22,%22API_Use_REST_For_DDP_Calls%22,%22CROWD_Enable%22,%22DirectMesssage_maxUsers%22,%22E2E_Enable%22,%22Accounts_Directory_DefaultView%22,%22FEDERATION_Enabled%22,%22Hide_System_Messages%22,%22LDAP_Enable%22,%22Livechat_request_comment_when_closing_conversation%22,%22Jitsi_Enabled%22,%22Jitsi_SSL%22,%22Jitsi_Domain%22,%22Jitsi_Enabled_TokenAuth%22,%22Jitsi_URL_Room_Hash%22,%22Jitsi_URL_Room_Prefix%22,%22Message_AllowDeleting%22,%22Message_AllowDeleting_BlockDeleteInMinutes%22,%22Message_AllowEditing%22,%22Message_AllowEditing_BlockEditInMinutes%22,%22Message_AllowPinning%22,%22Message_AllowStarring%22,%22Message_AudioRecorderEnabled%22,%22Message_GroupingPeriod%22,%22Message_TimeFormat%22,%22Message_TimeAndDateFormat%22,%22Site_Name%22,%22Store_Last_Message%22,%22uniqueID%22,%22UI_Allow_room_names_with_special_chars%22,%22UI_Use_Real_Name%22,%22Assets_favicon_512%22,%22Message_Read_Receipt_Enabled%22,%22Message_Read_Receipt_Store_Users%22,%22Threads_enabled%22,%22FileUpload_MediaTypeWhiteList%22,%22FileUpload_MaxFileSize%22,%22AutoTranslate_Enabled%22,%22Force_Screen_Lock%22,%22Force_Screen_Lock_After%22,%22Allow_Save_Media_to_Gallery%22]}}
May 22 17:45:14 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:14 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:14 friend rocketchat[1402]:   body: {
May 22 17:45:14 friend rocketchat[1402]:     settings: [
May 22 17:45:14 friend rocketchat[1402]:       [Object], [Object], [Object], [Object],
May 22 17:45:14 friend rocketchat[1402]: message repeated 11 times: [       [Object], [Object], [Object], [Object],]
May 22 17:45:14 friend rocketchat[1402]:       [Object]
May 22 17:45:14 friend rocketchat[1402]:     ],
May 22 17:45:14 friend rocketchat[1402]:     count: 49,
May 22 17:45:14 friend rocketchat[1402]:     offset: 0,
May 22 17:45:14 friend rocketchat[1402]:     total: 49,
May 22 17:45:14 friend rocketchat[1402]:     success: true
May 22 17:45:14 friend rocketchat[1402]:   }
May 22 17:45:14 friend rocketchat[1402]: }
May 22 17:45:14 friend rocketchat[1402]: API âž” debug GET: /api/info
May 22 17:45:14 friend rocketchat[1402]: API âž” debug Success { statusCode: 200, body: { version: '3.14.0', success: true } }
May 22 17:45:14 friend rocketchat[1402]: Meteor âž” publish null -> userId: null, arguments: []
May 22 17:45:14 friend rocketchat[1402]: API âž” debug POST: /api/v1/login
May 22 17:45:15 friend rocketchat[1402]: Meteor âž” publish null -> userId: Fuv9nzrYzGCkMJXMk, arguments: []
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/roles.list?
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: {
May 22 17:45:16 friend rocketchat[1402]:     roles: [
May 22 17:45:16 friend rocketchat[1402]:       [Object], [Object],
May 22 17:45:16 friend rocketchat[1402]: message repeated 4 times: [       [Object], [Object],]
May 22 17:45:16 friend rocketchat[1402]:       [Object]
May 22 17:45:16 friend rocketchat[1402]:     ],
May 22 17:45:16 friend rocketchat[1402]:     success: true
May 22 17:45:16 friend rocketchat[1402]:   }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/users.presence?ids=abzTtbRcebN5Wgxer%2CL9PrQDZEEfrRshpDk%2CFuv9nzrYzGCkMJXMk
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/commands.list?
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: {
May 22 17:45:16 friend rocketchat[1402]:     commands: [
May 22 17:45:16 friend rocketchat[1402]:       [Object], [Object], [Object],
May 22 17:45:16 friend rocketchat[1402]: message repeated 7 times: [       [Object], [Object], [Object],]
May 22 17:45:16 friend rocketchat[1402]:       [Object]
May 22 17:45:16 friend rocketchat[1402]:     ],
May 22 17:45:16 friend rocketchat[1402]:     offset: 0,
May 22 17:45:16 friend rocketchat[1402]:     count: 25,
May 22 17:45:16 friend rocketchat[1402]:     total: 25,
May 22 17:45:16 friend rocketchat[1402]:     success: true
May 22 17:45:16 friend rocketchat[1402]:   }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug POST: /api/v1/push.token
May 22 17:45:16 friend rocketchat[1402]: Push âž” debug Got push token from app: {
May 22 17:45:16 friend rocketchat[1402]:   id: 'YcNsxZ85GCZBjqmzj',
May 22 17:45:16 friend rocketchat[1402]:   token: {
May 22 17:45:16 friend rocketchat[1402]:     gcm: 'fWvLySQ0RJaoM1g1KEKwxz:APA91bFoq8jop_HfDk-RFbkIs-BDIvWcBggLU0ScNlk1iZpXes3LjwSwZ9_0Dkq3RwNdAxtsV0CHJ9VzsfRlRh-CgUFNaml0oasYk-J6hKScbwBvkttCjOxoqOzBydg5JBOM_IUSt-Ye'
May 22 17:45:16 friend rocketchat[1402]:   },
May 22 17:45:16 friend rocketchat[1402]:   appName: 'chat.rocket.android',
May 22 17:45:16 friend rocketchat[1402]:   userId: 'Fuv9nzrYzGCkMJXMk'
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug POST: /api/v1/method.call/license:getModules
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { message: '{"msg":"result","result":[]}', success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { users: [ [Object], [Object] ], full: false, success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: Push âž” debug updated {
May 22 17:45:16 friend rocketchat[1402]:   _id: '6MG9HcsbzW4DDtWJK',
May 22 17:45:16 friend rocketchat[1402]:   token: {
May 22 17:45:16 friend rocketchat[1402]:     gcm: 'fWvLySQ0RJaoM1g1KEKwxz:APA91bFoq8jop_HfDk-RFbkIs-BDIvWcBggLU0ScNlk1iZpXes3LjwSwZ9_0Dkq3RwNdAxtsV0CHJ9VzsfRlRh-CgUFNaml0oasYk-J6hKScbwBvkttCjOxoqOzBydg5JBOM_IUSt-Ye'
May 22 17:45:16 friend rocketchat[1402]:   },
May 22 17:45:16 friend rocketchat[1402]:   appName: 'chat.rocket.android',
May 22 17:45:16 friend rocketchat[1402]:   userId: 'Fuv9nzrYzGCkMJXMk',
May 22 17:45:16 friend rocketchat[1402]:   enabled: true,
May 22 17:45:16 friend rocketchat[1402]:   createdAt: 2021-05-12T03:31:19.705Z,
May 22 17:45:16 friend rocketchat[1402]:   updatedAt: 2021-05-21T22:51:03.991Z
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: {
May 22 17:45:16 friend rocketchat[1402]:     result: {
May 22 17:45:16 friend rocketchat[1402]:       _id: '6MG9HcsbzW4DDtWJK',
May 22 17:45:16 friend rocketchat[1402]:       token: [Object],
May 22 17:45:16 friend rocketchat[1402]:       appName: 'chat.rocket.android',
May 22 17:45:16 friend rocketchat[1402]:       userId: 'Fuv9nzrYzGCkMJXMk',
May 22 17:45:16 friend rocketchat[1402]:       enabled: true,
May 22 17:45:16 friend rocketchat[1402]:       createdAt: 2021-05-12T03:31:19.705Z,
May 22 17:45:16 friend rocketchat[1402]:       updatedAt: 2021-05-21T22:51:03.991Z
May 22 17:45:16 friend rocketchat[1402]:     },
May 22 17:45:16 friend rocketchat[1402]:     success: true
May 22 17:45:16 friend rocketchat[1402]:   }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/permissions.listAll?updatedSince=2021-05-04T18%3A59%3A22.133Z
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success { statusCode: 200, body: { update: [], remove: [], success: true } }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/emoji-custom.list?
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/subscriptions.get?updatedSince=2021-05-22T00%3A41%3A43.983Z
May 22 17:45:16 friend rocketchat[1402]: Meteor âž” method subscriptions/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: [{}]
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/rooms.get?updatedSince=2021-05-22T00%3A41%3A43.983Z
May 22 17:45:16 friend rocketchat[1402]: Meteor âž” method rooms/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: [{}]
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { emojis: { update: [], remove: [] }, success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { update: [ [Object] ], remove: [], success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { update: [ [Object] ], remove: [], success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:16 friend rocketchat[1402]: API âž” debug GET: /api/v1/chat.syncMessages?roomId=Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer&lastUpdate=2021-05-22T00%3A34%3A22.068Z
May 22 17:45:16 friend rocketchat[1402]: Meteor âž” method messages/get -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer",{"lastUpdate":"2021-05-22T00:34:22.068Z"}]
May 22 17:45:16 friend rocketchat[1402]: Meteor âž” method canAccessRoom -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer","Fuv9nzrYzGCkMJXMk"]
May 22 17:45:16 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:16 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:16 friend rocketchat[1402]:   body: { result: { updated: [Array], deleted: [] }, success: true }
May 22 17:45:16 friend rocketchat[1402]: }
May 22 17:45:17 friend rocketchat[1402]: API âž” debug GET: /api/v1/users.info?userId=abzTtbRcebN5Wgxer
May 22 17:45:17 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:17 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:17 friend rocketchat[1402]:   body: {
May 22 17:45:17 friend rocketchat[1402]:     user: {
May 22 17:45:17 friend rocketchat[1402]:       _id: 'abzTtbRcebN5Wgxer',
May 22 17:45:17 friend rocketchat[1402]:       type: 'user',
May 22 17:45:17 friend rocketchat[1402]:       status: 'offline',
May 22 17:45:17 friend rocketchat[1402]:       active: true,
May 22 17:45:17 friend rocketchat[1402]:       name: 'Denis',
May 22 17:45:17 friend rocketchat[1402]:       username: 'denis',
May 22 17:45:17 friend rocketchat[1402]:       statusText: '',
May 22 17:45:17 friend rocketchat[1402]:       utcOffset: -5
May 22 17:45:17 friend rocketchat[1402]:     },
May 22 17:45:17 friend rocketchat[1402]:     success: true
May 22 17:45:17 friend rocketchat[1402]:   }
May 22 17:45:17 friend rocketchat[1402]: }
May 22 17:45:17 friend rocketchat[1402]: API âž” debug POST: /api/v1/subscriptions.read
May 22 17:45:17 friend rocketchat[1402]: Meteor âž” method readMessages -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer"]
May 22 17:45:17 friend rocketchat[1402]: API âž” debug Success { statusCode: 200, body: { success: true } }
May 22 17:45:26 friend rocketchat[1402]: API âž” debug POST: /api/v1/chat.sendMessage
May 22 17:45:26 friend rocketchat[1402]: API âž” debug Success {
May 22 17:45:26 friend rocketchat[1402]:   statusCode: 200,
May 22 17:45:26 friend rocketchat[1402]:   body: {
May 22 17:45:26 friend rocketchat[1402]:     message: {
May 22 17:45:26 friend rocketchat[1402]:       _id: 'hsTDaIHNfWVgYDOAi',
May 22 17:45:26 friend rocketchat[1402]:       rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',
May 22 17:45:26 friend rocketchat[1402]:       msg: 'Hello there',
May 22 17:45:26 friend rocketchat[1402]:       ts: 2021-05-22T17:45:26.903Z,
May 22 17:45:26 friend rocketchat[1402]:       u: [Object],
May 22 17:45:26 friend rocketchat[1402]:       urls: [],
May 22 17:45:26 friend rocketchat[1402]:       mentions: [],
May 22 17:45:26 friend rocketchat[1402]:       channels: [],
May 22 17:45:26 friend rocketchat[1402]:       _updatedAt: 2021-05-22T17:45:26.929Z
May 22 17:45:26 friend rocketchat[1402]:     },
May 22 17:45:26 friend rocketchat[1402]:     success: true
May 22 17:45:26 friend rocketchat[1402]:   }
May 22 17:45:26 friend rocketchat[1402]: }
May 22 17:45:26 friend rocketchat[1402]: Integrations âž” Outgoing WebHook.debug Execute Trigger: sendMessage
May 22 17:45:26 friend rocketchat[1402]: Integrations âž” Outgoing WebHook.debug Got the event arguments for the event: sendMessage {
May 22 17:45:26 friend rocketchat[1402]:   event: 'sendMessage',
May 22 17:45:26 friend rocketchat[1402]:   message: {
May 22 17:45:26 friend rocketchat[1402]:     _id: 'hsTDaIHNfWVgYDOAi',
May 22 17:45:26 friend rocketchat[1402]:     rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',
May 22 17:45:26 friend rocketchat[1402]:     msg: 'Hello there',
May 22 17:45:26 friend rocketchat[1402]:     ts: 2021-05-22T17:45:26.903Z,
May 22 17:45:26 friend rocketchat[1402]:     u: { _id: 'Fuv9nzrYzGCkMJXMk', username: 'babe', name: undefined },
May 22 17:45:26 friend rocketchat[1402]:     urls: [],
May 22 17:45:26 friend rocketchat[1402]:     mentions: [],
May 22 17:45:26 friend rocketchat[1402]:     channels: [],
May 22 17:45:26 friend rocketchat[1402]:     _updatedAt: 2021-05-22T17:45:26.929Z
May 22 17:45:26 friend rocketchat[1402]:   },
May 22 17:45:26 friend rocketchat[1402]:   room: {
May 22 17:45:26 friend rocketchat[1402]:     _id: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',
May 22 17:45:26 friend rocketchat[1402]:     t: 'd',
May 22 17:45:26 friend rocketchat[1402]:     usernames: [ 'babe', 'denis' ],
May 22 17:45:26 friend rocketchat[1402]:     usersCount: 2,
May 22 17:45:26 friend rocketchat[1402]:     msgs: 46,
May 22 17:45:26 friend rocketchat[1402]:     ts: 2021-05-12T03:53:47.868Z,
May 22 17:45:26 friend rocketchat[1402]:     uids: [ 'Fuv9nzrYzGCkMJXMk', 'abzTtbRcebN5Wgxer' ],
May 22 17:45:26 friend rocketchat[1402]:     _updatedAt: 2021-05-22T02:14:11.202Z,
May 22 17:45:26 friend rocketchat[1402]:     lastMessage: {
May 22 17:45:26 friend rocketchat[1402]:       _id: 'EzihPPuQZ7xrgKQM1',
May 22 17:45:26 friend rocketchat[1402]:       rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',
May 22 17:45:26 friend rocketchat[1402]:       msg: 'Another test',
May 22 17:45:26 friend rocketchat[1402]:       ts: 2021-05-22T02:14:11.170Z,
May 22 17:45:26 friend rocketchat[1402]:       u: [Object],
May 22 17:45:26 friend rocketchat[1402]:       urls: [],
May 22 17:45:26 friend rocketchat[1402]:       mentions: [],
May 22 17:45:26 friend rocketchat[1402]:       channels: [],
May 22 17:45:26 friend rocketchat[1402]:       _updatedAt: 2021-05-22T02:14:11.187Z
May 22 17:45:26 friend rocketchat[1402]:     },
May 22 17:45:26 friend rocketchat[1402]:     lm: 2021-05-22T02:14:11.170Z,
May 22 17:45:26 friend rocketchat[1402]:     jitsiTimeout: 2021-05-14T22:06:23.580Z
May 22 17:45:26 friend rocketchat[1402]:   }
May 22 17:45:26 friend rocketchat[1402]: }
May 22 17:45:26 friend rocketchat[1402]: Integrations âž” Outgoing WebHook.debug Starting search for triggers for the room: Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer
May 22 17:45:26 friend rocketchat[1402]: Integrations âž” Outgoing WebHook.debug Found 0 to iterate over and see if the match the event.
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug Sending notification {
May 22 17:45:27 friend rocketchat[1402]:   createdAt: 2021-05-22T17:45:27.775Z,
May 22 17:45:27 friend rocketchat[1402]:   createdBy: '<SERVER>',
May 22 17:45:27 friend rocketchat[1402]:   sent: false,
May 22 17:45:27 friend rocketchat[1402]:   sending: 0,
May 22 17:45:27 friend rocketchat[1402]:   from: 'push',
May 22 17:45:27 friend rocketchat[1402]:   title: 'babe',
May 22 17:45:27 friend rocketchat[1402]:   text: 'Hello there',
May 22 17:45:27 friend rocketchat[1402]:   userId: 'abzTtbRcebN5Wgxer',
May 22 17:45:27 friend rocketchat[1402]:   payload: {
May 22 17:45:27 friend rocketchat[1402]:     host: 'https://chat.mystockphotos.eu/',
May 22 17:45:27 friend rocketchat[1402]:     messageId: 'hsTDaIHNfWVgYDOAi',
May 22 17:45:27 friend rocketchat[1402]:     notificationType: 'message',
May 22 17:45:27 friend rocketchat[1402]:     rid: 'Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer',
May 22 17:45:27 friend rocketchat[1402]:     sender: { _id: 'Fuv9nzrYzGCkMJXMk', username: 'babe' },
May 22 17:45:27 friend rocketchat[1402]:     senderName: 'babe',
May 22 17:45:27 friend rocketchat[1402]:     type: 'd'
May 22 17:45:27 friend rocketchat[1402]:   },
May 22 17:45:27 friend rocketchat[1402]:   badge: 1,
May 22 17:45:27 friend rocketchat[1402]:   sound: 'default',
May 22 17:45:27 friend rocketchat[1402]:   notId: 62867164,
May 22 17:45:27 friend rocketchat[1402]:   apn: { category: 'MESSAGE' },
May 22 17:45:27 friend rocketchat[1402]:   gcm: {
May 22 17:45:27 friend rocketchat[1402]:     image: 'https://chat.mystockphotos.eu/images/logo/android-chrome-192x192.png',
May 22 17:45:27 friend rocketchat[1402]:     style: 'inbox'
May 22 17:45:27 friend rocketchat[1402]:   }
May 22 17:45:27 friend rocketchat[1402]: }
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug send message "babe" to userId abzTtbRcebN5Wgxer
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug send to token {
May 22 17:45:27 friend rocketchat[1402]:   gcm: 'cAmmTtMCQ9-Fv-q5ye6uDQ:APA91bGpCgX1t6pzMTHIVvgwj4AEPab8SrulfXE8DZbqdsGr5w6nh6UJv3I7IbSSibKuE1gLDc7xpnaom2ek8sR4EpmyZXCLpAVUD2cWcKEZtR5SficMcs8l0Q8b62kON6qxswbnG64Y'
May 22 17:45:27 friend rocketchat[1402]: }
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug send to token {
May 22 17:45:27 friend rocketchat[1402]:   gcm: 'cAmmTtMCQ9-Fv-q5ye6uDQ:APA91bGpCgX1t6pzMTHIVvgwj4AEPab8SrulfXE8DZbqdsGr5w6nh6UJv3I7IbSSibKuE1gLDc7xpnaom2ek8sR4EpmyZXCLpAVUD2cWcKEZtR5SficMcs8l0Q8b62kON6qxswbnG64Y'
May 22 17:45:27 friend rocketchat[1402]: }
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug Sent message "babe" to 0 ios apps 1 android apps
May 22 17:45:27 friend rocketchat[1402]: Push âž” debug GUIDE: The "appTokensCollection" - No APN clients have registered on the server yet...
May 22 17:45:28 friend rocketchat[1402]: API âž” debug POST: /api/v1/subscriptions.read
May 22 17:45:28 friend rocketchat[1402]: Meteor âž” method readMessages -> userId: Fuv9nzrYzGCkMJXMk, arguments: ["Fuv9nzrYzGCkMJXMkabzTtbRcebN5Wgxer"]
May 22 17:45:28 friend rocketchat[1402]: API âž” debug Success { statusCode: 200, body: { success: true } }
May 22 17:46:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:46:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:48:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:48:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:50:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:50:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:51:05 friend rocketchat[1402]: Meteor âž” method UserPresence:away -> userId: Fuv9nzrYzGCkMJXMk, arguments: [""]
May 22 17:51:07 friend rocketchat[1402]: Meteor âž” method UserPresence:away -> userId: L9PrQDZEEfrRshpDk, arguments: [{}]
May 22 17:52:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:52:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:54:00 friend rocketchat[1402]: SyncedCron âž” info Starting "Generate download files for user data".
May 22 17:54:00 friend rocketchat[1402]: SyncedCron âž” info Finished "Generate download files for user data".
May 22 17:55:06 friend rocketchat[1402]: Meteor âž” method UserPresence:online -> userId: L9PrQDZEEfrRshpDk, arguments: [{}]
May 22 17:55:26 friend systemd[1]: Started Session 149 of user root.

Edit: added codeblocks for readability

immanuelfodor commented 3 years ago

Are you sure your screenshot corresponds to the same events that are in the RC and system logs? The user agents are from curl, the service name is success which is my example route, and even the timestamps are off by approx 17 hours:

RC would use the actual service name gcm or apn, and when unsuccessful, it would retry a couple of times, and there are no "Error sending push to gateway" lines in the log as well, so RC must hit the gateway later but we are looking at an earlier manual test log.

githubdeb commented 3 years ago

Are you sure your screenshot corresponds to the same events that are in the RC and system logs? The user agents are from curl, the service name is success which is my example route, and even the timestamps are off by approx 17 hours:

RC would use the actual service name gcm or apn, and when unsuccessful, it would retry a couple of times, and there are no "Error sending push to gateway" lines in the log as well, so RC must hit the gateway later but we are looking at an earlier manual test log.

See the related push logic here: https://github.com/RocketChat/Rocket.Chat/blob/develop/app/push/server/push.js#L118

Hi Immanuel. Yes. I'm sure. I shown you the entire logs to see that in fact the gateway does not get anything. You see the logs are 17 hours off because those are the only one I got. I got logs only when I curl, otherwise I get nothing, However, like I said, I can do telnet to the push gateway. If you have time, I can do a share screen with you and show you everything in my settings.

immanuelfodor commented 3 years ago

That's strange because RC somehow gets a 200 OK response to the push. If not from the gateway, from what/who? 😃 It's clearly using the push gateway sender from the log messages, not the built in GCM/APN senders. Don't you have multiple docker instances running, or experimenting with an old RC admin config? Just guessing.

githubdeb commented 3 years ago

That's strange because RC somehow gets a 200 OK response to the push. If not from the gateway, from what/who? 😃 It's clearly using the push gateway sender from the log messages, not the built in GCM/APN senders. Don't you have multiple docker instances running, or experimenting with an old RC admin config? Just guessing.

NO. I have installed Rocketchat using their website. I used the manual installation, so no docker. The only docker image running is the push gateway. My Rocketchat version is 3.14.0

immanuelfodor commented 3 years ago

I can give you a few ideas I'd check when debugging the communication:

Is there an active firewall like ufw that can get disturbed by Docker (Docker is famous of its messy iptables rules) and try to deactivate it
You could try to run the Python program on the host directly. Of course, you'd need to install all dependencies, pip packages, etc but the Dockerfile can help with that
If you have a separate machine, run the bridge with docker-compose there to avoid using the same VM IP or localhost in the RC admin gateway address
Try to run the bridge on a separate port and also update the RC admin gateway URL
Try to run RC in docker, too, to be able to use Docker service names when referencing the projects (eg: http://gateway:8000)
Check the reverse proxy settings if there is a misconfiguration and it somehow returns a 200 OK for RC
The ultimate debug with tcpdump on the docker bridge to see the raw payloads RC sends and if these are the same as in the logs

immanuelfodor commented 2 years ago

Closing as stale

immanuelfodor / rocketchat-push-gateway

Setting up rocketchat with Gotify #1