Noodlesoft Forums

I have a simple rule: watch a file `foo.txt` , if modified, post a notification. When `foo.txt` is left untouched (e.g. date last modified is, say, yesterday), the preview correctly identified the rule as unmatched. However, in the main hazel preference pane, it show rule as matched (though correctly listing date last modified as yesterday), and left click> run rule now runs the script. And it happens with automatic hazel run: even if `foo.txt` is not modified, I still get the notification that the file is modified every now and then. The 'date last modified field' in hazel pref pane is not changed (still yesterday). I also noticed that hazel somehow thinks date last modified is changed when I just view the file in finder. I noticed this after macos 10.13, possible due to APFS?

Can you post the rule?

Mr_Noodle wrote:Can you post the rule?

This is the rule view, where preview correctly identifies that date modified is not satisfied


This is the show rule status view in main preference pane, where it shows a light blue highlight and wrongly thinks the condition is satisfied


Hazel follow the decision of the wrong rule status view and think the file is modified every now and then, when I did not touch the file and hazel correctly sees the date modified field

What version of Hazel do you have installed?

Mr_Noodle wrote:What version of Hazel do you have installed?

Latest, v4.2.1. I also tried resetting the rule by removing the folder and import the rule back, the first rule match is correct (no match for unmodified file); however, after modify the file, the rule is matched (expected), and it stays matched (not expected behavior: e.g. file modified only once at 1pm, rule matched at 1:01pm, at 1:02 matched again but file not modified, etc.) The issue is not with other processes modifying the file since hazel sees the unchanged date last modified field.

Can you turn on debug mode as described here? https://www.noodlesoft.com/kb/hazel-debug-mode/

After that post/email in the logs showing it running when it shouldn't.

Mr_Noodle wrote:Can you turn on debug mode as described here? https://www.noodlesoft.com/kb/hazel-debug-mode/

After that post/email in the logs showing it running when it shouldn't.

here is the debug log, seeing next scheduled run at year 4001?

Code: Select all

2017-10-13 09:58:15.225 HazelHelper[396] DEBUG: Deploy folders: (
    ".hammerspoon",
    Trash
)
2017-10-13 09:58:15.225 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Deploying worker for folder: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:15.226 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Deploying worker for folder: /Users/<redacted_username>/.Trash
2017-10-13 09:58:15.252 HazelHelper[396] DEBUG: Thread 0x604000064cc0: FOLDERS SYNCED: (
    Trash,
    ".hammerspoon"
)
2017-10-13 09:58:15.252 HazelHelper[396] DEBUG: Mount table: {(
    "/net",
    "/",
    "/private/var/vm",
    "/home",
    "/Volumes/Recovery"
)}
2017-10-13 09:58:30.227 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Timer fired for folder: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:30.227 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Run worker for folder: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:30.254 hazelworker[23509] ###main load address: 0x10b0cf000
2017-10-13 09:58:30.255 hazelworker[23509] ###Noodle load address: 0x10b1f3000
2017-10-13 09:58:30.255 hazelworker[23509] ###CK load address: 0x10b1b5000
2017-10-13 09:58:30.263 hazelworker[23509] DEBUG: Program is licensed.
2017-10-13 09:58:30.276 hazelworker[23509] DEBUG: Error reading file /Users/<redacted_username>/Library/Application Support/Firefox/prefs.js: Error Domain=NSCocoaErrorDomain Code=260 "The file “prefs.js” couldn’t be opened because there is no such file." UserInfo={NSFilePath=/Users/<redacted_username>/Library/Application Support/Firefox/prefs.js, NSUnderlyingError=0x7f8ce3c35380 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2017-10-13 09:58:30.285 hazelworker[23509] DEBUG: Could not find entry for default_directory in Chrome preference file.
2017-10-13 09:58:30.289 hazelworker[23509] Processing folder .hammerspoon
2017-10-13 09:58:30.290 hazelworker[23509] DEBUG: Pausing to wait for things to settle down.
2017-10-13 09:58:32.295 hazelworker[23509] DEBUG: Processing directories: (
    "/Users/<redacted_username>/.hammerspoon"
)
2017-10-13 09:58:32.297 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.hammerspoon, folder .hammerspoon
2017-10-13 09:58:32.299 hazelworker[23509] DEBUG: Received file event: {
    date = "2017-10-13 13:58:30 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7f8ce601dba0>\n  /Users/<redacted_username>/.hammerspoon : 18446744073709551615\n";
}
2017-10-13 09:58:32.299 hazelworker[23509] DEBUG: About to process directory /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:32.301 hazelworker[23509] init.lua: Rule init matched.
2017-10-13 09:58:32.301 hazelworker[23509] DEBUG: New rule signature. Executing actions.
Old signatures: (
)
New Signature:{displayName ==[cd] "init.lua" AND dateModified hazelDidChange: <null>}:{(copy:/Users/<redacted_username>/code/misc/hs,{
    keepFolderStructure = 0;
    replaceExisting = 1;
    throwAwayDupes = 0;
})(shellscript:/bin/bash:fc6d8b219910b60f83660eb046341c20,{
})}
2017-10-13 09:58:32.302 hazelworker[23509] DEBUG: Performing clone operation.
2017-10-13 09:58:32.302 hazelworker[23509] [File Event] File copied: init.lua copied from folder /Users/<redacted_username>/.hammerspoon to folder /Users/<redacted_username>/code/misc/hs.

2017-10-13 09:58:32.386 hazelworker[23509] DEBUG: Rule executed. Updating match date for file /Users/<redacted_username>/code/misc/hs/init.lua: 2017-10-13 13:58:32 +0000
2017-10-13 09:58:32.386 hazelworker[23509] DEBUG: Rule requires extra matching pass.
2017-10-13 09:58:32.386 hazelworker[23509] DEBUG: Action changed file: init.lua
2017-10-13 09:58:32.404 hazelworker[23509] DEBUG: .DS_Store: File is hidden/invisible. Skipping.
2017-10-13 09:58:32.405 hazelworker[23509] DEBUG: Spoons: Did not match any rules.
2017-10-13 09:58:32.405 hazelworker[23509] DEBUG: Writing out DB file for /Users/<redacted_username>/.hammerspoon to path: /Users/<redacted_username>/Library/Application Support/Hazel/16777220-27086946.hazeldb
2017-10-13 09:58:32.407 hazelworker[23509] DEBUG: Directory /Users/<redacted_username>/.hammerspoon processed in 0.107968 seconds
2017-10-13 09:58:32.407 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.hammerspoon, folder .hammerspoon
2017-10-13 09:58:32.408 hazelworker[23509] DEBUG: Sleeping
2017-10-13 09:58:33.314 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Received events (
        {
        date = "2017-10-13 13:58:33 +0000";
        path = "/Users/<redacted_username>/.Trash/init.lua";
        shouldDoFullScan = 0;
    }
) for stream at path: /Users/<redacted_username>/.Trash
2017-10-13 09:58:33.314 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Run worker for folder: /Users/<redacted_username>/.Trash
2017-10-13 09:58:33.315 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Received events (
        {
        date = "2017-10-13 13:58:33 +0000";
        path = "/Users/<redacted_username>/.hammerspoon/init.lua";
        shouldDoFullScan = 0;
    }
) for stream at path: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:33.315 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Run worker for folder: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:33.315 HazelHelper[396] DEBUG: Task already running for folder: /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:33.341 hazelworker[23521] ###main load address: 0x107d4b000
2017-10-13 09:58:33.342 hazelworker[23521] ###Noodle load address: 0x107e69000
2017-10-13 09:58:33.342 hazelworker[23521] ###CK load address: 0x107e30000
2017-10-13 09:58:33.349 hazelworker[23521] DEBUG: Program is licensed.
2017-10-13 09:58:33.351 hazelworker[23521] Processing folder Trash
2017-10-13 09:58:33.376 hazelworker[23521] DEBUG: Pausing to wait for things to settle down.
2017-10-13 09:58:34.376 hazelworker[23521] DEBUG: Processing directories: (
    "/Users/<redacted_username>/.Trash",
    "/.Trashes/501"
)
2017-10-13 09:58:34.379 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.Trash, folder Trash
2017-10-13 09:58:34.380 hazelworker[23521] DEBUG: Received file event: {
    date = "2017-10-13 13:58:33 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7fed8f601c90>\n  /Users/<redacted_username>/.Trash/init.lua : 0\n";
}
2017-10-13 09:58:34.380 hazelworker[23521] DEBUG: About to process directory /Users/<redacted_username>/.Trash
2017-10-13 09:58:34.383 hazelworker[23521] DEBUG: Writing out DB file for /Users/<redacted_username>/.Trash to path: /Users/<redacted_username>/Library/Application Support/Hazel/trash-ECBE86F8-B2ED-3350-8969-AA43D3E14CC3-.Trash.hazeldb
2017-10-13 09:58:34.385 hazelworker[23521] DEBUG: Directory /Users/<redacted_username>/.Trash processed in 0.005129 seconds
2017-10-13 09:58:34.385 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.Trash, folder Trash
2017-10-13 09:58:34.386 hazelworker[23521] DEBUG: Writing out DB file: /Users/<redacted_username>/.Trash
2017-10-13 09:58:34.387 HazelHelper[396] DEBUG: Checking events for path /.Trashes/501, folder Trash
2017-10-13 09:58:34.387 hazelworker[23521] DEBUG: About to process directory /.Trashes/501
2017-10-13 09:58:34.387 hazelworker[23521] DEBUG: Directory /.Trashes/501 processed in 0.000244 seconds
2017-10-13 09:58:34.387 HazelHelper[396] DEBUG: Checking events for path /.Trashes/501, folder Trash
2017-10-13 09:58:34.388 hazelworker[23521] DEBUG: Sending metrics to scheduler. Next scheduled run: 2017-10-16 09:58:32.000
2017-10-13 09:58:34.388 HazelHelper[396] DEBUG: Received metrics for folder /Users/<redacted_username>/.Trash: {
    directoryDepth = 0;
    requestedSchedulingTime = "2017-10-16 13:58:32 +0000";
    triggerPaths = "<ComNoodlesoft_NoodlePathSet: 0x604000229080>\n";
    unavailablePaths = "{(\n)}";
}
2017-10-13 09:58:34.413 hazelworker[23509] DEBUG: About to process directory /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:34.417 HazelHelper[396] DEBUG: Timer scheduled for folder /Users/<redacted_username>/.Trash at 2017-10-16 13:58:32 +0000
2017-10-13 09:58:34.417 hazelworker[23521] Done processing folder Trash
2017-10-13 09:58:34.419 hazelworker[23509] DEBUG: init.lua: Did not match any rules.
2017-10-13 09:58:34.419 hazelworker[23509] DEBUG: .DS_Store: File is hidden/invisible. Skipping.
2017-10-13 09:58:34.420 hazelworker[23509] DEBUG: Spoons: Did not match any rules.
2017-10-13 09:58:34.420 hazelworker[23509] DEBUG: Directory /Users/<redacted_username>/.hammerspoon processed in 0.006789 seconds
2017-10-13 09:58:34.421 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.hammerspoon, folder .hammerspoon
2017-10-13 09:58:34.421 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Task removed: [23521]
2017-10-13 09:58:34.421 hazelworker[23509] DEBUG: Received file event: {
    date = "2017-10-13 13:58:33 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7f8ce3d48fa0>\n  /Users/<redacted_username>/.hammerspoon/init.lua : 0\n";
}
2017-10-13 09:58:34.421 hazelworker[23509] DEBUG: Sleeping
2017-10-13 09:58:36.428 hazelworker[23509] DEBUG: About to process directory /Users/<redacted_username>/.hammerspoon
2017-10-13 09:58:36.430 hazelworker[23509] DEBUG: init.lua: Did not match any rules.
2017-10-13 09:58:36.430 hazelworker[23509] DEBUG: .DS_Store: File is hidden/invisible. Skipping.
2017-10-13 09:58:36.430 hazelworker[23509] DEBUG: Skipped /Users/<redacted_username>/.hammerspoon/Spoons. File/folder not part of change set/file event.
2017-10-13 09:58:36.430 hazelworker[23509] DEBUG: Directory /Users/<redacted_username>/.hammerspoon processed in 0.001738 seconds
2017-10-13 09:58:36.431 HazelHelper[396] DEBUG: Checking events for path /Users/<redacted_username>/.hammerspoon, folder .hammerspoon
2017-10-13 09:58:36.431 hazelworker[23509] DEBUG: Sending metrics to scheduler. Next scheduled run: 4000-12-31 19:00:00.000
2017-10-13 09:58:36.431 HazelHelper[396] DEBUG: Received metrics for folder /Users/<redacted_username>/.hammerspoon: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<ComNoodlesoft_NoodlePathSet: 0x600000a2b020>\n";
    unavailablePaths = "{(\n)}";
}
2017-10-13 09:58:36.431 HazelHelper[396] DEBUG: Timer scheduled for folder /Users/<redacted_username>/.hammerspoon at 4001-01-01 00:00:00 +0000
2017-10-13 09:58:36.432 hazelworker[23509] Done processing folder .hammerspoon
2017-10-13 09:58:36.440 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Task removed: [23509]
2017-10-13 09:58:38.431 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Undeploying worker for folder: /Users/<redacted_username>/.Trash
2017-10-13 09:58:38.458 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Undeploying worker for folder: /Users/<redacted_username>/.hammerspoon


