Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Messages sometimes show up late and/or in bunches #8692

Open
2 tasks done
jeremymasters opened this issue Mar 18, 2019 · 139 comments
Open
2 tasks done

Messages sometimes show up late and/or in bunches #8692

jeremymasters opened this issue Mar 18, 2019 · 139 comments

Comments

@jeremymasters
Copy link


Bug description

Typing on the desktop client and after awhile I heard my phone buzz. Opened it up and a flood of signal messages come in that were from the last several minutes (15 minutes maybe)

Steps to reproduce

  • use desktop client, message friends on signal.
  • sometimes hear phone buzz
  • pick up phone and turn on screen

Actual result: signal messages from recent history flood in
Expected result: messages come into phone roughly at the same flow as desktop while on the same network

Device info

Device: Samsung galaxy s9
Android version: 9.0 stock Verizon
Signal version: 4.35.3

Link to debug log

https://debuglogs.org/6d156ab53db2297c534498e59937440ab48bb8d5ef77527afd850adcaa89c26f

@greyson-signal
Copy link
Contributor

Looking at your log, I'll assume your referring to right around here:

2019-03-18 09:05:07.118 MDT I FcmService: FCM message... Original Priority: 1, Actual Priority: 1

Which is point where we get a ton of FCM messages.

Unfortunately, Android isn't super kind with GCM/FCM message delivery these days (read: Android 8 and above). We send high-priority notifications, but the system itself may still batch them together, particularly if your phone is sitting still on your desk disconnected from a charger. It's a battery optimization that's particularly harmful to messengers.

You can check to see if disabling battery optimizations in your system settings helps, but this particular behavior tends to pop up from time to time even if battery optimizations are off. We're looking into some possible workarounds.

@jeremymasters
Copy link
Author

All battery optimizations for signal are shut off and it was off the charger. It's set as my default SMS client, so battery opts are not allowed to be turned on by me. I suppose going on under the hood.

@Noah-Huppert
Copy link

Noah-Huppert commented Apr 11, 2019

Signal Android 9, I can reproduce this bug.

Let me know if there are any additional diagnostic steps I can take to help with this bug.

