K-9 Mail sync hangs when Dovecot reports "corrupted record in index cache file"

I have been using k9 for 10+ years now.
I access 3 different types of email accounts

  • Postfix/Dovecot IMAP on my Ubuntu home server
  • Gmail
  • Work email on MS Exchange

I recently upgraded from a Samsung Galaxy 8+ to a Pixel 5a running Android 12.

None of my accounts are now reliablly sending/receiving email — whether via manual, poll, or push.
Specifically,

  • Regarding receiving email, each account either loads NO emails ever or it loads the email once after installing but then fails to update or it uploads a non-Imap folder into the Inbox and fails to update.
  • When I try to manually refresh, the circle spins but nothing happens
  • Either way, no new emails are being fetched on any of my accounts!
  • Regarding sending, none of the accounts are sending email (though the Outbox shows as empty)

All 3 accounts used to work (and continue to work) on my old Galaxy S8+ which is on the same WiFi Lan as the new Pixel 5a (and is using the same version of K9 with the same settings)

I have tried (repeatedly) clearing cache, clearing all storage, reinstalling the app and nothing works.
I tried importing the exact same settings from my working S8+ and still nothing.
I looked at logcat, but I only get messages of the following form:

  • com.fsck.k9: Background concurrent copying GC freed 1823311(34MB) AllocSpace objects, 0(0B) LOS objects, 75% free, 10091KB/39MB, paused 303us,134us total 137.466ms
  • com.fsck.k9: Waiting for a blocking GC Alloc
  • com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 7.588ms
  • Alloc young concurrent copying GC freed 1612160(30MB) AllocSpace objects, 0(0B) LOS objects, 79% free, 8377KB/39MB, paused 55us,43us total 14.982ms

Specifically logging doesn’t show any evidence about accessing/polling/pushing any of the 3 email servers.
i.e. it seems like k9 isn’t doing anything on my Pixel.
In contrast, on my working S8+, the logcat is filled with entries including all the expected imap and push entries. which are completely missing on the pixel.

Also interestingly, on the Pixel, app info shows that there is no ‘cache’ data file while on the working S8 there is a multi-MB cache file – again seemingly confirming that K9 is not doing/recording/pulling/pushing anything on the Pixel.

For each of the 3 accounts, I manually went into the settings to check that the incoming and outgoing server connections were working and they completed without error message.

For all 3 accounts both pull and push are turned on.

Any idea what could be going wrong here?

After about 5-6 hours, the 3 accounts started separately to do their first sync…
I didn’t do or change anything… it is as if the app decided to suddenly wake up and start working…
For a few minutes, K9 on my Pixel seemed to be receiving and sending emails on all 3 accounts promptly and properly…
But then a few minutes later syncing/sending/receiving again stopped.
For example, I get the endless “circle” icon when attempted to manually refresh any of the accounts.

So, it seems like something is causing K9 on my pixel to intermittently work and not work…

Note: that app info still shows 0 cache for the K9 email app

And 11 hours later, still no new messages since that one time spurt of activity and connectivity.
While at the same time my S8+ on the same WiFi network with the same version of K9Mail with the same settings is perfectly responsive and is polling/pushing/sending emails automatically as well as manually. So this is not a problem with my K9 settings or with the email servers.

Note that my Pixel5a has full LAN and WAN connectivity – I can access Internet, I can ping it, I can ssh into it etc. so this is not a network connectivity issue.

Note that the logcat for the last 11 hours shows only lines of the form:

  • com.fsck.k9: Background concurrent copying GC freed 1823311(34MB) AllocSpace objects, 0(0B) LOS objects, 75% free, 10091KB/39MB, paused 303us,134us total 137.466ms
  • com.fsck.k9: Waiting for a blocking GC Alloc
  • com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 7.588ms
  • Alloc young concurrent copying GC freed 1612160(30MB) AllocSpace objects, 0(0B) LOS objects, 79% free, 8377KB/39MB, paused 55us,43us total 14.982ms

As well as clusters of the following:

  • WM-WorkerWrapper: Work [ id=f72926c6-695d-4f70-aec8-f853c27cbfa3, tags={ com.fsck.k9.job.MailSyncWorker, MailSync } ] was cancelled
  • WM-WorkerWrapper: java.util.concurrent.CancellationException: Task was cancelled.
  • WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1184)
  • WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.getDoneValue(AbstractFuture.java:514)
  • WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.get(AbstractFuture.java:475)
  • WM-WorkerWrapper: at androidx.work.impl.WorkerWrapper$2.run(WorkerWrapper.java:300)
  • WM-WorkerWrapper: at androidx.work.impl.utils.SerialExecutor$Task.run(SerialExecutor.java:91)
  • WM-WorkerWrapper: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
  • WM-WorkerWrapper: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
  • WM-WorkerWrapper: at java.lang.Thread.run(Thread.java:920)

