Page 1 of 1

Rule not running until forced

PostPosted: Sun Apr 14, 2019 4:07 pm
by GeekNeck
HI,

I have found that a rule chain that has worked previously is now not completing. Files get moved from one directory to another, then a new rule renames the files then moves them to a different folder. Hazel did not recognize the files at first, but operated on them correctly when I forced it. Any ideas? Here is the log surrounding the directory in question.

I am running Hazel 4.3.5 on Mojave 10.14.4

Code: Select all
019-04-14 10:05:11.110 hazelworker[8414] StatementPDFServlet.pdf: Rule Move remaining PDFs to 2.HazelSort matched.
2019-04-14 10:05:11.111 hazelworker[8414] [File Event] File moved: StatementPDFServlet.pdf moved from folder /Users/paul/Action/HazelAutomation/1.HazelOCR to folder /Users/paul/Action/HazelAutomation/2.HazelSort.
2019-04-14 10:05:12.259 hazelworker[8417] Processing folder 2.HazelSort
2019-04-14 10:05:15.295 hazelworker[8417] Done processing folder 2.HazelSort
2019-04-14 10:05:25.456 hazelworker[8430] StatementPDFServlet.pdf: Rule Move remaining PDFs to 2.HazelSort matched.
2019-04-14 10:05:25.457 hazelworker[8430] [File Event] File moved: StatementPDFServlet-1.pdf moved from folder /Users/paul/Action/HazelAutomation/1.HazelOCR to folder /Users/paul/Action/HazelAutomation/2.HazelSort.
2019-04-14 10:05:25.600 hazelworker[8432] Processing folder 2.HazelSort
2019-04-14 10:05:28.372 hazelworker[8432] Done processing folder 2.HazelSort
2019-04-14 15:59:44.417 hazelworker[9001] Processing folder 2.HazelSort (forced)
2019-04-14 15:59:47.285 hazelworker[9001] [File Event] File renamed: /Users/paul/Action/HazelAutomation/2.HazelSort/StatementPDFServlet.pdf renamed to /Users/paul/Action/HazelAutomation/2.HazelSort/2019-03-31 pnc personal savings statement.pdf.
2019-04-14 15:59:47.287 hazelworker[9001] [File Event] File moved: 2019-03-31 pnc personal savings statement.pdf moved from folder /Users/paul/Action/HazelAutomation/2.HazelSort to folder /Users/paul/Action/HazelAutomation/3.HazelProcessed.
2019-04-14 15:59:47.439 hazelworker[9001] [File Event] File renamed: /Users/paul/Action/HazelAutomation/2.HazelSort/StatementPDFServlet-1.pdf renamed to /Users/paul/Action/HazelAutomation/2.HazelSort/2019-03-26 pnc personal checking statement.pdf.
2019-04-14 15:59:47.440 hazelworker[9001] [File Event] File moved: 2019-03-26 pnc personal checking statement.pdf moved from folder /Users/paul/Action/HazelAutomation/2.HazelSort to folder /Users/paul/Action/HazelAutomation/3.HazelProcessed.
2019-04-14 15:59:51.556 hazelworker[9001] Done processing folder 2.HazelSort

Re: Rule not running until forced

PostPosted: Mon Apr 15, 2019 10:42 am
by Mr_Noodle
Can you post logs when the files were supposed to be processed but weren't? It might help if you turn on debug mode: https://www.noodlesoft.com/kb/hazel-debug-mode/

Re: Rule not running until forced

PostPosted: Mon Apr 15, 2019 2:22 pm
by GeekNeck
I was able to reproduce by placing a similar file into the first directory to be processed. I see that all goes well until processing of the folder "2.HazelSort". I also see a reference to an odd scheduling time:
requestedSchedulingTime = "4001-01-01 00:00:00 +0000";


Code: Select all
2019-04-15 14:08:09.542 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Received events (
        {
        date = "2019-04-15 18:08:09 +0000";
        path = "/Users/paul/Action/HazelAutomation/2.HazelSort/StatementPDFServlet.pdf";
        shouldDoFullScan = 0;
    }
) for stream at path: /Users/paul/Action/HazelAutomation/2.HazelSort
2019-04-15 14:08:09.542 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Run worker for folder: /Users/paul/Action/HazelAutomation/2.HazelSort
2019-04-15 14:08:09.572 hazelworker[5152] Running worker (v4.3.5) for folder with identifier: 16777223-12887417849.
2019-04-15 14:08:09.573 hazelworker[5152] ###main load address: 0x10fc85000
2019-04-15 14:08:09.573 hazelworker[5152] ###Noodle load address: 0x10fda7000
2019-04-15 14:08:09.573 hazelworker[5152] ###CK load address: 0x10fd6b000
2019-04-15 14:08:09.580 hazelworker[5152] DEBUG: Program is licensed.
2019-04-15 14:08:09.595 hazelworker[5152] DEBUG: Error reading file /Users/paul/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/paul/Library/Application Support/Firefox/prefs.js, NSUnderlyingError=0x7f946cf00e60 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:09.597 hazelworker[5152] DEBUG: Could not find entry for default_directory in Chrome preference file.
2019-04-15 14:08:09.598 hazelworker[5152] DEBUG: Could not get modfication date of Safari prefs file /Users/paul/Library/Preferences/com.apple.Safari.plist: Error Domain=NSCocoaErrorDomain Code=260 "The file “com.apple.Safari.plist” couldn’t be opened because there is no such file." UserInfo={NSURL=file:///Users/paul/Library/Preferences/com.apple.Safari.plist, NSFilePath=/Users/paul/Library/Preferences/com.apple.Safari.plist, NSUnderlyingError=0x7f946ce2ca40 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:09.598 hazelworker[5152] DEBUG: Could not read Mail preferences.
2019-04-15 14:08:09.601 hazelworker[5152] Processing folder 2.HazelSort
2019-04-15 14:08:09.601 hazelworker[5152] DEBUG: Pausing to wait for things to settle down.
2019-04-15 14:08:10.578 hazelworker[5139] DEBUG: Could not get modfication date of Safari prefs file /Users/paul/Library/Preferences/com.apple.Safari.plist: Error Domain=NSCocoaErrorDomain Code=260 "The file “com.apple.Safari.plist” couldn’t be opened because there is no such file." UserInfo={NSURL=file:///Users/paul/Library/Preferences/com.apple.Safari.plist, NSFilePath=/Users/paul/Library/Preferences/com.apple.Safari.plist, NSUnderlyingError=0x7f8a7a51d370 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:10.578 hazelworker[5139] DEBUG: Could not get modfication date of Safari prefs file /Users/paul/Library/Preferences/com.apple.Safari.plist: Error Domain=NSCocoaErrorDomain Code=260 "The file “com.apple.Safari.plist” couldn’t be opened because there is no such file." UserInfo={NSURL=file:///Users/paul/Library/Preferences/com.apple.Safari.plist, NSFilePath=/Users/paul/Library/Preferences/com.apple.Safari.plist, NSUnderlyingError=0x7f8a7a51d4c0 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:10.578 hazelworker[5139] DEBUG: Could not read Mail preferences.
2019-04-15 14:08:10.578 hazelworker[5139] DEBUG: About to process directory /Users/paul/Action/HazelAutomation/1.HazelOCR
2019-04-15 14:08:10.579 hazelworker[5139] DEBUG: Writing out DB file for /Users/paul/Action/HazelAutomation/1.HazelOCR to path: /Users/paul/Library/Application Support/Hazel/16777223-12887417848.hazeldb
2019-04-15 14:08:10.579 hazelworker[5139] DEBUG: Directory /Users/paul/Action/HazelAutomation/1.HazelOCR processed in 0.001079 seconds
2019-04-15 14:08:10.579 HazelHelper[344] DEBUG: Checking events for path /Users/paul/Action/HazelAutomation/1.HazelOCR, folder 1.HazelOCR
2019-04-15 14:08:10.580 hazelworker[5139] DEBUG: Writing out DB file: /Users/paul/Action/HazelAutomation/1.HazelOCR
2019-04-15 14:08:10.580 hazelworker[5139] DEBUG: Sending metrics to scheduler. Next scheduled run: 4000-12-31 19:00:00.000
2019-04-15 14:08:10.581 HazelHelper[344] DEBUG: Received metrics for folder /Users/paul/Action/HazelAutomation/1.HazelOCR: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<ComNoodlesoft_NoodlePathSet: 0x600000ab4dc0>\n";
    unavailablePaths = "{(\n)}";
}
2019-04-15 14:08:10.581 HazelHelper[344] DEBUG: Timer scheduled for folder /Users/paul/Action/HazelAutomation/1.HazelOCR at 4001-01-01 00:00:00 +0000
2019-04-15 14:08:10.581 hazelworker[5139] Done processing folder 1.HazelOCR
2019-04-15 14:08:10.584 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Task removed: [5139]
2019-04-15 14:08:11.605 hazelworker[5152] DEBUG: Processing directories: (
    "/Users/paul/Action/HazelAutomation/2.HazelSort"
)
2019-04-15 14:08:11.608 HazelHelper[344] DEBUG: Checking events for path /Users/paul/Action/HazelAutomation/2.HazelSort, folder 2.HazelSort
2019-04-15 14:08:11.609 hazelworker[5152] DEBUG: Received file event: {
    date = "2019-04-15 18:08:09 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7f946cd13f30>\n  /Users/paul/Action/HazelAutomation/2.HazelSort/StatementPDFServlet.pdf : 0\n";
}
2019-04-15 14:08:11.609 hazelworker[5152] DEBUG: About to process directory /Users/paul/Action/HazelAutomation/2.HazelSort
2019-04-15 14:08:12.437 hazelworker[5152] DEBUG: StatementPDFServlet.pdf: Did not match any rules.
2019-04-15 14:08:12.437 hazelworker[5152] DEBUG: .DS_Store: File is hidden/invisible. Skipping.
2019-04-15 14:08:12.437 hazelworker[5152] DEBUG: Writing out DB file for /Users/paul/Action/HazelAutomation/2.HazelSort to path: /Users/paul/Library/Application Support/Hazel/16777223-12887417849.hazeldb
2019-04-15 14:08:12.444 hazelworker[5152] DEBUG: Directory /Users/paul/Action/HazelAutomation/2.HazelSort processed in 0.835072 seconds
2019-04-15 14:08:12.444 HazelHelper[344] DEBUG: Checking events for path /Users/paul/Action/HazelAutomation/2.HazelSort, folder 2.HazelSort
2019-04-15 14:08:12.445 hazelworker[5152] DEBUG: Sending metrics to scheduler. Next scheduled run: 4000-12-31 19:00:00.000
2019-04-15 14:08:12.445 HazelHelper[344] DEBUG: Received metrics for folder /Users/paul/Action/HazelAutomation/2.HazelSort: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<ComNoodlesoft_NoodlePathSet: 0x600000ab4ee0>\n";
    unavailablePaths = "{(\n)}";
}
2019-04-15 14:08:12.445 HazelHelper[344] DEBUG: Timer scheduled for folder /Users/paul/Action/HazelAutomation/2.HazelSort at 4001-01-01 00:00:00 +0000
2019-04-15 14:08:12.445 hazelworker[5152] Done processing folder 2.HazelSort
2019-04-15 14:08:12.459 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Task removed: [5152]
2019-04-15 14:08:12.489 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Timer fired for folder: /Users/paul/Action/HazelAutomation/3.HazelProcessed
2019-04-15 14:08:12.489 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Run worker for folder: /Users/paul/Action/HazelAutomation/3.HazelProcessed
2019-04-15 14:08:12.526 hazelworker[5153] Running worker (v4.3.5) for folder with identifier: 16777223-12887417851.
2019-04-15 14:08:12.527 hazelworker[5153] ###main load address: 0x101f3b000
2019-04-15 14:08:12.527 hazelworker[5153] ###Noodle load address: 0x102060000
2019-04-15 14:08:12.527 hazelworker[5153] ###CK load address: 0x10201f000
2019-04-15 14:08:12.535 hazelworker[5153] DEBUG: Program is licensed.
2019-04-15 14:08:12.558 hazelworker[5153] DEBUG: Error reading file /Users/paul/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/paul/Library/Application Support/Firefox/prefs.js, NSUnderlyingError=0x7fa9f6515fe0 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:12.560 hazelworker[5153] DEBUG: Could not find entry for default_directory in Chrome preference file.
2019-04-15 14:08:12.561 hazelworker[5153] DEBUG: Could not get modfication date of Safari prefs file /Users/paul/Library/Preferences/com.apple.Safari.plist: Error Domain=NSCocoaErrorDomain Code=260 "The file “com.apple.Safari.plist” couldn’t be opened because there is no such file." UserInfo={NSURL=file:///Users/paul/Library/Preferences/com.apple.Safari.plist, NSFilePath=/Users/paul/Library/Preferences/com.apple.Safari.plist, NSUnderlyingError=0x7fa9f663f120 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2019-04-15 14:08:12.561 hazelworker[5153] DEBUG: Could not read Mail preferences.
2019-04-15 14:08:12.563 hazelworker[5153] Processing folder 3.HazelProcessed
2019-04-15 14:08:12.563 hazelworker[5153] DEBUG: Pausing to wait for things to settle down.
2019-04-15 14:08:14.567 hazelworker[5153] DEBUG: Processing directories: (
    "/Users/paul/Action/HazelAutomation/3.HazelProcessed"
)
2019-04-15 14:08:14.574 HazelHelper[344] DEBUG: Checking events for path /Users/paul/Action/HazelAutomation/3.HazelProcessed, folder 3.HazelProcessed
2019-04-15 14:08:14.575 hazelworker[5153] DEBUG: Received file event: {
    date = "2019-04-15 18:08:12 +0000";
    path = "<ComNoodlesoft_NoodlePathSet: 0x7fa9f6707d50>\n  /Users/paul/Action/HazelAutomation/3.HazelProcessed : 18446744073709551615\n";
}
2019-04-15 14:08:14.575 hazelworker[5153] DEBUG: About to process directory /Users/paul/Action/HazelAutomation/3.HazelProcessed
2019-04-15 14:08:14.576 hazelworker[5153] DEBUG: .DS_Store: File is hidden/invisible. Skipping.
2019-04-15 14:08:14.576 hazelworker[5153] DEBUG: Directory /Users/paul/Action/HazelAutomation/3.HazelProcessed processed in 0.001319 seconds
2019-04-15 14:08:14.577 HazelHelper[344] DEBUG: Checking events for path /Users/paul/Action/HazelAutomation/3.HazelProcessed, folder 3.HazelProcessed
2019-04-15 14:08:14.577 hazelworker[5153] DEBUG: Sending metrics to scheduler. Next scheduled run: 4000-12-31 19:00:00.000
2019-04-15 14:08:14.577 HazelHelper[344] DEBUG: Received metrics for folder /Users/paul/Action/HazelAutomation/3.HazelProcessed: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<ComNoodlesoft_NoodlePathSet: 0x600000aa67a0>\n";
    unavailablePaths = "{(\n)}";
}
2019-04-15 14:08:14.577 HazelHelper[344] DEBUG: Timer scheduled for folder /Users/paul/Action/HazelAutomation/3.HazelProcessed at 4001-01-01 00:00:00 +0000
2019-04-15 14:08:14.578 hazelworker[5153] Done processing folder 3.HazelProcessed
2019-04-15 14:08:14.580 HazelHelper[344] DEBUG: Thread 0x600001fb16c0: Task removed: [5153]

Re: Rule not running until forced

PostPosted: Tue Apr 16, 2019 11:11 am
by Mr_Noodle
Is this the file you are referring to?
StatementPDFServlet.pdf: Did not match any rules.


If so, then it's not matching your rules. Try using the preview function to see why it isn't matching when that happens.

Re: Rule not running until forced

PostPosted: Tue Apr 16, 2019 11:19 am
by GeekNeck
But it does match in the Hazel Pref Pane. I don't know how to attach a screen shot, but I'm looking at the preview for 2.HazelSort. It says StatementPDFServlet.pdf matches a rule. If I "Run Rules Now" It will be processed.

This rule has been running fine with no modification for a number of months.

Re: Rule not running until forced

PostPosted: Tue Apr 16, 2019 11:19 am
by Mr_Noodle
What is the rule? Maybe it doesn't match at first but something happens later?

Re: Rule not running until forced

PostPosted: Wed Apr 17, 2019 11:16 am
by GeekNeck
It turns out that a reboot did the trick. Once I logged into my account, Hazel kicked in and moved the file. Thanks!