Job SyncStorageJob failed: [SQLITE_CONSTRAINT_UNIQUE] A UNIQUE constraint failed (UNIQUE constraint failed: recipient.pni)

[dukhaSlayer]

After a couple of days of continious work in parallel with "native" signal sessions getting this error:

Job SyncStorageJob failed

java.lang.RuntimeException: Failed to sync remote storage
	at org.asamk.signal.manager.helper.StorageHelper.readDataFromStorage(StorageHelper.java:241)
	at org.asamk.signal.manager.helper.StorageHelper.syncDataWithStorage(StorageHelper.java:108)
	at org.asamk.signal.manager.jobs.SyncStorageJob.run(SyncStorageJob.java:30)
	at org.asamk.signal.manager.internal.JobExecutor.lambda$runNextJob$0(JobExecutor.java:59)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.sqlite.SQLiteException: [SQLITE_CONSTRAINT_UNIQUE] A UNIQUE constraint failed (UNIQUE constraint failed: recipient.pni)
	at org.sqlite.core.DB.newSQLException(DB.java:1179)
...

signal cli v0.13.10

[dukhaSlayer]

If it's not a bug in the library, could you please advise on it:

• what could be a possible reason for that?
• is it a critical issue? will client work as expected in the presence of these failures? From the code it looks like it will degrade and stop working at some point
• can I fix it myself by ignoring it or deleting duplicate PNI?

Will appreciate any hints.

[dukhaSlayer]

Another symptom here, not sure if it's related, was getting a decent amount of messages like

Found 69 records that were deleted remotely but only marked unregistered locally. Removed those from local store.

Sometimes the same message every 5 min or so.

[AsamK]

Looks like a bug, can you provide more lines of the stack trace? Storage sync doesn't work, but receiving/sending messages should still work normally.

The last line is unrelated, i think it reappears due to different storage sync behavior of linked devices, but i haven't yet found out if it's a bug in signal-cli or another client.

[dukhaSlayer]

Storage sync doesn't work, but receiving/sending messages should still work normally.

Thanks! That's helpful.

can you provide more lines of the stack trace?

My bad here it is:

java.lang.RuntimeException: Failed to sync remote storage
	at org.asamk.signal.manager.helper.StorageHelper.readDataFromStorage(StorageHelper.java:241)
	at org.asamk.signal.manager.helper.StorageHelper.syncDataWithStorage(StorageHelper.java:108)
	at org.asamk.signal.manager.jobs.SyncStorageJob.run(SyncStorageJob.java:30)
	at org.asamk.signal.manager.internal.JobExecutor.lambda$runNextJob$0(JobExecutor.java:59)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.sqlite.SQLiteException: [SQLITE_CONSTRAINT_UNIQUE] A UNIQUE constraint failed (UNIQUE constraint failed: recipient.pni)
	at org.sqlite.core.DB.newSQLException(DB.java:1179)
	at org.sqlite.core.DB.newSQLException(DB.java:1190)
	at org.sqlite.core.DB.execute(DB.java:985)
	at org.sqlite.core.DB.executeUpdate(DB.java:1054)
	at org.sqlite.jdbc3.JDBC3PreparedStatement.lambda$executeLargeUpdate$2(JDBC3PreparedStatement.java:129)
	at org.sqlite.jdbc3.JDBC3Statement.withConnectionTimeout(JDBC3Statement.java:454)
	at org.sqlite.jdbc3.JDBC3PreparedStatement.executeLargeUpdate(JDBC3PreparedStatement.java:124)
	at org.sqlite.jdbc3.JDBC3PreparedStatement.executeUpdate(JDBC3PreparedStatement.java:105)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
	at org.asamk.signal.manager.storage.recipients.RecipientStore.updateRecipientAddress(RecipientStore.java:1330)
	at org.asamk.signal.manager.storage.recipients.RecipientStore$HelperStore.updateRecipientAddress(RecipientStore.java:1666)
	at org.asamk.signal.manager.storage.recipients.MergeRecipientHelper.resolveRecipientTrustedLocked(MergeRecipientHelper.java:116)
	at org.asamk.signal.manager.storage.recipients.RecipientStore.resolveRecipientTrustedLocked(RecipientStore.java:1191)
	at org.asamk.signal.manager.storage.recipients.RecipientStore.resolveRecipientTrusted(RecipientStore.java:292)
	at org.asamk.signal.manager.syncStorage.ContactRecordProcessor.updateLocal(ContactRecordProcessor.java:225)
	at org.asamk.signal.manager.syncStorage.DefaultStorageRecordProcessor.process(DefaultStorageRecordProcessor.java:74)
	at org.asamk.signal.manager.syncStorage.ContactRecordProcessor.process(ContactRecordProcessor.java:36)
	at org.asamk.signal.manager.helper.StorageHelper.processKnownRecords(StorageHelper.java:638)
	at org.asamk.signal.manager.helper.StorageHelper.readDataFromStorage(StorageHelper.java:224)
	... 6 common frames omitted

[dukhaSlayer]

The last line is unrelated, i think it reappears due to different storage sync behavior of linked devices, but i haven't yet found out if it's a bug in signal-cli or another client.

Gotcha. I shut down signal cli session at the moment already for several days but sometimes continue to see interesting behavior in Signal desktop client, e.g.: today I see hunderds of unread messages in the left vertical bar (on the Chats button) but there are just several (< 10) really unread chats in the chats list.

Thought it might be helpful.

[dukhaSlayer]

Just to share some more context:

After reading logs and code and it seems that at a certain condition this issue might impact message sending.

There's Manager.getContactOrProfileName() which will contact server if the profile is older than 6h. Now, I'm not sure about that, but it seems if we cannot update profiles storage - we will be querying profiles more often than expected (basically, as if there is no cache for that).

It seems that created a rate limiting problem with a captcha for me.

[AsamK]

Can't figure out why the UNIQUE constraint is being violated here. With verbose logging (-v) there should a log message starting with Got separate recipients for high trust identifiers ... before the stack trace, can you provide that? That might give me a hint which code path is triggering this.

[dukhaSlayer]

I believe this stems from org.asamk.signal.manager.storage.recipients.MergeRecipientHelper#resolveRecipientTrustedLocked https://github.com/AsamK/signal-cli/blob/master/lib/src/main/java/org/asamk/signal/manager/storage/recipients/MergeRecipientHelper.java#L54

Here we take recipients from

SELECT r._id, r.number, r.aci, r.pni, r.username
                        FROM %s r
                        WHERE r.aci = ?1 OR
                              r.pni = ?2 OR
                              r.number = ?3 OR
                              r.username = ?4 

The code filters the list of recipients and takes first with the same aci as address.aci(). Turns out somehow, there's another recipient (I dunno maybe it has aci=null), which contains the same pni, as address.pni(). So I slightly updated that logic (from var resultingRecipient = ...) so that we first look for aci+pni, then aci only, then pni only, and only then do we update the contact, and this helped me with the error.

I don't want to share the code, as I don't think this is the fix for the root problem.