UDF Deletion causes queue to hang

[Rick McBride]

The queue (content queue?) appears to be stuck after removing a UDF. The original behavior I reported was as follows:

Purchased an album on the Music store last week. after several days my syncdaemon finally reached an idle state. in

~/.ubuntuone/Purchased from Ubuntu One/

I do have

Primus/They Can't All Be Zingers/

which is the artist and album title, however I have none of the songs in that location.

The songs do appear via https://one.ubuntu.com/files/#path=/User%20Defined%20Folders/Purchased%20from%20Ubuntu%20One/Primus/They%20Can%27t%20All%20Be%20Zingers

and can manually be downloaded from that location, however they never get synced to any of my clients.
---

The SD was processing another UDF, which I cleverly tried to delete as it appeared to be takign forever. This made things worse, as the queue is no longer being processed.

Investigation shows that the queue hung when the delete udf directive was processed.

[Rick McBride (rmcbride)]

apport information

[Rick McBride (rmcbride)]

apport information

[Rick McBride (rmcbride)]

apport information

[Facundo Batista (facundo)]

Hi!

We would need DEBUG logs to find the issue here.

You should do the following:

1. stop the syncdaemon client and be sure it's fully stopped ("ps -eaf | grep ubuntuone-client" should give you nothing).

2. put a file named syncdaemon.conf in your $HOME/.config/ubuntuone directory with the following information:

[__main__]
log_level = DEBUG

3. restart the client.

4. attach here the logs, just zip you $HOME/.cache/ubuntuone/log/ folder and attach the zip here.

Thanks for your time and help!

[Rick McBride (rmcbride)]

logs are in my chinstrap home directory.

[Facundo Batista (facundo)]

The bought album is found ok, the files inside it are found correctly

SV_FILE_NEW, ..., kw:{..., 'name': 'Coattails Of A Dead Man.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'DMV.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Jerry Was A Race Car Driver.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'John The Fisherman.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Mary The Ice Cube.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Mr. Krinkle.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'My Name Is Mud.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Over The Electric Grapevine.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Over The Falls.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Shake Hands With Beef.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Southbound Pachyderm.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Those Damned Blue-Collar Tweekers.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'To Defy The Laws Of Tradition.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Tommy The Cat.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': 'Too Many Puppies.mp3'}
SV_FILE_NEW, ..., kw:{..., 'name': "Wynona's Big Brown Beaver.mp3"}

A QUERY for all those file is queued to the server, in the metadata, and the syncdaemon will process it.

The problem here is that the syncdaemon still didn't finish processing the metaqueue.

The last MARK of your last log:

2010-03-30 10:31:04,145 - ubuntuone.SyncDaemon.Main - NOTE - ---- MARK (state: <State: 'QUEUE_MANAGER' (queues WORKING_ON_METADATA connection 'With User With Network')>; queues: metadata: 9095; content: 0; hash: 0, fsm-cache: hit=972622 miss=355973) ----

So, I'm marking this bug as invalid, please reopen it if *after the syncdaemon finished*, you still don't see the files.

[Rick McBride (rmcbride)]

Prior to the log you're referring to, the syncdaemon DID complete and I still had no songs synced down.

[Rick McBride (rmcbride)]

Tried adding a blank file to the directory to force a hash re-compare at John O'Brien's suggestion. Still waiting on the client to finish this round of queue sorting. At this time the client has been running 20 hours, with what should be nothing but the music UDF and the Shared With me directory. It has not finished its queue yet.

[Rick McBride (rmcbride)]

I do see the songs queued, however the syncdaemon is clearly stuck in some way. Working with Naty on this now.

[Natalia Bidart (nataliabidart)]

I have the full logs of Rick, you can find them at chinstrap:/home/rmcbride/20100401logs.tar.gz

Relevant part is:

