Not processing for hours

I've had a problem for a while now where Hazel won't look in all of the folders. This will go on for hours if not days just processing 2 folders.

In the log, the following appear about every 30 seconds.

Code: Select all: 2014-05-07 15:55:04.582 hazelworker[57282] ###main load address: 0x102275000 2014-05-07 15:55:04.583 hazelworker[57282] ###Noodle load address: 0x10234f000 2014-05-07 15:55:04.583 hazelworker[57282] ###CK load address: 0x102313000 2014-05-07 15:55:04.604 hazelworker[57281] ###main load address: 0x10261b000 2014-05-07 15:55:04.606 hazelworker[57281] ###Noodle load address: 0x1026fa000 2014-05-07 15:55:04.606 hazelworker[57281] ###CK load address: 0x1026b8000 2014-05-07 15:55:04.644 hazelworker[57281] Processing folder 4a-Processing 2014-05-07 15:55:04.826 hazelworker[57282] Processing folder 4b-Processed 2014-05-07 15:55:06.772 hazelworker[57281] Done processing folder 4a-Processing 2014-05-07 15:55:06.953 hazelworker[57282] Done processing folder 4b-Processed

It just keeps processing those 2 folders over and over.

When I notice that newly downloaded files haven't been processed, I'll open the other monitored folder or Hazel itself and it "wakes up" and starts processing the other folders.
For example, it last processed the "2c-Completed" folder at 2:59 last night.

Code: Select all: 2014-05-07 02:59:14.723 hazelworker[8446] ###main load address: 0x10e434000 2014-05-07 02:59:14.724 hazelworker[8446] ###Noodle load address: 0x10e511000 2014-05-07 02:59:14.724 hazelworker[8446] ###CK load address: 0x10e4d5000 2014-05-07 02:59:14.829 hazelworker[8446] Processing folder 2c-Completed 2014-05-07 02:59:17.231 hazelworker[8446] TV_Show_3.S09E01.720p.HDTV.X264-DIMENSION[rarbg]: Rule Run rules on folder contents matched. 2014-05-07 02:59:17.234 hazelworker[8446] TV_Show_3.S09E02.720p.HDTV.X264-DIMENSION[rarbg]: Rule Run rules on folder contents matched. 2014-05-07 02:59:17.238 hazelworker[8446] TV_Show_2.2009.S06E22.720p.HDTV.X264-DIMENSION[rarbg]: Rule Run rules on folder contents matched. 2014-05-07 02:59:17.241 hazelworker[8446] TV_Show_1.S03E23.720p.WEB-DL.DD5.1.H.264-YFN: Rule Run rules on folder contents matched. 2014-05-07 02:59:17.381 hazelworker[8446] Done processing folder 2c-Completed

This afternoon at 15:57, I opened Hazel control panel and clicked on the Preview icon for 2c, which had multiple files waiting to be processed. When I did that, Hazel processed the waiting files.

Code: Select all: 2014-05-07 15:57:33.606 hazelworker[57427] ###main load address: 0x1098d9000 2014-05-07 15:57:33.608 hazelworker[57427] ###Noodle load address: 0x1099b3000 2014-05-07 15:57:33.608 hazelworker[57427] ###CK load address: 0x109977000 2014-05-07 15:57:34.546 hazelworker[57427] Processing folder 2c-Completed 2014-05-07 15:57:37.072 hazelworker[57427] TV_Show_2.2009.S06E22.720p.HDTV.X264-DIMENSION[rarbg]: Rule Run rules on folder contents matched. 2014-05-07 15:57:37.102 hazelworker[57427] TV_Show_1.S03E23.720p.WEB-DL.DD5.1.H.264-YFN: Rule Run rules on folder contents matched. 2014-05-07 15:57:37.131 hazelworker[57427] Done processing folder 2c-Completed (1x of the 4a and 4b folders processed) 2014-05-07 15:57:49.803 hazelworker[57445] ###main load address: 0x104e00000 2014-05-07 15:57:49.804 hazelworker[57445] ###Noodle load address: 0x104edc000 2014-05-07 15:57:49.804 hazelworker[57445] ###CK load address: 0x104ea0000 2014-05-07 15:57:49.851 hazelworker[57445] Processing folder 2c-Completed (1x of the 4a and 4b folders processed) 2014-05-07 15:57:52.028 hazelworker[57445] TV_Show_1.S03E23.720p.WEB-DL.DD5.1.H.264-YFN: Rule Run rules on folder contents matched. 2014-05-07 15:57:52.034 hazelworker[57445] Done processing folder 2c-Completed (5x of the 4a and 4b folders processed) 2014-05-07 15:59:42.058 hazelworker[57587] Processing folder 2c-Completed 2014-05-07 15:59:44.232 hazelworker[57587] TV_Show_1.S03E23.720p.WEB-DL.DD5.1.H.264-YFN: Rule Run rules on folder contents matched. 2014-05-07 15:59:44.269 hazelworker[57587] TV_Show_1.S03E23.720p.WEB-DL.DD5.1.AAC2.0.H.264-YFN.mkv: Rule Found TV Episode File matched. 2014-05-07 15:59:45.082 hazelworker[57587] [File Event] File moved into subfolder 2014-05-07 15:59:45.113 hazelworker[57587] Done processing folder 2c-Completed

