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

unreasonably high CPU usage when idling #5444

Closed
wohltat opened this issue Aug 6, 2021 · 81 comments
Closed

unreasonably high CPU usage when idling #5444

wohltat opened this issue Aug 6, 2021 · 81 comments
Labels

Comments

@wohltat
Copy link

wohltat commented Aug 6, 2021

Bug Description

signal-desktop is constantly using around minimum 4% CPU on my computer even it is in the background and nothing is happening.

Steps to Reproduce

i just start signal-desktop via command line signal-desktop and minimize it.

Actual Result:
4%-10% or more CPU usage in idle state. This around as much or more than my window manager uses.

Expected Result:
1% or less CPU usage.

Platform Info

Signal Version:
v5.7.1

Operating System:
No LSB modules are available.
Distributor ID: Linuxmint
Description: Linux Mint 20.1
Release: 20.1
Codename: ulyssa

Linux 5.4.0-80-generic #90-Ubuntu SMP Fri Jul 9 22:49:44 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Linked Device Version:
Android Version: 6.0.1

strace, ltrace

profiling for 10seconds of app running

>>> sudo strace -f -p $(pgrep -x "signal-desktop" | cut -f1 -d' ' | head -1) --summary-only
strace: Process 1505438 attached with 31 threads
strace: Process 1508688 attached
^Cstrace: Process 1505438 detached
strace: Process 1505439 detached
strace: Process 1505445 detached
strace: Process 1505446 detached
strace: Process 1505449 detached
strace: Process 1505451 detached
strace: Process 1505452 detached
strace: Process 1505453 detached
strace: Process 1505454 detached
strace: Process 1505455 detached
strace: Process 1505456 detached
strace: Process 1505461 detached
strace: Process 1505464 detached
strace: Process 1505465 detached
strace: Process 1505466 detached
strace: Process 1505467 detached
strace: Process 1505468 detached
strace: Process 1505469 detached
strace: Process 1505470 detached
strace: Process 1505471 detached
strace: Process 1505473 detached
strace: Process 1505475 detached
strace: Process 1505476 detached
strace: Process 1505477 detached
strace: Process 1505478 detached
strace: Process 1505479 detached
strace: Process 1505482 detached
strace: Process 1505489 detached
strace: Process 1505499 detached
strace: Process 1505500 detached
strace: Process 1505552 detached
strace: Process 1508688 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 36,35    0,001031         515         2           restart_syscall
 35,33    0,001002         334         3           epoll_wait
  9,27    0,000263          65         4           futex
  6,42    0,000182           8        22        20 recvmsg
  4,55    0,000129         129         1           clone
  3,46    0,000098          19         5           poll
  1,73    0,000049          24         2         2 stat
  0,85    0,000024          24         1           set_robust_list
  0,53    0,000015          15         1           write
  0,35    0,000010          10         1           sendto
  0,35    0,000010          10         1           gettid
  0,25    0,000007           7         1           prctl
  0,21    0,000006           6         1           getpid
  0,21    0,000006           6         1           setpriority
  0,14    0,000004           4         1           read
------ ----------- ----------- --------- --------- ----------------
100.00    0,002836                    47        22 total



>> sudo ltrace -p $(pgrep -x "signal-desktop" | cut -f1 -d' ' | head -1) -c
^C% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 46.31   21.677400        7842      2764 epoll_wait
 25.65   12.007795        4144      2897 __errno_location
 16.49    7.717917        3868      1995 clock_gettime
  5.13    2.400149     1200074         2 g_main_context_iteration
  1.58    0.738548       12956        57 pthread_mutex_lock
  1.49    0.698618      349309         2 gtk_main_do_event
  1.35    0.630279      105046         6 xcb_poll_for_event
  1.16    0.541935        8884        61 pthread_mutex_unlock
  0.48    0.225044       37507         6 xcb_flush
  0.28    0.132212       22035         6 xcb_connection_has_error
  0.03    0.016099        1609        10 pthread_getspecific
  0.01    0.005189         864         6 memcpy
  0.01    0.004592        1530         3 bcmp
  0.01    0.004380        1095         4 pthread_mutex_trylock
  0.01    0.002773         924         3 __vsnprintf_chk
  0.01    0.002663         887         3 memset
  0.01    0.002573         857         3 strlen
------ ----------- ----------- --------- --------------------
100.00   46.808166                  7828 total

Most time is spend in library calls and not in syscalls. I still don't really know how to interpret this since with 4% CPU usage over 10s should be something like 0.4 seconds.

@hiqua
Copy link
Contributor

hiqua commented Aug 6, 2021

Are you really using v5.7? Can you update if that's the case?

@wohltat
Copy link
Author

wohltat commented Aug 6, 2021

Oh, it was from the ubuntu repos.

Now i'm on v5.12.2 but i see the same behaviour. Mostly 4%-5% CPU usage after start and minimized.

@hiqua
Copy link
Contributor

hiqua commented Aug 6, 2021

