Crash at startup with a specific spam

Support
1

Hi,
I recently received a spam, and it caused both K-9 Mail and FairEmail to crash when synchronizing. According to the maintainer of FairEmail, the root cause what the very long header. Maybe it’s the same for K-9 Email. Here is the header (with some text such as email addresses removed):

Return-Path: REDACTED_EMAIL
Received: from REDACTED_HOSTNAME (LHLO REDACTED_HOSTNAME)
 (REDACTED_IP) by REDACTED_HOSTNAME with LMTP; Wed, 13 Apr 2022
 16:32:51 +0200 (CEST)
Received: from [ec3804de8cea09ab7fab9c817dd7a474d8c743a561c714cb8c8348452edabe3929622f8886e5b9b6c780e9ad44296e1e9e5a50e9387feb5e16bde09ff1966b52accfaa0a141ba2dbf209111dbf32666d661563d9eef6ce798495dac908d1d7199760402f58e8f6f9be5f9dff7da43d559c2643878e12d921e06c89ecec66bd97748cf145873ddd4e20cdec664057a53ad1fc1c5c98ae7eb14798a544ab440a3d1bbef4ac1d20e04091f2eff84f63d8850b3d4bb3a0f950c61de339937591f2ac5eb4e00be6e9d1958da29c41c536211333b0629cbe666b23174a64bdcff409cd7f90714bf424c04bc4045b6e515321d6b6b35adade9dc9fe20fe9bba5228fabb1599a9aa8d9406726a53bb93d5c0cb0346945bd66f97fe62766494e81a1fb3d5dc49bb7a1c6d0eadc8408d4669850742b80aa52b26748c3b7b473cf7380b85deb35e31707cc7a6765aacc7324702423225dcfa99f9c76f1dd6a3b2cb3285e88dfdecd796a150d2e70081e2550ee82b03eb372123e517c22e80ab996ecf38852d22489de9f1f9f832bf486bf3910c77da9a9b54206a6e17c8aac26a2ced355a0eededd9fce49795caef721591077a5e2128ade12e2cece278b3c44eb6bdcfa9d24d89f15429926658fcf315dbaaaf2bd5af348ceb01143e12449c37efb34ed861765fc4fbe2878f
 c7d7e0a4bf093c7fd67c8e0b7b] (REDACTED_HOSTNAME [REDACTED_IP])
	by REDACTED_HOSTNAME (Postfix) with ESMTP id A6A85BC0EA4
	for <REDACTED_EMAIL>; Wed, 13 Apr 2022 16:32:41 +0200 (CEST)
Received: from [ec3804de8cea09ab7fab9c817dd7a474d8c743a561c714cb8c8348452edabe3929622f8886e5b9b6c780e9ad44296e1e9e5a50e9387feb5e16bde09ff1966b5 ([REDACTED_IP])
	by REDACTED_HOSTNAME (MXproxy) with ESMTPS for REDACTED_EMAIL
	(version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256);
	Wed, 13 Apr 2022 16:32:51 +0200 (CEST)

I could only start K-9 by either:

  • disabling the wi-fi
  • deleting the e-mail on the server using Thunderbird.

The e-mail itself contains some HTML and an image that does not look suspicious. Here is the e-mail (with the addresses and hostname redacted) as a zipped EML file. Scenario to reproduce:

  • Close K-9
  • Open the EML in Thunderbird. Move it to a IMAP folder.
  • Open K-9. It may crash. Otherwise, the email will be listed, and if you close K-9 and re-open it => it crashes.
  • Disable Wi-Fi (or mobile connection) and start K-9 => it does not crash, the e-mail is listed.
  • Close K-9, enable the Wi-Fi again, open K-9 => crash
  • Disable Wi-Fi, start K-9 and delete the e-mail => K-9 will not crash even if you restart it.

Cheers

2

The provided message doesn’t crash K-9 Mail for me. But it also doesn’t contain the proper line endings. It’s possible the editor you used to redact the header lines modified the file in a way that caused this difference in behavior.

Can you please provide a debug log? See LoggingErrors · k9mail/k-9 Wiki · GitHub

3

Here is the end of the log.

04-13 22:40:16.907 20168 20168 D Notification: allPendingIntents
04-13 22:40:16.908 20168 20168 V PushService: PushService.onDestroy()
04-13 22:40:16.910 20168 20168 D AndroidRuntime: Shutting down VM
--------- beginning of crash
04-13 22:40:16.910 20168 20168 E AndroidRuntime: FATAL EXCEPTION: main
04-13 22:40:16.910 20168 20168 E AndroidRuntime: Process: com.fsck.k9, PID: 20168
04-13 22:40:16.910 20168 20168 E AndroidRuntime: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground()
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1881)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:105)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:164)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:6944)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
04-13 22:40:16.910 20168 20168 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

Unfortunately it does not look very helpful.

4

That crash is unrelated to a specific email. It looks like a problem with starting the Push service. That also explains why the app doesn’t crash if you disable the network. In that case the Push service won’t be started.

