Reboot after network change with sd card inserted on Xperia XZ Premium

[Kareema]

Hi,

some days ago I got my new Xperia XZ Professional and I like it a lot 🙂

Yesterday, I finished the installation of all of my apps and encountered a really strange problem: With only some app data on my SD card, everything was fine. But after finishing my installation, I had reboots, when my network connection changed! This ony happens, when an SD card is inserted and the problem is reproducible. Test setting:

1. Disable Wifi on router or disable Wifi on phone via settings

2. After about ten seconds, the phone reboots

3. Remove SD card

4. Try point 1 again, no problem

5. Reinsert SD card

6. Same problem as before

I'm on Android 7.1.1 build number 45.0.A.1.229 and my sd card is a Lexar Professional 128GB High-Performance Class 10 UHS-I 600x 95MB/s Micro SDXC card. Here's the output of a exfatfsck under linux:

exfatfsck 1.2.5
WARN: volume was not unmounted cleanly.
Checking file system on /dev/sdb1.
File system version 1.0
Sector size 512 bytes
Cluster size 128 KB
Volume size 119 GB
Used space 70 GB
Available space 50 GB
Totally 880 directories and 42723 files.
File system checking finished. No errors found.

And a 'df -h' shows: 

Filesystem      Size  Used Avail Use%

/dev/sdb1       120G   70G   50G  59% 

As you can see, the sd card is heavily used, but this shouldn't be a problem. The warning about the unclean unmount is due to the sudden reboot of the phone, but the filesystem is consistent.

A 'adb logcat' before a reboot did not give me any insghts about the cause of the problem. But I'm not an Android programmer... perhaps I missed the essential messages due to inexperience in Android device debugging.

Any hint how to solve this strage issue would be appreciated!

[Kareema]

Intermediate answer to my problems: Seems that deleting all Spotify songs from my external SD card solved the problem with the reboots after a network change.

As a consequence, I reformatted the SD card and restored a backup of the contents. After that the SD card had a new name (seems to be generated randomly in the format XXXX-XXXX). Long story short: Some apps recognized the newly formatted SD card automatically (f.ex. Camera app), for some I had to change the path in the app settings manually (same as before) and some stopped working / don't recognize the SD card correctly / cannot write to the SD card anymore (f.ex. Sygic, MAPS.ME, Amazon Music).

Someone with similar experiences here?

[Kareema]

OK, here we go:

1. The problem with the phone reboots seems to be a Android timing issue in conjunction with sd card access of some third party apps like Spotify (with >18GB of offline music files on the sd card). But why a change in the network settings triggers a reboot is really strange and shouldn't happen! Would be nice, if this problem could be sorted out by the Sony devs or reported to Google.
   Maybe my old sd card is too slow - I will try to get a SanDisk Extreme 128 GB microSDXC class 10, U3, V30, A1 and test if the problem's gone then.
2. I followed Spotify's instructions in the [COMPLETE GUIDE] How to fix most Android issues, but couldn't get Spotify to recognize my sd card after reformatting it. Same with some other apps like Sygic or MAPS.ME.
   The system recognizes the sd card without problems and after purging data/cache of Spotify, deactivating the app, checking that 'Android/data/com.spotify.music' folder is deleted on internal storage and sd card, rebooting the phone and reactivating the app, a new folder 'Android/data/com.spotify.music' is created on both internal storage and sd card, but there's no option in Spotify to select the external sd card as storage after starting it. And when downloading music, it's stored on internal storage instead of the sd card.
   Same behaviour with MAPS.ME, Sygic freezes after selecting external storage. All these apps worked with their data on external sd card before reformatting the card.
   Maybe there's something wrong with filesystem symlinks to the external sd card - perhaps some leftovers from the previous sd card label before reformatting it?

Would be nice to get an answer from a support team member! Perhaps a suggestion what I could try to find the source of the remaining problem (second point) or some fix 😉

And please don't suggest to do a factory reset of the phone - I know that this would most certanly fix my second problem for the moment. But things like that shouldn't happen at all - so I'd like to know the reason why 🙂

[Kareema]

Summary of the last two days:

I tried everything that came to my mind in the last 2 days, but couldn't find a solution for some apps not recognizing my sd card after a reformat. Here's a short recapture of the problem with Spotify as an example:

• sdcard named B919-A751 was present during the first setup of the phone and Spotify asked me during the first startup, if I'd like to use the external storage --> I answered yes and everything was fine at first
• because of the reboots, I made a backup of the sdcard (tar-backup) and reformatted the sdcard; after reformatting, the sdcard had a new name (same format: 0F8A-9EFB). I restored the original data from a backup an reinserted the card into the phone
• after deleting cache and data of the Spotify app, I granted the app all the necessary rights, turned the phone off and on again and started Spotify
• after starting Spotify, there was no prompt to select the external sdcard this time; the sdcard is recognized correctly by the Android system and is writeable. Spotify even creates a folder /storage/0F8A-9EFB/Android/data/com.spotify.music with subfolders cache and files, but still the spotifycache is stored on the internal storage!!
• I ordered a new sdcard and tried the same procedure with exactly the same result 😞

[Kareema]

Ok, here's my daily post about this issue - no solution yet, but some more insight (maybe):

I looked at the debug logs of another app that's not working after reformatting my sd card: MAPS.ME - and here's the output:

