D, [2018-06-22T09:05:34.598000 #3328] DEBUG -- : Thread-6848: Post-processed params: {:id=>63121, :repo_id=>2, :resolve=>["subjects", "related_resources", "linked_agents", "revision_statements", "container_locations", "digital_object", "classifications", "related_agents", "resource", "parent", "creator", "linked_instances", "linked_records", "related_accessions", "linked_events", "linked_events::linked_records", "linked_events::linked_agents", "top_container", "container_profile", "location_profile", "owner_repo"]} D, [2018-06-22T09:05:34.598000 #3328] DEBUG -- : Thread-6876: Responded with [500, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"34"}, ["{\"error\":\"key not found: :63121\"}\n"]]... in 32ms I, [2018-06-22T09:05:34.598000 #3328] INFO -- : Completed 200 OK in 32ms (Views: 0.6ms) D, [2018-06-22T09:05:34.613000 #3328] DEBUG -- : Thread-6848: Responded with [404, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"37"}, ["{\"error\":\"ArchivalObject not found\"}\n"]]... in 16ms I, [2018-06-22T09:05:34.613000 #3328] INFO -- : Rendering 404.html.erb I, [2018-06-22T09:05:34.613000 #3328] INFO -- : Rendered 404.html.erb (0.0ms) I, [2018-06-22T09:05:34.629000 #3328] INFO -- : Completed 200 OK in 47ms (Views: 9.8ms) I, [2018-06-22T09:05:34.832000 #3328] INFO -- : Thread-6858: Retrying transaction after retriable exception (Java::ComMysqlJdbcExceptionsJdbc4::MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction) E, [2018-06-22T09:05:36.973000 #3328] ERROR -- : Java::ComMysqlJdbcExceptionsJdbc4::MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction java.lang.reflect.Constructor.newInstance(java/lang/reflect/Constructor) com.mysql.jdbc.Util.handleNewInstance(com/mysql/jdbc/Util.java:425) com.mysql.jdbc.Util.getInstance(com/mysql/jdbc/Util.java:408) com.mysql.jdbc.SQLError.createSQLException(com/mysql/jdbc/SQLError.java:951) com.mysql.jdbc.MysqlIO.checkErrorPacket(com/mysql/jdbc/MysqlIO.java:3973) com.mysql.jdbc.MysqlIO.checkErrorPacket(com/mysql/jdbc/MysqlIO.java:3909) com.mysql.jdbc.MysqlIO.sendCommand(com/mysql/jdbc/MysqlIO.java:2527) com.mysql.jdbc.MysqlIO.sqlQueryDirect(com/mysql/jdbc/MysqlIO.java:2680) com.mysql.jdbc.ConnectionImpl.execSQL(com/mysql/jdbc/ConnectionImpl.java:2483) com.mysql.jdbc.StatementImpl.executeUpdateInternal(com/mysql/jdbc/StatementImpl.java:1552) com.mysql.jdbc.StatementImpl.executeLargeUpdate(com/mysql/jdbc/StatementImpl.java:2607) com.mysql.jdbc.StatementImpl.executeUpdate(com/mysql/jdbc/StatementImpl.java:1480) java.lang.reflect.Method.invoke(java/lang/reflect/Method) D, [2018-06-22T09:05:36.973000 #3328] DEBUG -- : Thread-6830: Responded with [400, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"192"}, ["{\"error\":{\"db_error\":[\"Database integrity constraint conflict: Java::ComMysqlJdbcExceptionsJdbc4::MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction\"]}}\n"]]... in 520658ms I, [2018-06-22T09:05:36.988000 #3328] INFO -- : Completed 500 Internal Server Error in 520876ms F, [2018-06-22T09:05:36.988000 #3328] FATAL -- : F, [2018-06-22T09:05:36.988000 #3328] FATAL -- : Exception (Unknown response: #): F, [2018-06-22T09:05:36.988000 #3328] FATAL -- : F, [2018-06-22T09:05:36.988000 #3328] FATAL -- : app/controllers/archival_objects_controller.rb:164:in `delete' I, [2018-06-22T09:05:38.910000 #3328] INFO -- : Started GET "/resources" for 10.11.141.57 at 2018-06-22 09:05:38 -0500 I, [2018-06-22T09:05:38.910000 #3328] INFO -- : Processing by ResourcesController#index as HTML D, [2018-06-22T09:05:38.973000 #3328] DEBUG -- : Thread-6876: GET /repositories/2/search?page=1&facet%5B%5D=subjects&facet%5B%5D=publish&facet%5B%5D=level&facet%5B%5D=classification_path&facet%5B%5D=primary_type&type%5B%5D=resource&filter=%7B%22query%22%3A%7B%22op%22%3A%22AND%22%2C%22subqueries%22%3A%5B%7B%22field%22%3A%22types%22%2C%22value%22%3A%22pui_only%22%2C%22negated%22%3Atrue%2C%22literal%22%3Atrue%2C%22jsonmodel_type%22%3A%22field_query%22%7D%5D%2C%22jsonmodel_type%22%3A%22boolean_query%22%7D%2C%22jsonmodel_type%22%3A%22advanced_query%22%7D [session: #"daniel", :login_time=>2018-06-22 09:05:32 -0500, :expirable=>true}, @system_mtime=2018-06-22 14:05:35 UTC, @id="3f3fe04e98cfd5752fc11686263a3e167f280fd848f2e3be90fced248451602f">] D, [2018-06-22T09:05:38.973000 #3328] DEBUG -- : Thread-6876: Post-processed params: {"page"=>1, :repo_id=>2, :type=>["resource"], :facet=>["subjects", "publish", "level", "classification_path", "primary_type"], :filter=>#{"op"=>"AND", "subqueries"=>[{"field"=>"types", "value"=>"pui_only", "negated"=>true, "literal"=>true, "jsonmodel_type"=>"field_query"}], "jsonmodel_type"=>"boolean_query"}, "jsonmodel_type"=>"advanced_query"}>, "modified_since"=>0, "page_size"=>10} D, [2018-06-22T09:05:39.004000 #3328] DEBUG -- : Thread-6876: {"page"=>1, :repo_id=>2, :type=>["resource"], :facet=>["subjects", "publish", "level", "classification_path", "primary_type"], :filter=>#{"op"=>"AND", "subqueries"=>[{"field"=>"types", "value"=>"pui_only", "negated"=>true, "literal"=>true, "jsonmodel_type"=>"field_query"}], "jsonmodel_type"=>"boolean_query"}, "jsonmodel_type"=>"advanced_query"}>, "modified_since"=>0, "page_size"=>10} Jun 22, 2018 9:05:39 AM org.apache.solr.core.SolrCore execute INFO: [collection1] webapp= path=/select params={op=AND&facet.field=subjects&facet.field=publish&facet.field=level&facet.field=classification_path&facet.field=primary_type&csv.escape=\&start=0&fq=repository:"/repositories/2"+OR+repository:global&fq=types:("resource")&fq=(-types:("pui_only")+AND+*:*)&fq=-exclude_by_default:true&sort=&rows=10&q=*:*&facet.limit=100&defType=edismax&qf=four_part_id^3+title^2+finding_aid_filing_title^2+fullrecord&pf=four_part_id^4&csv.header=true&csv.encapsulator="&facet.mincount=0&wt=json&facet=true} hits=186 status=0 QTime=0 D, [2018-06-22T09:05:39.051000 #3328] DEBUG -- : Thread-6876: Responded with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"331953"}, ["{\"page_size\":10,\"first_page\":1,\"last_page\":19,\"this_page\":1,\"offset_first\":1,\"offset_last\":10,\"total_hits\":186,\"results\":[{\"id\":\"/repositories/2/resources/18\",\"uri\":\"/repositories/2/resources/18\",\"title\":\"Alonso S. Perales Papers\",\"primary_type\":\"resource\",\"types\":[\"resource\",\"pui_collection\",\"pui\"],\"json\":\"{\\\"lock_version\\\":30,\\\"ti... in 78ms I, [2018-06-22T09:05:39.082000 #3328] INFO -- : Rendering resources/index.html.erb within layouts/application I, [2018-06-22T09:05:39.098000 #3328] INFO -- : Rendered shared/_breadcrumb.html.erb (16.0ms) D, [2018-06-22T09:05:39.113000 #3328] DEBUG -- : Thread-6830: GET /repositories/2/current_preferences [session: #"daniel", :login_time=>2018-06-22 09:05:32 -0500, :expirable=>true}, @system_mtime=2018-06-22 14:05:35 UTC, @id="3f3fe04e98cfd5752fc11686263a3e167f280fd848f2e3be90fced248451602f">] D, [2018-06-22T09:05:39.113000 #3328] DEBUG -- : Thread-6830: Post-processed params: {:repo_id=>2} D, [2018-06-22T09:05:39.129000 #3328] DEBUG -- : Thread-6830: Responded with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"1740"}, ["{\"defaults\":{\"default_values\":false,\"note_order\":[]},\"user_repo\":{\"lock_version\":0,\"user_id\":15,\"defaults\":{\"default_values\":false,\"note_order\":[],\"jsonmodel_type\":\"defaults\"},\"created_by\":\"daniel\",\"last_modified_by\":\"daniel\",\"create_time\":\"2017-04-06T18:26:03Z\",\"system_mtime\":\"2017-04-06T18:26:03Z\",\"user_mtime\":\"2017-04-06T18:26:03Z\",\"json... in 31ms I, [2018-06-22T09:05:39.160000 #3328] INFO -- : Rendered search/_components_switch.html.erb (0.0ms) I, [2018-06-22T09:05:39.192000 #3328] INFO -- : Rendered search/_filter.html.erb (32.0ms) I, [2018-06-22T09:05:39.207000 #3328] INFO -- : Rendered shared/_flash_messages.html.erb (15.0ms) I, [2018-06-22T09:05:39.223000 #3328] INFO -- : Rendered shared/_pagination_summary.html.erb (16.0ms) I, [2018-06-22T09:05:39.317000 #3328] INFO -- : Rendered shared/_pagination.html.erb (0.0ms) I, [2018-06-22T09:05:39.317000 #3328] INFO -- : Rendered search/_listing.html.erb (110.0ms) I, [2018-06-22T09:05:39.317000 #3328] INFO -- : Rendered resources/index.html.erb within layouts/application (235.0ms) I, [2018-06-22T09:05:39.348000 #3328] INFO -- : Rendered shared/_header_user.html.erb (0.0ms) I, [2018-06-22T09:05:39.348000 #3328] INFO -- : Rendered shared/_header_global.html.erb (16.0ms) I, [2018-06-22T09:05:39.348000 #3328] INFO -- : Rendered site/_branding.html.erb (0.0ms) I, [2018-06-22T09:05:39.395000 #3328] INFO -- : Rendered shared/_advanced_search.html.erb (16.0ms) I, [2018-06-22T09:05:39.395000 #3328] INFO -- : Rendered shared/_header_repository.html.erb (31.0ms) I, [2018-06-22T09:05:39.410000 #3328] INFO -- : Rendered site/_footer.html.erb (0.0ms) I, [2018-06-22T09:05:39.426000 #3328] INFO -- : Rendered shared/_templates.html.erb (0.0ms) I, [2018-06-22T09:05:39.426000 #3328] INFO -- : Completed 200 OK in 500ms (Views: 346.3ms) D, [2018-06-22T09:05:41.410000 #3328] DEBUG -- : Thread-6876: POST /update_monitor [session: #"staff_system", :login_time=>2018-06-20 16:50:26 -0500, :expirable=>false}, @system_mtime=2018-06-22 14:05:35 UTC, @id="01365bdaa3e387f689cf7ae6d3ecc194d4b37a89fbb8fd5f2cca6fb4f8253d7c">] D, [2018-06-22T09:05:41.410000 #3328] DEBUG -- : Thread-6876: Post-processed params: {:active_edits=>#"active_edits", "active_edits"=>[]}>} D, [2018-06-22T09:05:41.442000 #3328] DEBUG -- : Thread-6876: Responded with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"3"}, ["{}\n"]]... in 47ms I, [2018-06-22T09:05:42.020000 #3328] INFO -- : Thread-6870: Retrying transaction after retriable exception (Java::ComMysqlJdbcExceptionsJdbc4::MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction) I, [2018-06-22T09:05:46.598000 #3328] INFO -- : Started GET "/resources?utf8=%E2%9C%93&q=rg20" for 10.11.141.57 at 2018-06-22 09:05:46 -0500 I, [2018-06-22T09:05:46.598000 #3328] INFO -- : Processing by ResourcesController#index as HTML I, [2018-06-22T09:05:46.614000 #3328] INFO -- : Parameters: {"utf8"=>"✓", "q"=>"rg20"} D, [2018-06-22T09:05:46.645000 #3328] DEBUG -- : Thread-6848: GET /repositories/2/search?q=rg20&page=1&facet%5B%5D=subjects&facet%5B%5D=publish&facet%5B%5D=level&facet%5B%5D=classification_path&facet%5B%5D=primary_type&type%5B%5D=resource&filter=%7B%22query%22%3A%7B%22op%22%3A%22AND%22%2C%22subqueries%22%3A%5B%7B%22field%22%3A%22types%22%2C%22value%22%3A%22pui_only%22%2C%22negated%22%3Atrue%2C%22literal%22%3Atrue%2C%22jsonmodel_type%22%3A%22field_query%22%7D%5D%2C%22jsonmodel_type%22%3A%22boolean_query%22%7D%2C%22jsonmodel_type%22%3A%22advanced_query%22%7D [session: #"daniel", :login_time=>2018-06-22 09:05:32 -0500, :expirable=>true}, @system_mtime=2018-06-22 14:05:40 UTC, @id="3f3fe04e98cfd5752fc11686263a3e167f280fd848f2e3be90fced248451602f">] D, [2018-06-22T09:05:46.645000 #3328] DEBUG -- : Thread-6848: Post-processed params: {"page"=>1, :repo_id=>2, :q=>"rg20", :type=>["resource"], :facet=>["subjects", "publish", "level", "classification_path", "primary_type"], :filter=>#{"op"=>"AND", "subqueries"=>[{"field"=>"types", "value"=>"pui_only", "negated"=>true, "literal"=>true, "jsonmodel_type"=>"field_query"}], "jsonmodel_type"=>"boolean_query"}, "jsonmodel_type"=>"advanced_query"}>, "modified_since"=>0, "page_size"=>10} D, [2018-06-22T09:05:46.676000 #3328] DEBUG -- : Thread-6848: {"page"=>1, :repo_id=>2, :q=>"rg20", :type=>["resource"], :facet=>["subjects", "publish", "level", "classification_path", "primary_type"], :filter=>#{"op"=>"AND", "subqueries"=>[{"field"=>"types", "value"=>"pui_only", "negated"=>true, "literal"=>true, "jsonmodel_type"=>"field_query"}], "jsonmodel_type"=>"boolean_query"}, "jsonmodel_type"=>"advanced_query"}>, "modified_since"=>0, "page_size"=>10} Jun 22, 2018 9:05:46 AM org.apache.solr.core.SolrCore execute INFO: [collection1] webapp= path=/select params={op=AND&facet.field=subjects&facet.field=publish&facet.field=level&facet.field=classification_path&facet.field=primary_type&csv.escape=\&start=0&fq=repository:"/repositories/2"+OR+repository:global&fq=types:("resource")&fq=(-types:("pui_only")+AND+*:*)&fq=-exclude_by_default:true&sort=&rows=10&q=rg20&facet.limit=100&defType=edismax&qf=four_part_id^3+title^2+finding_aid_filing_title^2+fullrecord&pf=four_part_id^4&csv.header=true&csv.encapsulator="&facet.mincount=0&wt=json&facet=true} hits=2 status=0 QTime=16 D, [2018-06-22T09:05:46.692000 #3328] DEBUG -- : Thread-6848: Responded with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private, must-revalidate, max-age=0", "Content-Length"=>"15581"}, ["{\"page_size\":10,\"first_page\":1,\"last_page\":1,\"this_page\":1,\"offset_first\":1,\"offset_last\":2,\"total_hits\":2,\"results\":[{\"id\":\"/repositories/2/resources/437\",\"uri\":\"/repositories/2/resources/437\",\"title\":\"RG20: TAMUK Conner Museum\",\"primary_type\":\"resource\",\"types\":[\"resource\",\"pui_collection\",\"pui\"],\"json\":\"{\\\"lock_version\\\":1,\\\"title... in 63ms I, [2018-06-22T09:05:46.707000 #3328] INFO -- : Rendering resources/index.html.erb within layouts/application I, [2018-06-22T09:05:46.723000 #3328] INFO -- : Rendered shared/_breadcrumb.html.erb (16.0ms) I, [2018-06-22T09:05:46.739000 #3328] INFO -- : Rendered search/_components_switch.html.erb (0.0ms) I, [2018-06-22T09:05:46.754000 #3328] INFO -- : Rendered search/_filter.html.erb (15.0ms) I, [2018-06-22T09:05:46.770000 #3328] INFO -- : Rendered shared/_flash_messages.html.erb (16.0ms) I, [2018-06-22T09:05:46.786000 #3328] INFO -- : Rendered shared/_pagination_summary.html.erb (16.0ms) I, [2018-06-22T09:05:46.848000 #3328] INFO -- : Rendered shared/_pagination.html.erb (0.0ms) I, [2018-06-22T09:05:46.848000 #3328] INFO -- : Rendered search/_listing.html.erb (78.0ms) I, [2018-06-22T09:05:46.864000 #3328] INFO -- : Rendered resources/index.html.erb within layouts/application (157.0ms) I, [2018-06-22T09:05:46.879000 #3328] INFO -- : Rendered shared/_header_user.html.erb (15.0ms) I, [2018-06-22T09:05:46.895000 #3328] INFO -- : Rendered shared/_header_global.html.erb (31.0ms) I, [2018-06-22T09:05:46.895000 #3328] INFO -- : Rendered site/_branding.html.erb (0.0ms) I, [2018-06-22T09:05:46.973000 #3328] INFO -- : Rendered shared/_advanced_search.html.erb (16.0ms) I, [2018-06-22T09:05:46.973000 #3328] INFO -- : Rendered shared/_header_repository.html.erb (62.0ms) I, [2018-06-22T09:05:46.989000 #3328] INFO -- : Rendered site/_footer.html.erb (16.0ms) I, [2018-06-22T09:05:47.004000 #3328] INFO -- : Rendered shared/_templates.html.erb (15.0ms) I, [2018-06-22T09:05:47.004000 #3328] INFO -- : Completed 200 OK in 390ms (Views: 304.6ms)