weixin_39761255
weixin_39761255
2020-12-26 02:40

ANR when starting app

  • Android version:9
  • Device: Fairphone 3
  • Delta Chat version: 1.6.2
  • Actual behavior: ANR, sometimes when starting DC, sometimes when opening the "Testing Delta Chat" group
  • Steps to reproduce the problem: No idea, it just happended with the stable (!) version of DC. I imported a backup some weeks ago (like #1205) but I did not have any problems since then. Also, I used another resource-intensive app right before trying to use DC.

I did not find anything interesting in the logs except Reason: executing service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService.

Any ideas? It's kinda sad that it happened with the stable version, so that I can't add some more debug logs specific for this problem when trying to fix this.

  • Logs:


2020-05-15 12:46:08.819 17096-17096/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:46:09.050 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3930...
2020-05-15 12:46:09.105 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:46:09.106 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:215: received message 3930 has Message-Id: Gr.MkHMTOtfNRM.PzC0oLeGtwB.net
2020-05-15 12:46:09.187 17096-17096/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:46:09.208 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:46:09.265 1012-3465/? I/ActivityManager: START u0 {cmp=chat.delta/org.thoughtcrime.securesms.ConversationActivity (has extras)} from uid 10127
2020-05-15 12:46:09.273 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3931...
2020-05-15 12:46:09.317 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:46:09.318 17096-17122/? I/DeltaChat: ThreadId(5) src/dc_receive_imf.rs:215: received message 3931 has Message-Id: Gr.MkHMTOtfNRM.Pe2Tynxl1H5.net
2020-05-15 12:46:09.324 17096-17096/? W/chat.delta: type=1400 audit(0.0:57914): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:46:09.344 17096-17096/? W/chat.delta: type=1400 audit(0.0:57915): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:46:09.374 17096-17096/? W/chat.delta: type=1400 audit(0.0:57916): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:46:09.505 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:112: INBOX-fetch done in 296 ms.
2020-05-15 12:46:09.505 17096-17121/? W/DeltaChat: ThreadId(6) src/job_thread.rs:93: connect+fetch failed: IMAP got error from elsewhere
2020-05-15 12:46:09.506 17096-17121/? I/DeltaChat: ThreadId(6) src/job.rs:708: INBOX-IDLE will not be started because of waiting jobs.
2020-05-15 12:46:09.506 17096-17121/? I/DeltaChat: ThreadId(6) src/job.rs:1027: dc_perform_inbox_jobs starting.
2020-05-15 12:46:09.507 17096-17121/? I/DeltaChat: ThreadId(6) src/job.rs:1034: dc_perform_inbox_jobs ended.
2020-05-15 12:46:09.507 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:46:09.626 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:112: INBOX-fetch done in 118 ms.
2020-05-15 12:46:09.626 17096-17121/? W/DeltaChat: ThreadId(6) src/job_thread.rs:90: connect+fetch failed: IMAP got error from elsewhere, reconnect & retry
2020-05-15 12:46:09.630 17096-17121/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:303: IMAP unsetup_handle step 2 (acquiring session.lock)
2020-05-15 12:46:09.755 17096-17121/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:314: IMAP unsetup_handle step 3 (clearing config).
2020-05-15 12:46:09.755 17096-17121/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:317: IMAP unsetup_handle step 4 (disconnected)
2020-05-15 12:46:10.252 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:46:10.543 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:112: INBOX-fetch done in 291 ms.
2020-05-15 12:46:10.544 17096-17121/? W/DeltaChat: ThreadId(6) src/job_thread.rs:93: connect+fetch failed: IMAP got error from elsewhere
2020-05-15 12:46:10.558 17096-17121/? I/DeltaChat: ThreadId(6) src/job_thread.rs:177: INBOX-IDLE started...
2020-05-15 12:46:10.663 17096-17121/? I/DeltaChat: ThreadId(6) src/imap/idle.rs:91: Idle entering wait-on-remote state
2020-05-15 12:46:55.303 1012-1120/? W/ActivityManager: Activity pause timeout for ActivityRecord{55cf19 u0 chat.delta/org.thoughtcrime.securesms.ConversationActivity t1643}
2020-05-15 12:46:58.088 1012-3919/? I/ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=chat.delta/org.thoughtcrime.securesms.RoutingActivity bnds=[52,926][174,1048]} from uid 10115
2020-05-15 12:47:05.646 1012-1120/? W/ActivityManager: Activity destroy timeout for ActivityRecord{fcabd35 u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1643 f}
2020-05-15 12:47:05.667 1012-1120/? W/ActivityManager: Activity destroy timeout for ActivityRecord{55cf19 u0 chat.delta/org.thoughtcrime.securesms.ConversationActivity t1643 f}
2020-05-15 12:47:15.665 1012-1120/? W/ActivityManager: Timeout executing service: ServiceRecord{99f01a0 u0 chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService}
2020-05-15 12:47:16.192 17096-17102/? I/chat.delta: Thread[3,tid=17102,WaitingInMainSignalCatcherLoop,Thread*=0x7531816400,peer=0x139c0020,"Signal Catcher"]: reacting to signal 3
2020-05-15 12:47:16.514 17096-17102/? I/chat.delta: Wrote stack traces to '[tombstoned]'
2020-05-15 12:47:20.802 1012-1120/? E/ActivityManager: ANR in chat.delta
    PID: 17096
    Reason: executing service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService
    Load: 3.41 / 3.96 / 4.2
    CPU usage from 0ms to 5083ms later (2020-05-15 12:47:15.666 to 2020-05-15 12:47:20.749):
      24% 1012/system_server: 13% user + 11% kernel / faults: 5494 minor 9 major
      15% 786/media.codec: 11% user + 4.5% kernel / faults: 11483 minor
      6.6% 1718/com.android.systemui: 4.3% user + 2.3% kernel / faults: 3320 minor 5 major
      6.1% 17096/chat.delta: 3.1% user + 2.9% kernel / faults: 4711 minor
      0.1% 723/media.extractor: 0% user + 0% kernel / faults: 4388 minor 67 major
      4.1% 983/adbd: 1.9% user + 2.1% kernel / faults: 26235 minor
      3.9% 15744/com.android.phone: 1.5% user + 2.3% kernel / faults: 1031 minor
      3.3% 16911/com.google.android.gms.persistent: 1.9% user + 1.3% kernel / faults: 1906 minor 36 major
      2.9% 14450/com.google.android.gms: 0.9% user + 1.9% kernel / faults: 1615 minor 1 major
      2.5% 2606/com.touchtype.swiftkey: 2.1% user + 0.3% kernel / faults: 1743 minor
      2.3% 3000/com.android.nfc: 1.9% user + 0.3% kernel / faults: 1007 minor 2 major
      0% 3021/com.qualcomm.qti.services.secureui:sui_service: 0% user + 0% kernel / faults: 976 minor
      1.7% 465/surfaceflinger: 0.7% user + 0.9% kernel / faults: 459 minor
      1.7% 1853/.dataservices: 1.3% user + 0.3% kernel / faults: 785 minor
      1.5% 592/android.hardware.sensors.0-service: 0.9% user + 0.5% kernel / faults: 124 minor
      0% 1873/com.qualcomm.qti.telephonyservice: 0% user + 0% kernel / faults: 742 minor
      1.3% 2571/sugov:0: 0% user + 1.3% kernel
      ...rest censored, but everything less than 1%
    14% TOTAL: 7.6% user + 6.2% kernel + 0.1% iowait + 0.3% irq + 0.1% softirq
    CPU usage from 84ms to 491ms later (2020-05-15 12:47:15.749 to 2020-
2020-05-15 12:47:34.540 1012-1131/? W/ActivityManager:   Force finishing activity chat.delta/org.thoughtcrime.securesms.RoutingActivity
2020-05-15 12:47:34.562 1012-1131/? I/ActivityManager: Killing 17096:chat.delta/u0a127 (adj 0): user request after error
2020-05-15 12:47:34.617 465-636/? W/SurfaceFlinger: Attempting to destroy on removed layer: e2bca5b Application Not Responding: chat.delta#0
2020-05-15 12:47:34.727 1012-5214/? W/ActivityManager: Scheduling restart of crashed service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService in 78128ms
2020-05-15 12:47:34.728 1012-5214/? W/ActivityManager: Scheduling restart of crashed service chat.delta/androidx.work.impl.background.systemjob.SystemJobService in 1000ms
2020-05-15 12:47:34.737 465-877/? W/SurfaceFlinger: Attempting to set client state on removed layer: Splash Screen chat.delta#0
2020-05-15 12:47:34.737 465-877/? W/SurfaceFlinger: Attempting to destroy on removed layer: Splash Screen chat.delta#0
2020-05-15 12:47:34.743 465-1549/? W/SurfaceFlinger: Attempting to destroy on removed layer: AppWindowToken{3985d7c token=Token{c015c6f ActivityRecord{712034e u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1644}}}#0
2020-05-15 12:47:34.810 1012-1118/? I/ActivityManager: Displayed chat.delta/org.thoughtcrime.securesms.RoutingActivity: +36s682ms
2020-05-15 12:47:37.543 1012-5214/? I/ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=chat.delta/org.thoughtcrime.securesms.RoutingActivity bnds=[52,926][174,1048]} from uid 10115
2020-05-15 12:47:37.572 1012-1120/? W/ActivityManager: Stopping service due to app idle: u0a127 -1m30s986ms chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService
2020-05-15 12:47:37.581 1012-1140/? I/ActivityManager: Start proc 17426:chat.delta/u0a127 for activity chat.delta/org.thoughtcrime.securesms.RoutingActivity
2020-05-15 12:47:37.588 17426-17426/? E/chat.delta: Not starting debugger since process cannot load the jdwp agent.
2020-05-15 12:47:37.680 17426-17426/? I/DeltaChat: ThreadId(4) src/sql.rs:923: Opened "/data/user/0/chat.delta/files/messenger.db".
2020-05-15 12:47:37.681 17426-17450/? I/DeltaChat: ###################### IMAP-Thread started. ######################
2020-05-15 12:47:37.682 17426-17451/? I/DeltaChat: ###################### MVBOX-Thread started. ######################
2020-05-15 12:47:37.682 17426-17452/? I/DeltaChat: ###################### SENTBOX-Thread started. ######################
2020-05-15 12:47:37.682 17426-17453/? I/DeltaChat: ###################### SMTP-Thread started. ######################
2020-05-15 12:47:37.683 17426-17450/? I/DeltaChat: ThreadId(5) src/job.rs:1027: dc_perform_inbox_jobs starting.
2020-05-15 12:47:37.684 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:789: SMTP-jobs started...
2020-05-15 12:47:37.684 17426-17451/? I/DeltaChat: ThreadId(6) src/job.rs:1038: dc_perform_mbox_jobs EMPTY (for now).
2020-05-15 12:47:37.686 17426-17452/? I/DeltaChat: ThreadId(8) src/job.rs:1042: dc_perform_sentbox_jobs EMPTY (for now).
2020-05-15 12:47:37.688 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:791: SMTP-jobs ended.
2020-05-15 12:47:37.688 17426-17450/? I/DeltaChat: ThreadId(5) src/job.rs:1034: dc_perform_inbox_jobs ended.
2020-05-15 12:47:37.689 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:802: SMTP-idle started...
2020-05-15 12:47:37.718 17426-17426/? I/DeltaChat: ThreadId(4) src/chat.rs:2467: device-message update1.6.0-h already added
2020-05-15 12:47:37.839 17426-17426/? I/DeltaChat: ++++++++++++++++++ Connected ++++++++++++++++++
2020-05-15 12:47:37.840 17426-17426/? I/DeltaChat: *** KeepAliveService.onCreate()
2020-05-15 12:47:37.840 17426-17486/? I/DeltaChat: calling maybeNetwork()
2020-05-15 12:47:37.840 17426-17486/? I/DeltaChat: ThreadId(14) src/job.rs:1294: Interrupting SMTP-idle...
2020-05-15 12:47:37.840 17426-17486/? I/DeltaChat: ThreadId(14) src/job.rs:1302: Interrupting SMTP-idle... ended
2020-05-15 12:47:37.840 17426-17486/? I/DeltaChat: ThreadId(14) src/job.rs:744: interrupt_inbox_idle called
2020-05-15 12:47:37.840 17426-17486/? W/DeltaChat: ThreadId(14) src/job.rs:755: could not interrupt idle: try_lock failed because the operation would block
2020-05-15 12:47:37.840 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:831: SMTP-idle ended.
2020-05-15 12:47:37.841 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:789: SMTP-jobs started...
2020-05-15 12:47:37.841 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:791: SMTP-jobs ended.
2020-05-15 12:47:37.842 17426-17453/? I/DeltaChat: ThreadId(7) src/job.rs:802: SMTP-idle started...
2020-05-15 12:47:37.843 17426-17426/? I/DeltaChat: *** KeepAliveService.onStartCommand()
2020-05-15 12:47:37.919 17426-17426/? I/chatty: uid=10127(chat.delta) identical 3 lines
2020-05-15 12:47:38.009 1012-1118/? I/ActivityManager: Displayed chat.delta/org.thoughtcrime.securesms.RoutingActivity: +454ms
2020-05-15 12:47:38.013 465-1549/? W/SurfaceFlinger: Attempting to set client state on removed layer: Splash Screen chat.delta#0
2020-05-15 12:47:38.013 465-1549/? W/SurfaceFlinger: Attempting to destroy on removed layer: Splash Screen chat.delta#0
2020-05-15 12:47:38.047 17426-17426/? I/chatty: uid=10127(chat.delta) identical 6 lines
2020-05-15 12:47:38.087 17426-17501/? I/DeltaChat: -------------------- FetchWorker.doWork() started --------------------
2020-05-15 12:47:38.087 17426-17501/? I/DeltaChat: ThreadId(15) src/job.rs:744: interrupt_inbox_idle called
2020-05-15 12:47:38.087 17426-17501/? W/DeltaChat: ThreadId(15) src/job.rs:755: could not interrupt idle: try_lock failed because the operation would block
2020-05-15 12:47:38.136 17426-17451/? I/DeltaChat: ThreadId(6) src/job_thread.rs:105: MVBOX-fetch started...
2020-05-15 12:47:38.153 17426-17452/? I/DeltaChat: ThreadId(8) src/job_thread.rs:105: SENTBOX-fetch started...
2020-05-15 12:47:38.165 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:47:38.388 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Mr.9TaC4jAPeUh.tFE_mgRdJCv.de from "DeltaChat" by precheck.
2020-05-15 12:47:38.388 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Mr.iqIYCzg0IIk.moax0t1TkfL.de from "DeltaChat" by precheck.
2020-05-15 12:47:38.389 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Mr.HvSB61QRQ5P.vUkkgzLke6a.de from "DeltaChat" by precheck.
2020-05-15 12:47:38.389 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.Vy8NFVdi7Of.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.389 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.oduw8ojTuc-.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.389 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.UKJvB0ISkGt.de from "DeltaChat" by precheck.
2020-05-15 12:47:38.390 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.r9mSTI8aFKx.org from "DeltaChat" by precheck.
2020-05-15 12:47:38.390 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.Aj5_HebGBiY.org from "DeltaChat" by precheck.
2020-05-15 12:47:38.390 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.jbf78onQtEK.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.390 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.m5GYbmtrcDi.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.390 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.F3OMXY6Nn7c.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.391 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.J1If3_bDvx0.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.391 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.4uvfrJJKZXg.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.391 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.wSF5uXKEEp5.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.392 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.pRPDTPsCZ5u.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.392 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.DGiJi5IVSiE.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.392 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.-zjYevNKeaP.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.392 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.0VkBXQIGelo.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.392 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.g6kTHRGOBfo.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.393 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.PzC0oLeGtwB.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.393 17426-17451/? I/DeltaChat: ThreadId(6) src/imap/mod.rs:609: Skipping message Gr.MkHMTOtfNRM.Pe2Tynxl1H5.net from "DeltaChat" by precheck.
2020-05-15 12:47:38.430 17426-17452/? I/DeltaChat: ThreadId(8) src/imap/mod.rs:597: fetch_new_messages: ignoring uid 1039, last seen was 1039
2020-05-15 12:47:38.430 17426-17452/? I/DeltaChat: ThreadId(8) src/imap/mod.rs:662: 0 mails read from "Gesendet".
2020-05-15 12:47:38.430 17426-17452/? I/DeltaChat: ThreadId(8) src/job_thread.rs:112: SENTBOX-fetch done in 277 ms.
2020-05-15 12:47:38.431 17426-17452/? I/DeltaChat: ThreadId(8) src/job_thread.rs:177: SENTBOX-IDLE started...
2020-05-15 12:47:38.469 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:112: INBOX-fetch done in 303 ms.
2020-05-15 12:47:38.469 17426-17450/? W/DeltaChat: ThreadId(5) src/job_thread.rs:90: connect+fetch failed: IMAP got error from elsewhere, reconnect & retry
2020-05-15 12:47:38.471 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:303: IMAP unsetup_handle step 2 (acquiring session.lock)
2020-05-15 12:47:38.528 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3932...
2020-05-15 12:47:38.530 17426-17452/? I/DeltaChat: ThreadId(8) src/imap/idle.rs:91: Idle entering wait-on-remote state
2020-05-15 12:47:38.562 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:38.563 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3932 has Message-Id: Gr.MkHMTOtfNRM.DmtfLtvzp7L.de
2020-05-15 12:47:38.577 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:314: IMAP unsetup_handle step 3 (clearing config).
2020-05-15 12:47:38.577 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:317: IMAP unsetup_handle step 4 (disconnected)
2020-05-15 12:47:38.623 17426-17426/? I/chatty: uid=10127(chat.delta) identical 3 lines
2020-05-15 12:47:38.791 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3933...
2020-05-15 12:47:38.819 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:38.819 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3933 has Message-Id: Gr.MkHMTOtfNRM.GdYiabNUoci.net
2020-05-15 12:47:38.871 17426-17426/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:47:39.029 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3934...
2020-05-15 12:47:39.065 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:39.066 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3934 has Message-Id: Gr.MkHMTOtfNRM.2nyJl8biiPe.net
2020-05-15 12:47:39.124 17426-17426/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:47:39.207 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:47:39.315 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3935...
2020-05-15 12:47:39.357 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:39.357 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3935 has Message-Id: .net
2020-05-15 12:47:39.406 17426-17426/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:47:39.459 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:112: INBOX-fetch done in 251 ms.
2020-05-15 12:47:39.459 17426-17450/? W/DeltaChat: ThreadId(5) src/job_thread.rs:93: connect+fetch failed: IMAP got error from elsewhere
2020-05-15 12:47:39.460 17426-17450/? I/DeltaChat: ThreadId(5) src/job.rs:708: INBOX-IDLE will not be started because of waiting jobs.
2020-05-15 12:47:39.461 17426-17450/? I/DeltaChat: ThreadId(5) src/job.rs:1027: dc_perform_inbox_jobs starting.
2020-05-15 12:47:39.462 17426-17450/? I/DeltaChat: ThreadId(5) src/job.rs:1034: dc_perform_inbox_jobs ended.
2020-05-15 12:47:39.462 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:47:39.511 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3936...
2020-05-15 12:47:39.551 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:39.551 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3936 has Message-Id: CENSORED.net
2020-05-15 12:47:39.595 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:112: INBOX-fetch done in 133 ms.
2020-05-15 12:47:39.595 17426-17450/? W/DeltaChat: ThreadId(5) src/job_thread.rs:90: connect+fetch failed: IMAP got error from elsewhere, reconnect & retry
2020-05-15 12:47:39.596 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:303: IMAP unsetup_handle step 2 (acquiring session.lock)
2020-05-15 12:47:39.609 17426-17426/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:47:39.808 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:314: IMAP unsetup_handle step 3 (clearing config).
2020-05-15 12:47:39.808 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/mod.rs:317: IMAP unsetup_handle step 4 (disconnected)
2020-05-15 12:47:39.860 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3937...
2020-05-15 12:47:39.928 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:39.929 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3937 has Message-Id: Gr.MkHMTOtfNRM.vWB2OSIqxqL.net
2020-05-15 12:47:39.992 17426-17426/? I/chatty: uid=10127(chat.delta) identical 2 lines
2020-05-15 12:47:40.196 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3938...
2020-05-15 12:47:40.253 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:40.254 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3938 has Message-Id: Gr.MkHMTOtfNRM.Y9JMxjsmk7l.de
2020-05-15 12:47:40.345 1012-5214/? I/ActivityManager: START u0 {cmp=chat.delta/org.thoughtcrime.securesms.ConversationActivity (has extras)} from uid 10127
2020-05-15 12:47:40.306 17426-17426/? I/chatty: uid=10127(chat.delta) identical 3 lines
2020-05-15 12:47:40.374 17426-17426/? W/chat.delta: type=1400 audit(0.0:57935): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:47:40.394 17426-17426/? W/chat.delta: type=1400 audit(0.0:57936): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:47:40.410 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message DeltaChat/3939...
2020-05-15 12:47:40.414 17426-17426/? W/chat.delta: type=1400 audit(0.0:57937): avc: denied { read } for name="u:object_r:vendor_camera_prop:s0" dev="tmpfs" ino=14710 scontext=u:r:untrusted_app:s0:c127,c256,c512,c768 tcontext=u:object_r:vendor_camera_prop:s0 tclass=file permissive=0
2020-05-15 12:47:40.456 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:671: Message has 1 parts and is assigned to chat #Chat#462.
2020-05-15 12:47:40.456 17426-17451/? I/DeltaChat: ThreadId(6) src/dc_receive_imf.rs:215: received message 3939 has Message-Id: Gr.MkHMTOtfNRM.urFMDFsRrNf.de
2020-05-15 12:47:40.509 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:105: INBOX-fetch started...
2020-05-15 12:47:40.764 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:112: INBOX-fetch done in 255 ms.
2020-05-15 12:47:40.765 17426-17450/? W/DeltaChat: ThreadId(5) src/job_thread.rs:93: connect+fetch failed: IMAP got error from elsewhere
2020-05-15 12:47:40.770 17426-17450/? I/DeltaChat: ThreadId(5) src/job_thread.rs:177: INBOX-IDLE started...
2020-05-15 12:47:40.884 17426-17450/? I/DeltaChat: ThreadId(5) src/imap/idle.rs:91: Idle entering wait-on-remote state
2020-05-15 12:48:20.254 1012-1120/? W/ActivityManager: Activity pause timeout for ActivityRecord{cd8ab6f u0 chat.delta/org.thoughtcrime.securesms.ConversationActivity t1645}
2020-05-15 12:48:25.086 1012-6005/? I/ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=chat.delta/org.thoughtcrime.securesms.RoutingActivity bnds=[52,765][174,887]} from uid 10115
2020-05-15 12:48:32.048 1012-1120/? W/ActivityManager: Activity destroy timeout for ActivityRecord{38ed471 u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1645 f}
2020-05-15 12:48:32.075 1012-1120/? W/ActivityManager: Activity destroy timeout for ActivityRecord{cd8ab6f u0 chat.delta/org.thoughtcrime.securesms.ConversationActivity t1645 f}
2020-05-15 12:48:32.081 465-631/? W/SurfaceFlinger: Attempting to destroy on removed layer: AppWindowToken{a192d05 token=Token{357007c ActivityRecord{cd8ab6f u0 chat.delta/org.thoughtcrime.securesms.ConversationActivity t1645}}}#0
2020-05-15 12:48:42.068 1012-1120/? W/ActivityManager: Timeout executing service: ServiceRecord{4c0160 u0 chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService}
2020-05-15 12:48:42.590 17426-17432/? I/chat.delta: Thread[3,tid=17432,WaitingInMainSignalCatcherLoop,Thread*=0x7531816400,peer=0x13a80020,"Signal Catcher"]: reacting to signal 3
2020-05-15 12:48:42.904 17426-17432/? I/chat.delta: Wrote stack traces to '[tombstoned]'
2020-05-15 12:48:46.670 1012-1120/? E/ActivityManager: ANR in chat.delta
    PID: 17426
    Reason: executing service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService
    Load: 3.87 / 3.99 / 4.19
    CPU usage from 25252ms to 0ms ago (2020-05-15 12:48:16.817 to 2020-05-15 12:48:42.069):
      7% 1012/system_server: 4.6% user + 2.4% kernel / faults: 8627 minor 10 major
      3.9% 465/surfaceflinger: 2.4% user + 1.4% kernel / faults: 174 minor 1 major
      3.7% 2606/com.touchtype.swiftkey: 3.2% user + 0.5% kernel / faults: 5172 minor 833 major
      2.6% 1718/com.android.systemui: 1.9% user + 0.7% kernel / faults: 993 minor 21 major
      1.8% 592/android.hardware.sensors.0-service: 0.5% user + 1.3% kernel / faults: 3 minor
      1.7% 585/android.hardware.graphics.composer.1-service: 0.6% user + 1% kernel / faults: 17 minor
      1.6% 8200/fr.neamar.kiss: 1.1% user + 0.4% kernel / faults: 4008 minor 34 major
      ...rest censored, but everything less than 1%
