auto-lock might not be working properly

[pulpdoctor]

I was originally going to make the subject "What does auto-lock do?" but thought everyone would think, "duh."

So, I'll just start out and give you my idea of what auto-lock does. I assume that it will lock the folder, meaning that the folder will be re-encrypted and the user won't be able to view the contents of the folder.

If I'm wrong, then what comes next may be a moot point. Or more correctly, I need more information.

Here are my preferences for Espionage:

https://www.dropbox.com/s/7gr9vt3hx900zcl/Espionage%20preferences.jpg

As you can see, I have Espionage auto-lock after 10 minutes and the folders lock after 45 minutes. So this morning, I was working on a folder that I have encrypted using Espionage. I had Finder open to the folder that I had protected by Espionage. I got up and left and came back about 2 hours later and noticed that the files were still visible within the still open Finder.

So did auto-lock not work or, because Finder was still open, did Espionage "sense" that I was still working with the files and not trigger auto-lock?

Also, what is the effect of Espionage auto-locking? I would assume that when Espionage auto-locks, all the folders encrypted by Espionage would be re-encrypted but that is not what happening on my system.

[zsolt]

Hello, first a brief explanation how the auto locks work: the espionage auto lock will lock the application itself, i.e. will prevent further administration of protected folders. The counter is running since the moment of unlocking Espionage, and continues to run no matter what. The folder auto lock is something you define per folder, independent for each folder and from Espionage aoutolock setting. What is more peculiar here, is that the counter will run only when the Mac is idle. So whenever you use your Mac, the counter will keep resetting to zero.

Now to find out what is preventing the folder to lock, I would kindly ask you to do the following:

In the console you can see the idle time of the computer that Espionage uses to auto lock the folders.
Something like this:

2014-01-25 10:33:51.404 Espionage[7304:303] DEBUG: Folders autolock pulse. Idle time: 0.900457
2014-01-25 10:34:00.357 Espionage[7304:303] DEBUG: Folders autolock pulse. Idle time: 1.149612

The number at the end it's the minutes the computer has been idle. In this lines , it's been idle 0.9 and 1.1 minutes.
In the logs we could see if the app is failing to auto lock, or maybe there is something that is making the computer non-idle.
In this case, we would see something like this:

2014-01-25 10:36:34.791 Espionage[7427:303] DEBUG: Folders autolock pulse. Idle time: 0.000080
2014-01-25 10:36:49.796 Espionage[7427:303] DEBUG: Folders autolock pulse. Idle time: 0.095037
2014-01-25 10:37:04.801 Espionage[7427:303] DEBUG: Folders autolock pulse. Idle time: 0.000054

The auto lock pulse would always be around 0 minutes.

Here you can see a full log of a folder auto locking after 1 minute.
When the pulse reaches 1.146923 (>1 min) it creates a task to lock the folder.(LockFolderTask)


25/01/14 10:59:05,589 Espionage[11092]: DEBUG: Folders autolock pulse. Idle time: 0.146921
25/01/14 10:59:20,594 Espionage[11092]: DEBUG: Folders autolock pulse. Idle time: 0.396931
25/01/14 10:59:35,598 Espionage[11092]: DEBUG: Folders autolock pulse. Idle time: 0.646920
25/01/14 10:59:50,604 Espionage[11092]: DEBUG: Folders autolock pulse. Idle time: 0.896931
25/01/14 11:00:05,608 Espionage[11092]: DEBUG: Folders autolock pulse. Idle time: 1.146923
25/01/14 11:00:05,608 Espionage[11092]: DEBUG: -[NSFileManager(TEAdditions) isVolumeAtURL:error:]: '/Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate' == '/Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate': YES
25/01/14 11:00:05,609 Espionage[11092]: DEBUG: -[LockFolderTask go:]: /Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate
25/01/14 11:00:05,609 Espionage[11092]: DEBUG: -[NSFileManager(TEAdditions) isVolumeAtURL:error:]: '/Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate' == '/Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate': YES
25/01/14 11:00:05,609 Espionage[11092]: DEBUG: +[DiskMaster sanityCheckFolderFace:error:]: translate is unlocked
25/01/14 11:00:05,609 Espionage[11092]: DEBUG: Lock actions for folder: translate
25/01/14 11:00:05,609 Espionage[11092]: DEBUG: Executing actions for folder: translate
25/01/14 11:00:05,610 Espionage[11092]: DEBUG: +[DiskMaster unmountDiskForFolderFace:mountpoint:forcefully:updateUI:error:]: /Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate
25/01/14 11:00:06,418 Espionage[11092]: DEBUG: -[TEAppDelegate unmountNotification:]: /Users/ernesto/Develop/TaoEffect/carpetas_pruebas/translate

If we get the console log, we can figure out if the problem is in the auto lock pulse, or in the actual folder locking.

So if you could be so kind and set the folder lock to 1 minute, take a note on exact time, then continue to use your mac for 2 minutes, then take again note on time, and leave the mac idle for 2 minutes, then again take a note on time, and start to use it.

If the folder does not auto lock, then send us the console.log and the timestamps.

Thank a lot for your test.

Rgds
Zsolt

[pulpdoctor]

I think this is what you are looking for. I did the test you suggested (sorry for the long delay), and oddly enough Espionage did autolock the one folder I was concerned about. That folder is named TEMP. Here's the log and although I am not a programer or even close to it, it appears that a program I use called Bartender may be doing something that affects Espionage but that is only a guess on my part.

Then again, maybe Espionage is working as expected. However, I didn't see any of the entries that you showed where Espionage is counting down the time, e.g., the DEBUG Folders autolock pulse. Idle time.

Here's the console log with only Espionage entries:

Mar  5 06:18:04 unknown9027e4f92aaa Espionage[3217]: Bartender: Loaded BartenderHelperSixtySeven
Mar  5 06:18:07 unknown9027e4f92aaa Espionage[3217]: WARN (+[DiskMaster sanityCheckFolderFace:error:]:98): locked value was out of sync with reality for folder: /Users/admin/Temp
Mar  5 06:18:10 unknown9027e4f92aaa Espionage[3217]: WARN (_fastSize:361): accessDenied during size calc for: file://localhost/Users/admin/Temp/.DocumentRevisions-V100/
Mar  5 10:06:50 Jordans-MacbookPro.local Espionage[3217]: INFO: backed up: /Users/admin/Library/Application Support/com.taoeffect.Espionage3/Backups/database3 2014-03-05 100650
Mar  6 06:26:02 unknown9027e4f92aaa Espionage[1931]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 06:26:03 unknown9027e4f92aaa Espionage[1931]: Error loading /Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types:  dlopen(/Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types, 262): no suitable image found.  Did find:
Mar  6 06:26:03 unknown9027e4f92aaa Espionage[1931]: Bartender: Loaded BartenderHelperSixtySeven
Mar  6 06:26:13 unknown9027e4f92aaa Espionage[1931]: WARN (+[DiskMaster sanityCheckFolderFace:error:]:98): locked value was out of sync with reality for folder: /Users/admin/Temp
Mar  6 06:26:16 unknown9027e4f92aaa Espionage[1931]: WARN (_fastSize:361): accessDenied during size calc for: file://localhost/Users/admin/Temp/.DocumentRevisions-V100/
Mar  6 13:59:59 Jordans-MacbookPro.local Espionage[1931]: INFO: backed up: /Users/admin/Library/Application Support/com.taoeffect.Espionage3/Backups/database3 2014-03-06 135959
Mar  6 14:54:53 Jordans-MacbookPro.local Espionage[636]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 14:54:56 Jordans-MacbookPro.local Espionage[636]: Error loading /Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types:  dlopen(/Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types, 262): no suitable image found.  Did find:
Mar  6 14:54:56 Jordans-MacbookPro.local Espionage[636]: Bartender: Loaded BartenderHelperSixtySeven
Mar  6 14:55:01 Jordans-MacbookPro.local Espionage[636]: WARN (+[DiskMaster sanityCheckFolderFace:error:]:98): locked value was out of sync with reality for folder: /Users/admin/Temp
Mar  6 14:55:04 Jordans-MacbookPro.local Espionage[636]: WARN (_fastSize:361): accessDenied during size calc for: file://localhost/Users/admin/Temp/.DocumentRevisions-V100/
Mar  6 14:55:31 Jordans-MacbookPro.local Espionage[636]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 14:55:41 Jordans-MacbookPro.local Espionage[636]: *** WARNING: -[NSImage dissolveToPoint:fraction:] is deprecated in MacOSX 10.8 and later. Please use -[NSImage drawAtPoint:fromRect:operation:fraction:] instead.
Mar  6 14:55:41 Jordans-MacbookPro.local Espionage[636]: *** WARNING: -[NSImage dissolveToPoint:fromRect:fraction:] is deprecated in MacOSX 10.8 and later. Please use -[NSImage drawAtPoint:fromRect:operation:fraction:] instead.
Mar  6 14:56:18 Jordans-MacbookPro.local Espionage[636]: INFO: backed up: /Users/admin/Library/Application Support/com.taoeffect.Espionage3/Backups/database3 2014-03-06 145618
Mar  6 14:56:22 Jordans-MacbookPro.local Espionage[682]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 14:56:26 Jordans-MacbookPro.local Espionage[682]: Error loading /Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types:  dlopen(/Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types, 262): no suitable image found.  Did find:
Mar  6 14:56:26 Jordans-MacbookPro.local Espionage[682]: Bartender: Loaded BartenderHelperSixtySeven
Mar  6 14:56:44 Jordans-MacbookPro.local Espionage[682]: INFO: backed up: /Users/admin/Library/Application Support/com.taoeffect.Espionage3/Backups/database3 2014-03-06 145643
Mar  6 14:58:44 Jordans-MacbookPro.local Espionage[335]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 14:58:49 Jordans-MacbookPro.local Espionage[335]: Error loading /Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types:  dlopen(/Library/ScriptingAdditions/Adobe Unit Types.osax/Contents/MacOS/Adobe Unit Types, 262): no suitable image found.  Did find:
Mar  6 14:58:49 Jordans-MacbookPro.local Espionage[335]: Bartender: Loaded BartenderHelperSixtySeven
Mar  6 14:59:05 Jordans-MacbookPro.local Espionage[335]: FAILURE: Job com.taoeffect.Espionage3Helper is not loaded in launchd.
Mar  6 16:55:33 Jordans-MacbookPro.local Espionage[335]: WARN (_fastSize:361): accessDenied during size calc for: file://localhost/Users/admin/Temp/.DocumentRevisions-V100/
Mar  6 16:58:45 Jordans-MacbookPro.local Espionage[335]: ERROR (+[DiskMaster unmountDiskForFolderFace:mountpoint:forcefully:updateUI:error:]:515): FSEjectVolumeSync returned: -47
Mar  6 16:58:45 Jordans-MacbookPro.local Espionage[335]: ERROR (-[LockFolderTask go:]:82): failed to unmount '/Users/admin/Temp': (null)

[zsolt]

Hello, I forwarded the problem to our dev team, I'm waiting for their reply.
I will update you as soon as I get one.

Rgds
Zsolt

[zsolt]

Hello, I will provide you with a debug binary which should show the messages, but we are about to release version 3.6 in a few days, so if it is OK with you, let us release it first and then we will give you the 3.6 debug version.
Would that be fine with you?

Rgds
Zsolt

[pulpdoctor]

Sorry but I haven't been checking back and missed your message. I'm not in an hurry.

[zsolt]

Ok, I'll check the status of 3.6 and see when can we provide you with debug bin.
Rgds
Zsolt