From your logs, I'm not sure where you read 4 to 10%, but even then, there's no baseline which Signal-Desktop should reach (FWIW it's always less than 4% on my computer according to htop). The lower the better, and whatever can be done to lower this should indeed be done, but there's little that's actionable from this issue.

@wohltat
Copy link
Author

wohltat commented Aug 6, 2021

i read the cpu usage from htop as well. Btw i just kept it running without changing anything and it now is around 8% cpu usage. There are multiple signal-desktop processes in htop and if i add thier cpu usage i even get a lot over 10%.

There maybe no objective baseline. But for me subjectivly this is too much. I lot more such idling applications and the cpu (or one cpu) is fully loaded. What is it that signal-desktop is doing if there is nothing happening. Other messengers don't need that much resources. For comparison, my email client uses 0.0% when idling according to htop, just like every 10 seconds there is a spike of 1% or so.

As i said i also don't really know what to make of the strace/ltrace logs. This was just a starting point. I don't know any other way to see what signal-desktop is doing other that study the code.

What is your cpu usage? Maybe there is something special with my setup if other people don't see this behavior.

@wohltat
Copy link
Author

wohltat commented Aug 6, 2021

Also another way to look at the cpu usage is, not to compare it to the 100% possible but to the rest that is currently used.

When my computer is idle and im reading a website(and other apps closed) i have roughly 4% or less on each of the 4 CPU cores. If an app uses 8% than it is already half of what all other processes are using. Therefore this makes a huge difference how long my notebook battery lasts if i'm just reading.

@hiqua
Copy link
Contributor

hiqua commented Aug 7, 2021

Can you add a debug log?

@wohltat
Copy link
Author

wohltat commented Aug 9, 2021

@josh-signal
Copy link
Contributor

@wohltat we believe this is fixed in 5.13.x can you please upgrade?

@wohltat
Copy link
Author

wohltat commented Aug 12, 2021

There seems to be an improvement. Shortly after start of signal-desktop there is around only 1% cpu usage.

But after ten minutes or so, it looks almost like before. So it didn't change much.

@wohltat
Copy link
Author

wohltat commented Aug 12, 2021

I had a closer look when the increase in cpu usage happens.
I started signal 10 times and after a bit over 2 minutes the cpu usage was rising significantly. This behaviour was consistent over all trials.

The last four times i looked at the time even closer and it was pretty much exactly 2:07min after signal was launched.

Could it be that there is some timer that is initialized on program start (7 seconds after launch) that triggers something after 2 minutes?

@wohltat
Copy link
Author

wohltat commented Aug 12, 2021

I started signal at 20:35:01. in the log there is

{"level":30,"time":"2021-08-12T20:37:07.824Z","pid":1793148,"hostname":"computername","msg":"attachment_downloads/_maybeStartJob: no attachment jobs to run"}
{"level":30,"time":"2021-08-12T20:38:00.280Z","pid":1793148,"hostname":"computername","msg":"WebSocketResources: Sending a keepalive message"}
{"level":30,"time":"2021-08-12T20:38:07.825Z","pid":1793148,"hostname":"computername","msg":"attachment_downloads/_maybeStartJob: no attachment jobs to run"}
{"level":30,"time":"2021-08-12T20:38:09.558Z","pid":1793148,"hostname":"computername","msg":"getAllFromCache"}
{"level":30,"time":"2021-08-12T20:38:09.562Z","pid":1793148,"hostname":"taschenrechner","msg":"getAllFromCache loaded 0 saved envelopes"}

i tried again at 20:43:00

{"level":30,"time":"2021-08-12T20:45:05.613Z","pid":1794853,"hostname":"taschenrechner","msg":"attachment_downloads/_maybeStartJob: no attachment jobs to run"}
{"level":30,"time":"2021-08-12T20:45:08.547Z","pid":1794853,"hostname":"taschenrechner","msg":"getAllFromCache"}
{"level":30,"time":"2021-08-12T20:45:08.552Z","pid":1794853,"hostname":"taschenrechner","msg":"getAllFromCache loaded 0 saved envelopes"}

From exclusion and because other message have been there before, the rise in CPU usage could be connected to

"getAllFromCache" and "getAllFromCache loaded 0 saved envelopes"

whatever that means.

@indutny-signal
Copy link
Contributor

Hah, very interesting. Could you post your debug log or send it over email to me ([email protected])?

I'm looking for something like: "slow query getUnprocessedCount" or "slow query getAllUnprocessed", but it might be something else!

@indutny-signal
Copy link
Contributor

Nvm, it loaded zero saved envelopes. Interesting...

@indutny-signal
Copy link
Contributor

This code path runs every 2 minutes. Do you see CPU spikes every 2 minutes or just once 2 minutes after app restart?

@wohltat
Copy link
Author

wohltat commented Aug 13, 2021

I haven't figured out the pattern just yet. I'm about to make a recording of the CPU usage.

Sometimes its low for a while and then its high for at least several minutes.
What i find interesting is, that it if signal is maximized and then minimized again, it goes to low cpu usage quite reliably. But after minute or so (seems to vary) goes up again.

@wohltat
Copy link
Author

wohltat commented Aug 13, 2021

I don't know why but now the behavior is different. The rise in cpu usage is not appearing after 2 minutes but later.

Here is a plot of the 1 minute average CPU usage over some hours. The CPU load of all signal processes where summed up.
At the end you can see the phenomenon that the cpu load drops when minimizing signal.
@indutny-signal i sent you the debug log that should correspond to the plot.

image

Code to create the plot:

from pylab import *
import pandas as pd
import psutil
import time
from time import sleep

sp = [p for p in map(psutil.Process, psutil.pids()) if p.name().find('signal-desktop')!=-1]

cpu_usage = []
while True:
    cpu_usage.append([time.time()] + [p.cpu_percent() for p in sp])
    sleep(0.1)   # 0.1 = 100ms resolution
# manually interrupted the loop here after some time

%pylab notebook
# code for plotting the results
df = pd.DataFrame(cpu_usage, columns=['time'] + [p.pid for p in sp])

x = pd.to_datetime(df.time * 1e9)  # time in ns
cpu_usage_all_processes = df.iloc[:,2:].sum(axis=1)
y = cpu_usage_all_processes.rolling(10*60).mean()
h = plot(array(x), array(y))
_ = plt.xticks(rotation=45)
ylabel('CPU usage [%]')

@indutny-signal
Copy link
Contributor

I'm not entirely sure what's going on. The logs that you sent to me doesn't show any activity during that time on our end. The most work that we've done at that point was running a db query once per minute and sending a keepalive message to the server once per minute too. The query didn't take long time to run, and keepalive is generally inexpensive so I don't see how any of these could have triggered a high-CPU usage.

Did you happen to have a conversation open with GIFs running, or something that would use a lot CPU power to redraw UI often?

@wohltat
Copy link
Author

wohltat commented Aug 17, 2021

There wasn't anything happening and nothing open until around 10:45 when you can see a bit of turbulence in the graph.

I can do a long time recording of the cpu usage similar like the one i posted if this would help you.

@alien2003
Copy link

Happens for me too, Drains battery a lot

@indutny-signal
Copy link
Contributor

@wohltat we just released 5.14.0 which has some fresh performance improvements. Could you give it a try and see if it helps at all?

@wohltat
Copy link
Author

wohltat commented Aug 20, 2021

Updated to v5.14.0. Looks very similar to me.
image

@chmike
Copy link

chmike commented Aug 20, 2021

I have 5.13.0 installed on Ubuntu 21.04 and also see 10% CPU usage while Signal is idle. That is too much. It's 3 times more than firefox that I currently use to write this comment.

Why is the issue closed ? The problem is not at all resolved.
Edit: after some tests I found out that there is no such CPU usage after a fresh restart of the app. The problem thus shows up after receiving and sending messages for some time. Indeed, after sending a message, the CPU usage raises from 0.7% to 1.5-2%. After receiving a message, the CPU usage raise again and is now 4%. Such a CPU raise with only two message exchanges.

@scottnonnenberg-signal
Copy link
Contributor

@wohltat @chmike @alien2003 What we need is more information from you - we need you to be scientists. What I see when Signal Desktop is in the background is 0.1-0.3% CPU usage, so details from your configuration are really important.

I've opened the issue again - please let us know everything you can about how the behavior changes. The increase over time as the app is used after startup is really interesting. Does it change if you close the conversation with Ctrl+Shift+C to close the current conversation so no conversation is showing? What if you don't send any messages, just open a conversation with 30+ messages in it? How about opening a conversation with no messages in it?

That's the kind of information that may lead to a fix. Thanks!

@wohltat
Copy link
Author

wohltat commented Aug 21, 2021

Here is another recording.
I did not interact with signal-desktop in that time. I just opened some messages on my phone several times which did not seem to interfere.
image

There were no open conversations, i.e. closed with "Ctrl+Shift+C".

Couldn't we go more in the direction of the core, i.e. incorporate a debugger or use strace/ltrace? I'm trying but i'm just learning to do that.
Is the info of my first post telling you something?

>> sudo ltrace -p $(pgrep -x "signal-desktop" | cut -f1 -d' ' | head -1) -c
^C% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 46.31   21.677400        7842      2764 epoll_wait
 25.65   12.007795        4144      2897 __errno_location
 16.49    7.717917        3868      1995 clock_gettime
  5.13    2.400149     1200074         2 g_main_context_iteration
...

There is info on my system in the initial post. Which additional info do you need?

@wohltat wohltat closed this as completed Aug 22, 2021
@wohltat
Copy link
Author

wohltat commented Aug 22, 2021

What we need is more information from you - we need you to be scientists. What I see when Signal Desktop is in the background is 0.1-0.3% CPU usage, so details from your configuration are really important.

@scottnonnenberg-signal What would you do if if this would happen on you computer? Which tools would you use?
So far if never seen a CPU usage below 1%. Although i think this high for a idling app, i would be pretty happy already if it would not go higher than that.

I made another longer test. The interesting thing is that this time it was low for several hours. Then i opened signal, opened some conversations, ctrl+shift+c and then minimized it again. After that cpu usage stayed high again.
You can see that the rise happens approx at 15:10:45. The logs are linked below

image

image

log file around the time cpu load rose up again
INFO  2021-08-21T15:10:16.743Z WebSocketResources: Sending a keepalive message
INFO  2021-08-21T15:10:45.836Z Removing notification
INFO  2021-08-21T15:10:45.837Z GET https://textsecure-service.whispersystems.org/v1/config
INFO  2021-08-21T15:10:45.837Z Cycling agent for type -auth
INFO  2021-08-21T15:10:45.947Z GET https://textsecure-service.whispersystems.org/v1/config 200 Success
INFO  2021-08-21T15:10:45.950Z Remote Config: Flag desktop.groupCallOutboundRing has changed
INFO  2021-08-21T15:10:46.359Z markConversationRead {"conversationId":"[REDACTED]6f1","newestUnreadId":1629370520736,"unreadMessages":0,"unreadReactions":0}
INFO  2021-08-21T15:10:46.837Z Not updating notifications; notification status is noNotifications. 
INFO  2021-08-21T15:10:51.385Z unloading conversation groupv2([REDACTED]afU=) due to: model trigger - opened another conversation
INFO  2021-08-21T15:10:51.444Z waitForEmptyEventQueue: Waiting for event handler queue idle...
INFO  2021-08-21T15:10:51.463Z maybeFetchCredentials: fetching credentials for 18867 through 18867
INFO  2021-08-21T15:10:51.463Z GET https://textsecure-service.whispersystems.org/v1/certificate/group/18867/18867
INFO  2021-08-21T15:10:51.463Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.463Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.463Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.463Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.463Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.464Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.465Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.466Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:51.469Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b21/[REDACTED]a4d
INFO  2021-08-21T15:10:51.469Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]562/[REDACTED]dbb (unauth)
INFO  2021-08-21T15:10:51.471Z Cycling agent for type -unauth
INFO  2021-08-21T15:10:51.471Z SocketManager: connecting unauthenticated socket
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]072/[REDACTED]75a (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]6fb/[REDACTED]f25 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]32b/[REDACTED]c26 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b63/[REDACTED]390 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]339/[REDACTED]589 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]1e8/[REDACTED]2f6 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]bfa/[REDACTED]3dd (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]24b/[REDACTED]6ac (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3ea/[REDACTED]407 (unauth)
INFO  2021-08-21T15:10:51.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]611/[REDACTED]40a (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b98/[REDACTED]c6e (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2ae/[REDACTED]099 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c1d/[REDACTED]dfc (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]33f/[REDACTED]328 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]188/[REDACTED]e61 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2dd/[REDACTED]5c1 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]65d/[REDACTED]cd7 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]df9/[REDACTED]7a6 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c82/[REDACTED]72f (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2bb/[REDACTED]f30 (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]a5a/[REDACTED]41d (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]49e/[REDACTED]a0b (unauth)
INFO  2021-08-21T15:10:51.474Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3ac/[REDACTED]f3c (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]7bb/[REDACTED]c48 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]86b/[REDACTED]ec5 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]97d/[REDACTED]85a (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b03/[REDACTED]3fb (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e2c/[REDACTED]b93 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e7a/[REDACTED]54c (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2d3/[REDACTED]dcf (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]062/[REDACTED]743 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]f36/[REDACTED]0c0 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]fb9/[REDACTED]dae (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]98c/[REDACTED]1ad (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]498/[REDACTED]589 (unauth)
INFO  2021-08-21T15:10:51.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]85d/[REDACTED]d25 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]227/[REDACTED]8ac (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]8b5/[REDACTED]f7a (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]928/[REDACTED]e41 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]9d0/[REDACTED]725 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]41a/[REDACTED]924 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]44b/[REDACTED]b71 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]5de/[REDACTED]aed (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]fd2/[REDACTED]9b4 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]6c9/[REDACTED]8b8 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3e9/[REDACTED]405 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3d0/[REDACTED]5d5 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]a7a/[REDACTED]ee4 (unauth)
INFO  2021-08-21T15:10:51.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e64/[REDACTED]e2a (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]636/[REDACTED]718 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]78c/[REDACTED]426 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d4d/[REDACTED]c84 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]966/[REDACTED]bcd (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]cee/[REDACTED]754 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d4b/[REDACTED]bb8 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c31/[REDACTED]cb9 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d50/[REDACTED]de4 (unauth)
INFO  2021-08-21T15:10:51.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]50a/[REDACTED]75c (unauth)
INFO  2021-08-21T15:10:51.800Z GET https://textsecure-service.whispersystems.org/v1/certificate/group/18867/18867 200 Success
INFO  2021-08-21T15:10:51.807Z maybeFetchCredentials: Saving new credentials...
INFO  2021-08-21T15:10:51.807Z maybeFetchCredentials: Save complete.
INFO  2021-08-21T15:10:51.807Z getGroupUpdates/groupv2([REDACTED]Mb4=): Starting...
INFO  2021-08-21T15:10:51.808Z updateGroupViaState/groupv2([REDACTED]Mb4=): Getting full group state...
INFO  2021-08-21T15:10:51.815Z GET https://storage.signal.org/v1/groups
INFO  2021-08-21T15:10:51.818Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b21/[REDACTED]a4d 200 Success
INFO  2021-08-21T15:10:51.820Z Setting sealedSender to ENABLED for conversation [REDACTED]b21 ([REDACTED]62b)
INFO  2021-08-21T15:10:52.002Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.020Z markConversationRead {"conversationId":"[REDACTED]874","newestUnreadId":1629370520793,"unreadMessages":3,"unreadReactions":0}
INFO  2021-08-21T15:10:52.044Z Sending 3 read syncs
INFO  2021-08-21T15:10:52.045Z read sync job queue: added new job [REDACTED]82a
INFO  2021-08-21T15:10:52.045Z JobQueueDatabaseStore adding job [REDACTED]82a to queue "read sync"
INFO  2021-08-21T15:10:52.045Z Sending 3 read receipts
INFO  2021-08-21T15:10:52.045Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.045Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.045Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.046Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.047Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.048Z Sender certificate service found a valid yes-E164 certificate in storage; skipping fetch
INFO  2021-08-21T15:10:52.053Z commitZoneChanges(storeSession): pending sessions 1 pending unprocessed 0
INFO  2021-08-21T15:10:52.053Z commitZoneChanges(storeSession): pending sessions 1 pending unprocessed 0
INFO  2021-08-21T15:10:52.053Z commitZoneChanges(storeSession): pending sessions 1 pending unprocessed 0
INFO  2021-08-21T15:10:52.061Z read sync job queue: enqueuing job [REDACTED]82a
INFO  2021-08-21T15:10:52.063Z read sync job queue: running job [REDACTED]82a, attempt 1 of 110
INFO  2021-08-21T15:10:52.067Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]a5a (unauth)
INFO  2021-08-21T15:10:52.073Z commitZoneChanges(storeSession): pending sessions 1 pending unprocessed 0
INFO  2021-08-21T15:10:52.074Z commitZoneChanges(storeSession): pending sessions 1 pending unprocessed 0
INFO  2021-08-21T15:10:52.075Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]611 (unauth)
INFO  2021-08-21T15:10:52.083Z SocketManager: connected unauthenticated socket
INFO  2021-08-21T15:10:52.099Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]b21
INFO  2021-08-21T15:10:52.191Z GET https://storage.signal.org/v1/groups 200 Success
INFO  2021-08-21T15:10:52.324Z getCurrentGroupState/groupv2([REDACTED]Mb4=): Applying full group state, from version 39 to 39.
INFO  2021-08-21T15:10:52.325Z GET https://cdn.signal.org/groups/zv0YfBdFthubVVocCt4cFQzAZmlHVJYVDvh4TXt4Mb4/e4ZUiajEOoqEi371AcHjug
INFO  2021-08-21T15:10:52.327Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]072/[REDACTED]75a 200 Success
INFO  2021-08-21T15:10:52.327Z Setting sealedSender to ENABLED for conversation [REDACTED]072 ([REDACTED]61a)
INFO  2021-08-21T15:10:52.327Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]6fb/[REDACTED]f25 200 Success
INFO  2021-08-21T15:10:52.328Z Setting sealedSender to ENABLED for conversation [REDACTED]6fb ([REDACTED]d80)
INFO  2021-08-21T15:10:52.328Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]32b/[REDACTED]c26 200 Success
INFO  2021-08-21T15:10:52.328Z Setting sealedSender to ENABLED for conversation [REDACTED]32b ([REDACTED]352)
INFO  2021-08-21T15:10:52.329Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b63/[REDACTED]390 200 Success
INFO  2021-08-21T15:10:52.329Z Setting sealedSender to ENABLED for conversation [REDACTED]b63 ([REDACTED]12c)
INFO  2021-08-21T15:10:52.329Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]339/[REDACTED]589 200 Success
INFO  2021-08-21T15:10:52.329Z Setting sealedSender to ENABLED for conversation [REDACTED]339 ([REDACTED]8ec)
INFO  2021-08-21T15:10:52.330Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]1e8/[REDACTED]2f6 200 Success
INFO  2021-08-21T15:10:52.330Z Setting sealedSender to ENABLED for conversation [REDACTED]1e8 ([REDACTED]0d1)
INFO  2021-08-21T15:10:52.330Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]bfa/[REDACTED]3dd 200 Success
INFO  2021-08-21T15:10:52.330Z Setting sealedSender to ENABLED for conversation [REDACTED]bfa ([REDACTED]5e9)
INFO  2021-08-21T15:10:52.331Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]24b/[REDACTED]6ac 200 Success
INFO  2021-08-21T15:10:52.331Z Setting sealedSender to ENABLED for conversation [REDACTED]24b ([REDACTED]59b)
INFO  2021-08-21T15:10:52.331Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3ea/[REDACTED]407 200 Success
INFO  2021-08-21T15:10:52.331Z Setting sealedSender to ENABLED for conversation [REDACTED]3ea ([REDACTED]d9a)
INFO  2021-08-21T15:10:52.332Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]611/[REDACTED]40a 200 Success
INFO  2021-08-21T15:10:52.332Z Setting sealedSender to ENABLED for conversation [REDACTED]611 ([REDACTED]bf5)
INFO  2021-08-21T15:10:52.332Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b98/[REDACTED]c6e 200 Success
INFO  2021-08-21T15:10:52.332Z Setting sealedSender to ENABLED for conversation [REDACTED]b98 ([REDACTED]173)
INFO  2021-08-21T15:10:52.333Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]b21 200 Success
INFO  2021-08-21T15:10:52.336Z GET https://cdn.signal.org/[REDACTED]eOQ
INFO  2021-08-21T15:10:52.339Z GET https://cdn.signal.org/[REDACTED]HPA
INFO  2021-08-21T15:10:52.344Z GET https://cdn.signal.org/[REDACTED]PpA
INFO  2021-08-21T15:10:52.345Z GET https://cdn.signal.org/[REDACTED]DFA
INFO  2021-08-21T15:10:52.346Z GET https://cdn.signal.org/[REDACTED]e3Q
INFO  2021-08-21T15:10:52.349Z read sync job queue: job [REDACTED]82a succeeded on attempt 1
INFO  2021-08-21T15:10:52.350Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:52.361Z GET https://cdn.signal.org/[REDACTED]LOA
INFO  2021-08-21T15:10:52.363Z changedConvoBatcher: deduped 3 into 3
INFO  2021-08-21T15:10:52.405Z GET https://cdn.signal.org/groups/zv0YfBdFthubVVocCt4cFQzAZmlHVJYVDvh4TXt4Mb4/e4ZUiajEOoqEi371AcHjug 200 Success
INFO  2021-08-21T15:10:52.410Z extractDiffs/groupv2([REDACTED]Mb4=) complete, generated 0 change messages
INFO  2021-08-21T15:10:52.411Z Conversation job waitThenMaybeUpdateGroup took 949ms
INFO  2021-08-21T15:10:52.411Z Conversation job maybeSetPendingUniversalTimer was blocked for 899ms
INFO  2021-08-21T15:10:52.414Z GET https://cdn.signal.org/[REDACTED]HPA 200 Success
INFO  2021-08-21T15:10:52.418Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.424Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2ae/[REDACTED]099 200 Success
INFO  2021-08-21T15:10:52.424Z Setting sealedSender to ENABLED for conversation [REDACTED]2ae ([REDACTED]b5e)
INFO  2021-08-21T15:10:52.425Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c1d/[REDACTED]dfc 200 Success
INFO  2021-08-21T15:10:52.425Z Setting sealedSender to ENABLED for conversation [REDACTED]c1d ([REDACTED]ac4)
INFO  2021-08-21T15:10:52.426Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]33f/[REDACTED]328 200 Success
INFO  2021-08-21T15:10:52.427Z Setting sealedSender to ENABLED for conversation [REDACTED]33f ([REDACTED]ee6)
INFO  2021-08-21T15:10:52.428Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]188/[REDACTED]e61 200 Success
INFO  2021-08-21T15:10:52.428Z Setting sealedSender to ENABLED for conversation [REDACTED]188 ([REDACTED]1d5)
INFO  2021-08-21T15:10:52.429Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2dd/[REDACTED]5c1 200 Success
INFO  2021-08-21T15:10:52.430Z Setting sealedSender to ENABLED for conversation [REDACTED]2dd ([REDACTED]b58)
INFO  2021-08-21T15:10:52.430Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]65d/[REDACTED]cd7 200 Success
INFO  2021-08-21T15:10:52.431Z Setting sealedSender to ENABLED for conversation [REDACTED]65d ([REDACTED]158)
INFO  2021-08-21T15:10:52.431Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]df9/[REDACTED]7a6 200 Success
INFO  2021-08-21T15:10:52.432Z Setting sealedSender to ENABLED for conversation [REDACTED]df9 ([REDACTED]972)
INFO  2021-08-21T15:10:52.433Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c82/[REDACTED]72f 200 Success
INFO  2021-08-21T15:10:52.433Z Setting sealedSender to ENABLED for conversation [REDACTED]c82 ([REDACTED]53a)
INFO  2021-08-21T15:10:52.434Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2bb/[REDACTED]f30 200 Success
INFO  2021-08-21T15:10:52.434Z Setting sealedSender to ENABLED for conversation [REDACTED]2bb ([REDACTED]132)
INFO  2021-08-21T15:10:52.435Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]a5a/[REDACTED]41d 200 Success
INFO  2021-08-21T15:10:52.435Z Setting sealedSender to ENABLED for conversation [REDACTED]a5a ([REDACTED]73d)
INFO  2021-08-21T15:10:52.436Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]49e/[REDACTED]a0b 200 Success
INFO  2021-08-21T15:10:52.436Z Setting sealedSender to ENABLED for conversation [REDACTED]49e ([REDACTED]f3d)
INFO  2021-08-21T15:10:52.436Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3ac/[REDACTED]f3c 200 Success
INFO  2021-08-21T15:10:52.436Z Setting sealedSender to ENABLED for conversation [REDACTED]3ac ([REDACTED]782)
INFO  2021-08-21T15:10:52.437Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]7bb/[REDACTED]c48 200 Success
INFO  2021-08-21T15:10:52.437Z Setting sealedSender to ENABLED for conversation [REDACTED]7bb ([REDACTED]8c0)
INFO  2021-08-21T15:10:52.437Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]86b/[REDACTED]ec5 200 Success
INFO  2021-08-21T15:10:52.437Z Setting sealedSender to ENABLED for conversation [REDACTED]86b ([REDACTED]af8)
INFO  2021-08-21T15:10:52.438Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]97d/[REDACTED]85a 200 Success
INFO  2021-08-21T15:10:52.438Z Setting sealedSender to ENABLED for conversation [REDACTED]97d ([REDACTED]67d)
INFO  2021-08-21T15:10:52.438Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]b03/[REDACTED]3fb 200 Success
INFO  2021-08-21T15:10:52.438Z Setting sealedSender to ENABLED for conversation [REDACTED]b03 ([REDACTED]5df)
INFO  2021-08-21T15:10:52.439Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e2c/[REDACTED]b93 200 Success
INFO  2021-08-21T15:10:52.439Z Setting sealedSender to ENABLED for conversation [REDACTED]e2c ([REDACTED]626)
INFO  2021-08-21T15:10:52.439Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e7a/[REDACTED]54c 200 Success
INFO  2021-08-21T15:10:52.439Z Setting sealedSender to ENABLED for conversation [REDACTED]e7a ([REDACTED]976)
INFO  2021-08-21T15:10:52.439Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]2d3/[REDACTED]dcf 200 Success
INFO  2021-08-21T15:10:52.439Z Setting sealedSender to ENABLED for conversation [REDACTED]2d3 ([REDACTED]01b)
INFO  2021-08-21T15:10:52.440Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]062/[REDACTED]743 200 Success
INFO  2021-08-21T15:10:52.440Z Setting sealedSender to ENABLED for conversation [REDACTED]062 ([REDACTED]f94)
INFO  2021-08-21T15:10:52.440Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]f36/[REDACTED]0c0 200 Success
INFO  2021-08-21T15:10:52.440Z Setting sealedSender to UNRESTRICTED for conversation [REDACTED]f36 ([REDACTED]7fa)
INFO  2021-08-21T15:10:52.441Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]fb9/[REDACTED]dae 200 Success
INFO  2021-08-21T15:10:52.441Z Setting sealedSender to ENABLED for conversation [REDACTED]fb9 ([REDACTED]e99)
INFO  2021-08-21T15:10:52.441Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]98c/[REDACTED]1ad 200 Success
INFO  2021-08-21T15:10:52.441Z Setting sealedSender to UNRESTRICTED for conversation [REDACTED]98c ([REDACTED]5c2)
INFO  2021-08-21T15:10:52.442Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]498/[REDACTED]589 200 Success
INFO  2021-08-21T15:10:52.442Z Setting sealedSender to ENABLED for conversation [REDACTED]498 ([REDACTED]f6c)
INFO  2021-08-21T15:10:52.442Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]85d/[REDACTED]d25 200 Success
INFO  2021-08-21T15:10:52.442Z Setting sealedSender to ENABLED for conversation [REDACTED]85d ([REDACTED]a28)
INFO  2021-08-21T15:10:52.443Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]227/[REDACTED]8ac 200 Success
INFO  2021-08-21T15:10:52.443Z Setting sealedSender to ENABLED for conversation [REDACTED]227 ([REDACTED]f2e)
INFO  2021-08-21T15:10:52.443Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]8b5/[REDACTED]f7a 200 Success
INFO  2021-08-21T15:10:52.443Z Setting sealedSender to ENABLED for conversation [REDACTED]8b5 ([REDACTED]567)
INFO  2021-08-21T15:10:52.444Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]928/[REDACTED]e41 200 Success
INFO  2021-08-21T15:10:52.444Z Setting sealedSender to ENABLED for conversation [REDACTED]928 ([REDACTED]288)
INFO  2021-08-21T15:10:52.444Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]9d0/[REDACTED]725 200 Success
INFO  2021-08-21T15:10:52.444Z Setting sealedSender to ENABLED for conversation [REDACTED]9d0 ([REDACTED]d02)
INFO  2021-08-21T15:10:52.445Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]41a/[REDACTED]924 200 Success
INFO  2021-08-21T15:10:52.445Z Setting sealedSender to ENABLED for conversation [REDACTED]41a ([REDACTED]4ca)
INFO  2021-08-21T15:10:52.446Z GET https://cdn.signal.org/[REDACTED]JrQ
INFO  2021-08-21T15:10:52.453Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]44b/[REDACTED]b71 200 Success
INFO  2021-08-21T15:10:52.453Z Setting sealedSender to ENABLED for conversation [REDACTED]44b ([REDACTED]139)
INFO  2021-08-21T15:10:52.454Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]5de/[REDACTED]aed 200 Success
INFO  2021-08-21T15:10:52.454Z Setting sealedSender to ENABLED for conversation [REDACTED]5de ([REDACTED]5c0)
INFO  2021-08-21T15:10:52.454Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]fd2/[REDACTED]9b4 200 Success
INFO  2021-08-21T15:10:52.454Z Setting sealedSender to ENABLED for conversation [REDACTED]fd2 ([REDACTED]bc4)
INFO  2021-08-21T15:10:52.455Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]6c9/[REDACTED]8b8 200 Success
INFO  2021-08-21T15:10:52.455Z Setting sealedSender to ENABLED for conversation [REDACTED]6c9 ([REDACTED]c4e)
INFO  2021-08-21T15:10:52.455Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3e9/[REDACTED]405 200 Success
INFO  2021-08-21T15:10:52.455Z Setting sealedSender to ENABLED for conversation [REDACTED]3e9 ([REDACTED]d9f)
INFO  2021-08-21T15:10:52.455Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]3d0/[REDACTED]5d5 200 Success
INFO  2021-08-21T15:10:52.456Z Setting sealedSender to ENABLED for conversation [REDACTED]3d0 ([REDACTED]f3b)
INFO  2021-08-21T15:10:52.456Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]a7a/[REDACTED]ee4 200 Success
INFO  2021-08-21T15:10:52.456Z Setting sealedSender to ENABLED for conversation [REDACTED]a7a ([REDACTED]d9c)
INFO  2021-08-21T15:10:52.457Z GET https://cdn.signal.org/[REDACTED]e3Q 200 Success
INFO  2021-08-21T15:10:52.457Z GET https://cdn.signal.org/[REDACTED]DFA 200 Success
INFO  2021-08-21T15:10:52.460Z GET https://cdn.signal.org/[REDACTED]sdw
INFO  2021-08-21T15:10:52.461Z GET https://cdn.signal.org/[REDACTED]lcw
INFO  2021-08-21T15:10:52.463Z GET https://cdn.signal.org/[REDACTED]f2w
INFO  2021-08-21T15:10:52.463Z GET https://cdn.signal.org/[REDACTED]RVw
INFO  2021-08-21T15:10:52.465Z GET https://cdn.signal.org/[REDACTED]AKw
INFO  2021-08-21T15:10:52.466Z GET https://cdn.signal.org/[REDACTED]g0w
INFO  2021-08-21T15:10:52.468Z GET https://cdn.signal.org/[REDACTED]B0w
INFO  2021-08-21T15:10:52.473Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]e64/[REDACTED]e2a 200 Success
INFO  2021-08-21T15:10:52.474Z Setting sealedSender to ENABLED for conversation [REDACTED]e64 ([REDACTED]3eb)
INFO  2021-08-21T15:10:52.475Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]636/[REDACTED]718 200 Success
INFO  2021-08-21T15:10:52.475Z Setting sealedSender to ENABLED for conversation [REDACTED]636 ([REDACTED]760)
INFO  2021-08-21T15:10:52.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]78c/[REDACTED]426 200 Success
INFO  2021-08-21T15:10:52.476Z Setting sealedSender to ENABLED for conversation [REDACTED]78c ([REDACTED]621)
INFO  2021-08-21T15:10:52.476Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d4d/[REDACTED]c84 200 Success
INFO  2021-08-21T15:10:52.477Z Setting sealedSender to ENABLED for conversation [REDACTED]d4d ([REDACTED]147)
INFO  2021-08-21T15:10:52.477Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]966/[REDACTED]bcd 200 Success
INFO  2021-08-21T15:10:52.478Z Setting sealedSender to ENABLED for conversation [REDACTED]966 ([REDACTED]4fe)
INFO  2021-08-21T15:10:52.478Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]cee/[REDACTED]754 200 Success
INFO  2021-08-21T15:10:52.478Z Setting sealedSender to ENABLED for conversation [REDACTED]cee ([REDACTED]7a1)
INFO  2021-08-21T15:10:52.479Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d4b/[REDACTED]bb8 200 Success
INFO  2021-08-21T15:10:52.479Z Setting sealedSender to ENABLED for conversation [REDACTED]d4b ([REDACTED]3a7)
INFO  2021-08-21T15:10:52.480Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]c31/[REDACTED]cb9 200 Success
INFO  2021-08-21T15:10:52.480Z Setting sealedSender to ENABLED for conversation [REDACTED]c31 ([REDACTED]704)
INFO  2021-08-21T15:10:52.481Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]d50/[REDACTED]de4 200 Success
INFO  2021-08-21T15:10:52.481Z Setting sealedSender to ENABLED for conversation [REDACTED]d50 ([REDACTED]7c3)
INFO  2021-08-21T15:10:52.482Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]50a/[REDACTED]75c 200 Success
INFO  2021-08-21T15:10:52.482Z Setting sealedSender to ENABLED for conversation [REDACTED]50a ([REDACTED]dba)
INFO  2021-08-21T15:10:52.483Z GET https://cdn.signal.org/[REDACTED]LOA 200 Success
INFO  2021-08-21T15:10:52.485Z GET https://cdn.signal.org/[REDACTED]eOQ 200 Success
INFO  2021-08-21T15:10:52.490Z changedConvoBatcher: deduped 13 into 13
INFO  2021-08-21T15:10:52.491Z GET https://cdn.signal.org/[REDACTED]CgA
INFO  2021-08-21T15:10:52.492Z GET https://cdn.signal.org/[REDACTED]_LQ
INFO  2021-08-21T15:10:52.498Z changedConvoBatcher: deduped 3 into 3
INFO  2021-08-21T15:10:52.512Z GET https://cdn.signal.org/[REDACTED]cnA
INFO  2021-08-21T15:10:52.513Z GET https://cdn.signal.org/[REDACTED]I2Q
INFO  2021-08-21T15:10:52.514Z GET https://cdn.signal.org/[REDACTED]3LQ
INFO  2021-08-21T15:10:52.516Z GET https://cdn.signal.org/[REDACTED]ecw
INFO  2021-08-21T15:10:52.517Z GET https://cdn.signal.org/[REDACTED]GUQ
INFO  2021-08-21T15:10:52.522Z GET https://cdn.signal.org/[REDACTED]sdw 200 Success
INFO  2021-08-21T15:10:52.524Z GET https://cdn.signal.org/[REDACTED]6Tg
INFO  2021-08-21T15:10:52.525Z changedConvoBatcher: deduped 5 into 5
INFO  2021-08-21T15:10:52.528Z GET https://cdn.signal.org/[REDACTED]h3w
INFO  2021-08-21T15:10:52.529Z GET https://cdn.signal.org/[REDACTED]Z4w
INFO  2021-08-21T15:10:52.532Z GET https://cdn.signal.org/[REDACTED]Baw
INFO  2021-08-21T15:10:52.536Z changedConvoBatcher: deduped 6 into 6
INFO  2021-08-21T15:10:52.536Z GET https://cdn.signal.org/[REDACTED]SnQ
INFO  2021-08-21T15:10:52.538Z GET https://cdn.signal.org/[REDACTED]yAg
INFO  2021-08-21T15:10:52.541Z GET https://cdn.signal.org/[REDACTED]JrQ 200 Success
INFO  2021-08-21T15:10:52.542Z GET https://cdn.signal.org/[REDACTED]VjA
INFO  2021-08-21T15:10:52.543Z GET https://cdn.signal.org/[REDACTED]4EQ
INFO  2021-08-21T15:10:52.544Z GET https://cdn.signal.org/[REDACTED]15A
INFO  2021-08-21T15:10:52.547Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]a5a 200 Success
INFO  2021-08-21T15:10:52.547Z PUT https://textsecure-service.whispersystems.org/v1/messages/[REDACTED]611 200 Success
INFO  2021-08-21T15:10:52.548Z GET https://textsecure-service.whispersystems.org/v1/profile/[REDACTED]562/[REDACTED]dbb 200 Success
INFO  2021-08-21T15:10:52.548Z Setting sealedSender to ENABLED for conversation [REDACTED]562 ([REDACTED]687)
INFO  2021-08-21T15:10:52.549Z markConversationRead {"conversationId":"[REDACTED]874","newestUnreadId":1629370520793,"unreadMessages":0,"unreadReactions":0}
INFO  2021-08-21T15:10:52.550Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:52.562Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.567Z GET https://cdn.signal.org/[REDACTED]FLA
INFO  2021-08-21T15:10:52.573Z GET https://cdn.signal.org/[REDACTED]f2w 200 Success
INFO  2021-08-21T15:10:52.594Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:52.629Z GET https://cdn.signal.org/[REDACTED]lcw 200 Success
INFO  2021-08-21T15:10:52.635Z GET https://cdn.signal.org/[REDACTED]VjA 200 Success
INFO  2021-08-21T15:10:52.658Z GET https://cdn.signal.org/[REDACTED]6Tg 200 Success
INFO  2021-08-21T15:10:52.667Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.693Z GET https://cdn.signal.org/[REDACTED]CgA 200 Success
INFO  2021-08-21T15:10:52.694Z GET https://cdn.signal.org/[REDACTED]_LQ 200 Success
INFO  2021-08-21T15:10:52.702Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:52.713Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:52.753Z GET https://cdn.signal.org/[REDACTED]RVw 200 Success
INFO  2021-08-21T15:10:52.756Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.790Z GET https://cdn.signal.org/[REDACTED]g0w 200 Success
INFO  2021-08-21T15:10:52.796Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.829Z GET https://cdn.signal.org/[REDACTED]3LQ 200 Success
INFO  2021-08-21T15:10:52.833Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.872Z GET https://cdn.signal.org/[REDACTED]Z4w 200 Success
INFO  2021-08-21T15:10:52.876Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.885Z GET https://cdn.signal.org/[REDACTED]AKw 200 Success
INFO  2021-08-21T15:10:52.888Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.918Z GET https://cdn.signal.org/[REDACTED]ecw 200 Success
INFO  2021-08-21T15:10:52.926Z GET https://cdn.signal.org/[REDACTED]PpA 200 Success
INFO  2021-08-21T15:10:52.929Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.936Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.973Z GET https://cdn.signal.org/[REDACTED]15A 200 Success
INFO  2021-08-21T15:10:52.981Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:52.982Z GET https://cdn.signal.org/[REDACTED]h3w 200 Success
INFO  2021-08-21T15:10:52.994Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.005Z GET https://cdn.signal.org/[REDACTED]SnQ 200 Success
INFO  2021-08-21T15:10:53.011Z GET https://cdn.signal.org/[REDACTED]Baw 200 Success
INFO  2021-08-21T15:10:53.015Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.024Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.030Z markConversationRead {"conversationId":"[REDACTED]874","newestUnreadId":1629370520793,"unreadMessages":0,"unreadReactions":0}
INFO  2021-08-21T15:10:53.032Z GET https://cdn.signal.org/[REDACTED]4EQ 200 Success
INFO  2021-08-21T15:10:53.035Z GET https://cdn.signal.org/[REDACTED]B0w 200 Success
INFO  2021-08-21T15:10:53.040Z GET https://cdn.signal.org/[REDACTED]GUQ 200 Success
INFO  2021-08-21T15:10:53.043Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.048Z changedConvoBatcher: deduped 2 into 2
INFO  2021-08-21T15:10:53.064Z GET https://cdn.signal.org/[REDACTED]FLA 200 Success
INFO  2021-08-21T15:10:53.080Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.082Z GET https://cdn.signal.org/[REDACTED]yAg 200 Success
INFO  2021-08-21T15:10:53.088Z GET https://cdn.signal.org/[REDACTED]cnA 200 Success
INFO  2021-08-21T15:10:53.090Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.098Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.133Z GET https://cdn.signal.org/[REDACTED]I2Q 200 Success
INFO  2021-08-21T15:10:53.147Z changedConvoBatcher: deduped 1 into 1
INFO  2021-08-21T15:10:53.583Z attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO  2021-08-21T15:10:53.589Z checkExpiringMessages: checking for expiring messages
INFO  2021-08-21T15:10:53.592Z checkExpiringMessages: found no messages to expire
INFO  2021-08-21T15:10:53.595Z System tray service: setting unread count to 0
INFO  2021-08-21T15:10:53.595Z System tray service: rendering no tray
INFO  2021-08-21T15:10:55.541Z Background migration complete. Stopping idle detector.
INFO  2021-08-21T15:10:55.541Z Stop idle detector
INFO  2021-08-21T15:10:56.590Z ts/sql/main: slow query searchMessages duration=76ms
INFO  2021-08-21T15:10:56.990Z ts/sql/main: slow query searchMessages duration=118ms
INFO  2021-08-21T15:10:57.702Z ts/sql/main: slow query searchMessages duration=58ms
INFO  2021-08-21T15:11:31.370Z Removing notification
INFO  2021-08-21T15:11:32.378Z Not updating notifications; notification status is noNotifications. 
INFO  2021-08-21T15:11:47.333Z WebSocketResources: Sending a keepalive message

complete logs:
https://debuglogs.org/60974014ee8aed91149385b1b99463f2ed0404f0774b4c38b77b39d91c53683b.gz

@wohltat wohltat reopened this Aug 22, 2021
@stale stale bot removed the stale label Sep 9, 2022
@diaasami
Copy link

diaasami commented Sep 9, 2022

I'm running signal-desktop 5.54.0 and I would say the issue seems to be resolved for me, thank you :)

@wohltat
Copy link
Author

wohltat commented Oct 16, 2022

not solved for me on version v5.62.0 (linux Mint)

image

Clean start. No open chats. No open windows.


Platform Info

Signal Version:
v5.62.0

Operating System:
No LSB modules are available.
Distributor ID: Linuxmint
Description: Linux Mint 20.1
Release: 20.1
Codename: ulyssa
Linux 5.4.0-126-generic #142-Ubuntu SMP Fri Aug 26 12:12:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Linked Device Version:
Signal (Android): 5.52.5

@habbbe
Copy link

habbbe commented Nov 1, 2022

Adding my discovery to this issue:

I get a much lower idle CPU usage on version 5.60.0, but if I update to 5.61.1 I start getting around 5% CPU when idling, so something seems to have changed between these two versions. If I switch between these two versions the problem appears/disappears. 5.62.0 also exhibits the same problem.

