Missing search results

We use the following search on users' home pages to show their activity:

%SEARCHLOG{"user='%TOPIC%' AND action = "save"" reverse="true" limit="1000" format="| $time | [[$web.$topic][$percntSPACEOUT{$topic}$percnt]] Rev. $rev |" header="" footer=""}%

This works fine in at least one account, but in at least one other, it gives partial results, with the excluded results showing no pattern that I can discern. So far I've checked the following:

The events.log does contain the saves that are missing from the search,
the user name is invariant,
restricting the expected number of results to be less than 25 by narrowing the date range does not reveal the missing topic saves,
replacing the TOPIC call with the explicit user name does not fix the problem,
adding the user to the admin group does not fix the problem.

Any ideas as to what the problem might be?

While I'm here, I had to disable the header because the generated table was always scrambled when I tried to use it.

-- JacobEtches - 25 Sep 2012

Check over your event log files. make sure that each log record is on a single line. I've seen the logs get corrupted if someone manages to insert a newline into one of the fields. The data will be all there, but the eachEventSince log iterator might get confused.

I'm not sure what else to suggest. I've not used that plugin. Which logger are you using? Compatibility or the PlainFile logger?

-- GeorgeClark - 25 Sep 2012

Thanks. The log is not corrupted in that way. We use PlainFile. I also realized that there is not a user for whom this works correctly. All users have mysteriously missing activity.

We did resolve the header/footer problem. The header lacks $n at the end and the footer lacks $n at the beginning in ContributorsPlugin.pm.

This macro is also a privacy concern since it permits any user to monitor the viewing habits of other users. Is there an alternative search strategy to list the recent topic saves of users?

-- JacobEtches - 26 Sep 2012

Are you able to correlate the log records to the user activity? Is the issue that the log is missing the record of the activity (really bad) or that the eachEventSince iterator is missing the records, or the extension is somehow loosing the information. One point, the default Foswiki loggers don't do file locks, so on a busy system, it might be possible for collisions between apache workers to cause logging issues.

There is an experimental Extensions/Testing.LogDispatchContrib that was just released to the Extensions/Testing web. This is still a work in progress, I'm not sure of the stability yet. But it does provide a logger that does logging and is thread and fork safe.

I don't know of any other way to get the information. Regarding the leakage of viewing habits, that would probably need a change to the macro provided by the extensions.

-- GeorgeClark - 26 Sep 2012

Thanks again. The log is correct, but either the iterator misses records or the extension is losing the information. I don't know how to evaluate which - we have no one with experience writing PERL code. The system is not very busy, so I doubt collisions.

-- JacobEtches - 27 Sep 2012

You might check on IRC to try to catch SvenDowideit, who is the author of this extension. With timezones and all you might have to try a few times. His ID is logged in all the time, but he might not be around at the time.

There is a cache built in working/work_areas/ContributorPlugin (or something like that). You might try finding / clearing any cached data for the user in question.

-- GeorgeClark - 27 Sep 2012

From what I can tell, the cache contains only contributions data for page footers, not data for SEARCHLOG queries. I cleared it, and it makes no difference.

-- JacobEtches - 27 Sep 2012

Only other thing I can think of after reviewing the PlainFile code, the eachEventSince event iterator will skip any record if a problem with the timestamp causes it to not be understood as a foswiki date. If you can identify specific events in the log that were skipped, take a good look at the timestamp, and if you can sanitize the information, please post that record, and maybe the preceding event or two in a <verbatim> </verbatim> block here.

-- GeorgeClark - 27 Sep 2012

Thanks. I checked the timestamps, and they looked fine. I loaded them into R (http://www.r-project.org/) and converted them to posix with no errors, so I don't think there are any irregularities.

I also noticed while tinkering that the limit to the number of query results is applied before the reverse sort is applied, so that you don't get the most recent results if you exceed the limit.

So the bugs identified are: