[Archivesspace_Users_Group] (re)indexing in 2.8.1

Thu May 19 09:58:04 EDT 2022

Thanks again.

So, I currently break up my logs into four different individual logs with
these settings:

## Possible Log levels: debug, info, warn, error, fatal (severe only)
#
AppConfig[:frontend_log] = "/var/log/archivesspace/frontend.log"
AppConfig[:frontend_log_level] = "debug"
#
AppConfig[:backend_log] = "/var/log/archivesspace/backend.log"
AppConfig[:backend_log_level] = "debug"
#
AppConfig[:pui_log] = "/var/log/archivesspace/pui.log"
AppConfig[:pui_log_level] = "debug"
#
AppConfig[:indexer_log] = "/var/log/archivesspace/indexer.log"
AppConfig[:indexer_log_level] = "debug"

In each of the other logs I see both INFO and DEBUG statements, sometimes a
lot, other times fewer. But in the indexer.log file, I only see INFO
statements, no DEBUG.

But your suggestion above that the line is like "indexed ..." got me
searching other logs and I found a couple of lines like this in my backend
log:

D, [2022-05-16T14:31:45.734159 #5273] DEBUG -- : Thread-4912: Responded
with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private,
must-revalidate, max-age=0", "Content-Length"=>"21295"},
["{\"page_size\":1,\"first_page\":1,\"last_page\":1,\"this_page\":1,\"offset_first\":1,\"offset_last\":1,\"total_hits\":1,\"results\":[{\"id\":\"/repositories/2/archival_objects/1702566#pui\",\"uri\":\"/repositories/2/archival_objects/1702566\",\"title\":\"Brother
Paul Hermit CSC not
indexed.\",\"primary_type\":\"archival_object\",\"types\":[\"archival_object\",\"pui\",\"pui_archival...
in 73ms

Is this the type of thing I should continue to look for?

Thanks,
Tom

On Wed, May 18, 2022 at 4:12 PM Blake Carver <blake.carver at lyrasis.org>
wrote:

> > - Even though the config setting is for DEBUG, the indexer log is only
> showing INFO. Should there be more than that?
>
> Yep. Something must not be quite right in the config, you should see DEBUG
> showing up in the logs.
>
> If it's running 1x1 AND on DEBUG you should see something better by the
> crash, you should be able to spot the record. I can't remember what exactly
> it looks like, but something like "indexed some/path/with/an/id/in/it/here"
> and then you can see the Resource or Archival Object ID in the line 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:* Wednesday, May 18, 2022 3:21 PM
> *To:* Archivesspace Users Group <
> archivesspace_users_group at lyralists.lyrasis.org>
> *Subject:* Re: [Archivesspace_Users_Group] (re)indexing in 2.8.1
>
> 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
>
>
> _______________________________________________
> 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/20220519/0d09a609/attachment.html>