From 20b80513e43ae3cfbe5e2d4162a5cf8c00d5d093 Mon Sep 17 00:00:00 2001 From: Alan Orth Date: Fri, 20 Apr 2018 23:24:48 +0400 Subject: [PATCH] Add notes for 2018-04-20 --- content/posts/2018-04.md | 85 ++++++++++++++++++++++++++++++++++ docs/2018-04/index.html | 99 ++++++++++++++++++++++++++++++++++++++-- docs/sitemap.xml | 10 ++-- 3 files changed, 186 insertions(+), 8 deletions(-) diff --git a/content/posts/2018-04.md b/content/posts/2018-04.md index 7c0e67c3c..59619be6d 100644 --- a/content/posts/2018-04.md +++ b/content/posts/2018-04.md @@ -396,3 +396,88 @@ sys 2m2.687s ``` - This time is with about 70,000 items in the repository + +## 2018-04-20 + +- Gabriela from CIP emailed to say that CGSpace was returning a white page, but I haven't seen any emails from UptimeRobot +- I confirm that it's just giving a white page around 4:16 +- The DSpace logs show that there are no database connections: + +``` +org.apache.tomcat.jdbc.pool.PoolExhaustedException: [http-bio-127.0.0.1-8443-exec-715] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:250; busy:18; idle:0; lastwait:5000]. +``` + +- And there have been shit tons of errors in the last (starting only 20 minutes ago luckily): + +``` +# grep -c 'org.apache.tomcat.jdbc.pool.PoolExhaustedException' /home/cgspace.cgiar.org/log/dspace.log.2018-04-20 +32147 +``` + +- I can't even log into PostgreSQL as the `postgres` user, WTF? + +``` +$ psql -c 'select * from pg_stat_activity' | grep -o -E '(dspaceWeb|dspaceApi|dspaceCli)' | sort | uniq -c +^C +``` + +- Here are the most active IPs today: + +``` +# zcat --force /var/log/nginx/*.log /var/log/nginx/*.log.1 | grep -E "20/Apr/2018" | awk '{print $1}' | sort | uniq -c | sort -n | tail -n 10 + 917 207.46.13.182 + 935 213.55.99.121 + 970 40.77.167.134 + 978 207.46.13.80 + 1422 66.249.64.155 + 1577 50.116.102.77 + 2456 95.108.181.88 + 3216 104.196.152.243 + 4325 70.32.83.92 + 10718 45.5.184.2 +``` + +- It doesn't even seem like there is a lot of traffic compared to the previous days: + +``` +# zcat --force /var/log/nginx/*.log /var/log/nginx/*.log.1 | grep -E "20/Apr/2018" | wc -l +74931 +# zcat --force /var/log/nginx/*.log.1 /var/log/nginx/*.log.2.gz| grep -E "19/Apr/2018" | wc -l +91073 +# zcat --force /var/log/nginx/*.log.2.gz /var/log/nginx/*.log.3.gz| grep -E "18/Apr/2018" | wc -l +93459 +``` + +- I tried to restart Tomcat but `systemctl` hangs +- I tried to reboot the server from the command line but after a few minutes it didn't come back up +- Looking at the Linode console I see that it is stuck trying to shut down +- Even "Reboot" via Linode console doesn't work! +- After shutting it down a few times via the Linode console it finally rebooted +- Everything is back but I have no idea what caused this—I suspect something with the hosting provider +- Also super weird, the last entry in the DSpace log file is from `2018-04-20 16:35:09`, and then immediately it goes to `2018-04-20 19:15:04` (three hours later!): + +``` +2018-04-20 16:35:09,144 ERROR org.dspace.app.util.AbstractDSpaceWebapp @ Failed to record shutdown in Webapp table. +org.apache.tomcat.jdbc.pool.PoolExhaustedException: [localhost-startStop-2] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:250; busy:18; idle +:0; lastwait:5000]. + at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:685) + at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:187) + at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128) + at org.dspace.storage.rdbms.DatabaseManager.getConnection(DatabaseManager.java:632) + at org.dspace.core.Context.init(Context.java:121) + at org.dspace.core.Context.(Context.java:95) + at org.dspace.app.util.AbstractDSpaceWebapp.deregister(AbstractDSpaceWebapp.java:97) + at org.dspace.app.util.DSpaceContextListener.contextDestroyed(DSpaceContextListener.java:146) + at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:5115) + at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5779) + at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:224) + at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1588) + at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1577) + at java.util.concurrent.FutureTask.run(FutureTask.java:266) + at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) + at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) + at java.lang.Thread.run(Thread.java:748) +2018-04-20 19:15:04,006 INFO org.dspace.core.ConfigurationManager @ Loading from classloader: file:/home/cgspace.cgiar.org/config/dspace.cfg +``` + +- Very suspect! diff --git a/docs/2018-04/index.html b/docs/2018-04/index.html index 394354dbe..9e536c471 100644 --- a/docs/2018-04/index.html +++ b/docs/2018-04/index.html @@ -21,7 +21,7 @@ Catalina logs at least show some memory errors yesterday: - + @@ -53,9 +53,9 @@ Catalina logs at least show some memory errors yesterday: "@type": "BlogPosting", "headline": "April, 2018", "url": "https://alanorth.github.io/cgspace-notes/2018-04/", - "wordCount": "2148", + "wordCount": "2549", "datePublished": "2018-04-01T16:13:54+02:00", - "dateModified": "2018-04-19T12:40:52+03:00", + "dateModified": "2018-04-19T14:28:16+03:00", "author": { "@type": "Person", "name": "Alan Orth" @@ -565,6 +565,99 @@ sys 2m2.687s
  • This time is with about 70,000 items in the repository
    • +

    2018-04-20

    + + + +
    org.apache.tomcat.jdbc.pool.PoolExhaustedException: [http-bio-127.0.0.1-8443-exec-715] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:250; busy:18; idle:0; lastwait:5000].
