June, 2020

Mon Jun 01, 2020 by Alan Orth in Notes

2020-06-01

I tried to run the AtomicStatisticsUpdateCLI CUA migration script on DSpace Test (linode26) again and it is still going very slowly and has tons of errors like I noticed yesterday
- I sent Atmire the dspace.log from today and told them to log into the server to debug the process
In other news, I checked the statistics API on DSpace 6 and it’s working
I tried to build the OAI registry on the freshly migrated DSpace 6 on DSpace Test and I get an error:

$ dspace oai import -c
OAI 2.0 manager action started
Loading @mire database changes for module MQM
Changes have been processed
Clearing index
Index cleared
Using full import.
Full import
java.lang.NullPointerException
        at org.dspace.xoai.app.XOAI.willChangeStatus(XOAI.java:438)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:368)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:280)
        at org.dspace.xoai.app.XOAI.indexAll(XOAI.java:227)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:134)
        at org.dspace.xoai.app.XOAI.main(XOAI.java:560)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.dspace.app.launcher.ScriptLauncher.runOneCommand(ScriptLauncher.java:229)
        at org.dspace.app.launcher.ScriptLauncher.main(ScriptLauncher.java:81)

2020-06-02

I noticed that I was able to do a partial OAI import (ie, without -c)
- Then I tried to clear the OAI Solr core and import, but I get the same error:

$ curl http://localhost:8080/solr/oai/update -H "Content-type: text/xml" --data-binary '<delete><query>*:*</query></delete>'
$ curl http://localhost:8080/solr/oai/update -H "Content-type: text/xml" --data-binary '<commit />'
$ ~/dspace63/bin/dspace oai import
OAI 2.0 manager action started
...
There are no indexed documents, using full import.
Full import
java.lang.NullPointerException
        at org.dspace.xoai.app.XOAI.willChangeStatus(XOAI.java:438)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:368)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:280)
        at org.dspace.xoai.app.XOAI.indexAll(XOAI.java:227)
        at org.dspace.xoai.app.XOAI.index(XOAI.java:143)
        at org.dspace.xoai.app.XOAI.main(XOAI.java:560)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.dspace.app.launcher.ScriptLauncher.runOneCommand(ScriptLauncher.java:229)
        at org.dspace.app.launcher.ScriptLauncher.main(ScriptLauncher.java:81)

I found a bug report on DSpace Jira describing this issue affecting someone else running DSpace 6.3
- They suspect it has to do with the item having some missing group names in its authorization policies
- I added some debugging to dspace-oai/src/main/java/org/dspace/xoai/app/XOAI.java to print the Handle of the item that causes the crash and then I looked at its authorization policies
- Indeed there are some blank group names:

Missing group names in DSpace 6.3 item authorization policy

The same item on CGSpace (DSpace 5.8) also has groups with no name:

Missing group names in DSpace 5.8 item authorization policy

I added some debugging and found exactly where this happens
- As it turns out we can just check if the group policy is null there and it allows the OAI import to proceed
- Aaaaand as it turns out, this was fixed in dspace-6_x in 2018 after DSpace 6.3 was released (see DS-4019), so that was a waste of three hours.
- I cherry picked 150e83558103ed7f50e8f323b6407b9cbdf33717 into our current 6_x-dev-atmire-modules branch

2020-06-04

Maria was asking about some items they are trying to map from the CGIAR Big Data collection into their Alliance of Bioversity and CIAT journal articles collection, but for some reason the items don’t show up in the item mapper
- The items don’t even show up in the XMLUI Discover advanced search, and actually I don’t even see any recent items on the recently submitted part of the collection (but the item pages exist of course)
- Perhaps I need to try a full Discovery re-index:

$ time chrt -i 0 ionice -c2 -n7 nice -n19 dspace index-discovery -b

real    125m37.423s
user    11m20.312s
sys     3m19.965s

Still I don’t see the item in XMLUI search or in the item mapper (and I made sure to clear the Cocoon cache)
- I’m starting to think it’s something related to the database transaction issue…
- I removed our custom JDBC driver from /usr/local/apache-tomcat... so that DSpace will use its own much older one, version 9.1-901-1.jdbc4
- I ran all system updates on the server (linode18) and rebooted it
- After it came back up I had to restart Tomcat five times before all Solr statistics cores came up properly
- Unfortunately this means that the Tomcat JDBC pooling via JNDI doesn’t work, so we’re using only the 30 connections reserved for the DSpace CLI from DSpace’s own internal pool
- Perhaps our previous issues with the database pool from a few years ago will be less now that we have much more aggressive blocking and rate limiting of bots in nginx
I will also import a fresh database snapshot from CGSpace and check if I can map the item in my local environment
- After importing and forcing a full reindex locally I can see the item in search and in the item mapper
Abenet sent another message about two users who are having issues with submission, and I see the number of locks in PostgreSQL has sky rocketed again as of a few days ago:

PostgreSQL locks week

As far as I can tell this started happening for the first time in April, connections and locks:

PostgreSQL connections year PostgreSQL locks year

I think I need to just leave this as is with the DSpace default JDBC driver for now, but perhaps I could also downgrade the Tomcat version (I deployed Tomcat 7.0.103 in March, so perhaps that’s relevant)
Also, I’ll start another full reindexing to see if the issue with mapping is somehow also resolved now that the database connections are working better
- Perhaps related, but this one finished much faster:

$ time chrt -i 0 ionice -c2 -n7 nice -n19 dspace index-discovery -b

real    101m41.195s
user    10m9.569s
sys     3m13.929s

Unfortunately the item is still not showing up in the item mapper…
Something happened to AReS Explorer (linode20) so I ran all system updates and rebooted it

2020-06-07

Peter said he was annoyed with a CSV export from CGSpace because of the different text_lang attributes and asked if we can fix it
The last time I normalized these was in 2019-06, and currently it looks like this:

dspace=# SELECT DISTINCT text_lang, count(text_lang) FROM metadatavalue WHERE resource_type_id=2 GROUP BY text_lang ORDER BY count DESC;
  text_lang  |  count
-------------+---------
 en_US       | 2158377
 en          |  149540
             |   49206
 es_ES       |      18
 fr          |       4
 Peer Review |       1
             |       0
(7 rows)

In theory we can have different languages for metadata fields but in practice we don’t do that, so we might as well normalize everything to “en_US” (and perhaps I should make a curation task to do this)
For now I will do it manually on CGSpace and DSpace Test:

dspace=# UPDATE metadatavalue SET text_lang='en_US' WHERE resource_type_id=2;
UPDATE 2414738

Note: DSpace Test doesn’t have the resource_type_id column because it’s running DSpace 6 and the schema changed to use an object model there
- We need to use this on DSpace 6:

dspace=# UPDATE metadatavalue SET text_lang='en_US' WHERE dspace_object_id IN (SELECT uuid FROM item);

Peter asked if it was possible to find all ILRI items that have “zoonoses” or “zoonotic” in their titles and check if they have the ILRI subject “ZOONOTIC DISEASES” (and add it if not)
- Unfortunately the only way we have currently would be to export the entire ILRI community as a CSV and filter/edit it in OpenRefine

2020-06-08

I manually mapped the two Big Data items that Maria had asked about last week by exporting their metadata to CSV and re-importing it
- I still need to look into the underlying issue there, seems to be something in Solr
- Something strang is that, when I search for part of the title in Discovery I get 2,000 results on CGSpace, while on my local DSpace 5.8 environment I get 2!

On DSpace Test, which is currently running DSpace 6, I get 2,000 results but the top one is the correct match and the item does show up in the item mapper
- Interestingly, if I search directly in the Solr search core on CGSpace with a query like handle:10568/108315 I don’t see the item, but on my local Solr I see them!
Peter asked if it was easy for me to add ILRI subject “ZOONOTIC DISEASES” to any items in the ILRI community that had “zoonotic” or “zoonoses” in their title, but were missing the ILRI subject
- I exported the ILRI community metadata, cut the three fields I needed, and then filtered and edited the CSV in OpenRefine:

$ dspace metadata-export -i 10568/1 -f /tmp/2020-06-08-ILRI.csv
$ csvcut -c 'id,cg.subject.ilri[en_US],dc.title[en_US]' ~/Downloads/2020-06-08-ILRI.csv > /tmp/ilri.csv

Moayad asked why he’s getting HTTP 500 errors on CGSpace
- I looked in the Nginx logs and I see some HTTP 500 responses, but nothing in nginx’s error.log
- Looking in Tomcat’s log I see there are many:

# journalctl --since=today -u tomcat7  | grep -c 'Internal Server Error'
482