The last grouping appears in clusters of 3 with the same 3 different 'id’s suggesting one for each of my IMAP email servers.
However even so, their appearance is irregular. For example, one cluster at 11PM, then just before 1AM, then once every 10-15 min between 3AM and 6AM and then none again for the past 3 hours.

So it seems like at times mail sync is not even being attempted and at other times it is canceled.

This might be the same issue that was reported here: Excessive battery drain and data usage · Issue #5660 · k9mail/k-9 · GitHub

I have no idea what could be causing this. I’m hoping I might be able to narrow down the cause if someone manages to get a log where the app transitions from ‘everything is working fine’ to ‘nothing is working anymore’. You can probably get the app working properly for a short amount of time by force stopping the app, then starting it again.

Interesting… I haven’t noticed my phone getting hot… but checking the battery usage, I see that K9 has accounted for 29% of the battery usage over the past 24 hours (despite only actually syncing successfully at most a handful of times)

The log appended in Excessive battery drain and data usage · Issue #5660 · thunderbird/thunderbird-android · GitHub seems very similar to my logcat.

As well as the erratic behavior of syncing.
So presumably there is an actual bug here vs. “user error”
This is of course a show-stopper bug since it makes k9 completely unreliable/unusable for me

I should add that before I upgraded from Android 11 to Android 12 on my Pixel5a, I did notice that syncing was slow/delayed but not enough that I spent time investigating.

Ever since upgrading to Android 12, the delay/lack of syncing has made the app totally unusable – at it seems to sync at best every 6 to 12 hours…

Note that restarting the app doesn’t necessarily/always get it working again.
Also, I don’t understand why there is no data cache written (even after a successful sync is done).

Here is an example of where a restart worked to get at least an initial sync:

Blockquote
I libc : SetHeapTaggingLevel: tag level set to 0
E com.fsck.k9: Not starting debugger since process cannot load the jdwp agent.
D ProcessState: Binder ioctl to enable oneway spam detection failed: Invalid argument
D CompatibilityChangeReporter: Compat change id reported: 171979766; UID 10348; state: DISABLED
D ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.test.base.jar
V GraphicsEnvironment: ANGLE Developer option for ‘com.fsck.k9’ set to: ‘default’
V GraphicsEnvironment: ANGLE GameManagerService for com.fsck.k9: false
V GraphicsEnvironment: Updatable production driver is not supported on the device.
D NetworkSecurityConfig: Using Network Security Config from resource network_security_config debugBuild: false
D NetworkSecurityConfig: Using Network Security Config from resource network_security_config debugBuild: false
D CompatibilityChangeReporter: Compat change id reported: 160794467; UID 10348; state: DISABLED
E WM-WorkerWrapper: Didn’t find WorkSpec for id 22db67cd-232c-499c-8eaa-b7a33f5938ad
E WM-WorkerWrapper: Didn’t find WorkSpec for id e63dccdb-b938-40ba-aeed-dfa6a743cae7
E WM-WorkerWrapper: Didn’t find WorkSpec for id f72926c6-695d-4f70-aec8-f853c27cbfa3
D CompatibilityChangeReporter: Compat change id reported: 171228096; UID 10348; state: ENABLED
E WM-WorkerWrapper: Didn’t find WorkSpec for id f72926c6-695d-4f70-aec8-f853c27cbfa3
E WM-WorkerWrapper: Didn’t find WorkSpec for id e63dccdb-b938-40ba-aeed-dfa6a743cae7
E WM-WorkerWrapper: Didn’t find WorkSpec for id f72926c6-695d-4f70-aec8-f853c27cbfa3
I AdrenoGLES-0: QUALCOMM build : 4783c89, I46ff5fc46f
I AdrenoGLES-0: Build Date : 11/30/20
I AdrenoGLES-0: OpenGL ES Shader Compiler Version: EV031.31.04.01
I AdrenoGLES-0: Local Branch : QPR2
I AdrenoGLES-0: Remote Branch :
I AdrenoGLES-0: Remote Branch :
I AdrenoGLES-0: Reconstruct Branch :
I AdrenoGLES-0: Build Config : S P 10.0.4 AArch64
I AdrenoGLES-0: Driver Path : /vendor/lib64/egl/libGLESv2_adreno.so
D hw-ProcessState: Binder ioctl to enable oneway spam detection failed: Invalid argument
I AdrenoGLES-0: PFP: 0x016dd093, ME: 0x00000000
E Adreno-AppProfiles: Could not find QSPM HAL service
W AdrenoUtils: <ReadGpuID_from_sysfs:197>: Failed to open /sys/class/kgsl/kgsl-3d0/gpu_model
W AdrenoUtils: ReadGpuID:221: Failed to read chip ID from gpu_model. Fallback to use the GSL path
D hw-ProcessState: Binder ioctl to enable oneway spam detection failed: Invalid argument
D CompatibilityChangeReporter: Compat change id reported: 150939131; UID 10348; state: DISABLED
I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=99b3bee8-bc15-405d-b3c2-edc6695a555b, tags={ com.fsck.k9.job.MailSyncWorker, MailSync } ]
I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=ce1ac805-1241-4f2b-a1e4-1a63c1e1d62e, tags={ com.fsck.k9.job.MailSyncWorker, MailSync } ]
I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=ea81a89a-b204-486c-b7ab-9724ca047a82, tags={ com.fsck.k9.job.MailSyncWorker, MailSync } ]

