Error handling Matrix request internal server error: cannot publish to UnifiedPush topic without previously active subscriber

[barathrm]

🐞 Describe the bug

Matrix notifications no longer work. Other notifications work fine. Way I tested matrix notifications

• make sure matrix apps are using ntfy as the notification backend
• make sure other ntfy notifications work (using non-UP channels)
• send a message from another account to my main account, which schildichat is logged in with
• observe ntfy server logs
• observe no notification for schildichat popping up

💻 Components impacted

• matrix.org matrix account
• self-hosted ntfy server
• android phone running schildichat, fluffychat, android ntfy app.

💡 Screenshots and/or logs

DEBUG Error handling Matrix request (error=internal server error: cannot publish to UnifiedPush topic without previously active subscriber, error_code=50701, http_method=POST, http_path=/_matrix/push/v1/notify, http_status=507, tag=matrix, topic=, topic_subscribers=1, visitor_auth_limiter_limit=0.016666666666666666, visitor_auth_limiter_tokens=10, visitor_emails=0, visitor_emails_limit=24, visitor_emails_remaining=24, visitor_id=ip:, visitor_ip=, visitor_messages=0, visitor_messages_limit=17280, visitor_messages_remaining=17280, visitor_request_limiter_limit=0.2, visitor_request_limiter_tokens=59.0001245076)

🔮 Additional context

The problem only occurs on ntfy 2.1.1 and 2.1.0. Rolling back to 1.31.0 fixes the issue.

Let me know if there's anything I can do to help debug.

[binwiederhier]

Thanks for reporting this. While I do think this may actually be a bug, the way you describe it sounds like "intended behavior", so let me clarify:

Did you subscribe to the topic before sending the message? If you have debugging enabled, you should see some GET /up1234/(json|ws) message and something that says "registering rate visitor". Maybe post a more extensive excerpt from the logs?

@S1m @karmanyaahm I do think we'll have to urgently change this logic again if it is actually causing delivery issues. Maybe the 400k Matrix messages are not all dead letters after all.

[barathrm]

Did you subscribe to the topic before sending the message?

Well, I'm not sure. I never completely understood how subscribing to a topic works wrt. UP and matrix clients.

For my "regular" ntfy topics which I create and post messages to manually, I can obviously subscribe to manually in the ntfy app. The matrix topics seem to be created/subscribed to automatically in the ntfy app by the matrix clients (I assume?). Maybe there's a quirk in how matrix clients (don't) subscribe (re-subscribe?) to a topic before receiving notifications?

The way I tested this was making sure I had a ntfy user with read access to the 'up*' topic, restarting the ntfy android app, deleting all old matrix topics in the ntfy app to start clean, toggling usage of ntfy as a backend off and on in schildichat and then sending a message to the account used in schildichat. This failed when using the latest ntfy versions, but when I rolled back to an older version of ntfy, it started working.

But what prompted me to start looking into this in the first place was notifications not working anymore, for all my regular active conversations, so I assume that I was still subscribed to those at that time...? Unless ntfy requires some action from matrix clients to make sure that everything works after a ntfy restart/upgrade?

Either way, I'll try a newer version again and look for the GET messages and post more logs :)

[barathrm]

I forgot that I can just find the old logs in the journal 🤪
Here they are, slightly anonymized. They start after a restart of the ntfy server with trace logging enabled and end where it looks like I stopped testing sending messages. Judging from these lines it looks like my ntfy app connected via WS?

Mar 03 09:46:56 serverbox ntfy[5109]: DEBUG Rate limiters reset for visitor (visitor_auth_limiter_limit=0.016666666666666666, visitor_auth_limiter_tokens=10, visitor_emails=0, visitor_emails_limit=24, visitor_emails_remaining=24, visitor_id=ip:91.90.44.22, visitor_ip=91.90.44.22, visitor_messages=0, visitor_messages_limit=17280, visitor_messages_remaining=17280, visitor_request_limiter_limit=0.2, visitor_request_limiter_tokens=60)
Mar 03 09:46:57 serverbox ntfy[5109]: DEBUG HTTP request started (http_method=GET, http_path=/script_vm,upCE1337GSyybI,upAGM1337naVIx,upzvfIs13370IU,upvA1337DtdKxw,uptfU13373oEKa/ws?since=IWx5w2bLvVKi, tag=http, user_id=u_ghe5FtMebN, user_name=myandroidphone, visitor_auth_limiter_limit=0.016666666666666666, visitor_auth_limiter_tokens=10, visitor_emails=0, visitor_emails_limit=24, visitor_emails_remaining=24, visitor_id=ip:91.90.44.22, visitor_ip=91.90.44.22, visitor_messages=0, visitor_messages_limit=17280, visitor_messages_remaining=17280, visitor_request_limiter_limit=0.2, visitor_request_limiter_tokens=60)
Mar 03 09:46:57 serverbox ntfy[5109]: DEBUG WebSocket connection opened (http_method=GET, http_path=/script_vm,upCE1337GSyybI,upAGM1337naVIx,upzvfIs13370IU,upvA1337DtdKxw,uptfU13373oEKa/ws?since=IWx5w2bLvVKi, tag=websocket, user_id=u_ghe5FtMebN, user_name=myandroidphone, visitor_auth_limiter_limit=0.016666666666666666, visitor_auth_limiter_tokens=10, visitor_emails=0, visitor_emails_limit=24, visitor_emails_remaining=24, visitor_id=ip:91.90.44.22, visitor_ip=91.90.44.22, visitor_messages=0, visitor_messages_limit=17280, visitor_messages_remaining=17280, visitor_request_limiter_limit=0.2, visitor_request_limiter_tokens=59.0009335074)

Edit: fixed log file
ntfy.log

[binwiederhier]

The way I tested this was making sure I had a ntfy user with read access to the 'up*' topic

I think this is the key piece of info here. The user that is subscribing does not have write access? If that is the case, the visitor cannot set itself as "rate visitor". This all sounds like gibberish to you, probably, and it doesn't need to make sense to you.

Bottom line is: This is a slight design flaw in my opinion. We have to find a way to not have this stupid rate limiting logic for selfhosters. Maybe we just make the 507-logic opt-in with a flag.

[barathrm]

I can confirm that giving the ntfy user configured on the android phone read-write access to the up* topics, instead of just read, solves the issue for me with version 2.1.1. 🙏

[binwiederhier]

We will implement a enable-rate-visitor flag (off by default) and change the publishing logic to

if unifiedpush && s.config.EnableRateVisitor && t.RateVisitor() == nil {
  return 507
}

And the maybeSetRateVisitors() logic to:

if !s.config.EnableRateVisitors {
  return
}

[binwiederhier]

Implemented in #655 -- Will likely be released today.