06-14 20:08:47.141 I/com.mapswithme.maps.settings.StoragePathManager(32201): Additional storage path: /storage/3262-3632/Android/data/com.mapswithme.maps.pro/files
06-14 20:08:47.141 I/com.mapswithme.maps.settings.StoragePathManager(32201): Parsing /etc/vold.conf
06-14 20:08:47.142 W/StorageUtils(32201): Can't read file: /etc/vold.conf
06-14 20:08:47.142 W/StorageUtils(32201): java.io.FileNotFoundException: /etc/vold.conf (No such file or directory)
06-14 20:08:47.142 W/StorageUtils(32201): 	at java.io.FileInputStream.open(Native Method)
06-14 20:08:47.142 W/StorageUtils(32201): 	at java.io.FileInputStream.<init>(FileInputStream.java:146)
06-14 20:08:47.142 W/StorageUtils(32201): 	at java.io.FileInputStream.<init>(FileInputStream.java:99)
06-14 20:08:47.142 W/StorageUtils(32201): 	at java.io.FileReader.<init>(FileReader.java:58)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StorageUtils.parseMountFile(StorageUtils.java:94)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StorageUtils.parseStorages(StorageUtils.java:140)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StorageUtils.parseKitkatStorages(StorageUtils.java:166)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StoragePathManager.updateExternalStorages(StoragePathManager.java:158)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StoragePathManager.updateExternalStorages(StoragePathManager.java:150)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.StoragePathManager.startExternalStorageWatching(StoragePathManager.java:103)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.mapswithme.maps.settings.MapPrefsFragment.onAttach(MapPrefsFragment.java:219)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.Fragment.onAttach(Fragment.java:1454)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:941)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1175)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.BackStackRecord.run(BackStackRecord.java:816)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1589)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.FragmentController.execPendingActions(FragmentController.java:371)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.Activity.performStart(Activity.java:6740)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2683)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2781)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.ActivityThread.-wrap12(ActivityThread.java)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1508)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.os.Handler.dispatchMessage(Handler.java:102)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.os.Looper.loop(Looper.java:241)
06-14 20:08:47.142 W/StorageUtils(32201): 	at android.app.ActivityThread.main(ActivityThread.java:6281)
06-14 20:08:47.142 W/StorageUtils(32201): 	at java.lang.reflect.Method.invoke(Native Method)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:886)
06-14 20:08:47.142 W/StorageUtils(32201): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:776)
06-14 20:08:47.142 I/com.mapswithme.maps.settings.StoragePathManager(32201): Parsing /etc/vold.fstab
06-14 20:08:47.148 I/com.mapswithme.maps.settings.StoragePathManager(32201): Parsing /system/etc/vold.fstab
06-14 20:08:47.149 I/com.mapswithme.maps.settings.StoragePathManager(32201): Parsing /proc/mounts
06-14 20:08:47.153 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/runtime/default/3262-3632
06-14 20:08:47.153 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.143 W/withme.maps.pro(32201): type=1400 audit(0.0:546): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:547): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:548): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:549): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:550): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:551): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:552): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:553): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:554): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:555): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:556): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:557): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.154 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/media_rw/3262-3632
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:558): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:559): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:560): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.154 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:561): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.155 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/runtime/read/3262-3632
06-14 20:08:47.155 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.155 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /storage/sdcard1
06-14 20:08:47.155 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.156 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/secure/asec
06-14 20:08:47.156 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.156 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/media_rw/3262-3632.exfat
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:562): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:563): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:564): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:565): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:566): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:567): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.156 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.157 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /mnt/runtime/write/3262-3632
06-14 20:08:47.157 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.157 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /storage/3262-3632
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:568): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:569): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:570): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:571): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:572): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:573): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:574): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.166 I/com.mapswithme.maps.settings.StoragePathManager(32201): Storage found : /storage/emulated/0, size : 38909706240
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:575): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:576): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:577): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:578): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 20:08:47.169 I/com.mapswithme.maps.settings.StoragePathManager(32201): Storage found : /storage/emulated/0, size : 38909706240

As you can see from the first line, the app path on the SD card could be found correctly: 

Additional storage path: /storage/3262-3632/Android/data/com.mapswithme.maps.pro/files

But there seems to be a problem writing to the path (access denied):

06-14 20:08:47.157 I/com.mapswithme.maps.settings.StoragePathManager(32201): Try to create MWM path
06-14 20:08:47.157 I/com.mapswithme.maps.settings.StoragePathManager(32201): Test storage from config files : /storage/3262-3632
06-14 20:08:47.153 W/withme.maps.pro(32201): type=1400 audit(0.0:568): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"

Well, I don't know how the normal behavior should be - I checked that I granted the app all necessary rights (especially storage). But it's the same as with Spotify - the menu point to save the data to sd card just isn't there... I already reported the problem to MAPS.ME.

Is here somebody here in the forum who can make a bit more sense about the relevant messages in the log?

[Kareema]

And some more logs from starting Spotify this time (after app force close/purge app cache/purge app data and granting necessary rights manually):

Excerpt of adb logcat output filtered by "com.spotify.music":

...
06-14 22:04:15.431 3200 3345 I ActivityManager: Start proc 27315:com.spotify.music/u0a178 for activity com.spotify.music/.MainActivity
06-14 22:04:15.532 20116 20116 D KP2AAF : event: 2048, package = com.spotify.music
06-14 22:04:15.548 20116 20116 D KP2AAF : event: 32, package = com.spotify.music
06-14 22:04:15.637 20116 20116 D KP2AAF : event: 2048, package = com.spotify.music
06-14 22:04:15.888 3200 4756 D VoldConnector: SND -> {91 volume mkdirs /storage/3262-3632/Android/data/com.spotify.music/cache/}
06-14 22:04:16.247 27315 27315 W m.spotify.music: type=1400 audit(0.0:1826): avc: denied { write } for name="com.spotify.music" dev="ecryptfs" ino=17437088 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.247 27315 27315 W m.spotify.music: type=1400 audit(0.0:1827): avc: denied { write } for name="com.spotify.music" dev="ecryptfs" ino=17437088 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.247 4753 4753 W Binder:3200_B: type=1400 audit(0.0:1828): avc: denied { read open } for path="/mnt/media_rw/3262-3632.exfat/Android/data/com.spotify.music" dev="mmcblk0p1" ino=17437088 scontext=u:r:system_server:s0 tcontext=u:object_r:vfat:s0 tclass=dir permissive=0 ppid=2732 pcomm="main" pgid=3200 pgcomm="system_server"
06-14 22:04:16.258 3200 4753 D VoldConnector: SND -> {92 volume mkdirs /storage/3262-3632/Android/data/com.spotify.music/files/}
...

 My current mountpoints:

