From dce54f6c108e6770995bd5d4bd1cba8da88547ac Mon Sep 17 00:00:00 2001 From: Alan Orth Date: Mon, 25 Feb 2019 14:11:13 -0800 Subject: [PATCH] Update notes for 2019-02-25 --- content/posts/2019-02.md | 88 +++++++++++++++++++++++++++++++++ docs/2019-02/index.html | 102 +++++++++++++++++++++++++++++++++++++-- docs/sitemap.xml | 10 ++-- 3 files changed, 192 insertions(+), 8 deletions(-) diff --git a/content/posts/2019-02.md b/content/posts/2019-02.md index 913083aa7..54db07221 100644 --- a/content/posts/2019-02.md +++ b/content/posts/2019-02.md @@ -1113,4 +1113,92 @@ return "unmatched" - A few of them are actually in previous IITA batch updates, which means they have been uploaded to CGSpace yet, so I worry that there would be many more - I want to re-synchronize CGSpace to DSpace Test to make sure that the duplicate checking is accurate, but I'm not sure I can because the Earlham guys are still testing COPO actively on DSpace Test +## 2019-02-25 + +- There seems to be something going on with Solr on CGSpace (linode18) because statistics on communities and collections are blank for January and February this year +- I see some errors started recently in Solr (yesterday): + +``` +$ grep -c ERROR /home/cgspace.cgiar.org/log/solr.log.2019-02-* +/home/cgspace.cgiar.org/log/solr.log.2019-02-11.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-12.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-13.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-14.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-15.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-16.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-17.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-18.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-19.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-20.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-21.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-22.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-23.xz:0 +/home/cgspace.cgiar.org/log/solr.log.2019-02-24:34 +``` + +- But I don't see anything interesting in yesterday's Solr log... +- I see this in the Tomcat 7 logs yesterday: + +``` +Feb 25 21:09:29 linode18 tomcat7[1015]: Error while updating +Feb 25 21:09:29 linode18 tomcat7[1015]: java.lang.UnsupportedOperationException: Multiple update components target the same field:solr_update_time_stamp +Feb 25 21:09:29 linode18 tomcat7[1015]: at org.dspace.statistics.SolrLogger$9.visit(SourceFile:1241) +Feb 25 21:09:29 linode18 tomcat7[1015]: at org.dspace.statistics.SolrLogger.visitEachStatisticShard(SourceFile:268) +Feb 25 21:09:29 linode18 tomcat7[1015]: at org.dspace.statistics.SolrLogger.update(SourceFile:1225) +Feb 25 21:09:29 linode18 tomcat7[1015]: at org.dspace.statistics.SolrLogger.update(SourceFile:1220) +Feb 25 21:09:29 linode18 tomcat7[1015]: at org.dspace.statistics.StatisticsLoggingConsumer.consume(SourceFile:103) +... +``` + +- In the Solr admin GUI I see we have the following error: "statistics-2011: org.apache.solr.common.SolrException:org.apache.solr.common.SolrException: Error opening new searcher" +- I restarted Tomcat and upon startup I see lots of errors in the systemd journal, like: + +``` +Feb 25 21:37:49 linode18 tomcat7[28363]: SEVERE: IOException while loading persisted sessions: java.io.StreamCorruptedException: invalid type code: 00 +Feb 25 21:37:49 linode18 tomcat7[28363]: java.io.StreamCorruptedException: invalid type code: 00 +Feb 25 21:37:49 linode18 tomcat7[28363]: at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1601) +Feb 25 21:37:49 linode18 tomcat7[28363]: at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2287) +Feb 25 21:37:49 linode18 tomcat7[28363]: at java.io.ObjectInputStream.defaultReadObject(ObjectInputStream.java:561) +Feb 25 21:37:49 linode18 tomcat7[28363]: at java.lang.Throwable.readObject(Throwable.java:914) +Feb 25 21:37:49 linode18 tomcat7[28363]: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) +Feb 25 21:37:49 linode18 tomcat7[28363]: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) +``` +- I don't think that's related... +- Also, now the Solr admin UI says "statistics-2015: org.apache.solr.common.SolrException:org.apache.solr.common.SolrException: Error opening new searcher" +- In the Solr log I see: + +``` +2019-02-25 21:38:14,246 ERROR org.apache.solr.core.CoreContainer @ Error creating core [statistics-2015]: Error opening new searcher +org.apache.solr.common.SolrException: Error opening new searcher + at org.apache.solr.core.SolrCore.(SolrCore.java:873) + at org.apache.solr.core.SolrCore.(SolrCore.java:646) +... +Caused by: org.apache.solr.common.SolrException: Error opening new searcher + at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1565) + at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:1677) + at org.apache.solr.core.SolrCore.(SolrCore.java:845) + ... 31 more +Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/home/cgspace.cgiar.org/solr/statistics-2015/data/index/write.lock + at org.apache.lucene.store.Lock.obtain(Lock.java:89) + at org.apache.lucene.index.IndexWriter.(IndexWriter.java:753) + at org.apache.solr.update.SolrIndexWriter.(SolrIndexWriter.java:77) + at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:64) + at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:279) + at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:111) + at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1528) + ... 33 more +2019-02-25 21:38:14,250 ERROR org.apache.solr.core.SolrCore @ org.apache.solr.common.SolrException: Error CREATEing SolrCore 'statistics-2015': Unable to create core [statistics-2015] Caused by: Lock obtain timed out: NativeFSLock@/home/cgspace.cgiar.org/solr/statistics-2015/data/index/write.lock +``` + +- I tried to shutdown Tomcat and remove the locks: + +``` +# systemctl stop tomcat7 +# find /home/cgspace.cgiar.org/solr -iname "*.lock" -delete +# systemctl start tomcat7 +``` + +- ... but the problem still occurs +- I can see that there are still hits being recorded for items (in the Solr admin UI as well as my statistics API), so the main stats core is working at least! + diff --git a/docs/2019-02/index.html b/docs/2019-02/index.html index 29af9c92f..fc52206a5 100644 --- a/docs/2019-02/index.html +++ b/docs/2019-02/index.html @@ -42,7 +42,7 @@ sys 0m1.979s - + @@ -89,9 +89,9 @@ sys 0m1.979s "@type": "BlogPosting", "headline": "February, 2019", "url": "https://alanorth.github.io/cgspace-notes/2019-02/", - "wordCount": "6638", + "wordCount": "7043", "datePublished": "2019-02-01T21:37:30+02:00", - "dateModified": "2019-02-24T16:58:00-08:00", + "dateModified": "2019-02-24T17:29:12-08:00", "author": { "@type": "Person", "name": "Alan Orth" @@ -1430,6 +1430,102 @@ return "unmatched" +