They are all related to the REST API, like:

Jun 07 02:00:27 linode18 tomcat7[6286]: SEVERE: Mapped exception to response: 500 (Internal Server Error)
Jun 07 02:00:27 linode18 tomcat7[6286]: javax.ws.rs.WebApplicationException
Jun 07 02:00:27 linode18 tomcat7[6286]:         at org.dspace.rest.Resource.processException(Resource.java:151)
Jun 07 02:00:27 linode18 tomcat7[6286]:         at org.dspace.rest.ItemsResource.getItems(ItemsResource.java:195)
Jun 07 02:00:27 linode18 tomcat7[6286]:         at sun.reflect.GeneratedMethodAccessor548.invoke(Unknown Source)
Jun 07 02:00:27 linode18 tomcat7[6286]:         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 07 02:00:27 linode18 tomcat7[6286]:         at java.lang.reflect.Method.invoke(Method.java:498)
Jun 07 02:00:27 linode18 tomcat7[6286]:         at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
...

And:

Jun 08 09:28:29 linode18 tomcat7[6286]: SEVERE: Mapped exception to response: 500 (Internal Server Error)
Jun 08 09:28:29 linode18 tomcat7[6286]: javax.ws.rs.WebApplicationException
Jun 08 09:28:29 linode18 tomcat7[6286]:         at org.dspace.rest.Resource.processFinally(Resource.java:169)
Jun 08 09:28:29 linode18 tomcat7[6286]:         at org.dspace.rest.HandleResource.getObject(HandleResource.java:81)
Jun 08 09:28:29 linode18 tomcat7[6286]:         at sun.reflect.GeneratedMethodAccessor360.invoke(Unknown Source)
Jun 08 09:28:29 linode18 tomcat7[6286]:         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 08 09:28:29 linode18 tomcat7[6286]:         at java.lang.reflect.Method.invoke(Method.java:498)

And:

Jun 06 08:19:54 linode18 tomcat7[6286]: SEVERE: Mapped exception to response: 500 (Internal Server Error)
Jun 06 08:19:54 linode18 tomcat7[6286]: javax.ws.rs.WebApplicationException
Jun 06 08:19:54 linode18 tomcat7[6286]:         at org.dspace.rest.Resource.processException(Resource.java:151)
Jun 06 08:19:54 linode18 tomcat7[6286]:         at org.dspace.rest.CollectionsResource.getCollectionItems(CollectionsResource.java:289)
Jun 06 08:19:54 linode18 tomcat7[6286]:         at sun.reflect.GeneratedMethodAccessor598.invoke(Unknown Source)
Jun 06 08:19:54 linode18 tomcat7[6286]:         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 06 08:19:54 linode18 tomcat7[6286]:         at java.lang.reflect.Method.invoke(Method.java:498)

Looking back, I see ~800 of these errors since I changed the database configuration last week:

# journalctl --since=2020-06-04 --until=today -u tomcat7 | grep -c 'javax.ws.rs.WebApplicationException'
795

And only ~280 in the entire month before that…

# journalctl --since=2020-05-01 --until=2020-06-04 -u tomcat7 | grep -c 'javax.ws.rs.WebApplicationException'
286

So it seems to be related to the database, perhaps that there are less connections in the pool?
- … and on that note, working without the JDBC driver and DSpace’s built-in connection pool since 2020-06-04 hasn’t actually solved anything, the issue with locks and idle in transaction connections is creeping up again!

PostgreSQL connections day PostgreSQL connections week

It seems to have started today around 10:00 AM… I need to pore over the logs to see if there is a correlation
- I think there is some kind of attack going on because I see a bunch of requests for sequential Handles from a similar IP range in a datacenter in Sweden where the user does not re-use their DSpace session_id
- Looking in the nginx logs I see most (all?) of these requests are using the following user agent:

Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36

Looking at the nginx access logs I see that, other than something that seems like Google Feedburner, all hosts using this user agent are all in Sweden!