G8141:/ $ mount
rootfs on / type rootfs (ro,seclabel,size=1802908k,nr_inodes=450727)
tmpfs on /dev type tmpfs (rw,seclabel,nosuid,relatime,size=1893892k,nr_inodes=473473,mode=755)
devpts on /dev/pts type devpts (rw,seclabel,relatime,mode=600)
proc on /proc type proc (rw,relatime,gid=3009,hidepid=2)
sysfs on /sys type sysfs (rw,seclabel,relatime)
selinuxfs on /sys/fs/selinux type selinuxfs (rw,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,seclabel,relatime)
none on /acct type cgroup (rw,relatime,cpuacct)
none on /dev/stune type cgroup (rw,relatime,schedtune)
tmpfs on /mnt type tmpfs (rw,seclabel,relatime,size=1893892k,nr_inodes=473473,mode=755,gid=1000)
none on /config type configfs (rw,relatime)
none on /dev/memcg type cgroup (rw,relatime,memory)
none on /dev/cpuctl type cgroup (rw,relatime,cpu)
none on /dev/cpuset type cgroup (rw,relatime,cpuset,noprefix,release_agent=/sbin/cpuset_release_agent)
pstore on /sys/fs/pstore type pstore (rw,seclabel,relatime)
none on /sys/fs/cgroup type tmpfs (rw,seclabel,relatime,size=1893892k,nr_inodes=473473,mode=750,gid=1000)
none on /sys/fs/cgroup/memory type cgroup (rw,relatime,memory)
tmpfs on /tmp type tmpfs (rw,seclabel,nosuid,relatime,size=1893892k,nr_inodes=473473,mode=755)
/dev/block/dm-0 on /system type ext4 (ro,seclabel,relatime,discard,data=ordered)
/dev/block/bootdevice/by-name/oem on /oem type ext4 (ro,seclabel,relatime,data=ordered)
/dev/block/bootdevice/by-name/cache on /cache type ext4 (rw,seclabel,nosuid,nodev,noatime,discard,data=ordered)
/dev/block/bootdevice/by-name/appslog on /rca type ext4 (rw,seclabel,nosuid,nodev,noexec,noatime,discard,data=ordered)
/dev/block/bootdevice/by-name/diag on /idd type ext4 (rw,seclabel,nosuid,nodev,noexec,noatime,discard,data=ordered)
/dev/block/bootdevice/by-name/Qnovo on /qns type ext4 (rw,seclabel,nosuid,nodev,noexec,noatime,discard,data=ordered)
/dev/block/bootdevice/by-name/persist on /persist type ext4 (rw,seclabel,nosuid,nodev,relatime,data=ordered)
/dev/block/bootdevice/by-name/dsp on /dsp type ext4 (ro,seclabel,nosuid,nodev,relatime,data=ordered)
/dev/block/bootdevice/by-name/modem on /firmware type vfat (ro,context=u:object_r:firmware_file:s0,relatime,uid=1000,gid=1000,fmask=0337,dmask=0227,codepage=437,iocharset=iso8859-1,shortname=lower,errors=remount-ro)
/dev/block/bootdevice/by-name/bluetooth on /bt_firmware type vfat (ro,context=u:object_r:bt_firmware_file:s0,relatime,uid=1002,gid=3002,fmask=0337,dmask=0227,codepage=437,iocharset=iso8859-1,shortname=lower,errors=remount-ro)
/dev/block/bootdevice/by-name/LTALabel on /lta-label type ext4 (ro,context=u:object_r:lta_label:s0,nosuid,nodev,noexec,noatime,data=ordered)
tmpfs on /storage type tmpfs (rw,seclabel,relatime,size=1893892k,nr_inodes=473473,mode=755,gid=1000)
tracefs on /sys/kernel/debug/tracing type tracefs (rw,seclabel,relatime)
adb on /dev/usb-ffs/adb type functionfs (rw,relatime)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
/dev/block/dm-1 on /data type ext4 (rw,seclabel,nosuid,nodev,noatime,discard,noauto_da_alloc,data=ordered)
/data/media on /mnt/runtime/default/emulated type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,multiuser,allow_utime_grp)
/data/media on /storage/emulated type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,multiuser,allow_utime_grp)
/data/media on /mnt/runtime/read/emulated type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,multiuser,allow_utime_grp)
/data/media on /mnt/runtime/write/emulated type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,multiuser,allow_utime_grp)
/dev/block/vold/public:179,1 on /mnt/media_rw/3262-3632.exfat type texfat (rw,dirsync,nosuid,nodev,noexec,relatime,uid=1023,gid=1023,umask=0007,allow_utime=0020,utf8,min_prealloc_size=64k,max_prealloc_size=121910k,writeback_boundary=4M,readahead=4M,fail_safe,discard,hidden=show,errors=continue)
/mnt/media_rw/3262-3632.exfat on /mnt/media_rw/3262-3632 type ecryptfs (rw,relatime,ecryptfs_sig=df437334546623b0,ecryptfs_cipher=aes,ecryptfs_key_bytes=32,ecryptfs_enable_filtering,ecryptfs_passthrough,ecryptfs_unlink_sigs)
/dev/block/vold/public:179,1 on /mnt/secure/asec type texfat (rw,dirsync,nosuid,nodev,noexec,relatime,uid=1023,gid=1023,umask=0007,allow_utime=0020,utf8,min_prealloc_size=64k,max_prealloc_size=121910k,writeback_boundary=4M,readahead=4M,fail_safe,discard,hidden=show,errors=continue)
/mnt/media_rw/3262-3632 on /mnt/runtime/default/3262-3632 type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,allow_utime_grp)
/mnt/media_rw/3262-3632 on /storage/3262-3632 type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,allow_utime_grp)
/mnt/media_rw/3262-3632 on /mnt/runtime/read/3262-3632 type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,allow_utime_grp)
/mnt/media_rw/3262-3632 on /mnt/runtime/write/3262-3632 type sdcardfs (rw,nosuid,nodev,noexec,noatime,uid=1023,gid=1023,allow_utime_grp)

[JensG]

Hi @Kareema sorry to hear about your problem. You've done a really good job with investigation so far, my apologies for not seeing it earlier.

Do you regularly access the SD-card directly from PC or was that mainly because of this investigation?

The first crash is really interesting, but let's focus on your current situation first. I can't say that I've heard of this problem before and unfortunately I can already say that I currently don't have the solution at hand. Let's see what we can learn together.

One thing I know is that the XXXX-XXXX card name is kept if you move the card to another phone. So it's not that random, but kept on the card as a "unique identifier". Would be interesting to see if it could be renamed. Actually I didn't think it would get new name from a "format".

Did you format the external card in the phone or PC?
Did you try installing Spotify new on the phone with the External Card clean formatted (not restored backup)? You said "reactivating the app" so I wasn't sure if that was a clean install or not.
Was the backup you have created before or after the first crash (and FS corruption/repair)?
Do you have another phone where you can insert the SD-card and see what happens with Spotify there?

If we could clarify how the problem relates to "this phone", "the new card name", "the backup content" separately I think that could help.

> created on both internal storage and sd card, but there's no option in Spotify to select the external sd card as storage

The Spotify page said that they hide the option if the card is corrupt or missing. It's confusing that folders are created, but still not accessed.

On the other hand it seems to be Vold rather than Spotify that does the actual mkdir. Vold is a system process with special rights and it could be allowed even if app is denied access.

06-14 22:04:15.888 3200 4756 D VoldConnector: SND -> {91 volume mkdirs /storage/3262-3632/Android/data/com.spotify.music/cache/}
06-14 22:04:16.247 27315 27315 W m.spotify.music: type=1400 audit(0.0:1826): avc: denied { write } for name="com.spotify.music" dev="ecryptfs" ino=17437088 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"

The "avc: denied" is controlled by kernel "SELinux rules". All installed apps are "untrusted_app" (with rather limited permissions) and I suspect that the denial is all according to plans here. So a bit of a question why it worked first time and what changed since then.

Did the following log continue successful, or with similar "avc: denied" there?

06-14 22:04:16.258 3200 4753 D VoldConnector: SND -> {92 volume mkdirs /storage/3262-3632/Android/data/com.spotify.music/files/}
...

The interesting part is that (if they access it correctly) the app should have access rights to "their own" data under "Android/data/com.spotify.music/". If it could access the "files" but not "cache" it could be due to encryption.

In your mount list everything looks good, but I didn't have this one:

/mnt/media_rw/3262-3632.exfat on /mnt/media_rw/3262-3632 type ecryptfs (rw,relatime,ecryptfs_sig=df437334546623b0,ecryptfs_cipher=aes,ecryptfs_key_bytes=32,ecryptfs_enable_filtering,ecryptfs_passthrough,ecryptfs_unlink_sigs)

Do you know what created that mount?
Can you run these commands and post the output? We want to see that the file permissions looks ok.

