Rule with shell script not running automatically

[anto]

Hi all,

I have a rule setup on the /Volumes/ folder. The rule passes a shell script to check if a volume has been mounted and if not, runs an Apple Script to mount the volume.

It used to work without any issue but lately (about a week or two), I've noticed that it doesn't run unless I run the rule manually. When I do, it mounts the drive successfully. The rule preview also passes. When I check the logs it doesn't help as it only shows me the output from when it runs, not why it might not be running.

Any ideas what might be causing it?

Thank you!

The shell script (/bin/bash) on the matching condition is:

Code: Select all

if [ -d "/Volumes/Media" ]; then exit 1; else exit 0; fi

And the Apple Script is:

Code: Select all

tell application "Finder"
   if not (disk "Media" exists) then
      mount volume "afp://user:pass@servername.local/Media/"
   end if
end tell

[Mr_Noodle]

I'm not clear on when this should be triggered. Hazel doesn't really operate by triggering on the absence of something.

[anto]

The rule is set on the folder /Volumes/ so when the first script passes and fails to find the /Media/ volume, it should run the Apple Script to mount it. Works when triggering the rule on the /Volumes/ folder manually but if I eject the /Media/ volume it doesn't run the rule automatically, but it used to.

[Mr_Noodle]

In that case, check the logs during the time you ejected the drive.

[anto]

The drive hadn't mounted since I booted the machine this morning so when I ran the test this is what I got:

• Drive not mounted
• Force run the Volumes rule
• Drive mounted
• Eject drive
• Wait
• Reload logs

After waiting for a bit and reloading the logs, I don't see anything else happening and the drive is still unmounted.

Code: Select all

2021-06-08 13:39:31.813 hazelworker[2155] Processing folder Volumes (forced)
2021-06-08 13:39:33.964 hazelworker[2155] Macintosh HD: Rule Mount Media matched.
2021-06-08 13:39:40.503 hazelworker[2155] Done processing folder Volumes
2021-06-08 13:39:48.702 hazelworker[2334] Running worker (v5.0.7) for folder with identifier: 16777223-419757.
2021-06-08 13:39:48.710 hazelworker[2334] ###main load address: 0x10fc69000
2021-06-08 13:39:48.710 hazelworker[2334] ###Hazel Core load address: 0x10fca2000
2021-06-08 13:39:48.710 hazelworker[2334] ###Noodle load address: 0x10fdb9000
2021-06-08 13:39:48.710 hazelworker[2334] ###CK load address: 0x10fd73000
2021-06-08 13:39:48.760 hazelworker[2334] Processing folder Volumes
2021-06-08 13:39:50.843 hazelworker[2334] Done processing folder Volumes


[Mr_Noodle]

What time did you unmount the drive?

[anto]

I don't have the exact time and can't find it in the system.log. I repeated the steps just now and couldn't find details of the mount in the log either. So I can't say for certain.

If I unmount it now and don't force run the rule it won't ever mount unless I force the rule. Previously if the drive became disconnected it'd be caught and automatically mount. That's why I'm using Hazel instead of a login item.

[Mr_Noodle]

Seems like there an issue with the system. It should be generating file events. Does mounting a drive trigger a run? What os version are you running?

[anto]

Ran the test again, unmounted and was able to see a record of the unmount in /var/log/DiagnosticMessages/

I'm running 10.15.7 and Hazel 5.0.7.

[Mr_Noodle]

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

After doing that, post new logs when unmounting a drive.

[anto]

OK. Did that. Drive was mounted, turned on debug logging, unmounted drive.

Here's the log:

Code: Select all