Between last night and this afternoon, there were hundreds of log entries just cycling thru 4a and 4b and never looking in the other folders. Any idea why this is happening?

As a side question, can I turn off the "### load address" lines? I don't have the debug option enabled so I shouldn't see that level of logging details.

I suggest turning on debugging to figure out what's going on for those two folders. As for the #### lines, they are always printed out in case there is a crash. You can't count on users always being in debug mode when this happens.

Code: Select all: 2014-05-13 18:18:05.046 hazelworker[70403] Processing folder 4b-Processed 2014-05-13 18:18:05.046 hazelworker[70403] DEBUG: Initialized 2014-05-13 18:18:05.046 hazelworker[70403] DEBUG: Pausing to wait for things to settle down. 2014-05-13 18:18:05.071 hazelworker[70404] Processing folder 4a-Processing 2014-05-13 18:18:05.071 hazelworker[70404] DEBUG: Initialized 2014-05-13 18:18:05.071 hazelworker[70404] DEBUG: Pausing to wait for things to settle down. 2014-05-13 18:18:07.135 hazelworker[70403] DEBUG: Processing directories: ( "/Users/Shared/SynDS/4b-Processed" ) 2014-05-13 18:18:07.136 hazelworker[70403] DEBUG: About to process directory /Users/Shared/SynDS/4b-Processed 2014-05-13 18:18:07.139 hazelworker[70403] DEBUG: Received file event: { date = "2014-05-14 00:18:04 +0000"; path = "<ComNoodlesoft_NoodlePathSet: 0x7f8603f18d40> - (\n \"/Users/Shared/SynDS/4b-Processed\"\n)"; } 2014-05-13 18:18:07.140 hazelworker[70404] DEBUG: Processing directories: ( "/Users/Shared/SynDS/4a-Processing" ) 2014-05-13 18:18:07.141 hazelworker[70404] DEBUG: About to process directory /Users/Shared/SynDS/4a-Processing 2014-05-13 18:18:07.141 hazelworker[70403] DEBUG: Directory /Users/Shared/SynDS/4b-Processed processed in 0.004671 seconds 2014-05-13 18:18:07.141 hazelworker[70403] DEBUG: Sending metrics to scheduler. Next scheduled run: 2014-05-13 18:18:07.142 hazelworker[70403] Done processing folder 4b-Processed 2014-05-13 18:18:07.145 hazelworker[70404] DEBUG: Received file event: { date = "2014-05-14 00:18:04 +0000"; path = "<ComNoodlesoft_NoodlePathSet: 0x7fa3b3508b80> - (\n \"/Users/Shared/SynDS/4a-Processing\"\n)"; } 2014-05-13 18:18:07.145 hazelworker[70404] DEBUG: Directory /Users/Shared/SynDS/4a-Processing processed in 0.004817 seconds 2014-05-13 18:18:07.146 hazelworker[70404] DEBUG: Sending metrics to scheduler. Next scheduled run: 2014-05-13 18:18:07.148 hazelworker[70404] Done processing folder 4a-Processing

So it appears that Hazel is receiving a file event for these 2 folders about every 30 seconds.
Is there any way to find out why? Nothing else is using/monitoring those folders except Hazel.

You can try using the "fs_usage" command (requires root so you'll need to use sudo). That will trace all file activity and you can see what is generating the events for those directories.

So after some monitoring, it seems that this issue is being caused by the fseventsd process, which is for the drive journaling. Strange thing is that these directories are network mounted shares via AFP which is not journaled so I don't know why it would be sending the event alert.

As a quick test, I changed the mount type from AFP to NFS and this problem went away. This isn't a solution though as NFS from the NAS or within OSX is seriously messed up.

Mr_Noodle, is there any way that you could make Hazel ignore these excessive events for AFP mounts?

Thanks

Actually, fsevents usually doesn't generate events for network filesystems unless, sometimes, it is caused by the local machine. For network drives, Hazel has to poll because of that (and it does it every 5 minutes, not 30 seconds). Are you sure there's nothing else writing to that drive?

I've been digging and monitoring a lot more into this issue. It appears that fseventsd is reporting the fs access caused by launchd relaunching HazelHelper every 30 seconds.

Just to eliminate the chance it was something on the NAS share, I set up a different shared folder from another Mac and configured Hazel to monitor it. It did the same thing every 30 seconds.

Here is the output of fsusage during one of these calls.

Code: Select all: 12:20:18.120344 lstat64 /private/tmp/fsusage 0.000048 fseventsd.339156 12:20:26.909410 HFS_update (FM_c_m) 0.000012 launchd.225 12:20:26.909740 HFS_update (____a_) 0.000014 launchd.225 12:20:26.909863 HFS_update (___c_m) 0.000012 launchd.225 12:20:26.911304 WrData[AT3] D=0x0a148280 B=0x2000 /dev/disk0s2 /private/tmp/fsusage 0.001886 W launchd.225 12:20:26.911320 WrData[AT3] D=0x0a1432a0 B=0x1000 /dev/disk0s2 /private/var/log/com.apple.launchd.peruser.502/E495B11C-1998-4FF5-B1DF-B50CBF808BE4.launchd.events.O6p6nE.stats 0.001498 W launchd.225 12:20:26.912895 HFS_update (___c_m) 0.000011 launchd.225 12:20:26.912954 HFS_update (___c_m) 0.000005 launchd.225 12:20:26.914447 HFS_update (_M____) 0.000008 launchd.225 12:20:26.914457 HFS_update (_M____) 0.000003 launchd.225 12:20:26.914742 HFS_update (_M____) 0.000005 launchd.225 12:20:26.914770 HFS_update (FM__a_) 0.000004 launchd.225 12:20:26.914890 WrData[AT3] D=0x05003210 B=0x2000 /dev/disk0s2 /Users/jeff/Library/Logs/Hazel/Hazel.log 0.000117 W launchd.225 12:20:26.916271 HFS_update (_M____) 0.000004 launchd.225 12:20:26.916583 WrData[SP] D=0x00001bf0 B=0x200 /dev/disk0s2 0.000234 W kernel_task.339648 12:20:26.916846 IOCTL <DKIOCSYNCHRONIZECACHE> /dev/disk0s2 0.000246 W kernel_task.339648 12:20:26.917854 WrData[ST3] D=0x00008f9e B=0x3b200 /dev/disk0s2 0.000985 W launchd.225 12:20:26.918128 IOCTL <DKIOCSYNCHRONIZECACHE> /dev/disk0s2 0.000234 W launchd.225 12:20:26.918492 WrData[ST3] D=0x00001bf0 B=0x200 /dev/disk0s2 0.000361 W launchd.225 12:20:26.918731 WrMeta[AT3] D=0x00000a08 B=0x1000 /dev/disk0s2 0.000172 W launchd.225 12:20:26.918747 WrMeta[AT3] D=0x00001430 B=0x1000 /dev/disk0s2 0.000175 W launchd.225 12:20:26.918754 WrMeta[AT3] D=0x00009f80 B=0x1000 /dev/disk0s2 0.000172 W launchd.225 12:20:26.918761 WrMeta[AT3] D=0x0026fbf0 B=0x2000 /dev/disk0s2 0.000170 W launchd.225 12:20:26.919106 WrMeta[AT3] D=0x002f77a0 B=0x2000 /dev/disk0s2 0.000181 W launchd.225 12:20:26.919109 WrMeta[AT3] D=0x00303220 B=0x2000 /dev/disk0s2 /private/var/log/com.apple.launchd.peruser.502/E495B11C-1998-4FF5-B1DF-B50CBF808BE4.launchd.events.O6p6nE.stats 0.000170 W launchd.225 12:20:26.919199 WrMeta[AT3] D=0x0030ce10 B=0x2000 /dev/disk0s2 0.000243 W launchd.225 12:20:26.919209 WrMeta[AT3] D=0x00316a80 B=0x2000 /dev/disk0s2 0.000248 W launchd.225 12:20:26.919216 WrMeta[AT3] D=0x00326110 B=0x2000 /dev/disk0s2 0.000250 W launchd.225 12:20:26.919343 fcntl F=8 <PATHPKG_CHECK> 0.000005 mds.339452 12:20:28.079913 lstat64 /Volumes/jeff/ztest 0.088203 W fseventsd.339649 12:20:28.079968 lstat64 /Volumes/jeff/ztest 0.088258 W fseventsd.339156 12:20:28.080633 getattrlist /Volumes 0.000060 HazelHelper.1767 12:20:28.080675 getattrlist /Volumes/jeff 0.000040 HazelHelper.1767 12:20:28.080714 write F=4 B=0x103 0.000031 HazelHelper.339653 12:20:28.082521 statfs64 /Volumes/jeff 0.001846 W HazelHelper.1767 12:20:28.082536 lstat64 /Volumes/jeff 0.000014 HazelHelper.1767 12:20:28.082561 lstat64 /Volumes 0.000023 HazelHelper.1767 12:20:28.082575 getattrlist /Volumes/jeff/ztest 0.000012 HazelHelper.1767

I later enabled debug-level logging of launchd and it shows that launchd is calling HazelHelper.

Code: Select all: May 25 12:32:24 Minion com.apple.launchd[1] <Debug>: Dispatching kevent (ident/filter): 268/-5 May 25 12:32:24 Minion com.apple.launchd[1] (0x7fd60069af50.anonymous.HazelHelper[268]) <Debug>: Dispatching kevent callback. May 25 12:32:24 Minion com.apple.launchd[1] (0x7fd60069af50.anonymous.HazelHelper[268]) <Debug>: EVFILT_PROC event for job. May 25 12:32:24 Minion com.apple.launchd[1] (0x7fd60069af50.anonymous.HazelHelper[268]) <Debug>: fork()ed May 25 12:32:24 Minion com.apple.launchd[1] <Debug>: Handled kevent.

So does this shed any light on this issue?

I see that the default timeout period for a process that has registered with launchd is is 30 seconds. Perhaps HazelHelper has registered itself but then doesn't respond to the launchd calls so then launchd thinks it has died and is restarting it?

If you want to test this problem yourself, it should be easy enough to reproduce.
- Set up a shared folder from another Mac.
- Mount that share onto the Mac running Hazel
- Configure Hazel to monitor that folder
- Set up the monitored with a simple Hazel rule like "Any File" then "Ignore"
- Enable Debug logging in Hazel
- Watch the Hazel log and it will show the monitored folder needs to be rescanned every 30 seconds

Thanks for helping. Hopefully this problem can be fixed soon.

I don't think it's launching HazelHelper but just sending it file events. HazelHelper runs constantly and if you have Hazel set to show the menubar icon, you would notice it flickering on and off if the helper was constantly being restarted.

Have you tried turning off all non-local folders and seeing if the problem still occurs?

Right, the launchd debug output above is just showing that HazelHelper is forking off a child process (hazelworker) to process the directory. I don't see that HazelHelper has actually died because the PID remains constant and the bar icon does not dim.

This 30 second repeating issue only happens with AFP mounted shares. I have Hazel working on other local folders and it doesn't act this way with them. However, because Hazel[Helper] is constantly busy with the network shares, it doesn't process the other monitored folders until I manually force it via "Run rules now" menu or Preview button (see my original post). Even just this morning while researching this issue, I had changed some of the other local folder rules and put files in to be processed. I checked about 5 hours later and none of them had been processed. I opened Hazel and paused the 2 folders on the AFP mount and Hazel immediately ran the rules for all of the other monitored folders.

I used watchdog and it did not show any file system events. When run on OSX, it shows the FSEvents by default. I enabled the --debug-force-kqueue option to show the BSD kqueue events and it showed that the .DS_Store file is being modified every 30 seconds.

Code: Select all: $ watchmedo log --debug-force-kqueue /Users/Shared/SynDS/4a-Processing event=<FileModifiedEvent: src_path=/Users/Shared/SynDS/4a-Processing/.DS_Store> event=<DirModifiedEvent: src_path=/Users/Shared/SynDS/4a-Processing>

So this shows that something is modifying the .DS_Store file. However, I question this because getting the file details shows that it has not been modified in almost 2 days.

Code: Select all: $ stat -x /Users/Shared/SynDS/4a-Processing/.DS_Store File: ".DS_Store" Size: 6148 FileType: Regular File Mode: (0666/-rw-rw-rw-) Uid: ( 502/ jeff) Gid: ( 0/ wheel) Device: 46,5 Inode: 3506517 Links: 1 Access: Sun May 25 20:06:31 2014 Modify: Sun May 25 20:06:31 2014 Change: Sun May 25 20:06:31 2014

I don't know why kqueue is reporting it being modified. Something related to Hazel and the monitored folder within the AFP mount is causing this trigger. Only the .DS_Store files of the directories that Hazel is monitoring is being triggered. I can browse around the rest of the mount (/Users/Shared/SynDS/) and it doesn't trigger an event.

Question/Request: What if you were to change the way that HazelHelper is listening for changes by using FSEvents instead of registering for kqueue events?

Even in the comments of watchdog's kqueue code, he mentions this problem.

Code: Select all: WARNING:: kqueue is a very heavyweight way to monitor file systems. Each kqueue-detected directory modification triggers a full directory scan. Traversing the entire directory tree and opening file descriptors for all files will create performance problems.

Hazel does use fsevents. There is one instance where it uses kqueue and that is to watch if the monitored folder changes. While fsevents also has this capability, it can't do it without making the associated drive unmountable, hence usage of kqueue in this instance (plus, it might be the case that fsevents uses kqueue for this functionality as well). I'm not sure how Hazel is modifying the .DS_Store. Hazel normally ignores hidden files. The only thing I can think of is that scanning the directory somehow updates some metadata.