[Archivesspace_Users_Group] 2.1.2 re-indexing loop

Thu Sep 21 16:54:04 EDT 2017

I'd love to know the solution as well, since I'm seeing a similar/related(?) error as I'm starting to test 2.1.2 locally. I've migrated from a 1.5.3 instance and see the following error when attempting to view an archival object. The archival object information renders in the record pane, but the tree fails to populate anything except the collection level. I checked the db and the id being referenced (14195) does exist in the archival_object table (I think that's what the id is referencing - assuming I'm reading the code right). This is running with only one plugin (our omniauthCas) plugin enabled, though the database contains some additional tables from some of our other plugins

key not found: :14195
org/jruby/RubyHash.java:1189:in `fetch'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/large_tree.rb:203:in `block in node_from_root'
org/jruby/RubyArray.java:1734:in `each'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/large_tree.rb:193:in `block in node_from_root'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:111:in `block in open'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:75:in `block in transaction'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:105:in `block in transaction'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/connection_pool/threaded.rb:85:in `hold'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/connecting.rb:255:in `synchronize'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:97:in `transaction'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:74:in `transaction'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:110:in `block in open'
org/jruby/RubyFixnum.java:305:in `times'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:107:in `open'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:432:in `block in DB'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/large_tree.rb:145:in `node_from_root'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/controllers/resource.rb:203:in `block in ArchivesSpaceService'
org/jruby/RubyBasicObject.java:1687:in `instance_eval'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:280:in `block in returns'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:111:in `block in open'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:75:in `block in transaction'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:134:in `_transaction'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:108:in `block in transaction'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/connection_pool/threaded.rb:98:in `hold'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/connecting.rb:255:in `synchronize'
/Applications/archivesspace-2.1.2/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:97:in `transaction'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:74:in `transaction'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:110:in `block in open'
org/jruby/RubyFixnum.java:305:in `times'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:107:in `open'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:432:in `block in DB'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:262:in `block in returns'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/request_context.rb:24:in `open'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:230:in `block in returns'
org/jruby/RubyMethod.java:111:in `call'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `block in compile!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block in route!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:994:in `route_eval'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block in route!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1015:in `block in process_route'
org/jruby/RubyKernel.java:1120:in `catch'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `process_route'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:973:in `block in route!'
org/jruby/RubyArray.java:1734:in `each'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `route!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1085:in `block in dispatch!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
org/jruby/RubyKernel.java:1120:in `catch'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1082:in `dispatch!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `block in call!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
org/jruby/RubyKernel.java:1120:in `catch'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `call!'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:895:in `call'
/Applications/archivesspace-2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/main.rb:291:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Applications/archivesspace-2.1.2/gems/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
uri:classloader:/vendor/rack-1.5.5/rack/nulllogger.rb:9:in `call'
uri:classloader:/vendor/rack-1.5.5/rack/head.rb:11:in `call'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:182:in `call'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:2013:in `call'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `block in call'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1787:in `synchronize'
/Applications/archivesspace-2.1.2/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `call'
uri:classloader:/vendor/rack-1.5.5/rack/builder.rb:138:in `call'
uri:classloader:/vendor/rack-1.5.5/rack/urlmap.rb:65:in `block in call'
org/jruby/RubyArray.java:1734:in `each'
uri:classloader:/vendor/rack-1.5.5/rack/urlmap.rb:50:in `call'
uri:classloader:/rack/handler/servlet.rb:22:in `call'

________________________________
From: archivesspace_users_group-bounces at lyralists.lyrasis.org <archivesspace_users_group-bounces at lyralists.lyrasis.org> on behalf of Stanonik, Ronald <rstanonik at ucsd.edu>
Sent: Friday, September 15, 2017 1:44:44 PM
To: Archivesspace Users Group
Subject: Re: [Archivesspace_Users_Group] 2.1.2 re-indexing loop

I notice a repeating error and stacktrace in the log about an unhandled exception.