2010-03-31 19:45:17,958 - ubuntuone.SyncDaemon.Main - NOTE - ---- MARK (state: <State: 'QUEUE_MANAGER' (queues WORKING_
ON_BOTH connection 'With User With Network')>; queues: metadata: 31498; content: 923; hash: 0, fsm-cache: hit=1389997 m
iss=138671) ----
2010-03-31 19:46:03,169 - ubuntuone.SyncDaemon.DBus - DEBUG - called current_status
2010-03-31 19:46:07,309 - ubuntuone.SyncDaemon.DBus - DEBUG - Folders.delete: dbus.String(u'cfd7e79f-a376-4719-8cc2-be38
10ad48dd')
2010-03-31 19:46:07,310 - ubuntuone.SyncDaemon.VM - INFO - delete_volume: dbus.String(u'cfd7e79f-a376-4719-8cc2-be3810ad
48dd')
2010-03-31 19:46:07,310 - ubuntuone.SyncDaemon.ActionQueue - DEBUG - DeleteVolume share:--- node:--- DeleteVolume() queueing in the %s META_QUEUE
2010-03-31 19:47:17,958 - ubuntuone.SyncDaemon.Main - NOTE - ---- MARK (state: <State: 'QUEUE_MANAGER' (queues WORKING_ON_BOTH connection 'With User With Network')>; queues: metadata: 31499; content: 923; hash: 0, fsm-cache: hit=1389997 miss=138671) ----

And then the SD is stuck on WORKING_ON_BOTH with metadata: 31499.

The output of u1sdtool --waiting-metadata is extremely big (31500 lines), and the first ~950 lines are ListDir over the deleted volume:

ListDir(share_id=cfd7e79f-a376-4719-8cc2-be3810ad48dd, node_id=30e8bccd-7843-431a-8756-8b41cfe5b29f, server_hash=sha1:bc552c97e4545d9353a4fca6e11fd24c8867c8b1)

[Natalia Bidart (nataliabidart)]

After analizing a lot of log files from the client and from the server, I've arrived to the following conclusions:

 * Until April, 5th the client was waiting for a ListDir that never finished, and we couldn't find any signs of it in the server logs:

2010-03-31 19:02:31,554 - ubuntuone.SyncDaemon.QueueManager - DEBUG - In WORKING_ON_BOTH: running META_QUEUE
2010-03-31 19:02:31,555 - ubuntuone.SyncDaemon.ActionQueue - DEBUG - ListDir share:'cfd7e79f-a376-4
719-8cc2-be3810ad48dd' node:'99169447-aace-4494-8f58-bf839dff53a3' ListDir(fileobj_factory='<function <lambda> at 0x
4200140>', share_id="'cfd7e79f-a376-4719-8cc2-be3810ad48dd'", node_id="'99169447-aace-4494-8f58-bf839dff53a3'", server_h
ash="'sha1:b291018d3c21ee41493d21c0d7f7dbb82c2e374e'") starting

(this behavior should be revised and it's filled under Bug #556507)

 * After that, Rick restarted the client and the following happened. Metadata load: 6 minutes 25 seconds:

2010-04-05 14:03:55,840 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2010-04-05 14:10:20,529 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 34081, idx_node_id: 34080, shares: 8

 * Local rescan: 6 minutes 36 seconds

2010-04-05 14:10:21,605 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan starting...
...
2010-04-05 14:16:57,765 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan finished!

 * While local rescan was working, Rick removed the 'Shared with me' folder, as per:

2010-04-05 14:10:39,121 - ubuntuone.SyncDaemon.local_rescan - INFO - comp yield: directory '/home/rmcbride/Ubuntu One/Shared With Me' is gone!

 * Since removing this directory is not supported (see Bug #556783 for details), the client entered on a loop of LR_SCAN_ERROR, as per:

2010-04-05 14:10:21,882 - ubuntuone.SyncDaemon.local_rescan - DEBUG - Disk error while scanning path '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User', reason: [Errno 2] No such file or directory: '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'

2010-04-05 14:10:39,162 - ubuntuone.SyncDaemon.EQ - DEBUG - push_event: LR_SCAN_ERROR, args:('4352976b-7042-4ad4-8568-2d737ca60131', False), kw:{}
2010-04-05 14:10:39,163 - ubuntuone.SyncDaemon.sync - DEBUG - T:SERVER:T 4352976b-7042-4ad4-8568-2d737ca60131 ['b2d8565f-e6e6-4025-878a-137bef9f6764'::'298c27ab-6d9e-4ac1-89c4-6fdd31f2d261'] ''/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'' | EVENT: LR_SCAN_ERROR:{} with ARGS:(False,)
2010-04-05 14:10:39,163 - ubuntuone.SyncDaemon.sync - DEBUG - T:SERVER:T 4352976b-7042-4ad4-8568-2d737ca60131 ['b2d8565f-e6e6-4025-878a-137bef9f6764'::'298c27ab-6d9e-4ac1-89c4-6fdd31f2d261'] ''/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'' | Calling rescan_dir
2010-04-05 14:10:39,164 - ubuntuone.SyncDaemon.local_rescan - INFO - scan dir: '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User' mdid: 4352976b-7042-4ad4-8568-2d737ca60131
2010-04-05 14:10:39,166 - ubuntuone.SyncDaemon.local_rescan - DEBUG - The received path is not in disk: path '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User' mdid 4352976b-7042...

[Facundo Batista (facundo)]

The last log analysis seems to indicate that you're doing something not supported, and that there are errors because of server too slow.

Do you have any other log that we could consider to see if there is any issue?

Thank you very much!

[John Lenton (chipaca)]

I believe I just got the same issue.
To reproduce: get a folder with a small number of big files (so the local rescan is fast, so you don't get bored while testing). The Videos folder works well for this. Using nautilus, check the 'synchronize this folder' checkbox (or via the menu, if you don't have the ribbon on videos as per the fix to bug #623482). As soon as the checkbox is clickable again, i.e. as soon as the udf is created, un-click the checkbox. Tadaa.

This scenario is called the "OMG NO DO NOT UPLOAD ALL MY VIDS LOL" scenario.

Logs attached.

[John O'Brien (jdobrien)]

Deleting a UDF was recently fixed. Please retest this as from my testing, this works correctly now.

[Rick McBride (rmcbride)]

This is indeed working correctly now for me