Maybe the app could detect when a bunch of notifications are coming in (X # of notifications for messages older than Y minutes) and delay notifications for a bit.

@jeremymasters
Copy link
Author

@Noah-Huppert this bug is more to do with the fact that in, say a window of time where messaging via desktop is occurring, FCM doesn't let the phone know until late in that window...sometimes many minutes later. I'm not as worried about rapid-fire notifications. I don't know squat about FCM, so if you know about that, you'd probably be able to help.

@Noah-Huppert
Copy link

Although I am annoyed by my desktop and phone not being in sync, I feel like the only thing Signal can do is manage the groups of notifications. I'm not sure how much control we could have of cloud messaging.

@FedericoCeratto
Copy link

I'm seeing a similar behavior: the desktop client and phone sync outgoing messages very quickly, showing two white circles, and the recipient does not get messages for up to 40 mins. Same with incoming messages.

@dlemire60
Copy link

I don't use the desktop app, but both my wife and I frequently experience delayed notification / message delivery on our Moto G5s phones (Android 8.1.0, security patch level 1 April 2019) running on Sprint (via reseller Ting). Message notifications are sometimes very prompt, sometimes quite delayed (30 min in some cases). Things seem fine while in an exchange, but it's common to unlock the phone and only then get notification of a message(s) (I just had that happen with a 15-min old message).

Battery optimization is off (at least on my phone, I think both). I have all requested Signal permissions enabled except Calendar and Location.

@dlemire60
Copy link

Just had another instance, where a message from another Signal user took 12 minutes to show up on my phone. This is very frustrating behavior. I really like this app, prefer to have the security it provides, and was very impressed with the quality of a 2-party video call when I used that. But the lack of timely delivery is a real negative that's causing me to re-think continuing to use the app.

App version: 4.43.8, installed from Google Play store, routinely updated

Android version: Android 8.1.0, security patch level 1 April 2019, no custom ROMs, not rooted

Device model: Moto G5S Plus phone

@janvlug
Copy link

janvlug commented Jul 29, 2019

I received a message from *75 at 9:04:27 PM GMT+02:00 that was sent at 5:55:08 PM GMT+02:00. Here is the debug log.

@flibbles
Copy link

flibbles commented Oct 6, 2019

Hey all,

I too am encountering this issue. Have conversation on desktop. Phone catches up later. I don't actually mind much.

What I do mind is how my phone will chime for every single delayed message. So, like, an hour after my conversation, my phone will start chiming constantly for a solid two minutes or so. It's irritating, and unstoppable. Each message appears on lock-screen notification for about half a second.

Can't there be a some way to at least have Signal not chime a bunch when delayed messages come in?

@bme13
Copy link

bme13 commented Jan 8, 2020

It's been quite a while since a noticed this behaviour and I think the deliver reliability has improved a lot however this morning a message took nearly 3 hours to be delivered. On the receiving device the message details show:
send: 9:28:53
received: 12:20:56
Now I have to say the battery on the receiving device was a bit low < 10% however during the timespan the Signal message was not delivered multiple Whatsapp messages were received. Both Whatsapp and Signal are excluded from battery optimization on the receiving phone.
Log sending device:
https://debuglogs.org/5af3fb0ada60fcc7b199a7cff2800ac9343be5e67ea65b43f03b6d13978eb376
Log receiving device:
https://debuglogs.org/3805b112765ae5838a2012bc0cf2d58d27d02bfd02579a47963139039bf9e123

@signaluser2
Copy link

Today a strange thing happened. Contact had sent message1 at say 00:00 but it wasn't delivered to me. I sent him message2 at 00:45 and got one tick. I didn't receive message1. Contact sent more messages at 01:00 and 03:00 and I did not receive those messages either. Fed up, contact notified me through another channel. I force-quit Signal and re-opened it and immediately got the messages sent by the contact and the read receipt for the one I had sent.

I have always had the problem of not receiving messages on time. So the messages sent at 01:00 and 03:00 not getting delivered is not surprising. But why didn't I get message1 even after I sent message2?

@IanSpam
Copy link

IanSpam commented Jan 22, 2020

This is a new problem on my Signal. There used to be no delay in receiving notification on my phone of new Signal message arriving. Now there is, and often no notification until I open the app. Then it goes off as each notification alert sounds sequentially. This is new behaviour so may be bug in newer version. To my knowledge nothing else has changed.
Family members used to mention this to me on their devices but I thought it was probably a notification setting. I have checked every setting I can think of. All seem correct, still no timely notifications.
Phone: HTC Desire 530
Android: 6.0.1
Signal: 4.53.7

@IanSpam
Copy link

IanSpam commented Jan 22, 2020

First mention I can find "No Push notifications on data #8400"
opened this issue on Nov 27, 2018

@greyson-signal
Copy link
Contributor

@IanSpam Please post a debuglog that was taken after you opened the app and discovered that messages were delivered late. There's a couple things that could happen that would result in delayed messages, and I can see what you're hitting.

@greyson-signal
Copy link
Contributor

@bme13 I saw this snippet in your log:

2020-01-08 12:21:02.995 CET I FcmService: FCM message... Delay: 10022865

Followed by a cluster of other delayed messages. That delay translates to ~2.75hrs. Lines up with what you said.

That means that Signal sent an FCM message to that device almost 3 hours before, but for whatever reason, the device chose not to deliver it to our app for 3 hours. The fact that the receiver's device was in a low battery state sounds like the likely explanation.

And unfortunately device manufacturers aren't neutral deliverers of notifications. They keep their own whitelist of apps they think are important, and it's likely that WhatsApp is on that list, hence why it didn't experience any delay.

@Tursko
Copy link

Tursko commented Jan 24, 2020

All battery optimizations for signal are shut off and it was off the charger. It's set as my default SMS client, so battery opts are not allowed to be turned on by me. I suppose going on under the hood.

My friends also had this issue on One UI, but I have, at times, experienced the delay myself (Pixel 4). Luckily making Signal 'not optimized' seemed to fix their issues.
I know you mentioned that all your optimizations are off though.

@MomentofClarity
Copy link

Debug Logs

This was earlier this week, at the time it was working fine for one contact but didn't go through when I sent a message to someone else: https://debuglogs.org/b359c0eb4169e971ba0f7c071b6123d5c674104b90ed1dd083ed4a60724c0ae6

This was just now, I had been talking to someone most of the day with no issues and then it just stopped delivering: https://debuglogs.org/ca9b6ce8d5980dbcdeadbf780419e986446dedf7a4438b3fc67b186d3ab07592


@greyson-signal I've had this issue for over a year. Normally it would just happen 1-2 times a month (negligible), but during some weeks (like now) it's almost unusable...when I message someone it's a coin toss of whether it goes through or not. And then it's another coin toss of whether it's going to be 30 mins or 10 hours later when it finally gets delivered.

I don't think it's fair to attribute it to the handling of the msg by the specific device or things like battery optimization settings as I've experienced it across many different device on all platforms. I've gotten new phones, friends have gotten new phones (including switching from Android to iOS, etc) and the issue still persists, meanwhile it has not happened one single time with any other messenger (to me) literally ever in the last decade.

If it was specific to the device then it would also not persist when multiple devices are actively connected (i.e., phone and desktop client), but it does.

This is a Signal issue. I love the app and have been an advocate since day one, it's by far my preferred messenger. I'm always trying to get friends to switch. And normally it works great, and I can live with infrequent "one-offs"...but there are periods when 'unreliable' is a huge understatement. This past week I've been using alternate messengers or calling multiple people telling them to open Signal so that messages can come through multiple times a day.

Please let me know if there is anything I can do to help diagnose this issue, I don't want to give up on Signal :(

Thanks for your help on this but also generally, I really appreciate you and everyone else that works on this app 🙏🙏🙏

@Tursko
Copy link

Tursko commented Feb 4, 2020

Encountered the issue today. I was using signal desktop for about an hour and when I went back to my phone all the notifications finally rushed in.

https://debuglogs.org/057079a28e187cd35b9022624b1200b5c9e9ce4b36e8e2d0c4bf915f5da7c6ac

@Noah-Huppert
Copy link

Noah-Huppert commented Feb 4, 2020 via email

@alcoolfire
Copy link

We had a longstanding problem with a Moto G3 where Signal messages will not be received after a restart and before the first unlock/login. The G3 ran a rather old version of Android, so we lived with it. We have now upgraded to the Google Pixel 3a running Android 10 and we have exactly the same problem. My wife likes to turn her phone off at night. If she forgets to unlock her phone after power up in the morning, it can be hours of delay in receiving messages that came in during the night from another time zone. I have missed multiple incoming Signal voice calls because I restarted the phone and forgot to unlock it so Signal would start functioning. I'm assuming the Signal app does NOT start up in the background until first unlock. Why? I wonder how many people experiencing delayed notifications just haven't noticed this correlation.

BTW, the same problem exists with K-9 Mail. I imagine this could be linked to Google's anti-background app "features", but I didn't think the old G3 would have been plagued with those.

@LeftHandRev
Copy link

I'm on CalyxOS with microG - I was having similar isues, @pflanzenandi, but the last two versions have stabilized things. Using the global installer seems to work better for me, since I think microG causes Signal to think it should be using the Google services.

@bubenheimer
Copy link

As an Android dev with first-hand experience regarding battery optimization workarounds I'd like to second the suggestion of providing fallbacks as options (in settings), like the websocket approach; there are countless devices, and they may change battery optimization behaviors at any time, so without pervasive whitelisting I'd consider it impossible to maintain responsive notification behavior everywhere at all times, especially without a large support staff and a huge device testing farm. With fallback options at least the more tinkering-minded users (of which there likely are many in the case of Signal) can find a way to keep their app running smoothly again.

There likely are other fallback options that could improve reliability, e.g. running a foreground service (just for the tinkerers, to be enabled via settings).

I don't know what it takes to be whitelisted by the big device manufacturers, but I'd imagine that many would be open to doing this at no cost for a popular open-source messaging app like Signal, for reasons of benevolent PR.

Also, consider contributing Signal's use cases to the new CTS-D suite, which will benefit everyone:
https://android-developers.googleblog.com/2022/06/developer-powered-cts-cts-d.html

The devs here may already be aware of the more humongous battery optimization threads on Google's issue tracker.

@Eric678
Copy link

Eric678 commented Jul 28, 2022

Yes I confirm that installing the universal APK does not fix this problem. I my case I am not able to stop or disable Play Services and it refused to instal without using play services to authenticate the number and still has the notification problem. I block play services from calling home at all other times. Is there any way to force the use of websocket?

@Eric678 - This is not a problem with Signal. This is a problem with allowing alternate installation sources. You need to grant that ability to your browser or whatever tool you are using to download the Universal APK. Your report doesn't seem to be relevant, since you were unable to install the Universal version. If you can install the Universal APK and verify that it does or does not fix your issue, then revisit this post.

Hear hear to above post.
@LeftHandRev I did not see your response: I could instal the universal APK however it refused to allow me to input the verification code to enable operation if it could see play services running (that I could not STOP) - it insisted on picking it up via PS. I am presuming that Signal wants to use PS to funnel real time metadata to NSA (as they seem to be required to do) and using Google is the easiest way, and sort of deniable. My contacts are pretty pissed off with Signal as a result of this problem and so I am moving over to hosting a home server on Matrix.

@LeftHandRev
Copy link

Hear hear to above post. @LeftHandRev I did not see your response: I could instal the universal APK however it refused to allow me to input the verification code to enable operation if it could see play services running (that I could not STOP) - it insisted on picking it up via PS. I am presuming that Signal wants to use PS to funnel real time metadata to NSA (as they seem to be required to do) and using Google is the easiest way, and sort of deniable. My contacts are pretty pissed off with Signal as a result of this problem and so I am moving over to hosting a home server on Matrix.

Yeah... how about we just keep this discussion about the program's bug and not unfounded theories.

@CelianGdfrd
Copy link

Omg @LeftHandRev NSA agent exposed ?

More seriously, I think I was able to grasp a log of a failing message. I tried to isolate the relevant information, hope I didn't forget anything.
Please note it's from the receiver's (me) phone. I'm trying to obtain the sender's log aswell.

[5.43.7] [8900 ] 2022-07-29 13:10:58.776 GMT+02:00 I FcmReceiveService: onMessageReceived() ID: 0:1659093058689417%e3016397f9fd7ecd, Delay: 156, Priority: 1, Original Priority: 1, Network: [isOnVpn: false, isMetered: true] [5.43.7] [8900 ] 2022-07-29 13:10:58.777 GMT+02:00 D FcmReceiveService: [handleReceivedNotification] API: 30, FeatureFlag: true, RemoteMessagePriority: 1, TimeSinceLastRefresh: 1659093058777 ms [5.43.7] [8900 ] 2022-07-29 13:10:58.777 GMT+02:00 I FcmFetchManager: Starting in the background. [5.43.7] [8900 ] 2022-07-29 13:10:58.795 GMT+02:00 I FcmFetchManager: Incrementing active count to 1 [5.43.7] [8901 ] 2022-07-29 13:10:58.800 GMT+02:00 I BackgroundMessageRetrie: Performing normal message fetch. [5.43.7] [8901 ] 2022-07-29 13:10:58.801 GMT+02:00 I BackgroundMessageRetrie: Attempting strategy: RestStrategy (2 ms elapsed) [5.43.7] [8901 ] 2022-07-29 13:10:59.448 GMT+02:00 I RestStrategy: Retrieved an envelope. (646 ms elapsed) [5.43.7] [8901 ] 2022-07-29 13:10:59.455 GMT+02:00 I Job: [JOB::36eeea02-c1af-4b7c-a7a5-955a3299e978][PushDecryptMessageJob] onSubmit() (Time Since Submission: 6 ms, Lifespan: Immortal, Run Attempt: 1/Unlimited, Queue: __PUSH_DECRYPT_JOB__) [5.43.7] [8823 ] 2022-07-29 13:10:59.456 GMT+02:00 I JobSchedulerScheduler: JobScheduler enqueue of (0) [5.43.7] [8901 ] 2022-07-29 13:10:59.459 GMT+02:00 I RestStrategy: Successfully processed an envelope. (658 ms elapsed)

@LeftHandRev
Copy link

LeftHandRev commented Aug 7, 2022

Aaaaaaand, delays are back as of the latest update yesterday, 5.44.5. Had no problems with 5.44.4.

Edit: Confirmed with friends as well.

@greyson-signal
Copy link
Contributor

5.44.5 was a hotfix to address a very-unrelated issue (see commits here). I believe you're having notification problems, but I do not believe it was related to the release.

@wunderox
Copy link

wunderox commented Aug 8, 2022

Indeed, this has nothing to do with 5.44.5, as I experienced it over the weekend myself while on 5.44.4.
Here's the debug log: https://debuglogs.org/android/5.44.4/e6fdfb1f49c39f798953fd8c9f7b0042ef440d9ef466442f7ea828021cb5a053

Situation: suddenly I got a notification with messages from multiple senders, sent hours earlier. They were delayed by around 5h or so.
The timestamps of the messages of interest, per their sending times are: 1659871476935 and 1659866064161 (it also happened with 1659844640774 and some few other messages shortly after, thought that was earlier, during an extended period of time away from my phone so it might have dozed?).
My phone is not running an aggressively battery optimized flavor of Android, so I don't believe this is the issue here and I've followed all recommendations with respect to battery in the background.

The log is riddled with [5.44.4] [27 ] 2022-08-07 14:24:20.866 GMT+02:00 W IncomingMessageObserver: Application level read timeout... is this related to that? It keeps sending keep alive for hours, and this was between when messages were sent to me and I didn't receive anything for a few hours.

There's too much in this log for me to go through especially as I don't know what exactly to look for, but this log might hold some relevant information? I hope it helps.

Edit: formatting.

@ehussong
Copy link

Have had some issues similar to this over the last few months. Not regularly but this is the 3rd or 4th time it has happened now. Sent a message on desktop last night and it wasn't delivered until 11+ hours later.

It was sent via desktop to an iPhone. The iPhone was most likely in low power mode at the time, but the user can't specifically recall.

Desktop that it was sent from:
https://debuglogs.org/desktop/5.55.0/8c3f70a761fdbf154eeca60dcdf7997e3121fbb982f4ce3a276dd0dcf56040ef.gz

iPhone that it was sent to:
https://debuglogs.org/ios/5.48.0/34a5b73bd9f574fc822eabe57897e662c5a72844db03be2ce0a59ca2ab6b8ac6.zip

I'm not 100% certain what I'm looking at in the logs but it appears that the received log on the iPhone was this one:
2022/08/22 13:34:49:574 💛 [NotificationService.swift:164 didReceive(_:withContentHandler:)]: Processing received notification, memoryUsage: 13009984.

@greyson-signal
Copy link
Contributor

@ehussong Thank you for the detailed report! If the receiver was an iPhone though, I'd recommend opening an issue on the iOS repo so they can see it :) Thanks!

@lel-amri
Copy link

lel-amri commented Sep 9, 2022

I have the issue as well. For example, a contact sent a message today (2022/09/09) at 11:18, I only got notified when I opened the application at 11:52.

I don't really understand why the network is failing sometimes (should I rather say often ?) (look at all the "java.io.IOException: Connection closed!" exceptions, the EPIPE errors and the FCM WS onFailure callbacks).

I'm rarely using my phone during the day.

https://debuglogs.org/android/5.48.3/dab6117882f2f915edccf9258fe8ff77cbd8b70aa3de4e837433b3c92dfe5b2f

@signalworkplease
Copy link

I've had the same issues described here with messages arriving hours after they were sent to me. Often times they don't arrive until I or the sender sends another message in the thread. I have a OnePlus Nord n200 5g and Signals my default message app. Battery optimization is off for Signal. All the other settings I've adjusted based on advice online about issues like this. The delay seems to happen most frequently with voice texts. Here's my debug log hopefully it'll help there are several delays from the past two weeks. One message didn't arrive for two days until the sender sent another text. https://debuglogs.org/android/5.51.7/a4d797779ee6a9acbe95e93662ad1d980fbb4e998e97972273ba721f117f939e

@jmbuhr
Copy link

jmbuhr commented Oct 16, 2022

Interesting, I'm also on a OnePlus Nord (CE 5g) and had this issue for the first time today. Though this was on the previous version and I did an update afterwards, so I don't know if the issue will persist. The messages in question have time stamps of e.g. sent at 18:50, received at 19:30, but there is nothing in the logs around this time.

@pflanzenandi
Copy link

pflanzenandi commented Oct 21, 2022

I also have the same problem with messages not getting pushed, when my phone is blank and dozing (around the 5 min mark). Turning the phone on sets off the message notification push. This is going on for several weeks now. Signal was pushing perfectly fine at some point. What happened?

If I can help you debugging please let me know. If you need logs, also please let me know.
Also, are any defs actively reading this 'Sammelsurium' of pain?

Lineage 12
microG
Samsung S10e

@ColonelPanic-42
Copy link

Now with the removal of SMS (the only way I as the sender can force the recipient's device to wake TF up and receive a message) that does it for my support of Signal. This has been an issue for years with ZERO admission from the devs that there is even a problem, and not even an attempt to add a workaround (allowing manual selection of WebSockets), and with removal of SMS meaning I and my friends and family now need to use TWO apps to contact different people mean Signal is dead.

Let's just turn this thread into a "Signal alternatives" discussion instead at this point.

@jmbuhr
Copy link

jmbuhr commented Oct 27, 2022

@ColonelPanic-42 Since you seem to already know a solution, why don't you open a pull request with an attempted fix? Everyone can contribute.

@ColonelPanic-42
Copy link

@jmbuhr You must have missed the part in my message where I said Signal is dead to me now that they're removing SMS support. Why would I bother to waste my time pulling down the code, fiddle around with it to make sense of what's doing what and where, to add a little toggle in a Settings menu that forces the use of WebSockets, when I won't be using the app anymore? Simply put, it's not my problem anymore, I'm just frustrated at how obviously tone deaf the devs of this project are to their user base.

@Roaltexd
Copy link

@greyson-signal can you give more insights about Android 'batching' notifications ? I have seen it happens in an APP unrelated to signal. A single high priority message is sucessfully pushed from FCM and it is on the device, but it can take up to few good seconds to minutes to trigger a notification which i don't get it since the message is already there.

@greyson-signal
Copy link
Contributor

@Roaltexd While high-priority FCM messages are supposed to be delivered ASAP, OEM's can choose to do whatever they want with them. Many OEM's have lists of apps they prioritize, and if you're not on that list, they may batch notifications together in order to optimize for battery life.

In addition, in Signal's case, we can't put the actual message content in the FCM payload -- we have to fetch the message from the network. Sometimes OEM's will restrict network access even though (per the docs) they're not supposed to in response to a high-priority FCM message.

So lots of reasons, most of which are specific to a given OEM.

@SimonasPetk
Copy link

@greyson-signal Seems related but might require another bug report.

I have Signal on my Windows desktop as well as on Android. Once, messaging through a desktop application, Signal takes a lot of time to sync that conversation, receiving one message at a time and only when Signal is visibly open, otherwise, nothing is received.

I don't care about the notifications, I would like just the syncing would happen normally and wouldn't impede 2the ability to communicate with others, now it might take tens of minutes to update messaging history one message at a time. Also, during the "syncing" one cannot receive or send calls or send messages as they got lost, so basically, the signal is non-functioning for that user.

However, today for some reason the messages stop syncing at all with the messages that were sent yesterday on my laptop.
So, basically, I am unable to use Signal with that person at all as I don't get their messages, cannot call them or do anything with it.

Here is the debug report: https://debuglogs.org/android/6.6.3/2f102519ad47945c19d28aabb952368e233cf69a6cf6e6fa3d8082244472cece

@LeftHandRev
Copy link

Since the last update, I'm getting delays once again. Last time it affected me was 7-AUG-2022.

@015203087630
Copy link

015203087630 commented Jan 24, 2023 via email

@ericrshields
Copy link

I just started running into this issue a few days ago after having no problems for years. As part of my attempted solutions, I deleted the app and reinstalled it (and re-imported messages), so I do not have a debug log for that initial issue. I experienced it again today, however, so here is that log: https://debuglogs.org/android/6.15.3/060eadbbdae910a95b2cd39920209ae93567408b38f295bd75a6164c46b9d36c

Based on research a few minutes ago, I disabled both battery and data optimizations for Signal. Fingers crossed that does the trick. Stock Goggle Pixel 3a XL.

@CelianGdfrd
Copy link

It's been happening a lot for the past days, for no specific reason. Battery optimization was re-enabled. I disabled it, didn't help. Will try to post logs asap

@CelianGdfrd
Copy link

CelianGdfrd commented Jan 29, 2024

Just happened now. Tell me if more logs are required/what to look for.

01-29 15:59:55.770 26979 27016 I libsignal: rust/protocol/src/sealed_sender.rs:441: deserialized UnidentifiedSenderMessageContent from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with type Whisper
01-29 15:59:55.771 2479 3339 V WifiManager: TrafficStateCallbackProxy: onStateChanged state=3
01-29 15:59:55.771 1792 2391 D WifiClientModeImpl[wlan0]: L2ConnectedState screen=on 1 0 "Livebox-9002" a4:ce:da:17:90:07 rssi=-45 f=5300 sc=60 link=866 tx=7.8, 0.0, 0.0 rx=8.9 bcn=0 [on:0 tx:0 rx:0 period:3016] from screen [on:0 period:525820] score=60
01-29 15:59:55.771 2975 3647 D QCNEJ/WlanStaInfoRelay: Received action: android.net.wifi.RSSI_CHANGED
01-29 15:59:55.774 26979 27016 I libsignal: rust/protocol/src/session_cipher.rs:454: decrypted Whisper message from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with current session state (base key 7019c42b6e2ceadc7b86080b4971574aa499c5d8caecac0c948c84099627d623)
01-29 15:59:55.777 26979 27016 D MessageDecryptor: [1706539882824] c73bb5e8-1dd0-48c9-a743-7d85ed7f124b:1 | Successfully decrypted the envelope in 7,13 ms (GUID 2774cff7-df01-42fa-a2bb-c62fcb3554fb). Delivery latency: 511001 ms, Urgent: true
01-29 15:59:55.778 26979 27016 I MessageProcessorV2: [1706539882824] Beginning message processing. Sender: RecipientId::49 (c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1)
01-29 15:59:55.783 26979 27016 I MessageProcessorV2: [1706539882824] Media message.
01-29 15:59:55.788 26979 6006 D LocalMetrics: [message-latency-high-priority] total: 511001 | latency: 511001
01-29 15:59:55.810 26979 27016 D AttachmentTable: insertParts(1)
01-29 15:59:55.810 26979 27016 D AttachmentTable: Inserting attachment for mms id: 41581
01-29 15:59:55.829 26979 27016 I AttachmentTable: Inserted attachment at ID: AttachmentId::4910
01-29 15:59:55.897 2479 2479 I KeyButtonView: Back button event: ACTION_DOWN
01-29 15:59:55.899 1124 1124 D vendor.qti.vibrator: Vibrator perform effect 0
01-29 15:59:55.904 1124 1124 E (1)[1124:vendor.qti.hard][20240129_15:59:55.899786]@1 aw8697_rtp_store: val [0]
01-29 15:59:55.904 1124 1124 I : (2)[1124:vendor.qti.hard][20240129_15:59:55.900368]@2 aw8697_op_clean_status enter
01-29 15:59:55.904 1124 1124 E (1)[1124:vendor.qti.hard][20240129_15:59:55.903705]@1 aw8697_vmax_store: value=2500
01-29 15:59:55.904 1124 1124 E (1)[1124:vendor.qti.hard][20240129_15:59:55.904186]@1 aw8697_vmax_store: aw8697->gain[0x80], aw8697->vmax[0x16] end
01-29 15:59:55.904 1124 1124 E (1)[1124:vendor.qti.hard][20240129_15:59:55.904316]@1 aw8697_waveform_index_store: waveform_index = 1
01-29 15:59:55.909 1174 1223 W TransactionTracing: Could not find layer handle 0xb400007ae7514fb0
01-29 15:59:55.914 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:55.907511]@2 aw8697_haptic_ram_vbat_comp: aw8697->gain = 0x80, temp_gain = 0x0, aw8697->ram_vbat_comp=1.
01-29 15:59:55.924 1124 1124 E (1)[1124:vendor.qti.hard][20240129_15:59:55.914954]@1 aw8697_rtp_store: val [0]
01-29 15:59:55.924 1124 1124 I : (1)[1124:vendor.qti.hard][20240129_15:59:55.915262]@1 aw8697_op_clean_status enter
01-29 15:59:55.930 1124 6007 D vendor.qti.vibrator: Starting perform on another thread
01-29 15:59:55.970 2479 2479 I KeyButtonView: Back button event: ACTION_UP
01-29 15:59:55.977 1792 24228 D CoreBackPreview: Window{7907652 u0 org.thoughtcrime.securesms/org.thoughtcrime.securesms.conversation.v2.ConversationActivity}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.IOnBackInvokedCallback$Stub$Proxy@f48290a, mPriority=0}
01-29 15:59:56.056 1053 3377 I [email protected]_handler: DeviceSleep: TX Awake, Sending SLEEP_IND
01-29 15:59:56.057 1053 3377 D [email protected]_handler: SerialClockVote: vote for UART CLK OFF
01-29 15:59:56.081 1124 6007 D vendor.qti.vibrator: Notifying perform complete
01-29 15:59:56.082 1124 1124 D vendor.qti.vibrator: QTI Vibrator off
01-29 15:59:56.084 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:56.082866]@2 aw8697_activate_store: value=0
01-29 15:59:56.100 1124 1124 I (2)[1124:vendor.qti.hard][20240129_15:59:56.095487]@2 aw8697_activate_store: value=0
01-29 15:59:56.116 26979 6006 D LocalMetrics: [individual-message-receive] total: 343,442 | decryption: 7,538, pre-process: 0,857, media-insert: 333,681, post-process: 1,366
01-29 15:59:56.122 26979 27016 I Job : [JOB::523dd278-179c-4b5f-8b36-0c9f32becddb][AttachmentDownloadJob] onSubmit() (Time Since Submission: 8 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: AttachmentDownloadJob-4910)
01-29 15:59:56.122 26979 27016 I AttachmentDownloadJob: onAdded() messageId: 41581 attachmentId: 4910 manual: false
01-29 15:59:56.124 26979 27016 I AttachmentDownloadJob: onAdded() Marking attachment progress as 'started'
01-29 15:59:56.126 26979 27076 D NotificationChannels: ensureCustomChannelConsistency()
01-29 15:59:56.127 26979 27019 I JobSchedulerScheduler: JobScheduler enqueue of NETWORK (-1733499378)
01-29 15:59:56.128 26979 27017 I Job : [JOB::acaece98-b26a-4dba-84cd-ef0f4d3e99d1][SendDeliveryReceiptJob] onSubmit() (Time Since Submission: 11 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: RecipientId::49)
01-29 15:59:56.128 26979 27044 I JobRunner: [JOB::523dd278-179c-4b5f-8b36-0c9f32becddb][AttachmentDownloadJob][3] Running job. (Time Since Submission: 13 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: AttachmentDownloadJob-4910)
01-29 15:59:56.130 26979 26920 D ConversationDataSource: [size(), thread 23] 16 ms
01-29 15:59:56.131 26979 27043 I JobRunner: [JOB::acaece98-b26a-4dba-84cd-ef0f4d3e99d1][SendDeliveryReceiptJob][2] Running job. (Time Since Submission: 5 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: RecipientId::49)
01-29 15:59:56.131 26979 6008 W FixedSizePagingControll: [onDataNeededAroundIndex(10), size: 12317] Invalidated! At beginning of load task.
01-29 15:59:56.132 26979 27016 I Job : [JOB::45c2e504-1868-41e8-80b1-c586a4eddccc][ThreadUpdateJob] onSubmit() (Time Since Submission: 6 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: ThreadUpdateJob_23)
01-29 15:59:56.137 26979 27045 I JobRunner: [JOB::45c2e504-1868-41e8-80b1-c586a4eddccc][ThreadUpdateJob][4] Running job. (Time Since Submission: 5 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: ThreadUpdateJob_23)
01-29 15:59:56.137 26979 27016 D IncomingMessageObserver: Ended database transaction.
01-29 15:59:56.137 26979 27016 D IncomingMessageObserver: Running 0 follow-up operations...
01-29 15:59:56.137 26979 27016 D IncomingMessageObserver: Beginning database transaction...
01-29 15:59:56.138 26979 27016 I libsignal: rust/protocol/src/sealed_sender.rs:441: deserialized UnidentifiedSenderMessageContent from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with type Whisper
01-29 15:59:56.139 26979 27044 I AttachmentDownloadJob: onRun() messageId: 41581 attachmentId: 4910 manual: false
01-29 15:59:56.139 26979 27016 I libsignal: rust/protocol/src/session_cipher.rs:454: decrypted Whisper message from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with current session state (base key 7019c42b6e2ceadc7b86080b4971574aa499c5d8caecac0c948c84099627d623)
01-29 15:59:56.139 26979 27016 D MessageDecryptor: [1706539895333] c73bb5e8-1dd0-48c9-a743-7d85ed7f124b:1 | Successfully decrypted the envelope in 1,55 ms (GUID 9649ab0b-499e-4052-ad22-a924d7bce2cc). Delivery latency: 498439 ms, Urgent: true
01-29 15:59:56.140 26979 27016 I MessageProcessorV2: [1706539895333] Beginning message processing. Sender: RecipientId::49 (c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1)
01-29 15:59:56.140 26979 27016 I MessageProcessorV2: [1706539895333] Media message.
01-29 15:59:56.140 26979 27044 I AttachmentDownloadJob: Downloading push part AttachmentId::4910
01-29 15:59:56.141 26979 26920 D ConversationDataSource: [size(), thread 23] 10 ms
01-29 15:59:56.143 26979 27016 D AttachmentTable: insertParts(1)
01-29 15:59:56.143 26979 27016 D AttachmentTable: Inserting attachment for mms id: 41582
01-29 15:59:56.147 26979 6006 D LocalMetrics: [message-latency-high-priority] total: 498439 | latency: 498439
01-29 15:59:56.147 26979 27016 I AttachmentTable: Inserted attachment at ID: AttachmentId::4911
01-29 15:59:56.148 26979 26873 D ConversationListDataSou: [size(), UnarchivedConversationListDataSource, OFF] 5 ms
01-29 15:59:56.148 26979 27017 I JobSchedulerScheduler: JobScheduler enqueue of (0)
01-29 15:59:56.150 26979 27043 I UnidentifiedAccessUtil: Unidentified: 1, Other: 0
01-29 15:59:56.150 26979 27043 D SignalServiceMessageSender: [1706540396116] Sending a receipt.
01-29 15:59:56.152 26979 26979 I JobSchedulerScheduler: Waking due to job: -1733499378
01-29 15:59:56.152 26979 26979 I JobSchedulerScheduler: Waking due to job: 0
01-29 15:59:56.173 26979 26979 D ConversationFragment: Update scroll state ConversationScrollButtonState(hideScrollButtonsForReactionOverlay=false, showScrollButtonsForScrollPosition=false, willScrollToBottomOnNewMessage=true, unreadCount=1, hasMentions=false)
01-29 15:59:56.179 26979 6008 D ConversationDataSource: [load(0, 75), thread 23] messages: 11,57, extra-data: 23,07, models: 0,20, conversion: 2,15, header: 0,00, total: 36,99 || mentions: 2,76, is-quoted: 22,35, reactions: 18,35, attachments: 7,61, payments: 0,04, calls: 2,84 >> cpuTime: 54,02, wallTime: 22,99
01-29 15:59:56.191 26979 26979 D ThumbnailView: setBounds: update {minW473,maxW756,minH315,maxH1008}
01-29 15:59:56.191 26979 26979 D ThumbnailView: setBounds: update {minW756,maxW756,minH315,maxH1008}
01-29 15:59:56.195 26979 26979 I ThumbnailView: loading part with id null, progress 1, fast preflight id: null
01-29 15:59:56.195 26979 26979 D ThumbnailView: override: apply w756xh1008
01-29 15:59:56.195 26979 26979 D GlideDrawableListeningT: Loaded null resource
01-29 15:59:56.207 1053 3225 D [email protected]_lock: Release wakelock is released
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 9
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 8
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 7
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 6
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 5
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 4
01-29 15:59:56.216 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 3
01-29 15:59:56.217 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 2
01-29 15:59:56.217 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 1
01-29 15:59:56.219 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 0
01-29 15:59:56.228 26979 26979 D ConversationItemAnimato: Starting 10 animations.
01-29 15:59:56.230 26979 27017 I Job : [JOB::b7c35ea9-cec8-407f-b233-95a5e8efd086][SendDeliveryReceiptJob] onSubmit() (Time Since Submission: 1 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: RecipientId::49)
01-29 15:59:56.231 26979 6006 D LocalMetrics: [individual-message-receive] total: 91,474 | decryption: 1,801, pre-process: 0,149, media-insert: 89,443, post-process: 0,082
01-29 15:59:56.231 26979 27016 I Job : [JOB::4d178d67-8a45-40ee-8c38-2675f5cd02da][AttachmentDownloadJob] onSubmit() (Time Since Submission: 0 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: AttachmentDownloadJob-4911)
01-29 15:59:56.231 26979 27016 I AttachmentDownloadJob: onAdded() messageId: 41582 attachmentId: 4911 manual: false
01-29 15:59:56.233 26979 27016 I AttachmentDownloadJob: onAdded() Marking attachment progress as 'started'
01-29 15:59:56.239 2479 2479 I KeyButtonView: Back button event: ACTION_DOWN
01-29 15:59:56.240 1124 1124 D vendor.qti.vibrator: Vibrator perform effect 0
01-29 15:59:56.242 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:56.241083]@2 aw8697_rtp_store: val [0]
01-29 15:59:56.242 1124 1124 I : (1)[1124:vendor.qti.hard][20240129_15:59:56.241379]@1 aw8697_op_clean_status enter
01-29 15:59:56.244 1124 1124 E (3)[1124:vendor.qti.hard][20240129_15:59:56.244018]@3 aw8697_vmax_store: value=2500
01-29 15:59:56.253 26979 6008 D ConversationListDataSou: [load(0, 45), UnarchivedConversationListDataSource, OFF] cursor: 71,85, cache-recipients: 1,23, recipient-resolve: 0,03, total: 73,11
01-29 15:59:56.253 26979 6008 W FixedSizePagingControll: Notified of key org.thoughtcrime.securesms.conversation.v2.data.ThreadHeaderKey@27e5562 but it wasn't in the cache!
01-29 15:59:56.254 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:56.244756]@2 aw8697_vmax_store: aw8697->gain[0x80], aw8697->vmax[0x16] end
01-29 15:59:56.254 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:56.244858]@2 aw8697_waveform_index_store: waveform_index = 1
01-29 15:59:56.254 1124 1124 E (0)[1124:vendor.qti.hard][20240129_15:59:56.248034]@0 aw8697_haptic_ram_vbat_comp: aw8697->gain = 0x80, temp_gain = 0x0, aw8697->ram_vbat_comp=1.
01-29 15:59:56.264 1124 1124 E (0)[1124:vendor.qti.hard][20240129_15:59:56.255231]@0 aw8697_rtp_store: val [0]
01-29 15:59:56.264 1124 1124 I : (0)[1124:vendor.qti.hard][20240129_15:59:56.255500]@0 aw8697_op_clean_status enter
01-29 15:59:56.272 1124 6029 D vendor.qti.vibrator: Starting perform on another thread
01-29 15:59:56.304 4862 4862 E : (1)[4862:kworker/u24:5][20240129_15:59:56.294792]@1 msm_bus_device 16e0000.ad-hoc-bus: TCS Busy, retrying RPMH message send
01-29 15:59:56.335 2479 2479 I KeyButtonView: Back button event: ACTION_UP
01-29 15:59:56.337 26979 26979 D ConversationFragment: onBackPressed()
01-29 15:59:56.349 26979 27013 D MarkReadHelper: Marking 1 messages as read.
01-29 15:59:56.350 26979 27013 I Job : [JOB::77b3868a-be99-4a68-821e-bc8e332256bb][MultiDeviceReadUpdateJob] onSubmit() (Time Since Submission: 1 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: null)
01-29 15:59:56.351 26979 27013 I Job : [JOB::103b12b1-002c-433f-b2ab-1f132141ab76][SendReadReceiptJob] onSubmit() (Time Since Submission: 1 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: RecipientId::49)
01-29 15:59:56.354 26979 27042 I JobRunner: [JOB::4d178d67-8a45-40ee-8c38-2675f5cd02da][AttachmentDownloadJob][1] Running job. (Time Since Submission: 123 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: AttachmentDownloadJob-4911)
01-29 15:59:56.355 26979 27042 I AttachmentDownloadJob: onRun() messageId: 41582 attachmentId: 4911 manual: false
01-29 15:59:56.356 26979 27076 I DefaultMessageNotifier: threads: 1 messages: 1
01-29 15:59:56.357 26979 26979 D BaseActivity: [MainActivity] onStart()
01-29 15:59:56.357 26979 26979 D LoggingFragment: [ConversationListFragmen] onStart()
01-29 15:59:56.357 26979 26979 W OnBackInvokedCallback: OnBackInvokedCallback is not enabled for the application.
01-29 15:59:56.357 26979 26979 W OnBackInvokedCallback: Set 'android:enableOnBackInvokedCallback="true"' in the application manifest.
01-29 15:59:56.358 26979 27042 I AttachmentDownloadJob: Downloading push part AttachmentId::4911
01-29 15:59:56.358 26979 27015 I Job : [JOB::d52116d7-13cf-462d-b148-077669179d4c][ConversationShortcutUpdateJob] onSubmit() (Time Since Submission: 5 ms, Lifespan: 900000 ms, Run Attempt: 1/1, Queue: ConversationShortcutUpdateJob)
01-29 15:59:56.361 26979 27076 E DefaultMessageNotifier: Notifications should be showing but are not for 1 threads
01-29 15:59:56.361 26979 27076 D NotificationChannels: ensureCustomChannelConsistency()
01-29 15:59:56.365 26979 26920 D ConversationDataSource: [size(), thread 23] 10 ms
01-29 15:59:56.366 26979 27016 I Job : [JOB::3b74a31c-bbc6-4ede-9f28-adeb14fba030][ThreadUpdateJob] onSubmit() (Time Since Submission: 0 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: ThreadUpdateJob_23)
01-29 15:59:56.366 26979 27016 D IncomingMessageObserver: Ended database transaction.
01-29 15:59:56.366 26979 27016 D IncomingMessageObserver: Running 0 follow-up operations...
01-29 15:59:56.367 26979 27016 D IncomingMessageObserver: Beginning database transaction...
01-29 15:59:56.371 26979 26920 D ConversationDataSource: [size(), thread 23] 6 ms
01-29 15:59:56.373 26979 27025 E OpenGLRenderer: Unable to match the desired swap behavior.
01-29 15:59:56.382 26979 26920 D ConversationDataSource: [size(), thread 23] 10 ms
01-29 15:59:56.383 26979 6008 D ConversationDataSource: [load(0, 75), thread 23] messages: 11,55, extra-data: 6,29, models: 0,01, conversion: 0,00, header: 0,00, total: 17,85 || mentions: 4,84, is-quoted: 0,00, reactions: 0,00, attachments: 0,00, payments: 0,01, calls: 0,00 >> cpuTime: 4,86, wallTime: 6,07
01-29 15:59:56.383 26979 6008 W FixedSizePagingControll: [onDataNeededAroundIndex(9), size: 12318] Invalidated! Just after data was loaded.
01-29 15:59:56.383 26979 6008 W FixedSizePagingControll: [onDataNeededAroundIndex(9), size: 12318] Invalidated! At beginning of load task.
01-29 15:59:56.395 26979 27044 I AttachmentDownloadJob: Downloading attachment with digest: 1a c3 82 36 85 85 68 33 9e ca ab be 78 9d 91 6d 75 ac c2 b8 6f 5d 6e a1 12 d7 b2 70 56 97 22 29
01-29 15:59:56.398 26979 27016 I libsignal: rust/protocol/src/sealed_sender.rs:441: deserialized UnidentifiedSenderMessageContent from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with type Whisper
01-29 15:59:56.400 26979 26920 D ConversationDataSource: [size(), thread 23] 5 ms
01-29 15:59:56.400 26979 27016 I libsignal: rust/protocol/src/session_cipher.rs:454: decrypted Whisper message from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with current session state (base key 7019c42b6e2ceadc7b86080b4971574aa499c5d8caecac0c948c84099627d623)
01-29 15:59:56.401 26979 27016 D MessageDecryptor: [1706539916136] c73bb5e8-1dd0-48c9-a743-7d85ed7f124b:1 | Successfully decrypted the envelope in 4,12 ms (GUID 8ec1f38f-f64b-40bc-8796-817c8f539409). Delivery latency: 478985 ms, Urgent: true
01-29 15:59:56.402 26979 27016 I MessageProcessorV2: [1706539916136] Beginning message processing. Sender: RecipientId::49 (c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1)
01-29 15:59:56.402 26979 27016 I MessageProcessorV2: [1706539916136] Text message.
01-29 15:59:56.406 26979 6008 D ConversationDataSource: [load(0, 75), thread 23] messages: 14,61, extra-data: 8,10, models: 0,00, conversion: 0,00, header: 0,00, total: 22,71 || mentions: 7,73, is-quoted: 0,00, reactions: 0,00, attachments: 0,00, payments: 0,01, calls: 0,01 >> cpuTime: 7,75, wallTime: 8,01
01-29 15:59:56.406 26979 6008 W FixedSizePagingControll: [onDataNeededAroundIndex(9), size: 12318] Invalidated! Just after data was loaded.
01-29 15:59:56.415 26979 27044 D TrafficStats: tagSocket(190) with statsTag=0xffffffff, statsUid=-1
01-29 15:59:56.422 1124 6029 D vendor.qti.vibrator: Notifying perform complete
01-29 15:59:56.423 2732 2757 W System : A resource failed to call release.
01-29 15:59:56.424 2732 2757 W System : A resource failed to call release.
01-29 15:59:56.424 1124 1124 D vendor.qti.vibrator: QTI Vibrator off
01-29 15:59:56.424 2732 2757 W System : A resource failed to call release.
01-29 15:59:56.434 1124 1124 E (2)[1124:vendor.qti.hard][20240129_15:59:56.425122]@2 aw8697_activate_store: value=0
01-29 15:59:56.434 26979 27019 I EmojiPageCache: Loading page EmojiPageRequest(emojiPage=Disk(uri=content://org.thoughtcrime.securesms/emoji/Objects_0), inSampleSize=1)
01-29 15:59:56.440 1124 1124 I (3)[1124:vendor.qti.hard][20240129_15:59:56.439118]@3 aw8697_activate_store: value=0
01-29 15:59:56.441 26979 27019 D EmojiFiles: Verifying all name files exist.
01-29 15:59:56.444 26979 27019 D EmojiFiles: All names exist? true
01-29 15:59:56.456 26979 6008 D ConversationDataSource: [load(0, 75), thread 23] messages: 3,47, extra-data: 36,03, models: 0,49, conversion: 9,79, header: 0,00, total: 49,78 || mentions: 0,64, is-quoted: 35,41, reactions: 1,56, attachments: 7,47, payments: 0,05, calls: 1,22 >> cpuTime: 46,37, wallTime: 35,83
01-29 15:59:56.464 26979 6008 D ConversationListDataSou: [load(45, 4), UnarchivedConversationListDataSource, OFF] cursor: 7,10, cache-recipients: 0,08, recipient-resolve: 0,01, total: 7,18
01-29 15:59:56.464 26979 26979 D MainActivityListHostFra: Initializing profile icon
01-29 15:59:56.466 26979 26979 D ConversationItemAnimato: Finished running animations.
01-29 15:59:56.484 26979 26979 D VoiceNoteMediaControlle: MediaController successfully initialized. (RoutingActivity)
01-29 15:59:56.490 26979 26979 D ThumbnailView: setBounds: update {minW473,maxW756,minH315,maxH1008}
01-29 15:59:56.490 26979 26979 D ThumbnailView: setBounds: update {minW756,maxW756,minH315,maxH1008}
01-29 15:59:56.491 26979 26979 I ThumbnailView: loading part with id null, progress 1, fast preflight id: null
01-29 15:59:56.491 26979 26979 D ThumbnailView: override: apply w756xh1008
01-29 15:59:56.491 26979 26979 D GlideDrawableListeningT: Loaded null resource
01-29 15:59:56.496 26979 26979 D ThumbnailView: setBounds: update {minW473,maxW756,minH315,maxH1008}
01-29 15:59:56.496 26979 26979 D ThumbnailView: setBounds: update {minW756,maxW756,minH315,maxH1008}
01-29 15:59:56.496 26979 26979 I ThumbnailView: Not re-loading slide null
01-29 15:59:56.501 3097 4340 D androidtc: Initializing SystemTextClassifier, type = System
01-29 15:59:56.502 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 4
01-29 15:59:56.502 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 3
01-29 15:59:56.502 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 2
01-29 15:59:56.502 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 1
01-29 15:59:56.502 26979 26979 D ConversationItemAnimato: Dispatched slide animation for view at 0
01-29 15:59:56.514 26979 26979 D ConversationItemAnimato: Starting 5 animations.
01-29 15:59:56.577 26979 27013 I Job : [JOB::f51deac7-3549-46e6-a22f-50d3a6c80894][SendDeliveryReceiptJob] onSubmit() (Time Since Submission: 1 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited, Queue: RecipientId::49)
01-29 15:59:56.597 26979 27016 D LeakyBucketLimiter: Overflowed!
01-29 15:59:56.597 26979 27016 W JobController: [JOB::a4ee73fc-99e3-4b0e-b92f-7eb56c21ddfe][ThreadUpdateJob] Already at the max instance count. Factory limit: -1, Queue limit: 2. Skipping. (Time Since Submission: 0 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: ThreadUpdateJob_23)
01-29 15:59:56.597 26979 27016 D IncomingMessageObserver: Ended database transaction.
01-29 15:59:56.597 26979 27016 D IncomingMessageObserver: Running 0 follow-up operations...
01-29 15:59:56.598 26979 27016 D IncomingMessageObserver: Beginning database transaction...
01-29 15:59:56.605 26979 26920 D ConversationDataSource: [size(), thread 23] 5 ms
01-29 15:59:56.629 26979 27016 I libsignal: rust/protocol/src/sealed_sender.rs:441: deserialized UnidentifiedSenderMessageContent from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with type Whisper
01-29 15:59:56.630 26979 27016 I libsignal: rust/protocol/src/session_cipher.rs:454: decrypted Whisper message from c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1 with current session state (base key 7019c42b6e2ceadc7b86080b4971574aa499c5d8caecac0c948c84099627d623)
01-29 15:59:56.630 26979 27016 D MessageDecryptor: [1706540113199] c73bb5e8-1dd0-48c9-a743-7d85ed7f124b:1 | Successfully decrypted the envelope in 1,70 ms (GUID c330da20-02aa-4c1d-b105-71e1bd97ad7f). Delivery latency: 281999 ms, Urgent: true
01-29 15:59:56.630 26979 27016 I MessageProcessorV2: [1706540113199] Beginning message processing. Sender: RecipientId::49 (c73bb5e8-1dd0-48c9-a743-7d85ed7f124b.1)
01-29 15:59:56.630 26979 27016 I MessageProcessorV2: [1706540113199] Text message.

@Albertklk
Copy link

Hi @greyson-signal I see you done an extensive research about this issues.
From your experience does OEM restrict FCM high priority network access when there's some motion on the device but screen is off and unplugged from charger?
A bad workaround would be having the device in the pocket instead of sitting still on desk.

@BluePixel4k
Copy link

I also experience this delay frequently.
Just now again. The first message didn't arrive until an hour later, after I had received another message.
https://debuglogs.org/android/7.16.4/1947f83930337943ce56de0f97c8d5231fb30223da049336fe894307cd34e604

I often receive messages with a delay, even though I'm surfing the Internet or using apps on my cell phone at the time.
It's very frustrating when you're waiting for an important reply.

I have already disabled battery optimization. My Pixel 8 is running GrapheneOS.

@BluePixel4k
Copy link

@greyson-signal, Maybe a workaround would be to send an empty notification after a timeout if the phone has not fetched the message from the Signal server to get a higher FCM priority?

@Tursko
Copy link

Tursko commented Sep 19, 2024

My friend is encountering this issue on their phone.

Pixel 8 on Signal 7.16.4.

Sometimes they never get any messages until they open the app. Other times it works fine.

https://debuglogs.org/android/7.16.4/b64c805b37f7312c82fb8fdc47c5f234fbab11b1d7a4fed4191a72b6b95e7e60

@corobin
Copy link

corobin commented Oct 16, 2024

I am also seeing intermittent message or notification delays. sometimes when i am also on desktop i can see that the message came through on desktop, but there is no notification on android for an extended period of time. i also noticed that a message i sent was not seen on the other end until the next day, and the message i receive i am not notified about for anything between minutes to hours+. i do see the new message if i open the app. the messages do show the original timestamp when it is viewed, not when i am notified about it or happen to see it in app. this applies for both messages i receive and send (it shows on the other end with original send time). i am on Android and the other end is on iOS so it may be a cross platform issue.

Based on these observations, there are a number of possibilities that I can't tell between:

  • sending or receiving is delayed on all platforms
  • sending and receiving is delayed on Android, causing the other end to not receive it but the problem is on my end
  • sending and receiving is fine, but notifications is not provided on all platforms
  • a combination of the above

I am on Android 15 but also had this with Andraid 14, on Pixel 7.

Signal 7.19.2 from play store. Setting not battery optimized and allowed to have background data.

I see that there have been numerous past issues opened for similar problem, a non-exhaustive selection from a quick search: #970, #1102, #5323, #5670, #8214, #8604, #8934, #9259, #9533, #9793, #10693, #11079, #11731, #12867, #13249, #13630, #13695

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests