search

OregonDigital / OD2

Next generation of Oregon Digital ( https://oregondigital.org ) digital collections platform, built on Samvera Hyrax ( https://github.com/samvera/hyrax/ )
18 stars 1 forks source link

Server error writing document id <pid> to the index #954

Closed luisgreg99 closed 4 years ago

luisgreg99 commented 4 years ago

Descriptive summary

When approving df65vf79s and df65vf157 in Fairbanks_Fine_Art_Prints_Collection, found that item.save! (in bulk approver) is failing due to a solr error Server error writing document id df65vf157 to the index. All the other works got approved successfully except these works in Fairbanks_Fine_Art_Prints_Collection.

I'm wondering if it's due to the index getting out of sync after failing with the modeshape error https://github.com/OregonDigital/OD2/issues/926.

Error backtrace

irb(main):019:0> item.save!
D, [2020-01-17T23:23:30.521430 #26667] DEBUG -- :   OembedError Load (1.3ms)  SELECT  "oembed_errors".* FROM "oembed_errors" WHERE "oembed_errors"."document_id" = $1 LIMIT $2  [["document_id", "df65vf157"], ["LIMIT", 1]]
I, [2020-01-17T23:23:30.610633 #26667]  INFO -- : Fetching http://vocab.getty.edu/aat/300041391 from the authorative source. (this is slow)
I, [2020-01-17T23:23:30.623923 #26667]  INFO -- : Fetched From Cache
I, [2020-01-17T23:23:30.711553 #26667]  INFO -- : ["", 0.07642699999999891, 0.0012150000000001882, 0.0, 0.0, 0.08751924335956573]
I, [2020-01-17T23:23:30.876188 #26667]  INFO -- : Fetching http://vocab.getty.edu/aat/300041405 from the authorative source. (this is slow)
I, [2020-01-17T23:23:30.877280 #26667]  INFO -- : Fetched From Cache
I, [2020-01-17T23:23:30.954929 #26667]  INFO -- : ["", 0.07440499999999872, 0.0, 0.0, 0.0, 0.07756232656538486]
I, [2020-01-17T23:23:31.146194 #26667]  INFO -- : Fetching http://vocab.getty.edu/ulan/500357048 from the authorative source. (this is slow)
I, [2020-01-17T23:23:31.147235 #26667]  INFO -- : Fetched From Cache
I, [2020-01-17T23:23:31.167868 #26667]  INFO -- : ["", 0.017571000000000225, 0.0005689999999995976, 0.0, 0.0, 0.02054956927895546]
I, [2020-01-17T23:23:31.203817 #26667]  INFO -- : Fetching http://dbpedia.org/resource/Oregon_State_University from the authorative source. (this is slow)
I, [2020-01-17T23:23:31.204666 #26667]  INFO -- : Fetched From Cache
I, [2020-01-17T23:23:31.285169 #26667]  INFO -- : ["", 0.07615300000000147, 0.00012699999999998823, 0.0, 0.0, 0.08042083866894245]
I, [2020-01-17T23:23:31.443204 #26667]  INFO -- : Fetching http://opaquenamespace.org/ns/repository/FairbanksGallery from the authorative source. (this is slow)
I, [2020-01-17T23:23:31.444280 #26667]  INFO -- : Fetched From Cache
I, [2020-01-17T23:23:31.451924 #26667]  INFO -- : ["", 0.006885000000000474, 0.0, 0.0, 0.0, 0.007539043202996254]
D, [2020-01-17T23:23:31.934612 #26667] DEBUG -- :   Sipity::Role Load (1.7ms)  SELECT "sipity_roles".* FROM "sipity_roles" WHERE "sipity_roles"."id" IN (SELECT "sipity_workflow_roles"."role_id" FROM "sipity_workflow_roles" WHERE "sipity_workflow_roles"."workflow_id" = 5)
D, [2020-01-17T23:23:31.943472 #26667] DEBUG -- :   Hyrax::PermissionTemplate Load (0.8ms)  SELECT  "permission_templates".* FROM "permission_templates" WHERE "permission_templates"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
D, [2020-01-17T23:23:31.951221 #26667] DEBUG -- :   Sipity::WorkflowState Load (0.7ms)  SELECT  "sipity_workflow_states".* FROM "sipity_workflow_states" WHERE "sipity_workflow_states"."id" = $1 LIMIT $2  [["id", 14], ["LIMIT", 1]]
Traceback (most recent call last):
        2: from (irb):19
        1: from (eval):2:in `post'
RSolr::Error::Http (RSolr::Error::Http - 500 Internal Server Error)
Error: {
  "responseHeader":{
    "status":500,
    "QTime":2},
  "error":{
    "metadata":[
      "error-class","org.apache.solr.common.SolrException",
      "root-error-class","java.nio.file.NoSuchFileException"],
    "msg":"Server error writing document id df65vf157 to the index",
    "trace":"org.apache.solr.common.SolrException: Server error writing document id df65vf157 to the index\n\tat org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:243)\n\tat org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:76)\n\tat org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:55)\n\tat org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:259)\n\tat org.apache.solr.update.processor.DistributedUpdateProcessor.doVersionAdd(DistributedUpdateProcessor.java:489)\n\tat org.apache.solr.update.processor.DistributedUpdateProcessor.lambda$versionAdd$0(DistributedUpdateProcessor.java:339)\n\tat org.apache.solr.update.VersionBucket.runWithLock(VersionBucket.java:50)\n\tat org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:339)\n\tat org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:225)\n\tat org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:103)\n\tat org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.handleAdds(JsonLoader.java:507)\n\tat org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.processUpdate(JsonLoader.java:145)\n\tat org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.load(JsonLoader.java:121)\n\tat org.apache.solr.handler.loader.JsonLoader.load(JsonLoader.java:84)\n\tat org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:97)\n\tat org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:68)\n\tat org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:198)\n\tat org.apache.solr.core.SolrCore.execute(SolrCore.java:2576)\n\tat org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:799)\n\tat org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:578)\n\tat org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:419)\n\tat org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:351)\n\tat org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)\n\tat org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)\n\tat org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)\n\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)\n\tat org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1711)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)\n\tat org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1347)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)\n\tat org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)\n\tat org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1678)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)\n\tat org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1249)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)\n\tat org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220)\n\tat org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)\n\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)\n\tat org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)\n\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)\n\tat org.eclipse.jetty.server.Server.handle(Server.java:505)\n\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)\n\tat org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)\n\tat org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)\n\tat org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)\n\tat org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)\n\tat org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)\n\tat org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)\n\tat org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)\n\tat org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)\n\tat org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)\n\tat org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:781)\n\tat org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:917)\n\tat java.base/java.lang.Thread.run(Thread.java:834)\nCaused by: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed\n\tat org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:681)\n\tat org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:695)\n\tat org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1591)\n\tat org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1586)\n\tat org.apache.solr.update.DirectUpdateHandler2.updateDocOrDocValues(DirectUpdateHandler2.java:971)\n\tat org.apache.solr.update.DirectUpdateHandler2.doNormalUpdate(DirectUpdateHandler2.java:344)\n\tat org.apache.solr.update.DirectUpdateHandler2.addDoc0(DirectUpdateHandler2.java:291)\n\tat org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:238)\n\t... 55 more\nCaused by: java.nio.file.NoSuchFileException: /var/solr/data/staging/data/index/write.lock\n\tat java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)\n\tat java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)\n\tat java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)\n\tat java.base/sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)\n\tat java.base/sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:149)\n\tat java.base/sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)\n\tat java.base/java.nio.file.Files.readAttributes(Files.java:1763)\n\tat org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:189)\n\tat org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43)\n\tat org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43)\n\tat org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:112)\n\tat org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:128)\n\tat org.apache.lucene.codecs.lucene50.Lucene50StoredFieldsFormat.fieldsWriter(Lucene50StoredFieldsFormat.java:183)\n\tat org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:39)\n\tat org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:46)\n\tat org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:367)\n\tat org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:403)\n\tat org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:250)\n\tat org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:495)\n\tat org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1594)\n\t... 60 more\n",
    "code":500}}

URI: http://solr8.default.svc.cluster.local:8983/solr/staging/update?wt=json&softCommit=true
Request Headers: {"Content-Type"=>"application/json"}
Request Data: "[{\"system_create_dtsi\":\"2020-01-17T00:38:33Z\",\"system_modified_dtsi\":\"2020-01-17T23:23:30Z\",\"has_model_ssim\":\"Image\",\"id\":\"df65vf157\",\"accessControl_ssim\":\"12e60cfc-fa17-4fca-a8bb-4e445f8c528c\",\"hasRelatedMediaFragment_ssim\":\"jm214p18d\",\"hasRelatedImage_ssim\":\"jm214p18d\",\"depositor_ssim\":\"admin@example.org\",\"depositor_tesim\":\"admin@example.org\",\"title_tesim\":\"River's Edge\",\"title_sim\":\"River's Edge\",\"date_uploaded_dtsi\":\"2020-01-17T00:38:29Z\",\"date_modified_dtsi\":\"2020-01-17T00:38:29Z\",\"isPartOf_ssim\":\"osu\",\"isPartOf_tesim\":\"osu\",\"resource_type_tesim\":\"http://purl.org/dc/dcmitype/Image\",\"resource_type_sim\":\"http://purl.org/dc/dcmitype/Image\",\"date_created_tesim\":\"2007-02-01\",\"description_tesim\":\"USA. Title: \\\"River's Edge\\\" 1/9\",\"rights_statement_tesim\":\"http://rightsstatements.org/vocab/InC/1.0/\",\"rights_statement_sim\":\"http://rightsstatements.org/vocab/InC/1.0/\",\"identifier_tesim\":\"61.1\",\"workType_tesim\":[\"http://vocab.getty.edu/aat/300041391\",\"http://vocab.getty.edu/aat/300041405\"],\"workType_sim\":[\"http://vocab.getty.edu/aat/300041391\",\"http://vocab.getty.edu/aat/300041405\"],\"workType_label_tesim\":[\"relief prints\",\"woodcuts (prints)\"],\"workType_label_sim\":[\"relief prints\",\"woodcuts (prints)\"],\"date_tesim\":\"1958\",\"artist_tesim\":\"http://vocab.getty.edu/ulan/500357048\",\"artist_sim\":\"http://vocab.getty.edu/ulan/500357048\",\"artist_label_tesim\":\"Huck, Robert\",\"artist_label_sim\":\"Huck, Robert\",\"institution_tesim\":\"http://dbpedia.org/resource/Oregon_State_University\",\"institution_sim\":\"http://dbpedia.org/resource/Oregon_State_University\",\"institution_label_tesim\":\"Oregon State University\",\"institution_label_sim\":\"Oregon State University\",\"repository_tesim\":\"http://opaquenamespace.org/ns/repository/FairbanksGallery\",\"repository_sim\":\"http://opaquenamespace.org/ns/repository/FairbanksGallery\",\"repository_label_tesim\":\"Oregon State University. Fairbanks Gallery\",\"repository_label_sim\":\"Oregon State University. Fairbanks Gallery\",\"thumbnail_path_ss\":\"/downloads/jm214p18d?file=thumbnail\",\"suppressed_bsi\":false,\"actionable_workflow_roles_ssim\":[\"osu-default-managing\",\"osu-default-approving\",\"osu-default-depositing\"],\"workflow_state_name_ssim\":\"deposited\",\"member_ids_ssim\":\"jm214p18d\",\"member_of_collections_ssim\":\"The Fairbanks Fine Arts Print Collection\",\"member_of_collection_ids_ssim\":\"fairbanks\",\"generic_type_sim\":\"Work\",\"file_set_ids_ssim\":\"jm214p18d\",\"visibility_ssi\":\"restricted\",\"admin_set_sim\":\"Oregon State University\",\"admin_set_tesim\":\"Oregon State University\",\"rights_statement_label_sim\":\"In Copyright\",\"rights_statement_label_ssim\":\"In Copyright\",\"rights_statement_label_tesim\":\"In Copyright\",\"type_label_sim\":\"Image\",\"type_label_ssim\":\"Image\",\"type_label_tesim\":\"Image\",\"human_readable_type_sim\":\"Image\",\"human_readable_type_tesim\":\"Image\",\"discover_access_group_ssim\":[\"collection_curator\",\"admin\",\"depositor\"],\"read_access_group_ssim\":[\"admin\",\"depositor\",\"collection_curator\"],\"edit_access_group_ssim\":[\"collection_curator\",\"admin\"]}]"

Backtrace: /usr/local/bundle/gems/rsolr-2.2.1/lib/rsolr/client.rb:206:in `rescue in execute'
/usr/local/bundle/gems/rsolr-2.2.1/lib/rsolr/client.rb:196:in `execute'
/usr/local/bundle/gems/rsolr-2.2.1/lib/rsolr/client.rb:191:in `send_and_receive'
(eval):2:in `post'
/usr/local/bundle/gems/rsolr-2.2.1/lib/rsolr/client.rb:94:in `update'
/usr/local/bundle/gems/rsolr-2.2.1/lib/rsolr/client.rb:113:in `add'
/usr/local/bundle/gems/active-fedora-11.5.4/lib/active_fedora/solr_service.rb:87:in `add'
/usr/local/bundle/gems/active-fedora-11.5.4/lib/active_fedora/indexing.rb:43:in `update_index'
/usr/local/bundle/bundler/gems/hyrax-da1b6ffd7c0e/app/models/concerns/hyrax/collection_nesting.rb:42:in `block in update_index'
/usr/local/bundle/gems/activesupport-5.1.7/lib/active_support/callbacks.rb:131:in `run_callbacks'
/usr/local/bundle/gems/activesupport-5.1.7/lib/active_support/callbacks.rb:827:in `_run_update_index_callbacks'

Expected behavior

It should successfully save the work.

Related work

Possibly related to https://github.com/OregonDigital/OD2/issues/926

Accessibility Concerns

NA

luisgreg99 commented 4 years ago

It looks like this issue has been resolved on staging. I updated the index for df65vf79s and df65vf157, including fairbanks collection, and they got updated successfully