I'm running:
Arch Linux
Linux 6.0.6-arch1-1 #1 SMP PREEMPT_DYNAMIC Sat, 29 Oct 2022 14:08:39 +0000 x86_64 GNU/Linux

@xlsigned
Copy link

xlsigned commented Nov 10, 2022

I'm currently (5.62.0) seeing 5% cpu usage on debian bullseye when idle (minimized).
But my feeling is that the actual cause is somewhere deep in electron ... or in other words: There is little hope unless signal gets rid of this monster.

Updated to 5.63.1: Now at <= 1% cpu usage when idle (minimized)
Maybe the electron update to 20.3.4 in 5.63.0 did something good ...

@dodiak
Copy link

dodiak commented Nov 10, 2022 via email

@scottnonnenberg-signal
Copy link
Contributor

@xlsigned I'm glad to hear that 5.63.1 improved things for you!

@wohltat @habbbe @dodiak What are you seeing on the latest builds? Would you be interested in providing debug logs, devtools performance traces, or maybe system-level traces so we can get to the bottom of your issues?

@habbbe
Copy link

habbbe commented Nov 12, 2022

@scottnonnenberg-signal:
Unfortunately 5.63.1 doesn't improve things on my end.

Here is a debug log from 5.60.0 (where I don't have the issue): https://debuglogs.org/desktop/5.60.0/1760593d7adc53c5f910960c53168f421ccff47ded99edd6995350095be37946.gz

And from 5.63.1 (where I have the issue): https://debuglogs.org/desktop/5.63.1/c1577ecea8b6dafb6fed9fe752ba59422d60da38b65c859f7bd9236b61444d84.gz

strace summaries (using strace --summary-only signal-desktop for exactly 60 seconds for each version).
These are run on freshly linked signal-desktop instances, so no conversations were present in the list, and no
messages were received while getting the traces.

strace for 5.60.0:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 26.83    0.069925          33      2060           poll
 21.59    0.056265       11253         5           wait4
 18.01    0.046928           8      5330       457 futex
  6.62    0.017250           3      5142      4944 recvmsg
  5.46    0.014230           5      2839           mprotect
  4.51    0.011753           8      1441           madvise
  2.44    0.006362           4      1511        11 statx
  2.30    0.005994           4      1408           read
  2.25    0.005863          22       265           gettid
  1.87    0.004870          12       393           write
  1.36    0.003549           6       558           mmap
  1.12    0.002911           4       631       217 openat
  0.92    0.002388           4       535           getrandom
  0.86    0.002239           4       551           epoll_wait
  0.74    0.001940          10       180           sendto
  0.51    0.001331           1       770           pread64
  0.44    0.001141           6       175           writev
  0.33    0.000869           2       406           close
  0.31    0.000804           3       236        34 newfstatat
  0.25    0.000652           1       373        64 access
  0.24    0.000621         124         5           clone
  0.12    0.000307           9        31           munmap
  0.12    0.000300           3        94           fstat
  0.11    0.000285          20        14           fallocate
  0.09    0.000236           6        38           lseek
  0.09    0.000231           1       192       117 readlink
  0.09    0.000222           1       185         8 stat
  0.08    0.000207           7        29           clone3
  0.07    0.000184           2        80           getpid
  0.04    0.000115          57         2           statfs
  0.04    0.000097           2        42           fcntl
  0.03    0.000086           4        20           fadvise64
  0.03    0.000079           1        46           fstatfs
  0.03    0.000069           0        72           rt_sigprocmask
  0.02    0.000042           3        11           sendmsg
  0.01    0.000038           2        16         2 unlink
  0.01    0.000031           2        12           getdents64
  0.01    0.000026           0        36           uname
  0.01    0.000022           1        14           ftruncate
  0.01    0.000019           9         2           inotify_add_watch
  0.01    0.000015           3         5           connect
  0.01    0.000015           1         8           eventfd2
  0.00    0.000012           1         7           socket
  0.00    0.000012           1         7           socketpair
  0.00    0.000011          11         1           inotify_init1
  0.00    0.000010           5         2         1 mkdir
  0.00    0.000009           4         2           sysinfo
  0.00    0.000008           0        14           prlimit64
  0.00    0.000007           0        26         2 ioctl
  0.00    0.000007           2         3           umask
  0.00    0.000007           3         2           clock_gettime
  0.00    0.000007           1         6           pipe2
  0.00    0.000004           0         7         4 prctl
  0.00    0.000004           2         2           epoll_create1
  0.00    0.000003           0        10           dup
  0.00    0.000002           0        23           rt_sigaction
  0.00    0.000002           1         2         1 arch_prctl
  0.00    0.000002           2         1           set_tid_address
  0.00    0.000002           0         3           epoll_ctl
  0.00    0.000002           2         1           set_robust_list
  0.00    0.000002           2         1           rseq
  0.00    0.000001           0         4           getsockname
  0.00    0.000001           0         9           getgid
  0.00    0.000001           1         1           epoll_create
  0.00    0.000001           1         1           clock_nanosleep
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         2           rt_sigreturn
  0.00    0.000000           0        17         1 recvfrom
  0.00    0.000000           0         2           shutdown
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         1           listen
  0.00    0.000000           0         2           getpeername
  0.00    0.000000           0         2           setsockopt
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         4           symlink
  0.00    0.000000           0        10           getuid
  0.00    0.000000           0        11           geteuid
  0.00    0.000000           0         9           getegid
  0.00    0.000000           0         4           getresuid
  0.00    0.000000           0         4           getresgid
  0.00    0.000000           0         1           getpriority
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0         2           dup3
  0.00    0.000000           0         1           sched_setattr
  0.00    0.000000           0         1           sched_getattr
  0.00    0.000000           0         1         1 pkey_alloc
------ ----------- ----------- --------- --------- ------------------
100.00    0.260628          10     25977      5864 total
strace for 5.63.1
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 27.08    0.100824           5     19991       493 futex
 24.88    0.092637          30      2992           poll
 14.95    0.055651       11130         5           wait4
  8.54    0.031787           4      6767      6570 recvmsg
  4.69    0.017465           5      3261           mprotect
  2.91    0.010839          19       563           getrandom
  2.74    0.010201           3      2998           read
  2.37    0.008836           5      1515           madvise
  1.91    0.007097           4      1524        11 statx
  1.64    0.006095           3      1913           write
  1.32    0.004908           8       572           mmap
  1.03    0.003829          21       177           writev
  1.01    0.003756          14       262           sendto
  0.75    0.002789         464         6           pipe2
  0.66    0.002460           3       659       217 openat
  0.61    0.002282         456         5           clone
  0.52    0.001944           0      1955           epoll_wait
  0.51    0.001895         105        18           fallocate
  0.28    0.001045          33        31           clone3
  0.23    0.000869           1       438           close
  0.21    0.000780           3       242        34 newfstatat
  0.17    0.000646           8        76           rt_sigprocmask
  0.17    0.000638           0       890           pread64
  0.13    0.000472          16        29           munmap
  0.12    0.000449           1       264           gettid
  0.11    0.000420           3       134           fstat
  0.08    0.000293          10        29           sendmsg
  0.05    0.000188           0       374        64 access
  0.05    0.000168           4        42           lseek
  0.04    0.000155           7        20         2 unlink
  0.04    0.000132           0       192       117 readlink
  0.03    0.000114           2        53           fcntl
  0.03    0.000100           1        87           getpid
  0.02    0.000089           4        18           ftruncate
  0.02    0.000077          11         7           socketpair
  0.02    0.000065           5        11           geteuid
  0.01    0.000052           1        36           uname
  0.01    0.000046           0       185         8 stat
  0.01    0.000029           1        23           rt_sigaction
  0.01    0.000027          13         2           statfs
  0.01    0.000026           2        12           getdents64
  0.00    0.000015           2         7         4 prctl
  0.00    0.000015           0        20           fadvise64
  0.00    0.000015           1        14           prlimit64
  0.00    0.000013           6         2           inotify_add_watch
  0.00    0.000010           0        34           recvfrom
  0.00    0.000009           0        46           fstatfs
  0.00    0.000009           9         1           inotify_init1
  0.00    0.000007           1         4           dup
  0.00    0.000006           3         2           setsockopt
  0.00    0.000006           2         3           epoll_ctl
  0.00    0.000005           2         2           shutdown
  0.00    0.000005           5         1           getpriority
  0.00    0.000004           0         5           connect
  0.00    0.000004           0        13           getuid
  0.00    0.000004           0         9           getgid
  0.00    0.000004           1         4           getresuid
  0.00    0.000004           1         4           getresgid
  0.00    0.000003           0         7           socket
  0.00    0.000003           3         1           epoll_create
  0.00    0.000003           3         1           clock_nanosleep
  0.00    0.000003           0         8           eventfd2
  0.00    0.000002           1         2           sysinfo
  0.00    0.000002           1         2           epoll_create1
  0.00    0.000001           0         2           rt_sigreturn
  0.00    0.000001           0         3         2 mkdir
  0.00    0.000001           0         2         1 arch_prctl
  0.00    0.000001           1         1           set_tid_address
  0.00    0.000001           1         1           set_robust_list
  0.00    0.000001           1         1           sched_setattr
  0.00    0.000001           1         1         1 pkey_alloc
  0.00    0.000001           1         1           rseq
  0.00    0.000000           0         1           brk
  0.00    0.000000           0        26         2 ioctl
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         1           listen
  0.00    0.000000           0         4           getsockname
  0.00    0.000000           0         2           getpeername
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         4           symlink
  0.00    0.000000           0         3           umask
  0.00    0.000000           0         9           getegid
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0         2           clock_gettime
  0.00    0.000000           0         2           dup3
  0.00    0.000000           0         1           sched_getattr
------ ----------- ----------- --------- --------- ------------------
100.00    0.372334           7     48641      7526 total

The futex syscall seems to be an obvious outlier.

Let me know if there is any other specific information I can provide!

@serakeri
Copy link

serakeri commented Nov 14, 2022

So is this an Electron 'disease'? I also see the Discord and Teams apps jumping into the CPU top 5 every now and then with ALL windows closed here on Windows 10.

I'm seeing a similar problem with Electron apps. On macOS the process "Signal Helper (Renderer)" idles at 3% with all windows closed and "Discord Helper (Renderer)" also idles at 3% with all windows closed.

edit: This was observed on macOS 11.7.1 using Signal 5.63.1

I tried building Signal with the latest versions of Electron 21.3.0 and 22.0.0-beta.6 but the issue was still there. However I am not seeing this issue when using the electron app "Electron Fiddle". The "Electron Fiddle Helper (Renderer)" idles at 0% with the window open, but I'm not certain if the issue is with a part of electron or with how it is being used.

@indutny-signal
Copy link
Contributor

@habbbe we just released a new beta version (v6.0.0-beta.1). Could you try installing it and running the binary with --enable-gpu flag? I'm hoping that it might improve idle CPU usage for you. Please let me know if not!

@habbbe
Copy link

habbbe commented Nov 25, 2022

@indutny-signal I tried the v6.0.0-beta.2, but it still gave me the same idle CPU usage. Adding or removing the --enable-gpu flag did not change the outcome.

@therentabrain
Copy link

therentabrain commented Dec 7, 2022

I don't know whether this is for sure related, but I err on the side of not opening a new issue :)
I am using 6.0.1 on Windows 10 with a very nice Ryzen 9 processor and lots of RAM etc.
Correct me if I'm wrong, but prior to 6.x, I think Signal only ran one Signal.exe process.
Now it seems to run five of them. Some are below normal priority, I think one is normal, and one is Above normal.
(I see Zoom doing the same sort of thing; is there a common reason?)

If I leave the priorities set that way, the rest of my system slows down a little. But more importantly, my OBS, which is often running a stream for a large audience with an Above Normal priority single process, begins to glitch.

Even with Signal totally idle, nothing really happening, my livestream begins to choke up and I am dropping hundreds of frames. CPU usage still shows as under 10%, and resource meters show everything I can think of is 2%-50% utilized; nothing above that. OBS is set to use a different GPU than Signal for rendering, but nonetheless, rendering is stuttery.

I find if I then do this:
wmic process where name="signal.exe" call setpriority "64"
The problem totally goes away.
(That command sets all Signal.exe processes to Low priority.)

After that, OBS works perfectly, 0 dropped frames, and Signal seems totally responsive and perfectly usable for sending/receiving texts. No perceivable difference in performance, but OBS is now happy.

What in the living.

Thanks, by the way. I do love Signal and use it all the time.

@lnicola
Copy link

lnicola commented Dec 7, 2022

Correct me if I'm wrong, but prior to 6.x, I think Signal only ran one Signal.exe process.

It didn't. This is usual for Chromium and Electron apps, and not something bad in itself.

@therentabrain
Copy link

I guess I never noticed. Thanks for the correction :)

