QRecall

Johannes · Bildschirmfoto 2010-12-12 um 19.14.13.png

Today I found QRecall missing one file change (a Mellel text file, which is a package with gziped xml inside).

As you can see in the screenshot, the file was first captured at Layer 32 (a few minutes after I created it) and recaptured half an hour later after some changes. After 17:00 I edited the file again (only one word or so) and saved at 17:14 as the modification time of the Finder (right in screenshot) says. But QRecall does not recapture it.

The Log in the console says:
2010-12-12 16:00:03.427 +0100 #debug# CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB) [2.734118.861.192]
2010-12-12 16:30:03.297 +0100 #debug# CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB) [2.734118.918.192]
2010-12-12 17:00:03.380 +0100 #debug# CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB) [2.734118.941.192]
2010-12-12 18:00:03.741 +0100 #debug# CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB) [2.734118.1154.184]
2010-12-12 18:30:03.403 +0100 #debug# CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB) [2.734118.1293.192]

To me it looks like QRecall does not detect the change at all.

Johannes

James Bucanek

Johannes wrote:To me it looks like QRecall does not detect the change at all.

OS X didn't detect the change.

To speed up captures, QRecall uses OS X's File System Events service (or just FSEvents). This file-system level facility is supposed to keep track of every directory that contains a change (new file, a change in data, etc.) that occurs anywhere on the volume. Applications can receive this information as a real-time stream of changes, or can query the volume for a list of historical changes.

QRecall uses the later. When it starts, it requests a list of every folder that has been changed or contains a file that changed, since the previous capture. This appears in the log as "Collected XXX folder changes." It then restricts its scan to just those folders that contain modifications. When you see a log message like this:

CaptureProcessor(Tscho:Privat:Korrespondenz:GEZ.mellel) content assumed stable: inherit package 676866 (10 KB)

it means that OS X has assured QRecall that no changes have occurred in that folder, or any folders it contains. QRecall accepts this, assumes all of the previously captured information is up-to-date (i.e. it "inherits" the previously captured folder) and moves on.

However, it turns out that this is not always the case. I have two other users who were able to document where files were changed, but never reported by FSEvents. The two things they have in common are (a) they were running Windows in a virtual machine, and (b) the changed file was inside a package. I've reported this to Apple, but Apple has not yet released a fix or provided a workaround.

There are also other, well documented, situations where FSEvents also fails to report changes. QRecall deals with this by periodically ignoring the FSEvent information and preforming a "deep scan" where it examines every file and folder for possible changes?obviously, a much more time consuming process. This appears in the log as "Filesystem change history ignored." The default period is approximately once a week, but you can change this using the QRAuditFileSystemHistoryDays advanced QRecall setting.

Johannes

Thanks again for the quick response (this kind of support is really outstanding!).

OS X didn't detect the change.

Time Machine was able to detect it. Doesn't Time Machine use FSEvents too?

I have two other users who were able to document where files were changed, but never reported by FSEvents. The two things they have in common are (a) they were running Windows in a virtual machine, and (b) the changed file was inside a package.

So I am in (b) too it seems.

QRecall deals with this by periodically ignoring the FSEvent information and preforming a "deep scan" where it examines every file and folder for possible changes?obviously, a much more time consuming process.

Couldn't QRecall simply check the modification time in addition to FSEvents? As the Finder displays the correct modification time it brings up the file with a simple smart search in no time. Just a thought.

The default period is approximately once a week, but you can change this using the QRAuditFileSystemHistoryDays advanced QRecall setting.

Changing this setting to 0.0 brought home the changed file (and produced a ton of "GID different" decisions that choked up the log window).

It would be nice to have an option for a "deep scan" in the Action window. So I would have my longtime and off-site Archives run a deep scan always, while the hourly thing could do without.

Or maybe I should go for always deep scanning. Missing changes is a serious issue for backups.

Johannes

James Bucanek

Johannes wrote:Thanks again for the quick response (this kind of support is really outstanding!).

I aim to please.

Time Machine was able to detect it. Doesn't Time Machine use FSEvents too?

Time Machine might detect it. Time Machine also uses FSEvents, but how it uses varies. If the process subscribes to the "live" feed of change events, the change event appears in the feed. But if a process requests the "historic" log of events, the change event is missing.

Time Machines uses a combination of both live and historic events. QRecall only uses historic events. I've performed controlled experiments and shown than when Time Machine (and every other backup utility that uses FSEvents) gets its change information from the historic record, it misses those changes too.

So I am in (b) too it seems.

That's good information to know. Can you also tell me what application was used to change the contents of the package?

Couldn't QRecall simply check the modification time in addition to FSEvents?

Yes, it's called a "deep scan".

QRecall can either read the metadata for every file and folder or it can trust FSEvents. There's really no middle ground.

Changing this setting to 0.0 brought home the changed file ...
It would be nice to have an option for a "deep scan" in the Action window.

I would prefer to address this some other way. I'm not a fan of adding user interface complexity just to work around a bug in the OS.

So I would have my longtime and off-site Archives run a deep scan always, while the hourly thing could do without.

Set QRAuditFileSystemHistoryDays to 0.95. That will force a deep scan once a day.

Or maybe I should go for always deep scanning. Missing changes is a serious issue for backups.

At least one of my users has chosen this route.

Johannes

Thanks for all the explanation. I will keep watching the issue.

Can you also tell me what application was used to change the contents of the package?

Mellel (http://www.mellel.com). The file format Mellel uses for its documents is a package containing a gziped xml and images (if any). Normally QRecall (or FSEvents) seems to be dealing fine with them.

Johannes

Johannes

James Bucanek wrote:
Set QRAuditFileSystemHistoryDays to 0.95. That will force a deep scan once a day

On what base will QRecall do the maths? Once a day for each Archive? For each Action? For each machine?

Consider the following scenario with your suggested setting:

Action 1: Folder 1+2+3 to Archive 1
running every hour backing up my three main working folders

Action 2: Folder 1+2+3+4+5 to Archive 1
running manually at the end of the day (when all files and databases are closed). This Action includes the three folders from Action and some more.

Action 3: Folder 1+2+3+4+5 to Archive 2
running when external offsite disk is connected (weekly)

Will I get a deep scan for Action 2 and 3 every time with the above setting?

Johannes

James Bucanek

Johannes wrote:

James Bucanek wrote:
Set QRAuditFileSystemHistoryDays to 0.95. That will force a deep scan once a day

On what base will QRecall do the maths? Once a day for each Archive? For each Action? For each machine?

It's based on how long it's been since a deep scan was performed for the items being captured.

Will I get a deep scan for Action 2 and 3 every time with the above setting?

Yes.

QRecall keeps track of how long it has trusted FSEvents to determine changes for each (top-level) item captured in the archive. During the next capture, it compares the scope of what's being captured to what's in the archive and determines the minimum common overlap between the two. It then compares the "FSEvent trust" dates and finds the largest interval.

Let's say QRAuditFileSystemHistoryDays was set to 1.0. Now let's say you captured '/' two days ago and '/Users/you/Document' two hours ago, both using a deep scan.

If you were to capture 'Documents' again, the difference in trust dates would be 2 hours, so no deep scan is required. If you captured '/Users/you' the difference would be 2 days, because the oldest capture that encompasses '/Users/you' in the archive is '/', which is now two days old.

Now instead of capturing '/Users/you', let's say you captured '/Users/you/Documents/Projects' an hour later, QRecall would not perform a deep scan because 'Projects' is encompassed by '/Users/you/Documents', and the latest capture of 'Documents' trusted FSEvents for 2 hours, so the aggregate trust time is now 3 hours.

So as you can see, it's kind of complicated, but it also can't easily be tricked into trusting FSEvents for longer then it should.

Johannes

Thanks for the explanation. I will test this. What is the indication in the Log for a deep scan?

Johannes

James Bucanek

James Bucanek wrote:This appears in the log as "Filesystem change history ignored."

James Bucanek

Johannes,

I forgot to mention this before; if you really want to have fun with file system events, there's a secret (well, not so secret now) setting for logging FSEvent records to the QRecall log. Use the defaults command tool to set QRLogFSEvents to true:

defaults write com.qrecall.client QRLogFSEvents -boolean true

With QRLogFSEvents set, QRecall will dump all of the individual change event records that it receives from the OS. If QRLogFSEvents and QRLogCaptureDecisions are both set, it will also dump the change history tree to the log before the capture begins. This tree represents the the composite folder structure which QRecall believes contains changes based on the FSEvent records it received. Basically, any folder outside of this tree is assumed to be unchanged since the previous capture.

Johannes

James Bucanek wrote:This appears in the log as "Filesystem change history ignored."

Can't find this string anywhere in the log. But it seems that with QRLogFSEvents set the EventRootDirectory item comes up when FSEvent is used and is missing for a deep scan.

Johannes

James Bucanek

Johannes wrote:Can't find this string anywhere in the log.

Make sure you have the log detail level control moved all the way to the right. This message is considered to be "minutia" and is only displayed at the very highest detail level.

Johannes

James Bucanek wrote:
Make sure you have the log detail level control moved all the way to the right.

I have. No luck. Even a string search in the logfile (within Konsole) does not reveal it.
Anyway. Not that important.

Johannes