2019-02-25

+ +
    +
  • There seems to be something going on with Solr on CGSpace (linode18) because statistics on communities and collections are blank for January and February this year
    • +
  • I see some errors started recently in Solr (yesterday):
    • +
+ +
$ grep -c ERROR /home/cgspace.cgiar.org/log/solr.log.2019-02-*
+/home/cgspace.cgiar.org/log/solr.log.2019-02-11.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-12.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-13.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-14.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-15.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-16.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-17.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-18.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-19.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-20.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-21.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-22.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-23.xz:0
+/home/cgspace.cgiar.org/log/solr.log.2019-02-24:34
+
+ +
    +
  • But I don’t see anything interesting in yesterday’s Solr log…
    • +
  • I see this in the Tomcat 7 logs yesterday:
    • +
+ +
Feb 25 21:09:29 linode18 tomcat7[1015]: Error while updating
+Feb 25 21:09:29 linode18 tomcat7[1015]: java.lang.UnsupportedOperationException: Multiple update components target the same field:solr_update_time_stamp
+Feb 25 21:09:29 linode18 tomcat7[1015]:         at org.dspace.statistics.SolrLogger$9.visit(SourceFile:1241)
+Feb 25 21:09:29 linode18 tomcat7[1015]:         at org.dspace.statistics.SolrLogger.visitEachStatisticShard(SourceFile:268)
+Feb 25 21:09:29 linode18 tomcat7[1015]:         at org.dspace.statistics.SolrLogger.update(SourceFile:1225)
+Feb 25 21:09:29 linode18 tomcat7[1015]:         at org.dspace.statistics.SolrLogger.update(SourceFile:1220)
+Feb 25 21:09:29 linode18 tomcat7[1015]:         at org.dspace.statistics.StatisticsLoggingConsumer.consume(SourceFile:103)
+...
+
+ +
    +
  • In the Solr admin GUI I see we have the following error: “statistics-2011: org.apache.solr.common.SolrException:org.apache.solr.common.SolrException: Error opening new searcher”
    • +
  • I restarted Tomcat and upon startup I see lots of errors in the systemd journal, like:
    • +
