files copying multiple times to external drive

Get help. Get answers. Let others lend you a hand.

Moderator: Mr_Noodle

I'm running a rule that moves movie files to an external drive. These files are typically 300mb-1gig. Hazel starts moving the file and (this is just a guess) since it takes a while to move the file to an external drive, starts the rule again since the file hasn't really moved yet. Thus, I end up with multiple copies of the file, sometimes as many as 100+!

Does anybody have any ideas of how to avoid this?
stevelucky76
 
Posts: 16
Joined: Fri Apr 23, 2010 10:58 pm

Hazel won't run on a folder if it is already running (you can't have overlapping runs). Is the file in question being used by another program? If so, then there is currently a bug (introduced in 2.3.6) for which I will have a patch soon, hopefully on Monday.

The bug pertains to the detection of busy files being broken. It ends up working out like this:

1. Hazel fails to detect busy file and runs rule on it anyways.
2. Rule tries to move file. Since it is on another drive, it does this by copying the file then deleting the original.
3. File gets copied but the part that deletes the file fails because the file is busy.
4. Routine aborts but leaves the copy at the destination.

Step 1 is my fault but the rest is Apple's code. While the copying part is Apple's fault, fixing step 1 will avoid the rest. If it is urgent, email support and I can send you a test build otherwise hold tight until Monday.
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City

Hmmm. That sounds like that could be it. Has this always been a problem because I've had this issue for as long as I've used Hazel. I can wait until Monday as this is definitely non-critical.
stevelucky76
 
Posts: 16
Joined: Fri Apr 23, 2010 10:58 pm

How long have you been using Hazel? If this was happening before the last version then please email me as I'd like to address this in this patch if possible. Go to the "Info" pane and click on "View Log". Send me anything in there that might show what is happening (if in doubt, go ahead and send me the whole thing). If this ends up being a different problem and it's something I can address quickly, I'd rather have it fixed in this patch as I'm hoping the next version I put out will be 3.0 which will be a while.
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City

Just sent you a PM with a link to the log file. Thanks for your help.
stevelucky76
 
Posts: 16
Joined: Fri Apr 23, 2010 10:58 pm

I just put up 2.3.7 which should fix this. Give it a spin and let me know if it addresses the problem.
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City

Installing now. Will test it for a few days and let you know. Thanks!
stevelucky76
 
Posts: 16
Joined: Fri Apr 23, 2010 10:58 pm

Unfortunately, it's a no go. I had the same problem tonight. You can download my updated log using the same link that I sent you last time.
stevelucky76
 
Posts: 16
Joined: Fri Apr 23, 2010 10:58 pm

I see nothing in the logs indicating it's doing much of anything, good or bad. Could you point me to an actual file that is exhibiting this behavior?

Also, try turning on debug mode (check the sticky article at the top of this forum).
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City

I've got the same issue going on. I'm on 2.3.8. Here's what happens for me:
  • My torrent application automatically moves files on completion to a specific folder
  • Hazel runs rules only on that folder, specifically: it looks to match filenames on files that have NOT been modified in the last 15 minutes.
  • Hazel is then set to move that file onto my NAS into a specific folder

However I wind up with the same issues as the OP - An initial notification that Hazel can't move the files, then if I don't catch it in time, hundreds and hundreds of copies of the same file in the target folder.

I too will turn on debug mode and give you the results.

EDIT to add the current log file results that can show an example of the errors that are generated:
2011-05-02 16:38:53.802 (null)[0] Desperate.Housewives.S07E20.HDTV.XviD-LOL.avi: Rule Desperate Housewives matched.
2011-05-02 16:39:55.009 hazelfolderwatch[45488] Error moving file /Volumes/Data/Downloads/Completed/Desperate.Housewives.S07E20.HDTV.XviD-LOL.avi to /Volumes/TV Shows/Desperate Housewives/Season 7/Desperate.Housewives.S07E20.HDTV.XviD-LOL-9.avi: -47 - File is busy (delete)
2011-05-02 16:39:55.010 hazelfolderwatch[45488] [Error] Move failed: Could not move file Desperate.Housewives.S07E20.HDTV.XviD-LOL.avi from folder /Volumes/Data/Downloads/Completed to folder /Volumes/TV Shows/Desperate Housewives/Season 7.


I'm not sure *how* it can be busy tho - it should've finished copying into the source directory at least 15 minutes prior to Hazel attempting the move.
kbrookes
 
Posts: 3
Joined: Mon May 02, 2011 2:45 am