@dodiak
Copy link

dodiak commented Dec 9, 2022 via email

@mac-linux-free
Copy link

This is somehow solved for me. Version 6.0.1 just 3-4% idle.

@dodiak
Copy link

dodiak commented Dec 9, 2022 via email

@habbbe
Copy link

habbbe commented Dec 18, 2022

Just reporting in that I'm still seeing 4-6% CPU when idle with 6.1.0.

@indutny-signal
Copy link
Contributor

This is still on our radar and we are trying to figure out what's going on. If y'all could send additional debug logs, that'd be very appreciated!

Could anyone on this thread try running profiler on it? I think perf is the recommended tool for it nowadays?

If someone here is on macOS - could you try profiling it using CPU Profiler in the Instruments.app that comes with Xcode?

Sorry, I know I'm asking for lots of details, but what we need to make progress on this is information!

Thanks!

@janvlug
Copy link

janvlug commented Feb 10, 2023

See also issue #4459.

@habbbe
Copy link

habbbe commented Mar 7, 2023

I can report that I'm seeing very low CPU usage (0-0.5%) when idling now. I could only test this back to 6.6.0, but the same is true for 6.8.0.

For me this seems to be solved!

@Ra72xx
Copy link

Ra72xx commented Mar 7, 2023

Same here, Ubuntu 22.10. Very low CPU usage now.

@sylv-io
Copy link

sylv-io commented Mar 7, 2023

Same here on Arch Linux.

@chronos000
Copy link

Same here. Low CPU usage (less than 1%, where I could see more than 10% before)
Pop!_OS 22.04
Signal 6.7.0, installed via flatpak

@scottnonnenberg-signal
Copy link
Contributor

Thanks for all your reports, everyone. I'm going to close this.

Future folks: Please enter a new bug if you see this behavior again.

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

No branches or pull requests