+ +
Feb 25 21:37:49 linode18 tomcat7[28363]: SEVERE: IOException while loading persisted sessions: java.io.StreamCorruptedException: invalid type code: 00
+Feb 25 21:37:49 linode18 tomcat7[28363]: java.io.StreamCorruptedException: invalid type code: 00
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1601)
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2287)
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at java.io.ObjectInputStream.defaultReadObject(ObjectInputStream.java:561)
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at java.lang.Throwable.readObject(Throwable.java:914)
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
+Feb 25 21:37:49 linode18 tomcat7[28363]:         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
+
+ +
    +
  • I don’t think that’s related…
    • +
  • Also, now the Solr admin UI says “statistics-2015: org.apache.solr.common.SolrException:org.apache.solr.common.SolrException: Error opening new searcher”
    • +
  • In the Solr log I see:
    • +
+ +
2019-02-25 21:38:14,246 ERROR org.apache.solr.core.CoreContainer @ Error creating core [statistics-2015]: Error opening new searcher
+org.apache.solr.common.SolrException: Error opening new searcher
+        at org.apache.solr.core.SolrCore.<init>(SolrCore.java:873)
+        at org.apache.solr.core.SolrCore.<init>(SolrCore.java:646)
+...
+Caused by: org.apache.solr.common.SolrException: Error opening new searcher
+        at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1565)
+        at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:1677)
+        at org.apache.solr.core.SolrCore.<init>(SolrCore.java:845)
+        ... 31 more
+Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/home/cgspace.cgiar.org/solr/statistics-2015/data/index/write.lock
+        at org.apache.lucene.store.Lock.obtain(Lock.java:89)
+        at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:753)
+        at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:77)
+        at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:64)
+        at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:279)
+        at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:111)
+        at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1528)
+        ... 33 more
+2019-02-25 21:38:14,250 ERROR org.apache.solr.core.SolrCore @ org.apache.solr.common.SolrException: Error CREATEing SolrCore 'statistics-2015': Unable to create core [statistics-2015] Caused by: Lock obtain timed out: NativeFSLock@/home/cgspace.cgiar.org/solr/statistics-2015/data/index/write.lock
+
+ +
    +
  • I tried to shutdown Tomcat and remove the locks:
    • +
+ +
# systemctl stop tomcat7
+# find /home/cgspace.cgiar.org/solr -iname "*.lock" -delete
+# systemctl start tomcat7
+
+ +
    +
  • … but the problem still occurs
    • +
  • I can see that there are still hits being recorded for items (in the Solr admin UI as well as my statistics API), so the main stats core is working at least!
    • +
+ diff --git a/docs/sitemap.xml b/docs/sitemap.xml index 4a347b5cb..afd989aa8 100644 --- a/docs/sitemap.xml +++ b/docs/sitemap.xml @@ -4,7 +4,7 @@ https://alanorth.github.io/cgspace-notes/2019-02/ - 2019-02-24T16:58:00-08:00 + 2019-02-24T17:29:12-08:00 @@ -209,7 +209,7 @@ https://alanorth.github.io/cgspace-notes/ - 2019-02-24T16:58:00-08:00 + 2019-02-24T17:29:12-08:00 0 @@ -220,7 +220,7 @@ https://alanorth.github.io/cgspace-notes/tags/notes/ - 2019-02-24T16:58:00-08:00 + 2019-02-24T17:29:12-08:00 0 @@ -232,13 +232,13 @@ https://alanorth.github.io/cgspace-notes/posts/ - 2019-02-24T16:58:00-08:00 + 2019-02-24T17:29:12-08:00 0 https://alanorth.github.io/cgspace-notes/tags/ - 2019-02-24T16:58:00-08:00 + 2019-02-24T17:29:12-08:00 0