Use the 'lsof' command to see what program has the file open. I think this is mentioned elsewhere but there is an Apple bug when moving files across filesystems. In such a case, it does a copy then deletes the original, but if the original is "busy", it will fail to delete the original but it also leaves the copy at the destination. On top of this, it signals an error so Hazel thinks the operation failed and tries again later.

I'm going to file an incident report with Apple since they don't seem to think this bug to be a priority but in the meantime, it might help to identify what program has the file open.
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City

Thanks for the info. I'll check on that next time it occurs.

I was trying to think of a creative way to address this. Perhaps by setting the label of a file to a certain colour prior to moving, then having the rule check to ensure that the rule will only be applied to files without that label?
kbrookes
 
Posts: 3
Joined: Mon May 02, 2011 2:45 am

No dice. I wound up with 142 copies of a file. The last one was marked purple. Unfortunately the error had resolved itself by the time I noticed, so I wasn't able to use lsof command.

Here's one of the sets of error messages generated by the full debug mode:
Code: Select all
2011-05-02 21:16:46.205 hazelfolderwatch[47861] DEBUG: About to process directory /Volumes/Data/Downloads/Completed
2011-05-02 21:16:46.255 hazelfolderwatch[47861] The.Borgias.S01E06.The.French.King.HDTV.XviD-FQM.[VTV].avi: Rule The Borgias matched.
2011-05-02 21:16:46.255 hazelfolderwatch[47861] DEBUG: Got error last time. Re-trying actions.
2011-05-02 21:18:30.738 hazelfolderwatch[47861] Error moving file /Volumes/Data/Downloads/Completed/The.Borgias.S01E06.The.French.King.HDTV.XviD-FQM.[VTV].avi to /Volumes/TV Shows/The Borgias/Season 1/The.Borgias.S01E06.The.French.King.HDTV.XviD-FQM.[VTV]-2.avi: -47 - File is busy (delete)
2011-05-02 21:18:30.754 hazelfolderwatch[47861] [Error] Move failed: Could not move file The.Borgias.S01E06.The.French.King.HDTV.XviD-FQM.[VTV].avi from folder /Volumes/Data/Downloads/Completed to folder /Volumes/TV Shows/The Borgias/Season 1.
2011-05-02 21:18:30.755 hazelfolderwatch[47861] DEBUG: Directory /Volumes/Data/Downloads/Completed processed.
2011-05-02 21:18:30.755 hazelfolderwatch[47861] DEBUG: Done
2011-05-02 21:21:43.756 (null)[0] DEBUG: Program is licensed.
2011-05-02 21:21:43.757 hazelfolderwatch[47913] DEBUG: Could not scan past browser.download.dir preference
2011-05-02 21:21:43.763 hazelfolderwatch[47913] DEBUG: Error reading file /Users/kelsey/Library/Application Support/Flock/profiles.ini: Error Domain=NSCocoaErrorDomain Code=260 UserInfo=0x10072fc00 "The file “profiles.ini” couldn’t be opened because there is no such file." Underlying Error=(Error Domain=NSPOSIXErrorDomain Code=2 "The operation couldn’t be completed. No such file or directory")
2011-05-02 21:21:43.816 hazelfolderwatch[47913] DEBUG: Could not resolve alias. Old path: (null) Error: -50
2011-05-02 21:21:43.816 hazelfolderwatch[47913] DEBUG: Could not resolve alias. Old path: (null) Error: -50
2011-05-02 21:21:43.816 hazelfolderwatch[47913] DEBUG: Initialized
2011-05-02 21:21:43.816 hazelfolderwatch[47913] DEBUG: Pausing to wait for things to settle down.
2011-05-02 21:21:45.816 hazelfolderwatch[47913] DEBUG: Processing directories: (
    "/Volumes/Data/Downloads/Completed"
)
kbrookes
 
Posts: 3
Joined: Mon May 02, 2011 2:45 am

I've worked around this (caused by an old but indispensible application that's not good about closing files) by copying the file to the external drive, and then running a separate rule which moves the original into the Trash. This is working splendidly, except that I do need to empty the Trash from time to time.
ErikMH
 
Posts: 36
Joined: Sat Jun 21, 2008 8:49 am
Location: northern Vermont

Just a note that I've put in a workaround in the 2.3.9 version that I just released. All it does it clean up the copy if the operation fails. It is assumed at some point that the source file will no longer be busy and that the actual move will execute successfully. If not, then you need to address the application that is keeping the file open.

Unfortunately, after talking with Apple engineering, it seems a better fix is not possible right now so this workaround will result in more file activity than I would like but it's the best I can do at the moment. I'll look into refining the workaround for 3.0.
Mr_Noodle
Site Admin
 
Posts: 11865
Joined: Sun Sep 03, 2006 1:30 am
Location: New York City


Return to Support