SD card and contents listed several times

[Selene ToyKeeper]

When connecting to a krillin running rtm image 142, I see the SD card device listed several times. If I connect to that device and list its contents, each file and directory is listed several times too. The exact number is consistent during a session, but varies per boot.

If I then add a new file, disconnect, and reconnect, that file is listed just once while everything else is listed several times.

The mtp client I'm using to test this is gmtp. Results may appear different with Nautilus, because I think it ignores duplicates.

Screenshots demonstrating what I see are attached.

This issue isn't new, but it seems to happen every time now instead of just once in a while.

[Brendan Donegan (brendan-donegan)]

I can't reproduce this here - are you sure your version of gmtp isn't buggy? I'm on Utopic and running 1.3.7-1

[Jean-Baptiste Lallement (jibel)]

There is definitely something wrong and it is not due to gmtp

ls -l /var/run/user/1000/gvfs/mtp\:host\=%5Busb%3A003%2C007%5D/
total 0
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Aquaris E4.5 Ubuntu Edition
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc (4)

[Jean-Baptiste Lallement (jibel)]

If I disconnect/reconnect the device then it changes to:
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Aquaris E4.5 Ubuntu Edition
drwx------ 1 j-lallement j-lallement 0 janv. 1 1970 Médias SDc

[Mathieu Trudel-Lapierre (cyphermox)]

I'm unable to reproduce this. Is there a particular set of steps to be able to get to this behavior? Are you popping in and out the SD card? Are you booting with the device connected or disconnected? Are you connecting, then disconnecting and reconnecting?

Seems like this may well also be an issue with libmtp; it's known to at least not support some object changes signals very well, but usually it would be more along the lines of objects not being visible when they should be rather than duplicate entries.

If you can easily reproduce this issue, please do so by starting gmtp with LIBMTP_DEBUG=-1 to enable all debugging logs, and attach all that is outputted on the console to this bug report (and please don't do anything more than just connecting the device and seeing whether it has duplicates, this logs *a lot*)

[Selene ToyKeeper (toykeeper)]

So, for at least a couple months I've been seeing this issue about 95% of the time when I connect via mtp. And now that I try to get logs, I haven't been able to trigger it. :(

I'll keep trying.

[Selene ToyKeeper (toykeeper)]

This log should show what happens when there are two copies of the SD card device and its contents.

This is the simplest broken case... sometimes I've seen as many as nine copies.

Sorry for the log size. It is, as you expected, rather large. All I did was start gmtp, connect, select a SD device, wait for the UI to update (with device contents), then disconnect and quit. That produced 8.6 MB of logs.

[Víctor R. Ruiz (vrruiz)]

I couldn't reproduce this in image 169 (ES 119).

[Selene ToyKeeper (toykeeper)]

I still see this on rtm krillin 169.

The issue is intermittent, but it only took me two tries to trigger it this time.

[Mathieu Trudel-Lapierre (cyphermox)]

Are you popping the SD card in and out a few times while USB is connected?

[Jean-Baptiste Lallement (jibel)]

No, the card is not removed from the slot when this happens.

[Mathieu Trudel-Lapierre (cyphermox)]

That's not what I mean though; my question is specifically about whether the card was removed and readded to the phone while the USB cable was connected. The SDcard would have to be in the phone at the moment for it to show up, but removal/addition of it might explain duplicates in the MTP database.

[Mathieu Trudel-Lapierre (cyphermox)]

Could you please get MTP debug logs? It's especially interesting for when you connect to the phone and request information, then we'll know whether the problem is on the MTP side not dealing with the card properly, or in the gvfs side, not handling how MTP sends its data (which can still be an issue in our MTP implementation).

To do this; edit /usr/share/upstart/sessions/mtp-server.conf; and add the following line:

env GLOG_v=2

[Selene ToyKeeper (toykeeper)]

No, the card wasn't removed/inserted at runtime; it was there at boot and stayed there.

The most reliable way to reproduce this issue is to go through QA's sanity test plan in order. By the time the mtp step is reached, it usually has devolved far enough to have several copies of the SD device.

In the logs I'm attaching, it was shortly after boot so there were only two copies. I connected, selected one of the two SD devices, listed the contents of the root dir, then disconnected. The relevant bits start at 01:42:59 in the log, and go to the end.

I think it's a phone-side bug, in part because the behavior depends on how long the device has been in use that boot, and in part because I see two copies of a file listed in the log under different object IDs.

I0115 01:42:59.180575 2734 UbuntuMtpDatabase.h:154] Adding "/media/phablet/3562-3231/XposedCM10-10.1NetflixWorkaround-Dinc.apk"
I0115 01:43:10.457561 2729 MtpObjectInfo.cpp:99] MtpObject Info 9: XposedCM10-10.1NetflixWorkaround-Dinc.apk
I0115 01:43:11.222623 2729 MtpObjectInfo.cpp:99] MtpObject Info 372: XposedCM10-10.1NetflixWorkaround-Dinc.apk

[Selene ToyKeeper (toykeeper)]

Could we raise the priority on this? It seems to be getting worse lately, enough to break file transfers after the phone has been in use for a while. By the time I get this far in the sanity tests, there are usually about seven copies of the SD card listed, and when I try to send a file (to internal memory) it times out and fails and no more MTP operations succeed until after a reboot.

It works fine fresh after a boot. I suspect that whatever is causing the reduced battery life recently may also be triggering whatever causes this issue, since the mtp issues are worse when the phone has been under load.

[Selene ToyKeeper (toykeeper)]

Drat, I just noticed the logs never got attached. My notebook has been awfully crashy lately too, and I don't have the files any more. Will have to get these logs during the next sanity test run.

I think the snippet from earlier is at least enough to show the issue is phone-side though, and not client-side.

[Víctor R. Ruiz (vrruiz)]

Folders duplicated using Windows Vista and browsing through the SD card.

RTM-Proposed, image 256, krillin.