2020-05-15 12:49:09.764 1012-1120/? W/ActivityManager: Activity pause timeout for ActivityRecord{42b2a5d u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1646}
2020-05-15 12:49:11.935 465-1549/? W/SurfaceFlinger: Attempting to destroy on removed layer: f8e70fb Application Not Responding: chat.delta#0
2020-05-15 12:49:14.924 1012-14973/? I/ActivityManager: START u0 {act=android.settings.APPLICATION_DETAILS_SETTINGS dat=package:chat.delta flg=0x10008000 cmp=com.android.settings/.applications.InstalledAppDetails} from uid 10115
2020-05-15 12:49:15.690 17681-17681/? V/BatteryUtils: package: chat.delta
2020-05-15 12:49:15.696 17681-17681/? E/AppInfoDashboard: Package: chat.delta not found for user: 10
2020-05-15 12:49:20.960 1012-1120/? W/ActivityManager: Activity stop timeout for ActivityRecord{42b2a5d u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1646}
2020-05-15 12:49:26.910 17681-17681/? V/BatteryUtils: package: chat.delta
2020-05-15 12:49:31.889 1012-1120/? W/ActivityManager: Timeout executing service: ServiceRecord{4c0160 u0 chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService}
2020-05-15 12:49:32.386 17426-17432/? I/chat.delta: Thread[3,tid=17432,WaitingInMainSignalCatcherLoop,Thread*=0x7531816400,peer=0x13a80020,"Signal Catcher"]: reacting to signal 3
2020-05-15 12:49:32.688 17426-17432/? I/chat.delta: Wrote stack traces to '[tombstoned]'
2020-05-15 12:49:36.588 1012-1120/? E/ActivityManager: ANR in chat.delta
    PID: 17426
    Reason: executing service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService
    Load: 3.7 / 3.93 / 4.16
    CPU usage from 910ms to -4657ms ago (2020-05-15 12:49:30.979 to 2020-05-15 12:49:36.547):
      17% 1012/system_server: 6.9% user + 10% kernel / faults: 3696 minor 7 major
      14% 786/media.codec: 9.6% user + 5% kernel / faults: 11522 minor
      6.9% 1718/com.android.systemui: 5.5% user + 1.4% kernel / faults: 3325 minor 1 major
      5.3% 17426/chat.delta: 3% user + 2.3% kernel / faults: 4033 minor
      4.8% 2606/com.touchtype.swiftkey: 4.4% user + 0.3% kernel / faults: 3314 minor
      3.5% 723/media.extractor: 1.9% user + 1.6% kernel / faults: 4353 minor
      3.4% 15744/com.android.phone: 2.3% user + 1% kernel / faults: 858 minor
      3.2% 983/adbd: 0% user + 3.2% kernel / faults: 21869 minor
      1.9% 592/android.hardware.sensors.0-service: 0.3% user + 1.6% kernel / faults: 128 minor
      1.7% 465/surfaceflinger: 0.8% user + 0.8% kernel / faults: 446 minor
      1.6% 1853/.dataservices: 0.7% user + 0.8% kernel / faults: 766 minor
      1.6% 3000/com.android.nfc: 1% user + 0.5% kernel / faults: 954 minor
      1.4% 3021/com.qualcomm.qti.services.secureui:sui_service: 1% user + 0.3% kernel / faults: 812 minor
      1.4% 14394/kworker/u16:3: 0% user + 1.4% kernel
      1.2% 1873/com.qualcomm.qti.telephonyservice: 1% user + 0.1% kernel / faults: 708 minor
      1.2% 2571/sugov:0: 0% user + 1.2% kernel
      1% 585/android.hardware.graphics.composer.1-service: 0.3% user + 0.7% kernel / faults: 144 minor
      1% 3007/com.android.se: 0.7% user + 0.3% kernel / faults: 701 minor
      1% 3044/com.android.arima: 0.7% user + 0.3% kernel / faults: 659 minor
      ...rest censored, but everything less than 1%