# zcat --force /var/log/nginx/access.log /var/log/nginx/access.log.1 /var/log/nginx/access.log.*.gz | grep 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36' | grep -v '/feed' | awk '{print $1}' | sort | uniq -c | sort -n
   1624 192.36.136.246
   1627 192.36.241.95
   1629 192.165.45.204
   1636 192.36.119.28
   1641 192.36.217.7
   1648 192.121.146.160
   1648 192.36.23.35
   1651 192.36.109.94
   1659 192.36.24.93
   1665 192.36.154.13
   1679 192.36.137.125
   1682 192.176.249.42
   1682 192.36.166.120
   1683 192.36.172.86
   1683 192.36.198.145
   1689 192.36.226.212
   1702 192.121.136.49
   1704 192.36.207.54
   1740 192.36.121.98
   1774 192.36.173.93

The earliest I see any of these hosts is 2020-06-05 (three days ago)
I will purge them from the Solr statistics and add them to abusive IPs ipset in the Ansible deployment scripts

$ ./check-spider-ip-hits.sh -f /tmp/ips -s statistics -p
Purging 1423 hits from 192.36.136.246 in statistics
Purging 1387 hits from 192.36.241.95 in statistics
Purging 1398 hits from 192.165.45.204 in statistics
Purging 1413 hits from 192.36.119.28 in statistics
Purging 1418 hits from 192.36.217.7 in statistics
Purging 1418 hits from 192.121.146.160 in statistics
Purging 1416 hits from 192.36.23.35 in statistics
Purging 1449 hits from 192.36.109.94 in statistics
Purging 1440 hits from 192.36.24.93 in statistics
Purging 1465 hits from 192.36.154.13 in statistics
Purging 1447 hits from 192.36.137.125 in statistics
Purging 1453 hits from 192.176.249.42 in statistics
Purging 1462 hits from 192.36.166.120 in statistics
Purging 1499 hits from 192.36.172.86 in statistics
Purging 1457 hits from 192.36.198.145 in statistics
Purging 1467 hits from 192.36.226.212 in statistics
Purging 1489 hits from 192.121.136.49 in statistics
Purging 1478 hits from 192.36.207.54 in statistics
Purging 1502 hits from 192.36.121.98 in statistics
Purging 1544 hits from 192.36.173.93 in statistics

Total number of bot hits purged: 29025

Skype with Enrico, Moayad, Jane, Peter, and Abenet to see the latest OpenRXV/AReS developments
- One thing Enrico mentioned to me during the call was that they had issues with Altmetric’s user agents, and he said they are apparently using Altmetribot and Postgenomic V2
- I looked in our logs and indeed we have those, so I will add them to the nginx rate limit bypass
- I checked the Solr stats and it seems there are only a few thousand in 2016 and a few hundred in other years so I won’t bother adding it to the DSpace robot user agents list
Atmire sent an updated pull request for the Font Awesome 5 update for CUA (#445) so I filed feedback on their tracker

2020-06-09

I’m still thinking about the issue with PostgreSQL “idle in transaction” and “waiting for lock” connections
- As far as I can see from the Munin graphs this issue started in late April or early May
- I don’t see any PostgreSQL updates around then, though I did update Tomcat to version 7.0.103 in March
- I will try to downgrade Tomcat to 7.0.99, which was the version I was using until early February, before we had seen any issues
- Also, I will use the PostgreSQL JDBC driver version 42.2.9, which is what we were using back then as well
- After deploying Tomcat 7.0.99 I had to restart Tomcat three times before all the Solr statistics cores came up OK
Well look at that, the “idle in transaction” and locking issues started in April on DSpace Test too…

PostgreSQL connections year DSpace Test

2020-06-13

Atmire sent some questions about DSpace Test related to our ongoing CUA indexing issue
- I had to clarify a few build steps and directories on the test server
I notice that the PostgreSQL connection issues have not come back since 2020-06-09 when I downgraded Tomcat to 7.0.99… fingers crossed that it was something related to that!
- On that note I notice that the AReS explorer is still not harvesting CGSpace properly…
- I looked at the REST API logs on CGSpace (linode18) and saw that the AReS harvester is being denied due to not having a user agent, oops:

172.104.229.92 - - [13/Jun/2020:02:00:00 +0200] "GET /rest/items?expand=metadata,bitstreams,parentCommunityList&limit=50&offset=0 HTTP/1.1" 403 260 "-" "-"

I created an nginx map based on the host’s IP address that sets a temporary user agent (ua) and then changed the conditional in the REST API location block so that it checks this mapped ua instead of the default one
- That should allow AReS to harvest for now until they update their user agent
- I restarted the AReS server’s docker containers with docker-compose down and docker-compose up -d and the next day I saw CGSpace was in AReS again finally