2021-06-11 15:36:58.893 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Checking events for path /Volumes, folder Volumes
2021-06-11 15:37:00.968 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Checking events for path /Volumes, folder Volumes
2021-06-11 15:37:00.968 hazelworker[4233] Done processing folder Volumes
2021-06-11 15:37:00.969 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Received metrics for folder /Volumes: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<NoodlePathSet: 0x7fcb4c9041d0>\n";
    unavailablePaths = "{(\n)}";
}
2021-06-11 15:37:00.969 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Timer scheduled for folder /Volumes at 4001-01-01 00:00:00 +0000
2021-06-11 15:37:00.976 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Thread 0x7fcb4af12cb0: Task removed: [4233]
2021-06-11 15:37:16.642 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Recorded unmount at path: /Volumes/Media
2021-06-11 15:37:17.638 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Thread 0x7fcb4af12cb0: Received events (
        {
        date = "2021-06-11 19:37:17 +0000";
        path = "/Volumes/Media";
        shouldDoFullScan = 0;
    }
) for stream at path: /Volumes
2021-06-11 15:37:17.638 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Error resolving symlinks for path /Volumes/Media:, No such file or directory
2021-06-11 15:37:17.638 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Thread 0x7fcb4af12cb0: Run worker for folder: /Volumes
2021-06-11 15:37:17.673 hazelworker[4509] Running worker (v5.0.7) for folder with identifier: 16777223-419757.
2021-06-11 15:37:17.674 hazelworker[4509] ###main load address: 0x105398000
2021-06-11 15:37:17.674 hazelworker[4509] ###Hazel Core load address: 0x1053d1000
2021-06-11 15:37:17.674 hazelworker[4509] ###Noodle load address: 0x1054eb000
2021-06-11 15:37:17.674 hazelworker[4509] ###CK load address: 0x1054a7000
2021-06-11 15:37:17.685 hazelworker[4509] DEBUG: Program is licensed.
2021-06-11 15:37:17.695 hazelworker[4509] DEBUG: Error reading file /Users/af/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/af/Library/Application Support/Firefox/prefs.js, NSUnderlyingError=0x7ff78d90f760 {Error Domain=NSPOSIXErrorDomain Code=2 "No such file or directory"}}
2021-06-11 15:37:17.698 hazelworker[4509] DEBUG: Could not find entry for default_directory in Chrome preference file.
2021-06-11 15:37:17.700 hazelworker[4509] Processing folder Volumes
2021-06-11 15:37:17.700 hazelworker[4509] DEBUG: Pausing to wait for things to settle down.
2021-06-11 15:37:19.771 hazelworker[4509] DEBUG: Processing directories: (
    "/Volumes"
)
2021-06-11 15:37:19.802 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Checking events for path /Volumes, folder Volumes
2021-06-11 15:37:19.802 hazelworker[4509] DEBUG: Received file event: {
    date = "2021-06-11 19:37:17 +0000";
    path = "<NoodlePathSet: 0x7ff78c425060>\n  /Volumes/Media : 0\n";
}
2021-06-11 15:37:19.802 hazelworker[4509] DEBUG: About to process directory /Volumes
2021-06-11 15:37:19.804 hazelworker[4509] DEBUG: Skipped /Volumes/Macintosh HD. File/folder not part of change set/file event.
2021-06-11 15:37:19.805 hazelworker[4509] DEBUG: .timemachine: File is hidden/invisible. Skipping.
2021-06-11 15:37:19.805 hazelworker[4509] DEBUG: Removed entry for file Media.
2021-06-11 15:37:19.805 hazelworker[4509] DEBUG: Writing out DB file for /Volumes to path: /Users/af/Library/Application Support/Hazel/16777223-419757.hazeldb
2021-06-11 15:37:19.805 hazelworker[4509] DEBUG: Directory /Volumes processed in 0.002879 seconds
2021-06-11 15:37:19.806 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Checking events for path /Volumes, folder Volumes
2021-06-11 15:37:19.806 hazelworker[4509] DEBUG: Writing out DB file: /Volumes
2021-06-11 15:37:19.806 hazelworker[4509] DEBUG: Sending metrics to scheduler. Next scheduled run: 4000-12-31 19:00:00.000
2021-06-11 15:37:19.806 hazelworker[4509] Done processing folder Volumes
2021-06-11 15:37:19.807 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Received metrics for folder /Volumes: {
    directoryDepth = 0;
    requestedSchedulingTime = "4001-01-01 00:00:00 +0000";
    triggerPaths = "<NoodlePathSet: 0x7fcb4ae2b960>\n";
    unavailablePaths = "{(\n)}";
}
2021-06-11 15:37:19.807 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Timer scheduled for folder /Volumes at 4001-01-01 00:00:00 +0000
2021-06-11 15:37:19.808 86Z3GCJ4MF.com.noodlesoft.HazelHelper[557] DEBUG: Thread 0x7fcb4af12cb0: Task removed: [4509]


[Mr_Noodle]

Thanks for the log. It seems me original guess was correct. The problem when you unmount a drive is that the drive no longer exists. It generates a file event but since the existing folders haven't changed, they are ignored. An alternative is to monitor the root directory and have a rule match Volumes, which will be updated everything a volume is mounted and unmounted.

[anto]

Thanks for looking into the log. I’ll try adjusting the rule. Will update if I get it working again.

Thanks!

[anto]

Got it working again. Setup a new rule to look at the root folder. Added a new rule to check for the subfolder "Volumes" and then ran my rules with my scripts. Works perfectly. Thanks again for your time and your suggestions.