2020-05-15 12:50:09.634 465-877/? W/SurfaceFlinger: Attempting to destroy on removed layer: dc0c82 Application Not Responding: chat.delta#0
2020-05-15 12:50:14.131 1012-5189/? I/ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=chat.delta/org.thoughtcrime.securesms.RoutingActivity bnds=[52,926][174,1048]} from uid 10115
2020-05-15 12:50:14.155 1012-1517/? W/WindowManager: TaskSnapshotSurface.create: Failed to find top fullscreen for task={taskId=1646 appTokens=[AppWindowToken{9e668a3 token=Token{e378fd2 ActivityRecord{42b2a5d u0 chat.delta/org.thoughtcrime.securesms.RoutingActivity t1646}}}] mdr=false}
2020-05-15 12:50:29.576 1012-1120/? W/ActivityManager: Timeout executing service: ServiceRecord{4c0160 u0 chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService}
2020-05-15 12:50:30.066 17426-17432/? I/chat.delta: Thread[3,tid=17432,WaitingInMainSignalCatcherLoop,Thread*=0x7531816400,peer=0x13a80020,"Signal Catcher"]: reacting to signal 3
2020-05-15 12:50:30.330 17426-17432/? I/chat.delta: Wrote stack traces to '[tombstoned]'
2020-05-15 12:50:33.828 1012-1120/? E/ActivityManager: ANR in chat.delta
    PID: 17426
    Reason: executing service chat.delta/org.thoughtcrime.securesms.connect.KeepAliveService
    Load: 3.62 / 3.85 / 4.12
    CPU usage from 53030ms to 0ms ago (2020-05-15 12:49:36.547 to 2020-05-15 12:50:29.576):
      5.4% 1012/system_server: 3.4% user + 2% kernel / faults: 8228 minor 8 major
      3% 465/surfaceflinger: 2.1% user + 0.9% kernel / faults: 688 minor 2 major
      2.4% 1718/com.android.systemui: 2% user + 0.4% kernel / faults: 1090 minor 4 major
      2% 592/android.hardware.sensors.0-service: 1% user + 1% kernel / faults: 11 minor
      1.3% 585/android.hardware.graphics.composer.1-service: 0.5% user + 0.7% kernel / faults: 67 minor
      ...rest censored, but everything less than 1%

该提问来源于开源项目:deltachat/deltachat-android

  • 点赞
  • 写回答
  • 关注问题
  • 收藏
  • 复制链接分享
  • 邀请回答

4条回答

  • weixin_39761255 weixin_39761255 4月前

    Update: Everything works fine now again.

    点赞 评论 复制链接分享
  • weixin_39633455 weixin_39633455 4月前

    I very seldom had similar issues. Smells like a race condition or similar multi thread stuff that is hard to debug.

    点赞 评论 复制链接分享
  • weixin_39852121 weixin_39852121 4月前

    might be related to the busy-database thing, we had just some discussions on that on irc #deltachat, i summed up things a bit at https://github.com/deltachat/deltachat-core-rust/issues/991#issuecomment-629536513

    busy-database block the ui-thread, it is directly visible if you have network after some time and lots of messages come in.

    i think, this has to be solved in the core, moving typically fast database queries to some threads in android is not an option, it makes the whole flow far too complicated.

    but possible solutions are already in reach, see linked issue.

    点赞 评论 复制链接分享
  • weixin_39761255 weixin_39761255 4月前

    I'll close this because it might be solved and we have no possibility of doing anything against this now.

    点赞 评论 复制链接分享

相关推荐