adb shell ls -l /storage/*-*/Android/data/com.spotify.music/*
adb shell ls -l /storage/self/primary/Android/data/com.spotify.music/*

> Some apps recognized the newly formatted SD card automatically (f.ex. Camera app),

Camera app is pre-installed and given special rigts.

> for some I had to change the path in the app settings manually (same as before)

Did you have any interesting app examples here? Perhaps there's a pattern to see.

> logs of another app that's not working after reformatting my sd card: MAPS.ME

I'm not familiar with the app, but the log looks a bit like a mess. I guess it's trying all kinds of things to work on as many platforms as possible, but I think it's correct to block several of those attempts for an "untrusted_app".

It's not exactly clear from the logs what happens, but reading directly at /storage/3262-3632 may be off limits. The "new way" is to ask the system for a private path.
https://stackoverflow.com/questions/5694933/find-an-external-sd-card-location

> I checked that I granted the app all necessary rights (especially storage)

Can you screen shot that for reference?

> And please don't suggest to do a factory reset of the phone

Hmm. I understand your thought, but we may end up there eventually. Less work now than later...

// Jens

[Kareema]

Hi @JensG

I'm glad to have somebody to talk about this issue - thank you very much! Here are the answers to your questions - hope this helps a bit to find a solution 🙂

>Do you regularly access the SD-card directly from PC or was that mainly because of this investigation?

I nearly never use the SD card directly on my computer - only for investigation of issues or for restoring data. Backup of all accessible files on the phone is done via SSHdroid and rsync to my BackupPC server on my network via Wifi 🙂

>Actually I didn't think it would get new name from a "format".

Well, I was a bit surprised as well: Every reformat on the device results in a new label - I tried it several times with the same SD card.

>Did you format the external card in the phone or PC?

I tried both at first - but to have reproducable results, the last few reformats were done on the phone.

>Did you format the external card in the phone or PC?

>Did you try installing Spotify new on the phone with the External Card clean formatted (not restored backup)? 

I tried both: I "reinstalled" Spotify after a clean format of the SD card and after restoring a backup of the SD card.

As Spotify comes pre-installed on the Xperia XZ Premium, "reinstall" means deactivating and reactivating the app (sorry for the confusion, hope you can understand what I mean). For reproducability, my normal procedure now with all the apps I investigate in regard to this issue is the following:

1. Force close the app under app settings
2. Purge app cache and app data
3. Uninstall/Deactivate app
4. Check that the app directories are deleted in external storage and on the SD card (under Android/data/)
5. Turn the device off and on again
6. Reinstall/reactivate the app and update to latest version
7. Check/activate app permissions (especially storage)
8. Start the app

>Was the backup you have created before or after the first crash (and FS corruption/repair)?

Unfortunately, the backup was made after the first crash. But as I tried the same with a newly formatted SD card, this isn't the root of the problem.

>Do you have another phone where you can insert the SD-card and see what happens with Spotify there?

Sorry, no phone with an external SD card slot ATM.

>If we could clarify how the problem relates to "this phone", "the new card name", "the backup content" separately I think that could help.

I already tried to narrow down the problem - here my thoughts about it:

• "this phone": I don't think it's phone/hardware-related. The apps (Spotify/MAPS.ME/Sygic) stored their data correctly after the initial installation. I downloaded all the Spotify songs, MAPS.ME and Sygic maps on my SD card. The problems started after reformatting the card the first time (in the device) and the corresponding change of the card name.
• "the new card name": Yes, this could be true. That's one reason I bought a second SD card and hoped that the problem would disappear with that (yes I know, that's a bit of wishful thinking - but I thought that perhaps some kind of hardware id of the card is linked to the device or something strange like that (UUID magic); or maybe really a hardware issue with the old card)
• "backup content": no, not possible as I already tried Spotify/MAPS.ME/Sygic with a cleanly formatted SD card (formatted via phone)

>Did the following log continue successful, or with similar "avc: denied" there?

Here are the spotify related logs after the timestamp:

Spoiler

06-14 22:04:16.247 27315 27315 W m.spotify.music: type=1400 audit(0.0:1826): avc: denied { write } for name="com.spotify.music" dev="ecryptfs" ino=17437088 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.247 27315 27315 W m.spotify.music: type=1400 audit(0.0:1827): avc: denied { write } for name="com.spotify.music" dev="ecryptfs" ino=17437088 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.247 4753 4753 W Binder:3200_B: type=1400 audit(0.0:1828): avc: denied { read open } for path="/mnt/media_rw/3262-3632.exfat/Android/data/com.spotify.music" dev="mmcblk0p1" ino=17437088 scontext=u:r:system_server:s0 tcontext=u:object_r:vfat:s0 tclass=dir permissive=0 ppid=2732 pcomm="main" pgid=3200 pgcomm="system_server"
06-14 22:04:16.258 3200 4753 D VoldConnector: SND -> {92 volume mkdirs /storage/3262-3632/Android/data/com.spotify.music/files/}
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1829): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1830): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1831): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1832): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1833): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1834): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1835): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1836): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1837): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1838): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1839): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1840): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1841): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1842): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1843): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1844): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.257 27315 27315 W m.spotify.music: type=1400 audit(0.0:1845): avc: denied { getattr } for path="/mnt/media_rw" dev="tmpfs" ino=21872 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:mnt_media_rw_file:s0 tclass=dir permissive=0 ppid=2733 pcomm="main" pgid=2733 pgcomm="main"
06-14 22:04:16.383 3765 4312 V Avrcp : Focus gained for player: com.spotify.music
06-14 22:04:16.383 3765 4312 V Avrcp : processRCCStateChange: com.spotify.music
06-14 22:04:16.383 3765 4312 V Avrcp : setting com.spotify.music focus: false

>The interesting part is that (if they access it correctly) the app should have access rights to "their own" data under "Android/data/com.spotify.music/". If it could access the "files" but not "cache" it could be due to encryption.

Time to remember some additional info: Before my initial problems with the network connectivity related reboots occured, I tried to encrypt my external SD card. Since then I decrypted the SD card (and never tried to encrypt the data on the SD card again), deleted most of the files on the SD card, reformatted the SD card several times (with and without restoring the data), replaced the SD card with a new one.

But it's not impossible, that the first encryption of the SD card triggered a bug... something to keep in mind!!

>In your mount list everything looks good, but I didn't have this one

Yes, that's something that I found strange as well! The name "3262-3632" corresponds to my newly bought SD card (SanDisk Extreme 128 GB). This card was never encrypted! So I wouldn't expect an ecryptfs entry in the mount output. The device security settings say, that the SD card encryption is deactivated.

>Do you know what created that mount?

No, not really - see my comments above 😞

>Can you run these commands and post the output? We want to see that the file permissions looks ok.

As you wanted to see the permissions, I modified the ls parameters slightly to show file and SELinux permissions 😉

~$ adb shell ls -alZ /storage/*-*/Android/data/com.spotify.music/*
/storage/3262-3632/Android/data/com.spotify.music/cache:
total 512
drwxrwx--x 1 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 131072 2017-06-16 17:52 .
drwxrwx--x 1 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 131072 2017-06-16 17:52 ..

/storage/3262-3632/Android/data/com.spotify.music/files:
total 512
drwxrwx--x 1 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 131072 2017-06-16 17:52 .
drwxrwx--x 1 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 131072 2017-06-16 17:52 ..

~$ adb shell ls -alZ /storage/self/primary/Android/data/com.spotify.music/*
/storage/self/primary/Android/data/com.spotify.music/cache:
total 24
drwxrwx--x 3 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:54 .
drwxrwx--x 4 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:52 ..
drwxrwx--x 3 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:54 video

/storage/self/primary/Android/data/com.spotify.music/files:
total 24
drwxrwx--x 3 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:52 .
drwxrwx--x 4 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:52 ..
drwxrwx--x 4 u0_a178 sdcard_rw u:object_r:sdcardfs:s0 4096 2017-06-16 17:54 spotifycache

~$ adb shell ps -Z | grep spotify
u:r:untrusted_app:s0:c512,c768 u0_a178   6599  2769  1970136 120156          0 0000000000 S com.spotify.music
~$ adb shell id u0_a178
uid=10178(u0_a178) gid=10178(u0_a178) groups=10178(u0_a178), context=u:r:shell:s0

>Did you have any interesting app examples here? Perhaps there's a pattern to see.

Woah! How ignorant of me 😞

I checked these apps only by starting them briefly, but didn't redownload contents. In fact, even those apps that are configured with a static path on the SD card can't access their private directory for writing! Here are some examples of these apps: OruxMap, Aedict, AnkiDroid
OK, but that was once again with a restored backup of the SD card contents; so let's delete the contents of the "Android" folder and the empty ".android_scure" folder on the SD card this time (don't want to initiate a renaming of the SD card name this time). Done on my Linux laptop. Result:

Aedict3 says it can't create the directory /storage/3262-3632/Android/data/sk.baka.aedict3/files/ on the sd card. I created it manually and tried again. This time the error is:

Aedict3 trying to download dictionaries

And here's the adb ls output for the directories:

Spoiler

~$ adb shell ls -al /storage/*-*/Android/data/
total 5120
drwxrwx--x 1 root sdcard_rw 131072 2017-06-15 21:37 .
drwxrwx--x 1 root sdcard_rw 131072 2017-06-15 21:17 ..
-rwxrwx--x 1 root sdcard_rw 0 2017-06-15 21:17 .nomedia
drwxrwx--x 1 u0_a239 sdcard_rw 131072 2017-06-15 21:34 com.bubblesoft.android.bubbleupnp
drwxrwx--x 1 u0_a240 sdcard_rw 131072 2017-06-15 21:17 com.busuu.android.enc
drwxrwx--x 1 u0_a258 sdcard_rw 131072 2017-06-15 21:36 com.dropbox.android
drwxrwx--x 1 u0_a299 sdcard_rw 131072 2017-06-15 21:34 com.google.android.apps.inbox
drwxrwx--x 1 u0_a130 sdcard_rw 131072 2017-06-15 21:17 com.google.android.apps.maps
drwxrwx--x 1 u0_a132 sdcard_rw 131072 2017-06-15 21:17 com.google.android.music
drwxrwx--x 1 u0_a338 sdcard_rw 131072 2017-06-15 21:18 com.microsoft.skydrive
drwxrwx--x 1 u0_a221 sdcard_rw 131072 2017-06-15 21:17 com.sand.airdroid
drwxrwx--x 1 u0_a197 sdcard_rw 131072 2017-06-15 21:17 com.sony.tvsideview.phone
drwxrwx--x 1 u0_a81 sdcard_rw 131072 2017-06-15 21:34 com.sonyericsson.album
drwxrwx--x 1 u0_a143 sdcard_rw 131072 2017-06-15 21:34 com.sonymobile.email
drwxrwx--x 1 u0_a162 sdcard_rw 131072 2017-06-15 21:17 com.sonymobile.xperiatransfermobile
drwxrwx--x 1 u0_a178 sdcard_rw 131072 2017-06-15 21:17 com.spotify.music
drwxrwx--x 1 u0_a180 sdcard_rw 131072 2017-06-15 21:17 com.touchtype.swiftkey
drwxrwx--x 1 u0_a234 sdcard_rw 131072 2017-06-15 21:17 com.voltasit.obdeleven
drwxrwx--x 1 u0_a341 sdcard_rw 131072 2017-06-15 21:17 de.avm.android.myfritz2
drwxrwx--x 1 u0_a328 sdcard_rw 131072 2017-06-15 21:34 jp.naver.line.android
drwxrwx--x 1 u0_a218 sdcard_rw 131072 2017-06-15 21:37 sk.baka.aedict3
:~$ adb shell ls -al /storage/*-*/Android/data/sk.baka.aedict3/
total 768
drwxrwx--x 1 u0_a218 sdcard_rw 131072 2017-06-15 21:37 .
drwxrwx--x 1 root sdcard_rw 131072 2017-06-15 21:37 ..
drwxrwx--x 1 u0_a218 sdcard_rw 131072 2017-06-15 21:37 files
:~$ adb shell ls -al /storage/*-*/Android/data/sk.baka.aedict3/files/
total 512
drwxrwx--x 1 u0_a218 sdcard_rw 131072 2017-06-15 21:37 .
drwxrwx--x 1 u0_a218 sdcard_rw 131072 2017-06-15 21:37 ..

