Noodlesoft Forums

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.