I guess the offending one is

Code: Select all

hazelworker[27998] DEBUG: New rule signature. Executing actions.
Old signatures: (
)
New Signature:{displayName ==[cd] "init.lua" AND dateModified hazelDidChange: <null>}:{(copy:/Users/.../code/misc/hs,{
    keepFolderStructure = 0;
    replaceExisting = 1;
    throwAwayDupes = 0;
})(shellscript:/bin/bash:fc6d8b219910b60f83660eb046341c20,{
})}


where old signatures is empty?
=====
Digging into the log, there are two events that shows up before hazel log says rule matched:

Code: Select all

HazelHelper[396] DEBUG: Thread 0x604000064cc0: Received events (
        {
        date = "2017-10-13 20:13:47 +0000";
        path = "/Users/david/.hammerspoon/init.lua";
        shouldDoFullScan = 0;
    }
) for stream at path: /Users/.../.hammerspoon

and

Code: Select all

hazelworker[31537] DEBUG: Received file event: {
    date = "2017-10-13 20:13:47 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7fc874ece5c0>\n  /Users/.../.hammerspoon/init.lua : 0\n";
}


The empty rule signature appears after hazel determines the rule is matched. Also, in the "show rule status" represented by an eye icon in the main interface>Folders, hazel shows the rule as matched regardless of whether hazel is stopped or not, so maybe the bug is there? Thanks!

