Missing files not detected by Ace AM

[Mike Hagedon]

Hi everyone,

Should we expect the audit manager to detect files that have gone missing? I would have assumed so, but we're investigating a case where the AM keeps humming along and doesn't notify about files missing from the filesystem. Here's the relevant part of the tree that I'm seeing when I browse the collection.

The problem is: I intentionally deleted testfiles/ and its contents from the filesystem, ran a full file audit, ran a partial audit of just that directory, and I cannot seem to get Ace to recognize that these files are no longer present. The aceam.log entries skip from 

[24/May/2019:21:30:33] Validation Thread: Waiting until: Fri May 24 21:30:38 UTC 2019

to 

[24/May/2019:21:30:34] [Audit] Exiting file supply iteration, Calling cancel on file supply iterator (just in case)

with nothing in between. On an audit with existing files, I see a bunch of entries relating to the files in between those lines.

Any pointers on what we can do? Am I misunderstanding something? I'm concerned that we can't currently trust our Ace installation to protect our content.

This is Ace AM 1.12, running under docker: https://github.com/ualibraries/ace-audit-manager (We're the institution that made that, though the specific person who made it has left.)

Thanks in advance for any guidance!

Mike

[Michael Ritter]

Hi Mike,

ACE should be marking the files as missing, both in its own Event Log (with 'File Missing') and in the browse applet where the files should be red (and selecting them should show them as missing).

I haven't used the docker installation but I can try it next week to see if I can replicate the issue. I will note that it is on an older version of ACE, but even then I wouldn't expect it to have the issue you're describing. I'd be interested in seeing if editing a file will have it be marked as 'Corrupt' as well.

-Mike

[Mike Hagedon]

Hi Mike,

Thanks! I figured it should behave something like that. 

We’ve definitely seen changed files marked as ‘Corrupt’ before, so it seems like that is working OK. I’d be happy to play with it more.

Mike

[Michael Ritter]

Hi Mike,

I got the ACE Docker deployed and was able to duplicate the issues you see. I was able to see this not only on the ACE AM which is provided in the Dockerfile, but also in the latest ACE AM version when deployed with Docker. After running a few audits I noticed that I had a "MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction" in my aceam.log, and the stack trace points to the location in the code where missing files are normally flagged.

I don't know why exactly this would be occurring in the Docker deployment, I'll need to see how the mysql deployment is handled and what is going on in the database itself. A cursory look makes it seem like a table being locked when the missing items query is executed. I'll need to do some more digging to see if I can understand more about why the table would be locked long enough for the query to fail.

-Mike

[Mike Hagedon]

Hi Mike,

Thank you so much for trying that! FWIW, our production Ace AM setups (2 peers) are installed with the "Singleton" approach in our docs, which just means we have a separate database and IMS. I'd guess you did the self-contained one; if so, it's good to know it's a problem either way.

For my own edification, can you link me to the place in the code where missing files are normally flagged?

Thanks again!

Mike

[Michael Ritter]

Hi Mike,

That's correct that I used the self-contained docker deployment. I didn't get any extra time today to look further into the issue, so perhaps tomorrow. The only thing I can say for now is that I'm used to using MyISAM as the database engine, but from my reading using today seems to be mostly an inheritance use case. I think the Docker images were using InnoDB so there's a good place to start on resolving the issue.

Within the code, the missing files are created at line 747 of AuditThread.java. The query itself is defined in MonitoredItem.java. There are a few things to know about the AuditThread that lead to that query:

1. It retrieves a list of files from the filesystem on which it iterates
2. Every file it sees on the filesystem has its 'lastVisited' field updated (which will be the start time of the Audit)
3. The MonitoredItem query can then request files which have a 'lastVisited' less than the current time.
1. This is done with an UPDATE to put the work on the database

There are also some log events which get added for each new missing item which similarly to the MonitoredItem query offloads to work to the database.

-Mike

[Michael Ritter]

Hi Mike,

An update of sorts:

I created a database for myself using InnoDB on my local MariaDB server and was able to see the same issue without using Docker, which was expected. After doing this I tried modifying the transaction isolation level to both READ-COMMITTED and READ-UNCOMMITTED in order to try see what type of behavior I would encounter:

• READ-COMMITTED was able to mark the files as missing, but did not commit the event log entries
  
• READ-UNCOMMITTED was able to mark the files as missing and commit the event log entries
  

I then tried to replicate this behavior in the Docker deployment since it is using MySQL. When doing this, both READ-COMMITTED and READ-UNCOMMITTED were able to mark the files as missing but neither commit the event log entries. I'm not sure why there's a difference in behavior between MariaDB and MySQL here, perhaps there's something that I missed in the setup. Likewise I'm not entirely certain of the implications of using READ-COMMITTED vs READ-UNCOMMITTED for the application.

-Mike

[Michael Ritter]

Hi Mike,

Upon looking into this further, I realized there was an issue in the code and I started up a branch in our gitlab to track the changes for fixing this issue:
https://gitlab.umiacs.umd.edu/adapt/ace/tree/docker-resolutions

The work is now mostly complete - it turns out that the update and the insert were on separate transactions, leading to the (dead) lock we saw when using InnoDB. There was an additional issue with the date times being sent to MySQL needing to be truncated in order for the log events to be inserted, which I have added a change for as well. There's still a little bit of work left to do: I want to revisit the date times to make sure we are not sending fractional seconds elsewhere, and I need to look into newer releases not loading the css properly through Docker. I had some other changes in the pipeline which are set to be in release 1.14, which I'm planning on getting out once this issue is resolved.

Once the release is out, I can make a post about it on this group. I could also send a pull request to your ace-docker repository to update the Dockerfile with the new version.

-Mike

[Mike Hagedon]

Oh, nice! Glad to help find bugs. :-)

If you do send a PR, of course, that's appreciated! If you don't have time for that, we'll see the announcement here. 

Thank you so much! I'm excited for the new release.