signalapp / Signal-Desktop

A private messenger for Windows, macOS, and Linux.
https://signal.org/download
GNU Affero General Public License v3.0
14.54k stars 2.64k forks source link

unreasonably high CPU usage when idling #5444

Closed wohltat closed 1 year ago

wohltat commented 3 years ago

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 commented 3 years ago

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

wohltat commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

Can you add a debug log?

wohltat commented 3 years ago

This is the debug log: https://debuglogs.org/893b0931083dc697fff52a7f318051f736c3832ab34a8cb2f539aa7ae734a378.gz

josh-signal commented 3 years ago

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

wohltat commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

Hah, very interesting. Could you post your debug log or send it over email to me (indutny@signal.org)?

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

indutny-signal commented 3 years ago

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

indutny-signal commented 3 years ago

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

wohltat commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

Happens for me too, Drains battery a lot

indutny-signal commented 3 years ago

@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 commented 3 years ago

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

chmike commented 3 years ago

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 commented 3 years ago

@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 commented 3 years ago

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 commented 3 years ago

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

scottnonnenberg-signal commented 3 years ago

What would you do if if this would happen on you computer?

I'd use the dev tools profiler. If you start Signal Desktop with --enable-dev-tools you can open it up and see what's using resources. Open the 'Performance' tab, uncheck 'screenshots' and then hit the circle button. Then let the app go idle, not opening anything. Come back after a couple minutes, then send the resultant trace to us. Feel free to send it to me directly. That'd give us a good baseline for what's happening in the background on your machine.

chmike commented 3 years ago

When I try to start signal on the command line with --enable-dev-tools, this is what I get:

$ signal-desktop --enable-dev-tools
NODE_ENV production
NODE_CONFIG_DIR /snap/signal-desktop/370/opt/Signal/resources/app.asar/config
NODE_CONFIG {}
ALLOW_CONFIG_MUTATIONS undefined
HOSTNAME undefined
NODE_APP_INSTANCE undefined
SUPPRESS_NO_CONFIG_WARNING undefined
SIGNAL_ENABLE_HTTP undefined
userData: /home/meessen/snap/signal-desktop/370/.config/Signal
config/get: Successfully read user config file
Set Windows Application User Model ID (AUMID) { appUserModelId: 'org.whispersystems.signal-desktop' }
x-attr dependency did not load successfully
config/get: Successfully read ephemeral config file
making app single instance
quitting; we are the second instance
Erreur de segmentation (core dumped)

The signal app in the tray is started though.

wohltat commented 3 years ago

@scottnonnenberg @indutny-signal I sent you the signal profiler logs. Those are two files corresponding two the states of either low or high cpu usage that you can see in my previous plots. Thanks for the hint to the dev-tools. Looks like a very nice and powerful tool.

I don't know the inner workings of signal but there are some things that look very suspicious to me: There are, besides some other stuff, two periodic events that occur most of the time.

ringrtc/Service.js:149: roughly 0.5ms every 50ms preload.bundle.js: roughly 0.3ms every 100ms

First question. Is it really necessary to run these events that frequently, 10Hz and 20Hz? Furthermore, do these functions really do that much. On the processor 1ms is like millions of operations. Sounds quite a lot to check if new messages have arrived. As far as i understand the RTC is for RealTimeCommunication. But when idling there is no real time communication like voice or video, correct? The RIngRTC service looks the most suspicious. One thing is that when i read "pollEvery" i think of polling as a great way to burn CPU resources. Second thing, why is there a "timer install" every 50ms? The timer id also increments by 1 every time. Doesn't look right to me to create a timer every 50ms.

So far i haven't found what is the difference between low and high cpu usage stat though. Before i started the recording and after stopping the cpu usage was high. But i can't say for sure if it was while the recording since i could not separate the dev-tools profiler usage from the rest, i.e. both is a signal-desktop process.

wohltat commented 3 years ago

if you want i can also try some development versions. I know how to handle git and how to compile stuff if this makes it easier for you.

wohltat commented 3 years ago

@chmike i guess there is an other instance running already. Try closing all signal-desktop processes before.

quitting; we are the second instance
Erreur de segmentation (core dumped)
chmike commented 3 years ago

I managed to run with the development panel. But the CPU monitoring is not accurate. With top I see one process using 10% CPU. There are currently 9 signal-desktop processes, but only one uses 10% cpu. It has now raised to 16% after measuring performances.

This is the process that burns CPU: 9671 9535 18 09:31 pts/3 00:10:31 /snap/signal-desktop/370/opt/Signal/signal-desktop --type=renderer --no-sandbox --field-trial-handle=12894220524609743222,11113728715403340456,131072 --disable-features=CookiesWithoutSameSiteMustBeSecure,SameSiteByDefaultCookies,SpareRendererForSitePerProcess --lang=fr --app-path=/snap/signal-desktop/370/opt/Signal/resources/app.asar --no-sandbox --no-zygote --num-raster-threads=2 --enable-main-frame-before-activation --renderer-client-id=5 --no-v8-untrusted-code-mitigations --shared-files=v8_context_snapshot_data:100 I don't understand why signal needs that many processes.

wohltat commented 3 years ago

@chmike i also have 9 processes with different types:

More on zygote here Maybe that helps a bit to understand why are there so many. But i dont know what the zygote processes are doing.

wohltat commented 3 years ago

@chmike also on my machine its the renderer process and and less the gpu process that is using most cpu time.

I guess this is the place for potential improvement since there should not be too much to render with a minimized app.

nickma82 commented 3 years ago

Maybe related to #5127

wohltat commented 3 years ago

What we need is more information from you - we need you to be scientists.

scientific enough?

sgebbie commented 2 years ago

I have regularly experienced a similar problem with signal-desktop. It ends up being a battery drain on a laptop, which is unfortunate.

Taking a look at strace didn't reveal much activity, other than timers. Which, for what it is work, implies that the behaviour is more user-land based:

Snippet from top show >20% CPU usage while signal-desktop should be idle:

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
198281 stewart   20   0   36.9g 246472 128616 S  21.1   1.5  18:00.13 signal-desktop 

The corresponding output from strace didn't show much:

clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=634689719}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=635234725}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=635743355}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=636054817}) = 0
gettimeofday({tv_sec=1635778054, tv_usec=201906}, {tz_minuteswest=0, tz_dsttime=0}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=636607698}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=636883577}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=637139954}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=637354790}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381412, tv_nsec=637568043}) = 0
futex(0x7ffd59efde58, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=381413, tv_nsec=632863043}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=633711139}) = 0
futex(0x7ffd59efde08, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=634445438}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=634690900}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=634932361}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=635216197}) = 0
gettimeofday({tv_sec=1635778055, tv_usec=201056}, {tz_minuteswest=0, tz_dsttime=0}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=635757912}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=636016498}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=636199541}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=636369918}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381413, tv_nsec=636550587}) = 0
futex(0x7ffd59efde58, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=381414, tv_nsec=632758587}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=633430212}) = 0
futex(0x7ffd59efde08, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=633972635}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=634198929}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=634432015}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=634596308}) = 0
gettimeofday({tv_sec=1635778056, tv_usec=200378}, {tz_minuteswest=0, tz_dsttime=0}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=635017188}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=635250357}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=635566486}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=635816780}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381414, tv_nsec=636149951}) = 0
futex(0x7ffd59efde58, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=381415, tv_nsec=632870951}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=381415, tv_nsec=633408268}) = 0
futex(0x7ffd59efde08, FUTEX_WAKE_PRIVATE, 1) = 0

With the above pattern repeating.

Skimming back up through the posts on this issue, the above seems to correlate with the findings with ltrace mentioned in: https://github.com/signalapp/Signal-Desktop/issues/5444#issuecomment-903029913, in terms of calls to clock_gettime. But, again, the rate of calls is not unreasonable and would not account for the high CPU loss or indicate a tightly loop that should be polling etc.

But, it would be nice to get to the bottom of this as it does detract from the day-to-day usage of, an otherwise, good application.

EvanHahn-Signal commented 2 years ago

@sgebbie Thanks for this investigation. We're still stumped, but this is helpful.

sgebbie commented 2 years ago

As another experiment, if another user starts typing the signal-desktop shows the "typing" ellipses....

image

Whenever this happens, I can correlate this with an increase in CPU usage from the reasonable idle state of 1% up to ~5% (and once up to 6%). But, once the ellipse animation stops, the CPU usage also falls back down to a more reasonable 1%.