+
    + + + +
    # grep -c 'org.apache.tomcat.jdbc.pool.PoolExhaustedException' /home/cgspace.cgiar.org/log/dspace.log.2018-04-20
+32147
+
    + + + +
    $ psql -c 'select * from pg_stat_activity' | grep -o -E '(dspaceWeb|dspaceApi|dspaceCli)' | sort | uniq -c 
+^C
+
    + + + +
    # zcat --force /var/log/nginx/*.log /var/log/nginx/*.log.1 | grep -E "20/Apr/2018" | awk '{print $1}' | sort | uniq -c | sort -n | tail -n 10
+    917 207.46.13.182
+    935 213.55.99.121
+    970 40.77.167.134
+    978 207.46.13.80
+   1422 66.249.64.155
+   1577 50.116.102.77
+   2456 95.108.181.88
+   3216 104.196.152.243
+   4325 70.32.83.92
+  10718 45.5.184.2
+
    + + + +
    # zcat --force /var/log/nginx/*.log /var/log/nginx/*.log.1 | grep -E "20/Apr/2018" | wc -l
+74931
+# zcat --force /var/log/nginx/*.log.1 /var/log/nginx/*.log.2.gz| grep -E "19/Apr/2018" | wc -l
+91073
+# zcat --force /var/log/nginx/*.log.2.gz /var/log/nginx/*.log.3.gz| grep -E "18/Apr/2018" | wc -l
+93459
+
    + + + +
    2018-04-20 16:35:09,144 ERROR org.dspace.app.util.AbstractDSpaceWebapp @ Failed to record shutdown in Webapp table.
+org.apache.tomcat.jdbc.pool.PoolExhaustedException: [localhost-startStop-2] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:250; busy:18; idle
+:0; lastwait:5000].
+        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:685)
+        at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:187)
+        at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
+        at org.dspace.storage.rdbms.DatabaseManager.getConnection(DatabaseManager.java:632)
+        at org.dspace.core.Context.init(Context.java:121)
+        at org.dspace.core.Context.<init>(Context.java:95)
+        at org.dspace.app.util.AbstractDSpaceWebapp.deregister(AbstractDSpaceWebapp.java:97)
+        at org.dspace.app.util.DSpaceContextListener.contextDestroyed(DSpaceContextListener.java:146)
+        at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:5115)
+        at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5779)
+        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:224)
+        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1588)
+        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1577)
+        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
+        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
+        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
+        at java.lang.Thread.run(Thread.java:748)
+2018-04-20 19:15:04,006 INFO  org.dspace.core.ConfigurationManager @ Loading from classloader: file:/home/cgspace.cgiar.org/config/dspace.cfg
+
    + + + diff --git a/docs/sitemap.xml b/docs/sitemap.xml index 11870e521..4d90110b5 100644 --- a/docs/sitemap.xml +++ b/docs/sitemap.xml @@ -4,7 +4,7 @@ https://alanorth.github.io/cgspace-notes/2018-04/ - 2018-04-19T12:40:52+03:00 + 2018-04-19T14:28:16+03:00 @@ -159,7 +159,7 @@ https://alanorth.github.io/cgspace-notes/ - 2018-04-19T12:40:52+03:00 + 2018-04-19T14:28:16+03:00 0 @@ -170,7 +170,7 @@ https://alanorth.github.io/cgspace-notes/tags/notes/ - 2018-04-19T12:40:52+03:00 + 2018-04-19T14:28:16+03:00 0 @@ -182,13 +182,13 @@ https://alanorth.github.io/cgspace-notes/posts/ - 2018-04-19T12:40:52+03:00 + 2018-04-19T14:28:16+03:00 0 https://alanorth.github.io/cgspace-notes/tags/ - 2018-04-19T12:40:52+03:00 + 2018-04-19T14:28:16+03:00 0