Android: UnifiedPush registration with Schildichat broken since v1.11.0

[binwiederhier]

As reported by Jakob on Discord:

This is a log of the ntfy Android app. The log shows up to 1,000 entries.
Server URLs (aside from ntfy.sh) and topics have been replaced with fruits 🍌🥝🍋🥥🥑🍊🍎🍑.

Device info:
--
ntfy: 1.11.0 (fdroid)
OS: 4.14.116
Android: 10 (SDK 29)
Model: HWVOG
Product: VOG-L29EEA

--
Settings:                    
{
  "autoDeleteSeconds": 2592000,
  "autoDownloadMaxSize": 1048576,
  "broadcastEnabled": true,
  "connectionProtocol": "ws",
  "darkMode": -1,
  "defaultBaseUrl": "",
  "lastSharedTopics": [],
  "minPriority": 1,
  "mutedUntil": 0,
  "recordLogs": true
}

Logs
--

1651348085689 2022-04-30 21:48:05.689 D NtfyLog Log was truncated
1651348090103 2022-04-30 21:48:10.103 D NtfyUpBroadcastRecv UNREGISTER received (connectorToken=)
1651348090105 2022-04-30 21:48:10.105 D NtfyUpBroadcastRecv UNREGISTER received (connectorToken=)
1651348090112 2022-04-30 21:48:10.112 D NtfyUpBroadcastRecv Subscription with connectorToken  does not exist. Ignoring.
1651348090112 2022-04-30 21:48:10.112 D NtfyUpBroadcastRecv Subscription with connectorToken  does not exist. Ignoring.
1651348090120 2022-04-30 21:48:10.120 D NtfyUpBroadcastRecv Adding subscription with for app de.spiritcroc.riotx (connectorToken raspberry): Subscription(id=-6776334696088911957, baseUrl=https://ntfy.sh, topic=strawberry, instant=true, mutedUntil=0, upAppId=de.spiritcroc.riotx, upConnectorToken=raspberry, totalCount=0, newCount=0, lastActive=1651348090, state=NOT_APPLICABLE)
1651348090120 2022-04-30 21:48:10.120 D NtfyUpBroadcastRecv REGISTER received for app de.spiritcroc.riotx (connectorToken=raspberry)
1651348090125 2022-04-30 21:48:10.125 D NtfyUpBroadcastRecv Adding subscription with for app de.spiritcroc.riotx (connectorToken raspberry): Subscription(id=-8361902847137317442, baseUrl=https://ntfy.sh, topic=upA7g3BlRWqyIS, instant=true, mutedUntil=0, upAppId=de.spiritcroc.riotx, upConnectorToken=raspberry, totalCount=0, newCount=0, lastActive=1651348090, state=NOT_APPLICABLE)
1651348090125 2022-04-30 21:48:10.125 D NtfyUpBroadcastRecv REGISTER received for app de.spiritcroc.riotx (connectorToken=raspberry)
1651348090146 2022-04-30 21:48:10.146 D NtfyUpDistributor Sending NEW_ENDPOINT to de.spiritcroc.riotx (token=raspberry): https://ntfy.sh/strawberry?up=1
1651348090149 2022-04-30 21:48:10.149 D NtfyUpDistributor Sending REGISTRATION_FAILED to de.spiritcroc.riotx (token=raspberry)
1651348090150 2022-04-30 21:48:10.150 D NtfySubscriberMgr Enqueuing work to refresh subscriber service
1651348090152 2022-04-30 21:48:10.152 W NtfyUpBroadcastRecv Failed to add subscription
Exception:
android.database.sqlite.SQLiteConstraintException: UNIQUE constraint failed: Subscription.upConnectorToken (Sqlite code 2067 SQLITE_CONSTRAINT_UNIQUE), (OS error - 110:Connection timed out)
	at android.database.sqlite.SQLiteConnection.nativeExecuteForLastInsertedRowId(Native Method)
	at android.database.sqlite.SQLiteConnection.executeForLastInsertedRowId(SQLiteConnection.java:923)
	at android.database.sqlite.SQLiteSession.executeForLastInsertedRowId(SQLiteSession.java:810)
	at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:88)
	at androidx.sqlite.db.framework.FrameworkSQLiteStatement.executeInsert(FrameworkSQLiteStatement.java:51)
	at androidx.room.EntityInsertionAdapter.insert(EntityInsertionAdapter.java:64)
	at io.heckel.ntfy.db.SubscriptionDao_Impl.add(SubscriptionDao_Impl.java:121)
	at io.heckel.ntfy.db.Repository.addSubscription(Repository.kt:72)
	at io.heckel.ntfy.up.BroadcastReceiver$register$1.invokeSuspend(BroadcastReceiver.kt:79)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)