But this does not trigger the long running higher CPU usage.

kaimast commented 2 years ago

Maybe close this issue in favor of #4459 ?

felix-engelmann commented 2 years ago

@kaimast after reading #4459 it looks like a different issue. Their issue is resolvable by not showing animations or minimizing the window. However this issue here persists even when no chat is selected, nothing is animation and the window is minimized. It does not seem to be related to the visualization.

dodiak commented 2 years ago

Same problem here. All the time about 20-22% of one core of my Debian running on i7-7600U CPU @ 2.80GHz

alien2003 commented 2 years ago

Reproduced on Arch Linux both on Desktop and mobile while just setting in tray and doing nothing. Both Beta and release affected

kaimast commented 2 years ago

Do you still see this with ozone enabled? --enable-features=UseOzonePlatform

I am on Arch as well and only see occasional spikes from 0% to 2% (like once a minute), when, I assume, it is checking for messages.

alien2003 commented 2 years ago

Do you still see this with ozone enabled? --enable-features=UseOzonePlatform

I am on Arch as well and only see occasional spikes from 0% to 2% (like once a minute), when, I assume, it is checking for messages.

The same with Ozone. It was 0% usage, I opened a chat with friend and minimized window to tray, now it just drains 7-8% doing nothing, not even rendering the window

UPD: 14-15% CPU now, doing nothing in background while sitting in tray. Electron is being electron

UPD: 54% in the morning after all the night just idling and doing nothing. That's ridiculous

alien2003 commented 2 years ago

Opening Signal window, selecting random chat, pressing Ctrl-Shift-C and minimazing Signal again helps, at least when Signal drains 7-8% CPU, it camls down after it. Not for a long time, for 1-2 minutes, after that, it starts doing electron things again

xadhatter commented 2 years ago

I am seeing the same issue. CPU usage ~10% when Signal is idle, more when in use. It creates a noticeable battery drain, to the point I now exit Signal when on battery. Please let me know if there is any additional information that would be helpful to diagnose.

Signal 5.26.1 Fedora Linux 35 Cinnamon 5.0.7 Kernel 5.15 AMD Ryzen 5 PRO 5650U

chronos000 commented 2 years ago

check out possible solution on this comment: https://github.com/signalapp/Signal-Desktop/issues/4459#issuecomment-1003053281

TL;DR: disable notifications in Signal's setting

otherwiseguy commented 2 years ago

I would be ecstatic to have ~10% CPU when idle. For me, it's currnetly like this:

1754222 twilson 20 0 26.3g 515540 249380 S 51.8 0.8 3360:43 signal-desktop

and I've seen it hover in the 70s when idle.

nagisa commented 2 years ago

I can reproduce this immediately after launch as well.

  1. Run signal, but don't select any chat;
  2. Monitor top/htop/etc – eventually signal will settle on low cpu usage;
  3. Select a chat;
  4. Monitor top/htop/etc – signal continuously consumes ~5% of CPU time.
    • Specifically it is the --type=renderer process.
  5. “Deselect” the chat as suggested by alien2003 above;
  6. Monitor top/htop/etc – eventually signal will settle.

So it looks like having signal with a chat contents showing is at least one of the causes here.

I'm using sway as my compositor and signal is placed on an workspace from which I've switch away. I have tried both --enable-features=UseOzonePlatform --ozone-platform=x11 and --enable-features=UseOzonePlatform --ozone-platform=wayland – both behave the same.

I've disabled the notifications as suggested two comments above – no difference.

The built-in chrome profiler reveals no interesting information, it shows ~12ms of busy time in a range of 10 seconds, clearly contradicting the system-wide metrics.

The following profile I did with perf for the offending --type=renderer process does look pretty interesting, though. Here I ran signal with a chat selected for ~30 seconds (high idle cpu use), and then deselected it (low idle cpu usage.) From the looks of it, mallinfo/node::GetEnvironmentIsolateData functions end up being called with significant frequency from the Compositor thread.

Does that help to narrow down the reason in any way?

VadimMuhtarov commented 2 years ago

I have the same problem. Idle wake-ups with closed window is almost equal to Skype wake-ups during video call. Screenshot