May, 2019
2019-05-01
- Help CCAFS with regenerating some item thumbnails after they uploaded new PDFs to some items on CGSpace
- A user on the dspace-tech mailing list offered some suggestions for troubleshooting the problem with the inability to delete certain items
- Apparently if the item is in the
workflowitemtable it is submitted to a workflow - And if it is in the
workspaceitemtable it is in the pre-submitted state
- Apparently if the item is in the
The item seems to be in a pre-submitted state, so I tried to delete it from there:
dspace=# DELETE FROM workspaceitem WHERE item_id=74648; DELETE 1But after this I tried to delete the item from the XMLUI and it is still present…
I managed to delete the problematic item from the database
- First I deleted the item’s bitstream in XMLUI and then ran
dspace cleanup -vto remove it from the assetstore Then I ran the following SQL:
dspace=# DELETE FROM metadatavalue WHERE resource_id=74648; dspace=# DELETE FROM workspaceitem WHERE item_id=74648; dspace=# DELETE FROM item WHERE item_id=74648;
- First I deleted the item’s bitstream in XMLUI and then ran
Now the item is (hopefully) really gone and I can continue to troubleshoot the issue with REST API’s
/items/find-by-metadata-valueendpointOf course I run into another HTTP 401 error when I continue trying the LandPortal search from last month:
$ curl -f -H "Content-Type: application/json" -X POST "http://localhost:8080/rest/items/find-by-metadata-field" -d '{"key":"cg.subject.cpwf", "value":"WATER MANAGEMENT","language": "en_US"}' curl: (22) The requested URL returned error: 401 Unauthorized
The DSpace log shows the item ID (because I modified the error text):
2019-05-01 11:41:11,069 ERROR org.dspace.rest.ItemsResource @ User(anonymous) has not permission to read item(id=77708)!If I delete that one I get another, making the list of item IDs so far:
- 74648
- 77708
- 85079
Some are in the
workspaceitemtable (pre-submission), others are in theworkflowitemtable (submitted), and others are actually approved, but withdrawn…- This is actually a worthless exercise because the real issue is that the
/items/find-by-metadata-valueendpoint is simply designed flawed and shouldn’t be fatally erroring when the search returns items the user doesn’t have permission to access - It would take way too much time to try to fix the fucked up items that are in limbo by deleting them in SQL, but also, it doesn’t actually fix the problem because some items are submitted but withdrawn, so they actually have handles and everything
- I think the solution is to recommend people don’t use the
/items/find-by-metadata-valueendpoint
- This is actually a worthless exercise because the real issue is that the
CIP is asking about embedding PDF thumbnail images in their RSS feeds again
- They asked in 2018-09 as well and I told them it wasn’t possible
- To make sure, I looked at the documentation for RSS media feeds and tried it, but couldn’t get it to work
- It seems to be geared towards iTunes and Podcasts… I dunno
CIP also asked for a way to get an XML file of all their RTB journal articles on CGSpace
I told them to use the REST API like (where
1179is the id of the RTB journal articles collection):https://cgspace.cgiar.org/rest/collections/1179/items?limit=812&expand=metadata
2019-05-03
A user from CIAT emailed to say that CGSpace submission emails have not been working the last few weeks
I checked the
dspace test-emailscript on CGSpace and they are indeed failing:$ dspace test-email About to send test email: - To: woohoo@cgiar.org - Subject: DSpace test email - Server: smtp.office365.com Error sending email: - Error: javax.mail.AuthenticationFailedException Please see the DSpace documentation for assistance.
I will ask ILRI ICT to reset the password
- They reset the password and I tested it on CGSpace
2019-05-05
- Run all system updates on DSpace Test (linode19) and reboot it
- Merge changes into the
5_x-prodbranch of CGSpace: - Re-deploy CGSpace from
5_x-prodbranch - Run all system updates on CGSpace (linode18) and reboot it
- Tag version 1.1.0 of the dspace-statistics-api (with Falcon 2.0.0)
- Deploy on DSpace Test
2019-05-06
Peter pointed out that Solr stats are only showing 2019 stats
I looked at the Solr Admin UI and I see:
statistics-2018: org.apache.solr.common.SolrException:org.apache.solr.common.SolrException: Error opening new searcher
As well as this error in the logs:
Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: NativeFSLock@/home/cgspace.cgiar.org/solr/statistics-2018/data/index/write.lockStrangely enough, I do see the statistics-2018, statistics-2017, etc cores in the Admin UI…
I restarted Tomcat a few times (and even deleted all the Solr write locks) and at least five times there were issues loading one statistics core, causing the Atmire stats to be incomplete
- Also, I tried to increase the
writeLockTimeoutinsolrconfig.xmlfrom the default of 1000ms to 10000ms - Eventually the Atmire stats started working, despite errors about “Error opening new searcher” in the Solr Admin UI
- I wrote to the dspace-tech mailing list again on the thread from March, 2019
- Also, I tried to increase the
There were a few alerts from UptimeRobot about CGSpace going up and down this morning, along with an alert from Linode about 596% load
- Looking at the Munin stats I see an exponential rise in DSpace XMLUI sessions, firewall activity, and PostgreSQL connections this morning:
The number of unique sessions today is ridiculously high compared to the last few days considering it’s only 12:30PM right now:
$ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-06 | sort | uniq | wc -l 101108 $ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-05 | sort | uniq | wc -l 14618 $ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-04 | sort | uniq | wc -l 14946 $ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-03 | sort | uniq | wc -l 6410 $ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-02 | sort | uniq | wc -l 7758 $ grep -o -E 'session_id=[A-Z0-9]{32}' dspace.log.2019-05-01 | sort | uniq | wc -l 20528The number of unique IP addresses from 2 to 6 AM this morning is already several times higher than the average for that time of the morning this past week:
# zcat --force /var/log/nginx/access.log /var/log/nginx/access.log.1 | grep -E '06/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 7127 # zcat --force /var/log/nginx/access.log.1 /var/log/nginx/access.log.2.gz | grep -E '05/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 1231 # zcat --force /var/log/nginx/access.log.2.gz /var/log/nginx/access.log.3.gz | grep -E '04/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 1255 # zcat --force /var/log/nginx/access.log.3.gz /var/log/nginx/access.log.4.gz | grep -E '03/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 1736 # zcat --force /var/log/nginx/access.log.4.gz /var/log/nginx/access.log.5.gz | grep -E '02/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 1573 # zcat --force /var/log/nginx/access.log.5.gz /var/log/nginx/access.log.6.gz | grep -E '01/May/2019:(02|03|04|05|06)' | awk '{print $1}' | sort | uniq | wc -l 1410Just this morning between the hours of 2 and 6 the number of unique sessions was very high compared to previous mornings:
$ cat dspace.log.2019-05-06 | grep -E '2019-05-06 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 83650 $ cat dspace.log.2019-05-05 | grep -E '2019-05-05 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 2547 $ cat dspace.log.2019-05-04 | grep -E '2019-05-04 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 2574 $ cat dspace.log.2019-05-03 | grep -E '2019-05-03 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 2911 $ cat dspace.log.2019-05-02 | grep -E '2019-05-02 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 2704 $ cat dspace.log.2019-05-01 | grep -E '2019-05-01 (02|03|04|05|06):' | grep -o -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 3699Most of the requests were GETs:
# cat /var/log/nginx/{access,library-access}.log /var/log/nginx/{access,library-access}.log.1 | grep -E '06/May/2019:(02|03|04|05|06)' | grep -o -E "(GET|HEAD|POST|PUT)" | sort | uniq -c | sort -n 1 PUT 98 POST 2845 HEAD 98121 GETI’m not exactly sure what happened this morning, but it looks like some legitimate user traffic—perhaps someone launched a new publication and it got a bunch of hits?
Looking again, I see 84,000 requests to
/handlethis morning (not including logs for library.cgiar.org because those get HTTP 301 redirect to CGSpace and appear here inaccess.log):# cat /var/log/nginx/access.log /var/log/nginx/access.log.1 | grep -E '06/May/2019:(02|03|04|05|06)' | grep -c -o -E " /handle/[0-9]+/[0-9]+" 84350But it would be difficult to find a pattern for those requests because they cover 78,000 unique Handles (ie direct browsing of items, collections, or communities) and only 2,492 discover/browse (total, not unique):
# cat /var/log/nginx/access.log /var/log/nginx/access.log.1 | grep -E '06/May/2019:(02|03|04|05|06)' | grep -o -E " /handle/[0-9]+/[0-9]+ HTTP" | sort | uniq | wc -l 78104 # cat /var/log/nginx/access.log /var/log/nginx/access.log.1 | grep -E '06/May/2019:(02|03|04|05|06)' | grep -o -E " /handle/[0-9]+/[0-9]+/(discover|browse)" | wc -l 2492In other news, I see some IP is making several requests per second to the exact same REST API endpoints, for example:
# grep /rest/handle/10568/3703?expand=all rest.log | awk '{print $1}' | sort | uniq -c 3 2a01:7e00::f03c:91ff:fe0a:d645 113 63.32.242.35According to viewdns.info that server belongs to Macaroni Brothers’
- The user agent of their non-REST API requests from the same IP is Drupal
- This is one very good reason to limit REST API requests, and perhaps to enable caching via nginx
2019-05-07
The total number of unique IPs on CGSpace yesterday was almost 14,000, which is several thousand higher than previous day totals:
# zcat --force /var/log/nginx/access.log.1 /var/log/nginx/access.log.2.gz | grep -E '06/May/2019' | awk '{print $1}' | sort | uniq | wc -l 13969 # zcat --force /var/log/nginx/access.log.2.gz /var/log/nginx/access.log.3.gz | grep -E '05/May/2019' | awk '{print $1}' | sort | uniq | wc -l 5936 # zcat --force /var/log/nginx/access.log.3.gz /var/log/nginx/access.log.4.gz | grep -E '04/May/2019' | awk '{print $1}' | sort | uniq | wc -l 6229 # zcat --force /var/log/nginx/access.log.4.gz /var/log/nginx/access.log.5.gz | grep -E '03/May/2019' | awk '{print $1}' | sort | uniq | wc -l 8051Total number of sessions yesterday was much higher compared to days last week:
$ cat dspace.log.2019-05-06 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 144160 $ cat dspace.log.2019-05-05 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 57269 $ cat dspace.log.2019-05-04 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 58648 $ cat dspace.log.2019-05-03 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 27883 $ cat dspace.log.2019-05-02 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 26996 $ cat dspace.log.2019-05-01 | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 61866The usage statistics seem to agree that yesterday was crazy:
- Sarah from RTB asked me about the RSS / XML link for the the CGIAR.org website again
- Apparently Sam Stacey is trying to add an RSS feed so the items get automatically syndicated to the CGIAR website
- I send her the link to the collection RSS feed
- Add requests cache to
resolve-addresses.pyscript
2019-05-08
A user said that CGSpace emails have stopped sending again
Indeed, the
dspace test-emailscript is showing an authentication failure:$ dspace test-email About to send test email: - To: wooooo@cgiar.org - Subject: DSpace test email - Server: smtp.office365.com Error sending email: - Error: javax.mail.AuthenticationFailedException Please see the DSpace documentation for assistance.
I checked the settings and apparently I had updated it incorrectly last week after ICT reset the password
Help Moayad with certbot-auto for Let’s Encrypt scripts on the new AReS server (linode20)
Normalize all
text_langvalues for metadata on CGSpace and DSpace Test (as I had tested last month):UPDATE metadatavalue SET text_lang='en_US' WHERE resource_type_id=2 AND metadata_field_id != 28 AND text_lang IN ('ethnob', 'en', '*', 'E.', ''); UPDATE metadatavalue SET text_lang='en_US' WHERE resource_type_id=2 AND metadata_field_id != 28 AND text_lang IS NULL; UPDATE metadatavalue SET text_lang='es_ES' WHERE resource_type_id=2 AND metadata_field_id != 28 AND text_lang IN ('es', 'spa');Send Francesca Giampieri from Bioversity a CSV export of all their items issued in 2018
- They will be doing a migration of 1500 items from their TYPO3 database into CGSpace soon and want an example CSV with all required metadata columns
2019-05-10
- I finally had time to analyze the 7,000 IPs from the major traffic spike on 2019-05-06 after several runs of my
resolve-addresses.pyscript (ipapi.co has a limit of 1,000 requests per day) - Resolving the unique IP addresses to organization and AS names reveals some pretty big abusers:
- 1213 from Region40 LLC (AS200557)
- 697 from Trusov Ilya Igorevych (AS50896)
- 687 from UGB Hosting OU (AS206485)
- 620 from UAB Rakrejus (AS62282)
- 491 from Dedipath (AS35913)
- 476 from Global Layer B.V. (AS49453)
- 333 from QuadraNet Enterprises LLC (AS8100)
- 278 from GigeNET (AS32181)
- 261 from Psychz Networks (AS40676)
- 196 from Cogent Communications (AS174)
- 125 from Blockchain Network Solutions Ltd (AS43444)
- 118 from Silverstar Invest Limited (AS35624)
All of the IPs from these networks are using generic user agents like this, but MANY more, and they change many times:
"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2703.0 Safari/537.36"I found a blog post from 2018 detailing an attack from a DDoS service that matches our pattern exactly
They specifically mention:
The attack that targeted the “Search” functionality of the website, aimed to bypass our mitigation by performing slow but simultaneous searches from 5500 IP addresses.
- So this was definitely an attack of some sort… only God knows why
- I noticed a few new bots that don’t use the word “bot” in their user agent and therefore don’t match Tomcat’s Crawler Session Manager Valve:
Blackboard SafeassignUnpaywall
2019-05-12
I see that the Unpaywall bot is resonsible for a few thousand XMLUI sessions every day (IP addresses come from nginx access.log):
$ cat dspace.log.2019-05-11 | grep -E 'ip_addr=(100.26.206.188|100.27.19.233|107.22.98.199|174.129.156.41|18.205.243.110|18.205.245.200|18.207.176.164|18.207.209.186|18.212.126.89|18.212.5.59|18.213.4.150|18.232.120.6|18.234.180.224|18.234.81.13|3.208.23.222|34.201.121.183|34.201.241.214|34.201.39.122|34.203.188.39|34.207.197.154|34.207.232.63|34.207.91.147|34.224.86.47|34.227.205.181|34.228.220.218|34.229.223.120|35.171.160.166|35.175.175.202|3.80.201.39|3.81.120.70|3.81.43.53|3.84.152.19|3.85.113.253|3.85.237.139|3.85.56.100|3.87.23.95|3.87.248.240|3.87.250.3|3.87.62.129|3.88.13.9|3.88.57.237|3.89.71.15|3.90.17.242|3.90.68.247|3.91.44.91|3.92.138.47|3.94.250.180|52.200.78.128|52.201.223.200|52.90.114.186|52.90.48.73|54.145.91.243|54.160.246.228|54.165.66.180|54.166.219.216|54.166.238.172|54.167.89.152|54.174.94.223|54.196.18.211|54.198.234.175|54.208.8.172|54.224.146.147|54.234.169.91|54.235.29.216|54.237.196.147|54.242.68.231|54.82.6.96|54.87.12.181|54.89.217.141|54.89.234.182|54.90.81.216|54.91.104.162)' | grep -E 'session_id=[A-Z0-9]{32}' | sort | uniq | wc -l 2206I added “Unpaywall” to the list of bots in the Tomcat Crawler Session Manager Valve
Set up nginx to use TLS and proxy pass to NodeJS on the AReS development server (linode20)
Run all system updates on linode20 and reboot it
Also, there is 10 to 20% CPU steal on that VM, so I will ask Linode to move it to another host
Commit changes to the
resolve-addresses.pyscript to add proper CSV output support