E, [2017-09-15T09:45:13.168412 #10788] ERROR -- : Thread-5342: Unhandled exception!

E, [2017-09-15T09:45:13.168722 #10788] ERROR -- :

key not found: :

org/jruby/RubyHash.java:1189:in `fetch'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/ancestor_listing.rb:63:in `root_record'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/ancestor_listing.rb:22:in `block in add_ancestors'

org/jruby/RubyArray.java:1734:in `each'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/ancestor_listing.rb:12:in `add_ancestors'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/archival_object.rb:69:in `sequel_to_jsonmodel'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/crud_helpers.rb:105:in `listing_response'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/crud_helpers.rb:68:in `handle_listing'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/controllers/archival_object.rb:95:in `block in ArchivesSpaceService'

org/jruby/RubyBasicObject.java:1687:in `instance_eval'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:280:in `block in returns'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:111:in `block in open'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:75:in `block in transaction'

/usr/local/archivesspace/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:134:in `_transaction'

/usr/local/archivesspace/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:108:in `block in transaction'

/usr/local/archivesspace/gems/gems/sequel-4.20.0/lib/sequel/connection_pool/threaded.rb:98:in `hold'

/usr/local/archivesspace/gems/gems/sequel-4.20.0/lib/sequel/database/connecting.rb:255:in `synchronize'

/usr/local/archivesspace/gems/gems/sequel-4.20.0/lib/sequel/database/transactions.rb:97:in `transaction'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:74:in `transaction'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:110:in `block in open'

org/jruby/RubyFixnum.java:305:in `times'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:107:in `open'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:432:in `block in DB'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:262:in `block in returns'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/request_context.rb:24:in `open'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/rest.rb:230:in `block in returns'

org/jruby/RubyMethod.java:111:in `call'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `block in compile!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block in route!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:994:in `route_eval'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block in route!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1015:in `block in process_route'

org/jruby/RubyKernel.java:1120:in `catch'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `process_route'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:973:in `block in route!'

org/jruby/RubyArray.java:1734:in `each'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `route!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1085:in `block in dispatch!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'

org/jruby/RubyKernel.java:1120:in `catch'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1082:in `dispatch!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `block in call!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'

org/jruby/RubyKernel.java:1120:in `catch'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `call!'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:895:in `call'

/usr/local/archivesspace-v2.1.2/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/main.rb:291:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'

/usr/local/archivesspace/gems/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'

uri:classloader:/vendor/rack-1.5.5/rack/nulllogger.rb:9:in `call'

uri:classloader:/vendor/rack-1.5.5/rack/head.rb:11:in `call'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:182:in `call'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:2013:in `call'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `block in call'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1787:in `synchronize'

/usr/local/archivesspace/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `call'

uri:classloader:/vendor/rack-1.5.5/rack/builder.rb:138:in `call'

uri:classloader:/vendor/rack-1.5.5/rack/urlmap.rb:65:in `block in call'

org/jruby/RubyArray.java:1734:in `each'

uri:classloader:/vendor/rack-1.5.5/rack/urlmap.rb:50:in `call'

uri:classloader:/rack/handler/servlet.rb:22:in `call'

D, [2017-09-15T09:45:13.169154 #10788] DEBUG -- : Thread-5342: Responded with [500, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"29"}, ["{\"error\":\"key not found: :\"}\n"]]... in 247ms

From: archivesspace_users_group-bounces at lyralists.lyrasis.org [mailto:archivesspace_users_group-bounces at lyralists.lyrasis.org] On Behalf Of Stanonik, Ronald
Sent: Friday, September 15, 2017 9:48 AM
To: archivesspace_users_group at lyralists.lyrasis.org
Subject: [Archivesspace_Users_Group] 2.1.2 re-indexing loop

I recently upgraded to 2.1.2 and it seems to be in an indexing loop.

I restarted the application.

I removed the solr index and restarted the application.

In the log I see it counting up

Staff Indexer [2017-09-15 07:42:21 -0700] ~~~ Indexed 185825 of 212959 archival_object records in repository SC&A
...
Staff Indexer [2017-09-15 03:50:30 -0700] ~~~ Indexed 201525 of 212959 archival_object records in repository SC&A

But then

Staff Indexer [2017-09-15 04:09:49 -0700] ~~~ Indexed 25 of 212959 archival_object records in repository SC&A

Since yesterday it has re-indexed ten times.

The resulting constant re-indexing causes a high load average and slow performance for users.

Any suggestions?

Thanks,

Ron

ps.  I also posted this question to https://groups.google.com/forum/#!forum/archivesspace<https://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgroups.google.com%2Fforum%2F%23!forum%2Farchivesspace&data=02%7C01%7Cjoshua.d.shaw%40dartmouth.edu%7C028f6cddc8a54f13039908d4fc61778d%7C995b093648d640e5a31ebf689ec9446f%7C0%7C0%7C636410942941690532&sdata=WypeTQ4t6O31ExmAoPwc34i%2B6%2BrkDCVV%2Fg6nYbnizPI%3D&reserved=0>.  Sorry if that is redundant.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lyralists.lyrasis.org/pipermail/archivesspace_users_group/attachments/20170921/b45823b0/attachment.html>