1651348090197 2022-04-30 21:48:10.197 D NtfySubscriberMgr ServiceStartWorker: Starting foreground service with action START (work ID: f9011e93-05b9-4914-a418-801d0a681def)
1651348090199 2022-04-30 21:48:10.199 D NtfySubscriberService onStartCommand executed with startId: 12
1651348090199 2022-04-30 21:48:10.199 D NtfySubscriberService using an intent with action START
1651348090202 2022-04-30 21:48:10.202 D NtfySubscriberService Refreshing subscriptions
1651348090203 2022-04-30 21:48:10.203 D NtfySubscriberService - Desired connections: [ConnectionId(baseUrl=https://banana.example.com, topicsToSubscriptionIds={kiwi=-2754791496466822081}), ConnectionId(baseUrl=https://ntfy.sh, topicsToSubscriptionIds={strawberry=-6776334696088911957})]
1651348090203 2022-04-30 21:48:10.203 D NtfySubscriberService - Active connections: [ConnectionId(baseUrl=https://banana.example.com, topicsToSubscriptionIds={kiwi=-2754791496466822081})]
1651348090203 2022-04-30 21:48:10.203 D NtfySubscriberService - New connections: [ConnectionId(baseUrl=https://ntfy.sh, topicsToSubscriptionIds={strawberry=-6776334696088911957})]
1651348090204 2022-04-30 21:48:10.204 D NtfySubscriberService - Obsolete connections: []
1651348090204 2022-04-30 21:48:10.204 D NtfySubscriberService - Match? --> false
1651348090208 2022-04-30 21:48:10.208 D NtfyWsConnection ntfy.sh/strawberry (gid=7): New connection with global ID 7
1651348090210 2022-04-30 21:48:10.210 D NtfyWsConnection ntfy.sh/strawberry (gid=7): Opening https://ntfy.sh/strawberry/ws?since=1651348090 with listener ID 1 ...
1651348090648 2022-04-30 21:48:10.648 D NtfyWsConnection ntfy.sh/strawberry (gid=7, lid=1): Opened connection
1651348090650 2022-04-30 21:48:10.650 D NtfyWsConnection ntfy.sh/strawberry (gid=7, lid=1): Received message: {"id":"y3pWDiMMzjuy","time":1651348090,"event":"open","topic":"strawberry"}

[binwiederhier]

As said on Discord, to me it looks like Schildi is sending the same registration twice within 5ms:

1651348090120 2022-04-30 21:48:10.120 D NtfyUpBroadcastRecv REGISTER received for app de.spiritcroc.riotx (connectorToken=raspberry)
1651348090125 2022-04-30 21:48:10.125 D NtfyUpBroadcastRecv REGISTER received for app de.spiritcroc.riotx (connectorToken=raspberry)

Looking at binwiederhier/ntfy-android@v1.10.0...v1.11.0 (only BroadcastReceiver and Distributor), it looks like I

(i) got rid of REGISTRATION_REFUSED and replaced it with REGISTRATION_FAILED
(ii) am now catching a SQLConstraintException and sending REGISTRATION_FAILED back. This was to address #185.

My question to the UP guys (@karmanyaahm, @p1gp1g, @sparchatus)

(a) is the way that ntfy behaves (in the latest version, see log) now correct?
(b) are you in touch with the schildi devs to maybe let them know not to send the registration twice?

[binwiederhier]

My guess is that (i) is incorrect, because: same app + same token -> return NEW_ENDPOINT, right?

[karmanyaahm]

My guess is that (i) is incorrect, because: same app + same token -> return NEW_ENDPOINT, right?

Yes, as Sparchatus said in the chat, it should return the same endpoint again if there's another call with same params.

(b) are you in touch with the schildi devs to maybe let them know not to send the registration twice?

@SpiritCroc

[SpiritCroc]

Hm, if I remember correctly, from @p1gp1g's implementation, it re-registered on every app start. Will have a look when I find time.

[binwiederhier]

Hi @SpiritCroc nice to meet you :-D

I was going totally insane for a while, because GitHub search doesn't show any results for unifiedpush in the SchildiChat Android repo. Turns out the search is just broken. Good old grep on your repo saved the day.

I briefly looked at the code, but not in an IDE, but it is entirely possible that registerApp is called more than once under certain circumstances. I think I just have to make sure that the BroadcastReceiver on my end is race-safe.

[SpiritCroc]

Hi @SpiritCroc nice to meet you :-D

Hi :)

I was going totally insane for a while, because GitHub search doesn't show any results for unifiedpush in the SchildiChat Android repo. Turns out the search is just broken. Good old grep on your repo saved the day.

Github search doesn't search code for projects with "fork" status unfortunately.

I briefly looked at the code, but not in an IDE, but it is entirely possible that registerApp is called more than once under certain circumstances. I think I just have to make sure that the BroadcastReceiver on my end is race-safe.

So will SchildiChat need changes, or is it fine as is?

[p1gp1g]

Hi !

Ntfy should resend the new endpoint when it receives a new registration :)

https://unifiedpush.org/spec/android/#orgunifiedpushandroidconnectornew_endpoint

The distributor MUST send this action to the registered application in the following cases:
[...]

• a registered application sends an action with the intent org.unifiedpush.android.distributor.REGISTER and a token for an existing registration. The distributor MUST also update the features associated with the registration.

[binwiederhier]

So will SchildiChat need changes, or is it fine as is?
Ntfy should resend the new endpoint when it receives a new registration :)

I mean while I of course agree, I think that the connector should maybe not send the same registration twice within 5ms (see above: 21:48:10.120 and 21:48:10.125). That makes it unnecessarily difficult, since now I have to lock/synchronize around something that happens once every full moon, but then happens twice at the exact same moment :-D

I'll fix it on my end, np.

[SpiritCroc]

send the same registration twice within 5ms (see above: 21:48:10.120 and 21:48:10.125)

I see, that indeed sounds unnecessary 🤔

[binwiederhier]

Fixed in binwiederhier/ntfy-android@821a1ac -- this looks like a lot, but it's just a Mutex around the entire register/unregister call. Will be in the next release.

I tested with MacroDroid tapping a floating action button many times. Since that didn't work I added an artificial delay(200) after the exists check and that reproduced the error above.