Don't worry about it becoming unmatched. That's how it works.

Is this part accurate?

date = "2017-10-13 20:13:47 +0000";
path = "/Users/david/.hammerspoon/init.lua";

That would indicate some sort of modification event happening.

Mr_Noodle wrote:Don't worry about it becoming unmatched. That's how it works.

Is this part accurate?

date = "2017-10-13 20:13:47 +0000";
path = "/Users/david/.hammerspoon/init.lua";

That would indicate some sort of modification event happening.

the date is from another trial run, the file is not modified [Finder>info shows date modified unchanged.] I noticed the 'date modified did change' seem to match when Finder is displaying the folder being monitored?

Can you post an excerpt specifically showing a run when there was definitely no change but it ran anyways?

Mr_Noodle wrote:Can you post an excerpt specifically showing a run when there was definitely no change but it ran anyways?

Just reinstalled to get a clean slate, here is the excerpt showing a run when there should be no match for 'date modified did change'. Confirmed file modified data in finder/terminal to make sure there's no other processes making changes to the file.

Code: Select all

2017-10-17 15:45:47.357 hazelworker[77943] Processing folder .hammerspoon
2017-10-17 15:45:47.357 hazelworker[77943] DEBUG: Pausing to wait for things to settle down.
2017-10-17 15:45:48.263 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Received events (
        {
        date = "2017-10-17 19:45:48 +0000";
        path = "/Users/.../.hammerspoon/.DS_Store";
        shouldDoFullScan = 0;
    }
) for stream at path: /Users/.../.hammerspoon
2017-10-17 15:45:48.263 HazelHelper[396] DEBUG: Thread 0x604000064cc0: Run worker for folder: /Users/.../.hammerspoon
2017-10-17 15:45:48.263 HazelHelper[396] DEBUG: Task already running for folder: /Users/.../.hammerspoon
2017-10-17 15:45:49.358 hazelworker[77943] DEBUG: Processing directories: (
    "/Users/.../.hammerspoon"
)
2017-10-17 15:45:49.360 HazelHelper[396] DEBUG: Checking events for path /Users/.../.hammerspoon, folder .hammerspoon
2017-10-17 15:45:49.362 hazelworker[77943] DEBUG: Received file event: {
    date = "2017-10-17 19:45:48 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7ff17740f900>\n  /Users/.../.hammerspoon/.DS_Store : 0\n  /Users/.../.hammerspoon/init.lua : 0\n";
}
2017-10-17 15:45:49.363 hazelworker[77943] DEBUG: About to process directory /Users/.../.hammerspoon
2017-10-17 15:45:49.366 hazelworker[77943] init.lua: Rule init matched.
2017-10-17 15:45:49.366 hazelworker[77943] DEBUG: New rule signature. Executing actions.
Old signatures: (
)
New Signature:{displayName ==[cd] "init.lua" AND dateModified hazelDidChange: <null>}:{(copy:/Users/.../code/misc/hs,{
    keepFolderStructure = 0;
    replaceExisting = 1;
    throwAwayDupes = 0;
})(shellscript:/bin/bash:fc6d8b219910b60f83660eb046341c20,{
})}
2017-10-17 15:45:49.368 hazelworker[77943] DEBUG: Performing clone operation.


going into ~/Library/Application Support/Hazel, there is a hazeldb plist file; in this hazeldb, the monitored file's last modified date is identified properly (in ValueCache's modificationDate):

Code: Select all

<key>init.lua</key>
      <dict>
         <key>Date Matched</key>
         <date>2017-10-17T19:45:49Z</date>
         <key>File ID</key>
         <string>27087007</string>
         <key>Predicted Process Time</key>
         <real>63113904000</real>
         <key>ValueCache</key>
         <dict>
            <key>14F29E48-52A4-4BB6-8F03-461F7253B676</key>
            <dict>
               <key>modificationDate</key>
               <date>2017-10-17T15:15:07Z</date>


Also to make sure it's not a hardware issue, I ran first aid in disk utilities, no problem detected.

I'm currently traveling so I won't be able to look more closely into this until later this week.

Alternatively, you can try using "Date last modified is after date last matched" to have the rule match when the file is modified.