Hello,
We imported a collection on Monday and it went through fine. Then we had an
error where we could not merge collections (it was an "db_error" {"Database
integrity constraint conflict: Java:
ComMysqlJdbcExceptionsJdbc4::MySQLTransactionRollbackException: Lock wait
timeout exceeded: try restarting transaction"). We tired to back up the
database straight from MySQL and took 30 minutes instead of the usual 10
seconds. Then we decided to roll back to a previous back-up, which worked. The
collection I put in on Monday was gone. Since we went to the back-up I had to
re-import the collection I put in on Monday. The collection did not go through
this time and got an "id_0 : That ID is already in use" error. We cleared the
indexes in the data folder and restored the backup again but the problem
continues to exist.
I have attached the part of the error log that corresponds with our problem.
Thanks,
Daniel Thacker
Digital Archivist
James C. Jernigan Library
Texas A&M University-Kingsville
MSC 197
700 University Blvd
Kingsville, TX 78363-8202
361-593-4154
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:
#<Net::HTTPBadRequest:0x6c337a73>):
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: #<Session:0x4c7ade77 @store={:user=>"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=>#<JSONModel(:advanced_query) {"query"=>{"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=>#<JSONModel(:advanced_query)
{"query"=>{"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: #<Session:0x28257610
@store={:user=>"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: #<Session:0x39791e95 @store={:user=>"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=>#<JSONModel(:active_edits)
{"jsonmodel_type"=>"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: #<Session:0x5d049604 @store={:user=>"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=>#<JSONModel(:advanced_query) {"query"=>{"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=>#<JSONModel(:advanced_query) {"query"=>{"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)_______________________________________________
Archivesspace_Users_Group mailing list
[email protected]
http://lyralists.lyrasis.org/mailman/listinfo/archivesspace_users_group