Meanwhile, I will turn debugging back on and try to catch where it transitions from bad to good…

1 Like

OK, I think I caught the transition…
This time, I went to my Sent folder which for some reason only was showing the one message I had sent locally but not the 24 other messages in the Sent folder on the Server (note that the folders are appropriately matched since the server does show the message sent locally from K9)

Anyway, I tried to manually sync by pulling down on “Loading messages”…
Well I got the spinning circle thing and now it is back to the non-syncing state.

Here is the transition:

Blockquote
12-10 11:48:09.039 18423 18442 V ImapResponseParser: conn45645012<<<#52# [OK, [READ-ONLY], Examine completed (0.001 + 0.000 secs).]
12-10 11:48:09.040 18423 18442 D RealImapFolder: Got untagged EXISTS with value 25 for MyEmailServer:Sent/MessagingController/conn45645012
12-10 11:48:09.040 18423 18442 D RealImapFolder: Got UidNext = 1000 for MyEmailServer:Sent/MessagingController/conn45645012
12-10 11:48:09.042 18423 18442 V ImapSync: SYNC: Remote message count for folder Sent is 25
12-10 11:48:09.042 18423 18442 V ImapSync: SYNC: About to get messages 1 through 25 for folder Sent
12-10 11:48:09.043 18423 18442 V RealImapConnection: conn45645012>>> 53 UID SEARCH 1:25 NOT DELETED
12-10 11:48:09.046 18423 18442 V ImapResponseParser: conn45645012<<<#null# [SEARCH, 112, 252, 365, 366, 367, 369, 370, 371, 628, 629, 830, 851, 852, 930, 937, 947, 948, 976, 977, 992, 993, 994, 995, 996,
999]
12-10 11:48:09.046 18423 18442 V ImapResponseParser: conn45645012<<<#53# [OK, Search completed (0.001 + 0.000 secs).]
12-10 11:48:09.046 18423 18442 V ImapSync: SYNC: Got 25 messages for folder Sent
12-10 11:48:09.046 18423 18442 V ImapSync: Message with uid 999 is present in the local store
12-10 11:48:09.047 18423 18442 V ImapSync: Message with uid 996 has not yet been downloaded
12-10 11:48:09.047 18423 18442 V ImapSync: Message with uid 995 has not yet been downloaded
<20 similar lines deleted>
12-10 11:48:09.050 18423 18442 V ImapSync: Message with uid 252 has not yet been downloaded
12-10 11:48:09.050 18423 18442 V ImapSync: Message with uid 112 has not yet been downloaded
12-10 11:48:09.050 18423 18442 D ImapSync: SYNC: Have 24 unsynced messages
12-10 11:48:09.051 18423 18442 D ImapSync: SYNC: About to fetch 24 unsynced messages for folder Sent
12-10 11:48:09.053 18423 18442 V RealImapConnection: conn45645012>>> 54 UID FETCH 996,995,994,993,992,977,976,948,947,937,930,852,851,830,629,628,371,370,369,367,366,365,252,112 (UID FLAGS INTERNALDATE R
FC822.SIZE BODY.PEEK[HEADER.FIELDS (date subject from content-type to cc reply-to message-id references in-reply-to X-K9mail-Identity)])
12-10 11:48:09.057 18423 18442 V RealImapConnection: conn45645012<<<#null# [1, FETCH, [UID, 112, FLAGS, [\Seen], INTERNALDATE, 09-Nov-2012 08:44:29 -0500, RFC822.SIZE, 32702, BODY, [HEADER.FIELDS, [DATE,
SUBJECT, FROM, CONTENT-TYPE, TO, CC, REPLY-TO, MESSAGE-ID, REFERENCES, IN-REPLY-TO, X-K9MAIL-IDENTITY]], Subject:
12-10 11:48:09.057 18423 18442 V RealImapConnection: other physician executive opportunities
12-10 11:48:09.057 18423 18442 V RealImapConnection: Message-ID: d7aypxbdo3m19hryiirr97vp.1352468649140@email.android.com
12-10 11:48:09.057 18423 18442 V RealImapConnection: From: “John@Mydomain.orgjohn@mydomain.org
12-10 11:48:09.057 18423 18442 V RealImapConnection: Date: Fri, 09 Nov 2012 08:44:09 -0500
12-10 11:48:09.057 18423 18442 V RealImapConnection: To:
12-10 11:48:09.057 18423 18442 V RealImapConnection: Content-Type: multipart/mixed; boundary=“----HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW”
12-10 11:48:09.057 18423 18442 V RealImapConnection:
12-10 11:48:09.057 18423 18442 V RealImapConnection: ]]
12-10 11:48:09.058 18423 18442 V RealImapConnection: conn45645012<<<#null# [2, FETCH, [UID, 252, FLAGS, [\Seen], INTERNALDATE, 20-Jan-2013 16:47:51 -0500, RFC822.SIZE, 1475, BODY, [HEADER.FIELDS, [DATE,
SUBJECT, FROM, CONTENT-TYPE, TO, CC, REPLY-TO, MESSAGE-ID, REFERENCES, IN-REPLY-TO, X-K9MAIL-IDENTITY]], Content-Type: multipart/alternative; boundary=“----XZ2N6I1QP1KR47BW8KV3BZB4W0YDTP”
12-10 11:48:09.058 18423 18442 V RealImapConnection: Message-ID: f3455c8b-9685-462d-952c-e98c27b7bb1b@email.android.com
12-10 11:48:09.058 18423 18442 V RealImapConnection: Subject:
12-10 11:48:09.058 18423 18442 V RealImapConnection: From: “John Doe” John@mydomain.org
12-10 11:48:09.058 18423 18442 V RealImapConnection: Date: Sun, 20 Jan 2013 16:47:28 -0500
12-10 11:48:09.058 18423 18442 V RealImapConnection: To:
12-10 11:48:09.058 18423 18442 V RealImapConnection:
12-10 11:48:09.058 18423 18442 V RealImapConnection: ]]
12-10 11:48:09.072 18423 18442 V RealImapConnection: conn45645012<<<#null# [24, FETCH, [UID, 996, FLAGS, [\Seen], INTERNALDATE, 09-Dec-2021 11:57:05 -0500, RFC822.SIZE, 414, BODY, [HEADER.FIELDS, [DATE,
SUBJECT, FROM, CONTENT-TYPE, TO, CC, REPLY-TO, MESSAGE-ID, REFERENCES, IN-REPLY-TO, X-K9MAIL-IDENTITY]], Date: Thu, 09 Dec 2021 11:57:04 -0500
12-10 11:48:09.072 18423 18442 V RealImapConnection: From: John Doe John@mydomain.org
12-10 11:48:09.072 18423 18442 V RealImapConnection: To:
12-10 11:48:09.072 18423 18442 V RealImapConnection: Subject:
12-10 11:48:09.072 18423 18442 V RealImapConnection: Message-ID: 2DE99A56-2BB1-4BCA-9FDD-5685B98DD0BF@mydomain.org
12-10 11:48:09.072 18423 18442 V RealImapConnection: Content-Type: text/plain;
12-10 11:48:09.072 18423 18442 V RealImapConnection: charset=utf-8
12-10 11:48:09.072 18423 18442 V RealImapConnection:
12-10 11:48:09.072 18423 18442 V RealImapConnection: ]]
12-10 11:48:09.073 18423 18442 V RealImapConnection: conn45645012<<<#54# [OK, Fetch completed (0.005 + 0.000 + 0.004 secs).]
12-10 11:48:09.073 18423 18442 D ImapSync: SYNC: Synced unsynced messages for folder Sent
12-10 11:48:09.073 18423 18442 D ImapSync: SYNC: Have 3 large messages and 21 small messages out of 24 unsynced messages
12-10 11:48:09.073 18423 18442 D ImapSync: SYNC: Fetching 21 small messages for folder Sent
12-10 11:48:09.074 18423 18442 V RealImapConnection: conn45645012>>> 55 UID FETCH 112,252,365,366,367,369,370,371,830,851,852,930,937,948,976,977,992,993,994,995,996 (UID BODY.PEEK)
12-10 11:48:09.203 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 1286365(87MB) AllocSpace objects, 69(5328KB) LOS objects, 63% free, 55MB/151MB, paused 100us,75us total 104.024ms
12-10 11:48:36.932 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:36.937 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:37.937 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:37.938 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:38.243 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:38.247 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:38.541 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:38.543 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:38.649 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:38.653 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:39.055 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:39.058 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:39.469 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:39.476 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 6.951ms
12-10 11:48:39.476 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:39.580 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:39.583 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:40.069 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:40.074 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 5.516ms
12-10 11:48:40.074 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:48:40.579 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:48:40.585 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 5.446ms

12-10 11:49:13.614 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.614 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.617 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:49:13.639 18423 18442 I com.fsck.k9: Alloc young concurrent copying GC freed 94514(94MB) AllocSpace objects, 0(0B) LOS objects, 86% free, 14MB/110MB, paused 57us,33us total 24.068ms
12-10 11:49:13.639 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Alloc for 21.504ms
12-10 11:49:13.639 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.707 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.707 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.717 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:49:13.732 18423 18442 I com.fsck.k9: Alloc young concurrent copying GC freed 94264(94MB) AllocSpace objects, 0(0B) LOS objects, 86% free, 14MB/110MB, paused 56us,31us total 24.855ms
12-10 11:49:13.732 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Alloc for 14.490ms
12-10 11:49:13.732 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.799 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.799 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:49:13.801 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc

12-10 11:50:37.784 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 31.021ms
12-10 11:50:37.784 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.784 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 23.677ms
12-10 11:50:37.784 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.853 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.853 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.860 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc

12-10 11:50:37.873 18423 18442 I com.fsck.k9: Alloc young concurrent copying GC freed 96014(96MB) AllocSpace objects, 0(0B) LOS objects, 91% free, 9578KB/105MB, paused 49us,32us total 20.088ms
12-10 11:50:37.874 18423 18433 I com.fsck.k9: WaitForGcToComplete blocked Background on Alloc for 20.230ms
12-10 11:50:37.874 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Alloc for 13.972ms
12-10 11:50:37.874 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.943 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.943 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:37.945 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:50:37.969 18423 18442 I com.fsck.k9: Alloc young concurrent copying GC freed 95766(95MB) AllocSpace objects, 0(0B) LOS objects, 91% free, 9578KB/105MB, paused 53us,33us total 26.025ms
12-10 11:50:37.969 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Alloc for 23.682ms
12-10 11:50:37.969 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:38.038 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:38.038 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:50:38.043 18423 18423 I com.fsck.k9: Waiting for a blocking GC
12-10 11:53:12.798 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 22.160ms
12-10 11:53:12.798 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:12.884 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:12.920 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 35.748ms
12-10 11:53:12.920 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:13.008 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:13.048 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 40.132ms
12-10 11:53:13.048 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:13.313 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:13.350 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 106230(106MB) AllocSpace objects, 0(0B) LOS objects, 71% free, 31MB/113MB, paused 167us,110us total 242.674ms
12-10 11:53:13.351 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 37.375ms
12-10 11:53:13.351 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:13.496 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:13.534 18423 18423 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:13.623 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 131680(130MB) AllocSpace objects, 0(0B) LOS objects, 75% free, 8331KB/32MB, paused 162us,155us total 145.299ms
12-10 11:53:13.624 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 128.230ms
12-10 11:53:13.624 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:13.624 18423 18423 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 90.667ms
12-10 11:53:13.624 18423 18423 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:13.853 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 88505(88MB) AllocSpace objects, 0(0B) LOS objects, 57% free, 70MB/166MB, paused 189us,115us total 113.310ms
12-10 11:53:16.989 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 130542(130MB) AllocSpace objects, 0(0B) LOS objects, 56% free, 59MB/136MB, paused 148us,208us total 365.230ms
12-10 11:53:17.371 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 190977(190MB) AllocSpace objects, 0(0B) LOS objects, 62% free, 58MB/154MB, paused 148us,116us total 323.411ms
12-10 11:53:18.762 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 147110(147MB) AllocSpace objects, 0(0B) LOS objects, 57% free, 66MB/154MB, paused 203us,135us total 327.389ms
12-10 11:53:18.922 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:18.955 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 211241(211MB) AllocSpace objects, 0(0B) LOS objects, 68% free, 44MB/140MB, paused 1.034ms,902us total 127.673ms
12-10 11:53:18.955 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 33.397ms
12-10 11:53:18.956 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:21.734 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 132684(132MB) AllocSpace objects, 0(0B) LOS objects, 47% free, 73MB/138MB, paused 945us,106us total 273.393ms
12-10 11:53:21.891 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 199876(199MB) AllocSpace objects, 0(0B) LOS objects, 66% free, 47MB/143MB, paused 155us,115us total 110.619ms
12-10 11:53:24.858 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 106686(106MB) AllocSpace objects, 0(0B) LOS objects, 56% free, 49MB/112MB, paused 141us,114us total 277.760ms
12-10 11:53:25.035 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:25.068 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 169067(169MB) AllocSpace objects, 0(0B) LOS objects, 52% free, 86MB/182MB, paused 997us,115us total 164.017ms
12-10 11:53:25.068 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 32.457ms
12-10 11:53:25.068 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:25.219 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:25.229 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 9.236ms
12-10 11:53:25.229 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:28.813 18423 18476 V RealImapConnection: conn236956861<<<#null# [OK, Still here]
12-10 11:53:28.814 18423 18475 V RealImapConnection: conn138320894<<<#null# [OK, Still here]
12-10 11:53:28.837 18423 18433 I com.fsck.k9: Background young concurrent copying GC freed 168361(168MB) AllocSpace objects, 0(0B) LOS objects, 61% free, 61MB/157MB, paused 875us,1.032ms total 362.099ms
12-10 11:53:28.875 18423 18476 W TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-MailFolder2 / id 6: acquired with no timeout. K-9 Mail should not do this
12-10 11:53:28.876 18423 18475 W TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-INBOX / id 3: acquired with no timeout. K-9 Mail should not do this
12-10 11:53:28.876 18423 18475 V RealImapFolderIdler: ImapFolderIdler[INBOX].idle(): Ignoring untagged response
12-10 11:53:28.876 18423 18476 V RealImapFolderIdler: ImapFolderIdler[MailFolder2].idle(): Ignoring untagged response
12-10 11:53:28.876 18423 18475 V TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-INBOX / id 3: releasing after 0 ms, timeout = null ms
12-10 11:53:28.876 18423 18476 V TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-MailFolder2 / id 6: releasing after 0 ms, timeout = null ms
12-10 11:53:28.997 18423 18442 I com.fsck.k9: Waiting for a blocking GC Alloc
12-10 11:53:29.064 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 214672(213MB) AllocSpace objects, 0(0B) LOS objects, 69% free, 42MB/138MB, paused 1.168ms,939us total 155.932ms
12-10 11:53:29.065 18423 18442 I com.fsck.k9: WaitForGcToComplete blocked Alloc on Background for 68.286ms
12-10 11:53:29.065 18423 18442 I com.fsck.k9: Starting a blocking GC Alloc
12-10 11:53:30.278 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 163511(163MB) AllocSpace objects, 0(0B) LOS objects, 75% free, 30MB/120MB, paused 1.075ms,150us total 115.345ms
12-10 11:54:02.198 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 146584(146MB) AllocSpace objects, 0(0B) LOS objects, 62% free, 58MB/154MB, paused 153us,64us total 100.470ms
12-10 11:54:41.360 18423 18433 I com.fsck.k9: Background concurrent copying GC freed 161666(161MB) AllocSpace objects, 0(0B) LOS objects, 54% free, 79MB/175MB, paused 632us,104us total 109.856ms
12-10 11:55:28.627 18423 18475 V RealImapConnection: conn138320894<<<#null# [OK, Still here]
12-10 11:55:28.629 18423 18476 V RealImapConnection: conn236956861<<<#null# [OK, Still here]
12-10 11:55:28.630 18423 18475 W TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-INBOX / id 3: acquired with no timeout. K-9 Mail should not do this
12-10 11:55:28.631 18423 18476 W TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-MailFolder2 / id 6: acquired with no timeout. K-9 Mail should not do this
12-10 11:55:28.631 18423 18475 V RealImapFolderIdler: ImapFolderIdler[INBOX].idle(): Ignoring untagged response
12-10 11:55:28.631 18423 18476 V RealImapFolderIdler: ImapFolderIdler[MailFolder2].idle(): Ignoring untagged response
12-10 11:55:28.631 18423 18475 V TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-INBOX / id 3: releasing after 0 ms, timeout = null ms
12-10 11:55:28.632 18423 18476 V TracingPowerManager$TracingWakeLock: TracingWakeLock for tag ImapFolderPusher-MyEmailServer-MailFolder2x / id 6: releasing after 1 ms, timeout = null ms

Hopefully this helps track down the bug(s)…

1 Like

It looks like K-9 Mail is hanging or at least taking very long when trying to parse the server response for the command 55 UID FETCH 112,252,365,366,367,369,370,371,830,851,852,930,937,948,976,977,992,993,994,995,996 (UID BODY.PEEK[]).

Can you manually connect to the server and issue such a command? I’m interested in the server response. Hopefully it will help me to reproduce the issue.

You can use the command openssl s_client -crlf -connect imap.domain.example:993 to connect to the server using a secure connection. Then enter the following commands (replace username and password with your actual username and password):

tag1 LOGIN "username" "password"
tag2 EXAMINE "Sent"
tag3 UID FETCH 112 (UID BODY.PEEK[])

The response to the last command is what I am interested in. It will contain the complete contents of the message. Hopefully the actual contents are not important, so feel free to replace the message data with something like <redacted>.

Hi, here is the redacted output… seems pretty normal to me at first
glance…

CONNECTED(00000005)
---
Certificate chain
 0 s:CN = ubuntu.home
   i:CN = ubuntu.home
---
Server certificate
-----BEGIN CERTIFICATE-----
<redacted>
-----END CERTIFICATE-----
subject=CN = ubuntu.home

issuer=CN = ubuntu.home

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: ECDH, P-384, 384 bits
---
SSL handshake has read 1446 bytes and written 771 bytes
Verification: OK
---
New, TLSv1.3, Cipher is TLS_AES_256_GCM_SHA384
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN] Dovecot (Ubuntu) ready.
a OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPA\
CE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE] Logged in
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded forwarded redistributed)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 25 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1338834643] UIDs valid
* OK [UIDNEXT 1000] Predicted next UID
* OK [HIGHESTMODSEQ 639] Highest
b OK [READ-ONLY] Examine completed (0.001 + 0.000 secs).
* 1 FETCH (UID 112 BODY[] {33442}
X-VM-v5-Data: ([nil t nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil]
        ["31844" "Friday" "9" "November" "2012" "08:44:09" "-0500" "John@mydomain.org" "john@mydomain.org" nil nil nil nil "csmitch@otherdomain.com" "Smitch, Crystal" "11" nil nil (number mark " U    To:\
 Smitch, Chris Nov  9 12 31K  " thread-indent "Re: FW: Regional opportunity in the Boston area as well as other physician executive opportunities\n") nil nil nil nil nil nil nil nil nil "Re: FW: Regional\
 opportunity in the Boston area as well as other physician executive opportunities" nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil]
        nil)
X-Mozilla-Status: 0000
X-Mozilla-Status2: 00000000
Subject: Re: FW: Regional opportunity in the Boston area as well as
 other
From: "John@mydomain.org" <john@mydomain.org>
Date: Fri, 09 Nov 2012 08:44:09 -0500
To: "Smitch, Crystal" <csmith@otherdomain.com>
Message-ID: <d7aypxbdo3m19hryiirr97vp.1352468649140@email.android.com>
Content-Type: multipart/mixed; boundary="----HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW"
MIME-Version: 1.0

------HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW
Content-Type: text/plain;
 charset=utf-8
Content-Transfer-Encoding: base64

<redacted>x

------HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW
Content-Type: text/plain;
 charset=utf-8
Content-Transfer-Encoding: base64
X-Android-Body-Quoted-Part: quoted-intro

<redacted>

------HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW
Content-Type: text/html;
 charset=utf-8
Content-Transfer-Encoding: base64
X-Android-Body-Quoted-Part: quoted-reply

<redacted>

------HAR7R1T1AUHLX5A8TUNGTXWSI5FUXW--
)
c OK Fetch completed (0.002 + 0.000 + 0.001 secs).
2 Likes

Couple of updates and corrections to earlier observations:

  • First, I think the problem is indeed due to potentially an unexpected result or badly constructed email in the Sent folder, as I can trigger the problem reliably by manually trying to retrieve emails from the Sent folder
  • Second, I can reliably reset the problem by stopping & restarting K9.
  • Conversely, if I don’t restart K9 the problem seems to persist indefinitely (as does the increased battery usage)
  • For the past 24 hours I didn’t use K9 at all and it is working and the battery usage is <1% (compared with ~30% when the error occurs)
  • The problem is actually not unique to my Pixel5a. The same problem occurs on my old Galaxy S8+ so long as I try to retrieve from the Sent folder. I hadn’t noticed it before because I hadn’t used that folder.

I am assuming that there is either a misconstructed email or an unexpected email response when fetching from my Sent folder.

1 Like

I think I found the problem…
There were errors in my dovecot index cache files of form:

Dec 11 17:51:58 myserver dovecot: imap(mylogname): Error: Corrupted record in index cache file /home/mylogname/mail-imap/.imap/Sent/dovecot.index.cache: UID 628: Broken physical size in mailbox Sent: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (3976641 < 3977220, box=Sent, UID=628)
Dec 11 17:51:58 myserver dovecot: imap(mylogname): Error: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (3976641 < 3977220, box=Sent, UID=628) (FETCH BODY for mailbox Sent UID 628)
Dec 11 17:52:04 myserver dovecot: imap(mylogname): Error: Corrupted record in index cache file /home/mylogname/mail-imap/.imap/Sent/dovecot.index.cache: UID 629: Broken physical size in mailbox Sent: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (3758994 < 3759428, box=Sent, UID=629)
Dec 11 17:52:04 myserver dovecot: imap(mylogname): Error: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (3758994 < 3759428, box=Sent, UID=629) (FETCH BODY for mailbox Sent UID 629)
Dec 11 17:53:10 myserver dovecot: imap(mylogname): Error: Corrupted record in index cache file /home/mylogname/mail-imap/.imap/Sent/dovecot.index.cache: UID 947: Broken physical size in mailbox Sent: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (187774 < 188210, box=Sent, UID=947)
Dec 11 17:53:10 myserver dovecot: imap(mylogname): Error: read(/home/mylogname/mail-imap/Sent) failed: Cached message size smaller than expected (187774 < 188210, box=Sent, UID=947) (FETCH BODY for mailbox Sent UID 947)

I rebuilt the cache (by removing the dovecot.index files and restarting the dovecot server…

As a result of the corrupted cached, the queries to dovecot were returning malformed mail messages and this presumably caused K9 to hang.

For example, messages with just partial headers or with just the body and no header…

While technically this is a dovecot error, I would think that the K9 app should be able to recover from it (as all my other imap mail readers are able to do)

Presumably, K9 could do a simple check to make sure there is a valid header and/or body and reject the message if not valid…

1 Like

Do you have one of the corrupted messages that you can share? I’d be awesome if you could send one (ideally as an attachment) to debugging@cketti.de.

The corruption seems to be due to cutoff MIME messages so that the concluding separator is not received. I have sent you several examples via private email.

Thanks, I received your email. However, in my tests with your redacted messages I couldn’t reproduce the behavior you’re seeing.

Is K-9 Mail now properly syncing your Sent folder after you have rebuilt the Dovecot index? Or is the app still hanging when trying to sync the folder?

Yes - as soon as I rebuilt the dovecot index, it started working perfectly on both phones.

Are you sure you were able to get your IMAP server to send such broken messages? I’m not sure they can unless you have server corruption.
I imagine the byte counts may be wrong…
Is it possible that K9 is expecting to read a certain number of bytes and then hangs waiting?

Yes - as soon as I rebuilt the dovecot index, it started working perfectly on both phones.

Thanks. That most likely means the message parser isn’t the problem. The parser encounters messages that end prematurely all the time when using POP3 and K-9 Mail is configured to only download the first X KB. It seems to handle such cases just fine.

I’m guessing Dovecot returned invalid IMAP responses in which it said it will send X bytes of data, but then sent Y bytes. This will lead to either interpreting the end of the message as part of the IMAP protocol response, or to read part of the IMAP response as belonging to the message.
Still, when reading the code I don’t see how that could lead to an endless loop that doesn’t produce any log messages.

Not sure if this helps… but I just noticed that messages 10 and 11 were not fetched…
i.e. the record goes from:

  • 8 FETCH (UID 371 BODY[] {6887}^M

to:

  • 11 FETCH (UID 830 BODY[] {49596}^M

Could this be the problem if K9mail is waiting for 25 messages but only receives 23?

Alternatively, if a message ends early or late, could some combo of characters in the message be misinterpreted as imap protocol?

When encountering {X} K-9 Mail will keep reading from the connection until it has received X bytes. If the server sends less data than that, the read operation times out after 60 seconds. However, if the server sends at least one byte every 59 seconds, the app could spend a very long time just waiting for all of the data to arrive. That could explain the behavior you’re seeing. But it seems rather unlikely that the server is sending data periodically with an interval smaller than 60 seconds. The default interval for Dovecot’s periodic “OK Still here” messages is 2 minutes.

I don’t think it’s a 60 second timeout issue, since the hanging persisted for more than 24 hours.
Also, as per the manual FETCH dump I sent you, the server completes it’s request very fast and presumably stops sending data.
Is there anywhere in the K9 code where a ‘wait’ is not timed out?
Is it possible that it is waiting for a message (or message component) to be sent that is never sent?
Is there a handshake that it is awaiting?

Also when it does hang, what is generating all the GC (garbage collection?) log lines that seem to indicate 100’s of megabytes continuing to be written and cleared?
Naively, it would seem that K9 is continuing or repeating to read/write large streams of data. Where (and why) is that triggered in the K9 code. Hard to think of any legitimate reason for it…

Note this heavy duty read/write activity could explain the high battery usage.

Any thoughts on how to further troubleshoot and fix?

From my selfish perspective, my problem is resolved and if it happens again, I know how to fix the Dovecot index cache files on my server.

But others will likely run into this at some point and they may not have the ability or access to fix the corruption on the server side.

So, would be great to fix the code to protect against this.