And the user Aedict3 is running under:

Spoiler

~$ adb shell ps | grep aedict
u0_a218 17519 2732 2388448 92404 0 0000000000 S sk.baka.aedict3

Hmm, strange indeed... "rwx" rights of the dirs for u0_a218 are right... and the app rights for storage have been granted (like in the picture for Spotify further down).

Well it's getting late here in Germany - so I'll stop at this point. If I can help with more logs/info/etc. please let me know! I really want to know what's the source of this strange problem!

Here's the last point you asked about (sorry, did't switch language to English - "Speicher" means "storage":

>I checked that I granted the app all necessary rights (especially storage)

>Can you screen shot that for reference?

App rights for Spotify

Ok, to sum it up: Most apps (not including system apps) are unable to access their private path under Android/data/ on the SD card. I do not say "all" because I didn't test all apps yet. The directory rights checked via adb and ls seem to be correct and correspond to the user ids of the running process of the app.

It starts to get really interesting! Well I would be happy if you could spare some more time to debug this strange behaviour... 🙂

Best regards

- Kareema

[Kareema]

UPDATE: adb-log of Aedict3 start:

Spoiler

~/tmp/xperia_xz_premium_debugging$ egrep -i "aedict|3262-3632" adb-all-aedict.log
06-15 21:09:43.478 652 661 E ProcessKiller: Process com.ichi2.anki (29766) has open file /storage/3262-3632/Android/data/com.ichi2.anki/files/AnkiDroid/collection.anki2
06-15 21:16:58.461 652 661 V vold : 3262-3632
06-15 22:19:19.332 4810 4810 I Timeline: Timeline: Activity_launch_request id:sk.baka.aedict3 time:102695084
06-15 22:19:19.334 3200 3364 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=sk.baka.aedict3/.search.MainActivity bnds=[540,216][798,514]} from uid 10083 on display 0
06-15 22:19:19.356 3200 3364 D ActivityTrigger: activityStartTrigger: Activity is Triggerred in full screen ApplicationInfo{7777b4e sk.baka.aedict3}
06-15 22:19:19.356 3200 3364 E ActivityTrigger: activityStartTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.search.MainActivity/33936
06-15 22:19:19.358 3200 3364 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:19.358 3200 3364 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.search.MainActivity/33936
06-15 22:19:19.362 3200 3362 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:19.362 3200 3362 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.search.MainActivity/33936
06-15 22:19:19.372 3200 3362 I ActivityManager: Start proc 28565:sk.baka.aedict3/u0a218 for activity sk.baka.aedict3/.search.MainActivity
06-15 22:19:19.492 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:19.495 14810 14810 D KP2AAF : event: 32, package = sk.baka.aedict3
06-15 22:19:19.505 28565 28565 I s*.b*.a*.AedictApp: Running on ordinary Android device
06-15 22:19:19.525 28565 28565 I s*.b*.a*.AedictApp: Storing the dictionaries to the following path: /storage/3262-3632/Android/data/sk.baka.aedict3/files/aedict3/dictionaries
06-15 22:19:19.525 28565 28565 I s*.b*.a*.AedictApp: Dictionary updates will be checked in 81463 seconds
06-15 22:19:19.527 28565 28565 I s*.b*.a*.c*.FileStorage: SDCard Aedict root set to /storage/emulated/0/aedict3
06-15 22:19:19.527 28565 28565 I s*.b*.a*.AedictApp: Reinit user data
06-15 22:19:19.578 28565 28565 I s*.b*.a*.AedictApp: UserData is now sk.baka.aedict.userdatastorage.couchbaselite.UserDataCBL@2145a0e
06-15 22:19:19.578 28565 28565 I s*.b*.a*.AedictApp: userid=452
06-15 22:19:19.583 28565 28565 W s*.b*.a*.AedictApp: Started CouchBaseLite replicators for userid 452 to https://aedict-online.eu:4984/db
06-15 22:19:19.583 28565 28565 I s*.b*.a*.AedictApp: User Data backend: sk.baka.aedict.userdatastorage.couchbaselite.UserDataCBL@2145a0e
06-15 22:19:19.583 28565 28565 I s*.b*.a*.AedictApp: AedictApp started in 78ms (prefs: 20ms, setRoot: 2ms, open-database: 56ms, start-services: 0ms)
06-15 22:19:19.645 28565 28565 I MainActivity: Starting Aedict 3.39.36 de_DE UTF-8
06-15 22:19:20.006 28565 28565 I Timeline: Timeline: Activity_launch_request id:sk.baka.aedict3 time:102695758
06-15 22:19:20.007 3200 4757 I ActivityManager: START u0 {cmp=sk.baka.aedict3/.WelcomeActivity} from uid 10218 on display 0
06-15 22:19:20.008 3200 4757 D ActivityTrigger: activityStartTrigger: Activity is Triggerred in full screen ApplicationInfo{7777b4e sk.baka.aedict3}
06-15 22:19:20.008 3200 4757 E ActivityTrigger: activityStartTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.WelcomeActivity/33936
06-15 22:19:20.009 3200 4757 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:20.009 3200 4757 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.WelcomeActivity/33936
06-15 22:19:20.012 3200 3869 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:20.012 3200 3869 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.WelcomeActivity/33936
06-15 22:19:20.115 3200 4731 I InputDispatcher: Focus entered window: Window{65c2089 u0 sk.baka.aedict3/sk.baka.aedict3.WelcomeActivity}
06-15 22:19:20.153 3200 3265 I ActivityManager: Displayed sk.baka.aedict3/.WelcomeActivity: +141ms (total +791ms)
06-15 22:19:20.153 3200 3265 I Timeline: Timeline: Activity_windows_visible id: ActivityRecord{d4bb851 u0 sk.baka.aedict3/.WelcomeActivity t1595} time:102695904 diff:144 start:lukewarm|top-activity batt:89|2 mw:off|1 mem:976732|0|94|27|24 cpu:[1900800, 1900800, 1900800, 1900800, 2361600, 2361600, 2361600, 2361600]
06-15 22:19:20.223 14810 14810 D KP2AAF : event: 32, package = sk.baka.aedict3
06-15 22:19:20.307 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:23.066 28565 28565 I Timeline: Timeline: Activity_launch_request id:sk.baka.aedict3 time:102698818
06-15 22:19:23.070 3200 4756 I ActivityManager: START u0 {cmp=sk.baka.aedict3/.dict.download.DownloadActivity (has extras)} from uid 10218 on display 0
06-15 22:19:23.072 3200 4756 D ActivityTrigger: activityStartTrigger: Activity is Triggerred in full screen ApplicationInfo{7777b4e sk.baka.aedict3}
06-15 22:19:23.072 3200 4756 E ActivityTrigger: activityStartTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.dict.download.DownloadActivity/33936
06-15 22:19:23.076 3200 4756 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:23.076 3200 4756 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.dict.download.DownloadActivity/33936
06-15 22:19:23.103 3200 3364 D ActivityTrigger: activityResumeTrigger: The activity in ApplicationInfo{7777b4e sk.baka.aedict3} is now in focus and seems to be in full-screen mode
06-15 22:19:23.103 3200 3364 E ActivityTrigger: activityResumeTrigger: not whiteListedsk.baka.aedict3/sk.baka.aedict3.dict.download.DownloadActivity/33936
06-15 22:19:23.139 17702 17742 D BaseStreamManager: Promised set @ r#166869 for (sk.baka.aedict3,tag=null,id=25,notifKey=0|sk.baka.aedict3|25|null|10218)
06-15 22:19:23.145 17702 17745 D DynamicBucketRankerImpl: StreamItemId{notifKey=0|sk.baka.aedict3|25|null|10218, packageName=sk.baka.aedict3, id=25, revision=166869, originalRevision=166869, updateCount=0} in bucket #3 (Ongoing)
06-15 22:19:23.146 17702 17745 D WatchStreamDB: StreamItem[StreamItemId{notifKey=0|sk.baka.aedict3|25|null|10218, packageName=sk.baka.aedict3, id=25, revision=166869, originalRevision=166869, updateCount=0},StreamItemDataImpl[title=6 chars creatorNode=null, originalPackageName=sk.baka.aedict3, localPackageName=sk.baka.aedict3, tag=null, appName=Aedict, postTime=1497557963095, lastDiffedTime=1497557963095, lastInterruptTime=0, user=UserHandle{0}, onlyAlertOnce=false, vibration pattern=null, interruptive=false, summary=false, hasCustomContentView=false, dismissalId=null, bridgeTag=null]] ranked at index 2
06-15 22:19:23.148 17702 17745 D DatabaseEventLogger: StreamItemId{notifKey=0|sk.baka.aedict3|25|null|10218, packageName=sk.baka.aedict3, id=25, revision=166869, originalRevision=166869, updateCount=0}
06-15 22:19:23.148 17702 17745 D DatabaseEventLogger: StreamItemId{notifKey=0|sk.baka.aedict3|25|null|10218, packageName=sk.baka.aedict3, id=25, revision=166869, originalRevision=166869, updateCount=0}
06-15 22:19:23.156 3200 3362 I InputDispatcher: Focus entered window: Window{4ba5b66 u0 sk.baka.aedict3/sk.baka.aedict3.dict.download.DownloadActivity}
06-15 22:19:23.199 3200 3265 I ActivityManager: Displayed sk.baka.aedict3/.dict.download.DownloadActivity: +95ms
06-15 22:19:23.267 14810 14810 D KP2AAF : event: 32, package = sk.baka.aedict3
06-15 22:19:23.284 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:23.296 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:23.308 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:23.349 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:23.373 3200 3265 I Timeline: Timeline: Activity_windows_visible id: ActivityRecord{3eddf9a u0 sk.baka.aedict3/.dict.download.DownloadActivity t1595} time:102699120 diff:292 start:lukewarm|top-activity batt:89|2 mw:off|1 mem:980416|0|94|28|24 cpu:[1900800, 1900800, 1900800, 1900800, 2361600, 2361600, 2361600, 2361600]
06-15 22:19:24.114 28565 28625 I s*.b*.a*.u*.LoaderEx: Loader #1 sk.baka.aedict3.dict.download.DictionaryListView$MyLoader@1d847b3: returned 22 item(s) in 977ms (scheduled: 0ms, running: 977ms)
06-15 22:19:24.223 14810 14810 D KP2AAF : event: 2048, package = sk.baka.aedict3
06-15 22:19:24.216 28624 28624 W Thread-12: type=1400 audit(0.0:5521): avc: denied { write } for name="files" dev="ecryptfs" ino=22937600 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:ecryptfs:s0 tclass=dir permissive=0 ppid=2732 pcomm="main" pgid=28565 pgcomm="sk.baka.aedict3"
06-15 22:19:24.239 28565 28624 E DownloaderService: java.lang.RuntimeException: sk.baka.aedict.util.IOExceptionWithCause: The directory '/storage/3262-3632/Android/data/sk.baka.aedict3/files/aedict3' couldn't be created: /storage/3262-3632/Android/data/sk.baka.aedict3/files not writable. Please make sure that the sdcard is inserted in the phone, mounted and is not write-protected.
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader$1.invoke(DownloaderService.java:383)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader$1.invoke(DownloaderService.java:371)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict.search.impl.LuceneCache.runExclusive(LuceneCache.kt:81)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader.download(DownloaderService.java:371)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$2.run(DownloaderService.java:270)
06-15 22:19:24.239 28565 28624 E DownloaderService: Caused by: sk.baka.aedict.util.IOExceptionWithCause: The directory '/storage/3262-3632/Android/data/sk.baka.aedict3/files/aedict3' couldn't be created: /storage/3262-3632/Android/data/sk.baka.aedict3/files not writable. Please make sure that the sdcard is inserted in the phone, mounted and is not write-protected.
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader.downloadImpl(DownloaderService.java:420)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader.access$800(DownloaderService.java:354)
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader$1.invoke(DownloaderService.java:381)
06-15 22:19:24.239 28565 28624 E DownloaderService: Caused by: java.io.IOException: The directory '/storage/3262-3632/Android/data/sk.baka.aedict3/files/aedict3' couldn't be created: /storage/3262-3632/Android/data/sk.baka.aedict3/files not writable
06-15 22:19:24.239 28565 28624 E DownloaderService: at sk.baka.aedict3.dict.download.DownloaderService$DictionaryDownloader.downloadImpl(DownloaderService.java:418)
...

BTW: Before the problems with the sd card started, I could download the dictionaries to the external SD card without problems (to /storage/XXXX-XXXX/Android/data/sk.baka.aedict3/files/ with the correct XXXX-XXXX at that time).

[Kareema]

Just tried to copy a file from internal storage to the SD card with X-plore file manager. I was asked to grant rights to write to the SD card and it was working without problems.