Can you post a complete log?

5

The crash was 100% sure related to the e-mail. It disappeared when I remove the e-mail from the IMAP folder (using Thunderbird), and it comes back again when I add the mail again. I made sure to disable this email account in FairEmail (so its crash does not cause a side effect in K9; who knows, I don’t know much about Android system).

In FairEmail, I got this exception in the logs:
Caused by: java.lang.ClassNotFoundException: Didn't find class "android.graphics.ImageDecoder$OnHeaderDecodedListener" on path: […path here…]
Maybe my crash in K-9 has the same cause, and maybe it’s related to my version of Android (Samsung Galaxy A5 2017, Android 8.0.0).

Please find bellow the full log:

--------- beginning of main
04-14 19:42:32.262 27853 27853 E Zygote  : isWhitelistProcess - Process is Whitelisted
--------- beginning of system
04-14 19:42:32.263 27853 27853 E libpersona: scanKnoxPersonas
04-14 19:42:32.263 27853 27853 E libpersona: Couldn't open the File - /data/system/users/0/personalist.xml - No such file or directory
04-14 19:42:32.269 27853 27853 W SELinux : SELinux selinux_android_compute_policy_index : Policy Index[2],  Con:u:r:zygote:s0 RAM:SEPF_SM-A520F_8.0.0_0018, [-1 -1 -1 -1 0 1]
04-14 19:42:32.270 27853 27853 I SELinux : SELinux: seapp_context_lookup: seinfo=untrusted, level=s0:c512,c768, pkgname=com.fsck.k9 
04-14 19:42:32.310 27853 27853 D ActivityThread: Added TimaKeyStore provider
04-14 19:42:32.360 27853 27853 I zygote64: find the special shared library, skip check
04-14 19:42:32.682 27853 27853 V TracingPowerManager: Creating TracingPowerManager
04-14 19:42:32.696 27853 27853 D NetworkSecurityConfig: Using Network Security Config from resource network_security_config debugBuild: false
04-14 19:42:32.698 27853 27858 I zygote64: Do partial code cache collection, code=24KB, data=26KB
04-14 19:42:32.698 27853 27858 I zygote64: After code cache collection, code=24KB, data=26KB
04-14 19:42:32.698 27853 27858 I zygote64: Increasing code cache capacity to 128KB
04-14 19:42:32.713 27853 27853 V K9JobManager: scheduling all jobs
04-14 19:42:32.714 27853 27853 V K9JobManager: canceling mail sync job
04-14 19:42:32.723 27853 27853 I Core    : Registered: unmount receiver
04-14 19:42:32.724 27853 27853 V MessageProvider: Registering content resolver notifier
04-14 19:42:32.765 27853 27876 V PushController: PushController.initInBackground()
04-14 19:42:32.768 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.776 27853 27858 I zygote64: Compiler allocated 5MB to compile void com.fsck.k9.AccountPreferenceSerializer.loadAccount(com.fsck.k9.Account, com.fsck.k9.preferences.Storage)
04-14 19:42:32.794 27853 27858 I zygote64: Do partial code cache collection, code=56KB, data=42KB
04-14 19:42:32.794 27853 27858 I zygote64: After code cache collection, code=56KB, data=42KB
04-14 19:42:32.794 27853 27858 I zygote64: Increasing code cache capacity to 256KB
04-14 19:42:32.806 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.806 27853 27876 V PushServiceManager: PushServiceManager.start()
04-14 19:42:32.810 27853 27876 V BootCompleteManager: Enable BootCompleteReceiver
04-14 19:42:32.812 27853 27853 D skia    : approximate: numPoints=51, lengths[0]=0.000000, totalLength=620.200073, segmentPoints[0]=[-197.600006,0.000000]
04-14 19:42:32.812 27853 27853 D skia    : approximate: approximation[0]=0.000000, approximation[1]=-197.600006, approximation[2]=0.000000
04-14 19:42:32.812 27853 27853 D skia    : approximate: numPoints=51, lengths[50]=620.200073, totalLength=620.200073, segmentPoints[50]=[422.600037,0.000000]
04-14 19:42:32.812 27853 27853 D skia    : approximate: approximation[150]=1.000000, approximation[151]=422.600037, approximation[152]=0.000000
04-14 19:42:32.813 27853 27853 D skia    : approximate: numPoints=4, lengths[0]=0.000000, totalLength=3.448155, segmentPoints[0]=[0.000000,0.100000]
04-14 19:42:32.813 27853 27853 D skia    : approximate: approximation[0]=0.000000, approximation[1]=0.000000, approximation[2]=0.100000
04-14 19:42:32.813 27853 27853 D skia    : approximate: numPoints=4, lengths[3]=3.448155, totalLength=3.448155, segmentPoints[3]=[3.000000,0.100000]
04-14 19:42:32.813 27853 27853 D skia    : approximate: approximation[9]=1.000000, approximation[10]=3.000000, approximation[11]=0.100000
04-14 19:42:32.814 27853 27876 D ConnectivityManager: requestNetwork; CallingUid : 10207, CallingPid : 27853
04-14 19:42:32.814 27853 27853 D skia    : approximate: numPoints=47, lengths[0]=0.000000, totalLength=722.199951, segmentPoints[0]=[-522.599976,0.000000]
04-14 19:42:32.814 27853 27853 D skia    : approximate: approximation[0]=0.000000, approximation[1]=-522.599976, approximation[2]=0.000000
04-14 19:42:32.814 27853 27853 D skia    : approximate: numPoints=47, lengths[46]=722.199951, totalLength=722.199951, segmentPoints[46]=[199.600006,0.000000]
04-14 19:42:32.814 27853 27853 D skia    : approximate: approximation[138]=1.000000, approximation[139]=199.600006, approximation[140]=0.000000
04-14 19:42:32.815 27853 27853 D skia    : approximate: numPoints=3, lengths[0]=0.000000, totalLength=2.472497, segmentPoints[0]=[0.000000,0.100000]
04-14 19:42:32.815 27853 27853 D skia    : approximate: approximation[0]=0.000000, approximation[1]=0.000000, approximation[2]=0.100000
04-14 19:42:32.815 27853 27853 D skia    : approximate: numPoints=3, lengths[2]=2.472497, totalLength=2.472497, segmentPoints[2]=[2.000000,0.100000]
04-14 19:42:32.815 27853 27853 D skia    : approximate: approximation[6]=1.000000, approximation[7]=2.000000, approximation[8]=0.100000
04-14 19:42:32.823 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.824 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.824 27853 27876 V PushServiceManager: PushServiceManager.start()
04-14 19:42:32.824 27853 27876 V PushServiceManager: ..PushService already running
04-14 19:42:32.824 27853 27876 V BootCompleteManager: Enable BootCompleteReceiver
04-14 19:42:32.824 27853 27879 V ConnectivityManagerApi24$networkCallback: Network available: 507
04-14 19:42:32.827 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.828 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.828 27853 27876 V PushServiceManager: PushServiceManager.stop()
04-14 19:42:32.830 27853 27876 V BootCompleteManager: Disable BootCompleteReceiver
04-14 19:42:32.831 27853 27876 D ConnectivityManager: unregisterNetworkCallback; CallingUid : 10207, CallingPid : 27853
04-14 19:42:32.832 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.833 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.833 27853 27876 V PushServiceManager: PushServiceManager.stop()
04-14 19:42:32.833 27853 27876 V PushServiceManager: ..PushService is not running
04-14 19:42:32.833 27853 27876 V BootCompleteManager: Disable BootCompleteReceiver
04-14 19:42:32.834 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.835 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.835 27853 27876 V PushServiceManager: PushServiceManager.stop()
04-14 19:42:32.835 27853 27876 V PushServiceManager: ..PushService is not running
04-14 19:42:32.835 27853 27876 V BootCompleteManager: Disable BootCompleteReceiver
04-14 19:42:32.836 27853 27876 V PushController: PushController.updatePushers()
04-14 19:42:32.837 27853 27876 V PushController: ..Running PushControllers: []
04-14 19:42:32.837 27853 27876 V PushServiceManager: PushServiceManager.stop()
04-14 19:42:32.837 27853 27876 V PushServiceManager: ..PushService is not running
04-14 19:42:32.837 27853 27876 V BootCompleteManager: Disable BootCompleteReceiver
04-14 19:42:33.063 27853 27883 D OpenGLRenderer: HWUI GL Pipeline
04-14 19:42:33.070 27853 27853 D ViewRootImpl@c7976b1[MessageList]: setView = DecorView@fc7a796[MessageList] TM=true MM=false
04-14 19:42:33.073 27853 27853 V PushService: PushService.onCreate()
04-14 19:42:33.073 27853 27853 V PushService: PushService.onStartCommand()
04-14 19:42:33.079 27853 27853 D Notification: allPendingIntents
04-14 19:42:33.080 27853 27853 V PushService: PushService.onDestroy()
04-14 19:42:33.081 27853 27853 D AndroidRuntime: Shutting down VM
--------- beginning of crash
04-14 19:42:33.081 27853 27853 E AndroidRuntime: FATAL EXCEPTION: main
04-14 19:42:33.081 27853 27853 E AndroidRuntime: Process: com.fsck.k9, PID: 27853
04-14 19:42:33.081 27853 27853 E AndroidRuntime: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground()
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1881)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:105)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:164)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:6944)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
04-14 19:42:33.081 27853 27853 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

Unfortunately, I cannot reproduce the problem any more:

  • I built and installed a debug version (version 5.807 like my f-droid version) and I could not reproduce the issue. I tried to remove the debug mode and the minification and I still could not get the issue. But on the f-droid installation the issue was still there.
  • Then I replaced by mistake the f-droid version by my release build, and I could not reproduce the issue any more. Also now that I switched back to the f-droid version, I still cannot reproduce it. So I guess the investigation stops there :cry: