[Archivesspace_Users_Group] (re)indexing in 2.8.1

Wed May 18 15:21:38 EDT 2022

Blake and others,

Overall, we went for a week or so with no errors in terms of re-indexing.
I'm looking into some database timeouts which are occurring periodically
(AS and our database server are in two different locations) but with the
connection getting re-established, I can work to address that separately.

But last night we did run into some errors which we are trying to track
down.  A couple of things:

- Even though the config setting is for DEBUG, the indexer log is only
showing INFO. Should there be more than that?

- If the log says:

I, [2022-05-17T22:27:11.756683 #5273]  INFO -- : Thread-2890: Staff Indexer
[2022-05-17 22:27:11 -0400] ~~~ Indexed 216
of 20898 archival_object records in repository UNDA

immediately followed by an error, how do we determine which record that is
in ArchivesSpace?  We are not sure how to find the record which is
indicated in the log.

Thanks again,
Tom

On Mon, May 16, 2022 at 5:19 PM Blake Carver <blake.carver at lyrasis.org>
wrote:

> That could be it, looks like some kind of "funny" character ArchivesSpace
> doesn't like in there probably. Do the "Indexed x of x whatever " numbers
> start over right there in the log?
> You should see what record it was working on just before there.
>
> ------------------------------
> *From:* archivesspace_users_group-bounces at lyralists.lyrasis.org <
> archivesspace_users_group-bounces at lyralists.lyrasis.org> on behalf of Tom
> Hanstra <hanstra at nd.edu>
> *Sent:* Monday, May 16, 2022 10:43 AM
> *To:* Archivesspace Users Group <
> archivesspace_users_group at lyralists.lyrasis.org>
> *Subject:* Re: [Archivesspace_Users_Group] (re)indexing in 2.8.1
>
> I've been monitoring logs and have run into a couple of instances where I
> receive this type of error:
>
> E, [2022-05-16T08:57:57.207392 #5273] ERROR -- : Thread-3962: Unhandled
> exception!
> E, [2022-05-16T08:57:57.207810 #5273] ERROR -- :
> invalid byte sequence in UTF-8
>
> and then a lot of detail. Are these errors with data that should be
> addressed?  I'm still in DEBUG mode in the backend log but it is not clear
> how to figure out which record(s) are being flagged. What am I looking for?
>
> Thanks,
> Tom
>
> On Thu, May 12, 2022 at 8:59 AM Blake Carver <blake.carver at lyrasis.org>
> wrote:
>
> > Could it be that we added a big record which is now having issues being
> extracted. Or a corrupted record which is causing such issues?
>
>  I don't think so? It could be, but those errors make me think there's
> something else going on with the DB, or maybe the network between the
> application and DB server? I'm not really sure what the problem is, but it
> seems more like a hardware/network/server issue than an ArchivesSpace
> issue. I can't be sure, but those errors don't look like ArchivesSpace
> troubles to me. Those are pretty common errors, so I'd do some searching
> around to see what you can find to troubleshoot.
> ------------------------------
> *From:* archivesspace_users_group-bounces at lyralists.lyrasis.org <
> archivesspace_users_group-bounces at lyralists.lyrasis.org> on behalf of Tom
> Hanstra <hanstra at nd.edu>
> *Sent:* Wednesday, May 11, 2022 9:30 AM
> *To:* Archivesspace Users Group <
> archivesspace_users_group at lyralists.lyrasis.org>
> *Subject:* Re: [Archivesspace_Users_Group] (re)indexing in 2.8.1
>
> Thanks again for your help.
>
> Late yesterday, both indexes indicated completion so I thought maybe
> things were going to be OK. Consequently, I did not do much in terms of
> testing.
>
> This morning, the logs again had errors, however.  In the logs, I found
> this error in the indexer log:
>
> I, [2022-05-10T21:36:07.181427 #30003]  INFO -- : Thread-2890: Staff
> Indexer [2022-05-10 21:36:07 -0400] Index round complete
> I, [2022-05-10T21:36:37.182006 #30003]  INFO -- : Thread-2890: Staff
> Indexer [2022-05-10 21:36:37 -0400] Running index round
> E, [2022-05-10T21:36:37.283423 #30003] ERROR -- : Thread-2890:
> uri:classloader:/jsonmodel_client.rb:493:in `all'
> /home/app/archivesspace/data/tmp/jetty-0.0.0.0-8091-indexer.war-_aspace-indexer-any-/webapp/WEB-INF/app/lib/periodic_indexer.rb:154:in
> `run_index_round'
> /home/app/archivesspace/data/tmp/jetty-0.0.0.0-8091-indexer.war-_aspace-indexer-any-/webapp/WEB-INF/app/lib/periodic_indexer.rb:283:in
> `run'
> /home/app/archivesspace/data/tmp/jetty-0.0.0.0-8091-indexer.war-_aspace-indexer-any-/webapp/WEB-INF/app/main.rb:32:in
> `block in main'
> E, [2022-05-10T21:36:37.284431 #30003] ERROR -- : Thread-2890:
> #<RuntimeError: {"error":{"db_error":["Database integrity constraint
> conflict: Java::JavaSql::SQLNonTransientConnectionException: No operations
> allowed after connection closed."]}}
>
> and in the backup log there were issues with timeouts retrieving a record:
>
> Java::ComMysqlCjJdbcExceptions::CommunicationsException: The last packet
> successfully received from the server was 1,759 milliseconds ago. The last
> packet sent successfully to the server was 28,849,143 milliseconds ago. is
> longer than the server configured value of 'wait_timeout'. You should
> consider either expiring and/or testing connection validity before use in
> your application, increasing the server configured values for client
> timeouts, or using the Connector/J connection property 'autoReconnect=true'
> to avoid this problem.
>
> Could it be that we added a big record which is now having issues being
> extracted. Or a corrupted record which is causing such issues?
>
> I've now restarted with the 1x1 and DEBUG on and only staff indexing and
> it is still thinking indexing is complete. I'll keep things going this way
> until we hit an error again and hopefully that will give additional
> information.
>
> I'll also look into the "autoReconnect=true" piece, since we seem to have
> a situation where, once this happens, nothing more works until a restart.
>
> Thanks again for any thoughts on this,
> Tom
>
> On Wed, May 11, 2022 at 5:03 AM Andrew Morrison <
> andrew.morrison at bodleian.ox.ac.uk> wrote:
>
> Indexing can also fail at the commit stage, not related to any one record.
> That is when ArchivesSpace tells Solr to transfer changes made in memory to
> storage. It does that at several points in the indexing process, but the
> longest one is at the end of the PUI indexer's run. If, because you've got
> a lot of records, or slow storage on your Solr server, it takes longer it
> respond than the value of AppConfig[:indexer_solr_timeout_seconds], it will
> start all over again, and potentially go into a loop. The workaround is to
> increase the timeout.
>
>
> You might not notice you've got enough records to cause this until you do
> a full re-index, or someone edits something linked to most or all records
> (e.g. a repository, or a very widely-used subject), triggering the
> re-indexing of most of the system's records.
>
>
> Andrew.
>
>
>
> On 10/05/2022 22:06, Blake Carver wrote:
>
>  1x1 would mean setting both records_per_thread and thread_count to 1.
> Having loglevel on debug and running at 1x1, you'll be able to see exactly
> which thing is being indexed as it happens, and when it crashes, you'll see
> what it was working through at the time.
>
> PUI will always take longer, and a VERY long time 1x1, but unless you're
> sure which indexer is crashing, I'd switch them both up.
>
> You can just `grep Indexed archivesspace.out` after it's running and watch
> those numbers. As long as they're going up, all is well.
>
> It is also possible that it will finish without crashing running so slow
> as well. I've seen that happen with LARGE records.
> ------------------------------
> *From:* archivesspace_users_group-bounces at lyralists.lyrasis.org
> <archivesspace_users_group-bounces at lyralists.lyrasis.org>
> <archivesspace_users_group-bounces at lyralists.lyrasis.org> on behalf of
> Tom Hanstra <hanstra at nd.edu> <hanstra at nd.edu>
> *Sent:* Tuesday, May 10, 2022 4:15 PM
> *To:* Archivesspace Users Group
> <archivesspace_users_group at lyralists.lyrasis.org>
> <archivesspace_users_group at lyralists.lyrasis.org>
> *Subject:* Re: [Archivesspace_Users_Group] (re)indexing in 2.8.1
>
> Thanks, Blake.
>
> Turns out we did add quite a few records recently, so maybe there was
> something in there that it did not like all that much.
>
> How can you tell which record it is choking on?  Is that your "1x1"
> suggestion?  Or does the DEBUG option make that more clear?  I have my
> indexing set to:
>
> AppConfig[:indexer_records_per_thread]      = 25
> AppConfig[:indexer_thread_count]            = 2
>
> for both PUI and Staff records. I believe you are suggesting it would most
> easily be found using 1 and 1?  I can see where that could take a long
> time. But it if is going to choke over and over on the same record, then
> that may be the best way to address it.
>
> Do you think if I just did staff indexing without PUI, that it would be
> identified faster?  Or could it pass the staff side but then die on PUI
> later?
>
> I hope to try some of these ideas after hours today, so if you can confirm
> that I've got the right idea, that would help.
>
> Tom
>
>
> On Tue, May 10, 2022 at 2:17 PM Blake Carver <blake.carver at lyrasis.org>
> wrote:
>
> > Is this possible?
>
> Short answer, Yes, it's possible your indexer is starting over.
>
> Long answer. This can be tricky to figure out. Something is wrong, the
> indexer never wants to do that. Sometimes "something" "bad" gets into
> ArchivesSpace and the indexer will just crash and start over. The problem
> is the "something" can be anything and the "bad" can be hard to figure out.
> The more stuff you have in your DB, the harder it is to figure out.
>
> First, I'd make sure this is happening. Your logs should make it obvious.
> You might see some FATAL errors just before it starts over.  You MIGHT be
> able to narrow it down from that. That is, what group of records had that
> error in the logs? Maybe that narrows it down enough. You just got lucky!
>
> I don't think I've ever been so lucky. What I'd do next is set your
> loglevel to DEBUG and restart. If you're feeling lucky or just impatient or
> both, leave the indexer speed as is. You'll get more details out of the
> logs and you should be able to narrow it down better. Ideally, you want to
> run the indexers at 1x1, which means it could take forrreeevverrrrr to get
> back around to the crash again. If you're lucky, it'll crash on a record,
> you'll go look at that record, the problem will be obvious, and there will
> be much rejoicing. With it running 1x1 you should see exactly what's
> causing the fail. If it's not crashing on the same record every time....
> ugh. That's an even longer answer.
>
>
>
> ------------------------------
> *From:* archivesspace_users_group-bounces at lyralists.lyrasis.org <
> archivesspace_users_group-bounces at lyralists.lyrasis.org> on behalf of Tom
> Hanstra <hanstra at nd.edu>
> *Sent:* Tuesday, May 10, 2022 10:23 AM
> *To:* Archivesspace Users Group <
> archivesspace_users_group at lyralists.lyrasis.org>
> *Subject:* [Archivesspace_Users_Group] (re)indexing in 2.8.1
>
> I don't look at the logs a lot unless there are issues with ArchivesSpace,
> so maybe this is something normal. But, after a restart due to some
> complaints about database connectivity, it looks like our ArchivesSpace
> instance has decided to do a full reindex. The index log sure looks as if
> it is starting from scratch and running through the indexing of both PUI
> and Staff indexes.
>
> Is this possible?  Is it something that happens periodically and I just
> did not notice it? Nothing has changed in my data directory, so I don't see
> any reason for indexing to occur. Yet that is what the logs show.
>
> If it is doing this for some reason, and knowing that we restart
> periodically, it seems like we will get into a loop where indexing just
> keeps happening all the time. Also, it would be helpful to understand what
> caused this to happen.
>
> Any thoughts or experiences from those who have run this for longer would
> be appreciated. I'd like to understand if it would be a good idea to clear
> the data directory and perform a full index over the weekend rather than an
> unexpected and possibly never ending round in the background.
>
> Thanks,
> Tom
> --
> *Tom Hanstra*
> *Sr. Systems Administrator*
> hanstra at nd.edu
>
>
> _______________________________________________
> Archivesspace_Users_Group mailing list
> Archivesspace_Users_Group at lyralists.lyrasis.org
> http://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
>
>
>
> --
> *Tom Hanstra*
> *Sr. Systems Administrator*
> hanstra at nd.edu
>
>
>
> _______________________________________________
> Archivesspace_Users_Group mailing listArchivesspace_Users_Group at lyralists.lyrasis.orghttp://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
>
> _______________________________________________
> Archivesspace_Users_Group mailing list
> Archivesspace_Users_Group at lyralists.lyrasis.org
> http://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
>
>
>
> --
> *Tom Hanstra*
> *Sr. Systems Administrator*
> hanstra at nd.edu
>
>
> _______________________________________________
> Archivesspace_Users_Group mailing list
> Archivesspace_Users_Group at lyralists.lyrasis.org
> http://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
>
>
>
> --
> *Tom Hanstra*
> *Sr. Systems Administrator*
> hanstra at nd.edu
>
>
> _______________________________________________
> Archivesspace_Users_Group mailing list
> Archivesspace_Users_Group at lyralists.lyrasis.org
> http://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
>

-- 
*Tom Hanstra*
*Sr. Systems Administrator*
hanstra at nd.edu
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lyralists.lyrasis.org/pipermail/archivesspace_users_group/attachments/20220518/6d8d3311/attachment-0001.html>