+++ date = "2016-04-04T11:06:00+03:00" author = "Alan Orth" title = "April, 2016" tags = ["notes"] +++ ## 2016-04-04 - Looking at log file use on CGSpace and notice that we need to work on our cron setup a bit - We are backing up all logs in the log folder, including useless stuff like solr, cocoon, handle-plugin, etc - After running DSpace for over five years I've never needed to look in any other log file than dspace.log, leave alone one from last year! - This will save us a few gigs of backup space we're paying for on S3 - Also, I noticed the `checker` log has some errors we should pay attention to: ``` Run start time: 03/06/2016 04:00:22 Error retrieving bitstream ID 71274 from asset store. java.io.FileNotFoundException: /home/cgspace.cgiar.org/assetstore/64/29/06/64290601546459645925328536011917633626 (Too many open files) at java.io.FileInputStream.open(Native Method) at java.io.FileInputStream.(FileInputStream.java:146) at edu.sdsc.grid.io.local.LocalFileInputStream.open(LocalFileInputStream.java:171) at edu.sdsc.grid.io.GeneralFileInputStream.(GeneralFileInputStream.java:145) at edu.sdsc.grid.io.local.LocalFileInputStream.(LocalFileInputStream.java:139) at edu.sdsc.grid.io.FileFactory.newFileInputStream(FileFactory.java:630) at org.dspace.storage.bitstore.BitstreamStorageManager.retrieve(BitstreamStorageManager.java:525) at org.dspace.checker.BitstreamDAO.getBitstream(BitstreamDAO.java:60) at org.dspace.checker.CheckerCommand.processBitstream(CheckerCommand.java:303) at org.dspace.checker.CheckerCommand.checkBitstream(CheckerCommand.java:171) at org.dspace.checker.CheckerCommand.process(CheckerCommand.java:120) at org.dspace.app.checker.ChecksumChecker.main(ChecksumChecker.java:236) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.dspace.app.launcher.ScriptLauncher.runOneCommand(ScriptLauncher.java:225) at org.dspace.app.launcher.ScriptLauncher.main(ScriptLauncher.java:77) ****************************************************** ``` - So this would be the `tomcat7` Unix user, who seems to have a default limit of 1024 files in its shell - For what it's worth, we have been setting the actual Tomcat 7 process' limit to 16384 for a few years (in `/etc/default/tomcat7`) - Looks like cron will read limits from `/etc/security/limits.*` so we can do something for the tomcat7 user there - Submit pull request for Tomcat 7 limits in Ansible dspace role ([#30](https://github.com/ilri/rmg-ansible-public/pull/30)) ## 2016-04-05 - Reduce Amazon S3 storage used for logs from 46 GB to 6GB by deleting a bunch of logs we don't need! ``` # s3cmd ls s3://cgspace.cgiar.org/log/ > /tmp/s3-logs.txt # grep checker.log /tmp/s3-logs.txt | awk '{print $4}' | xargs s3cmd del # grep cocoon.log /tmp/s3-logs.txt | awk '{print $4}' | xargs s3cmd del # grep handle-plugin.log /tmp/s3-logs.txt | awk '{print $4}' | xargs s3cmd del # grep solr.log /tmp/s3-logs.txt | awk '{print $4}' | xargs s3cmd del ``` - Also, adjust the cron jobs for backups so they only backup `dspace.log` and some stats files (.dat) - Try to do some metadata field migrations using the Atmire batch UI (`dc.Species` → `cg.species`) but it took several hours and even missed a few records ## 2016-04-06 - A better way to move metadata on this scale is via SQL, for example `dc.type.output` → `dc.type` (their IDs in the metadatafieldregistry are 66 and 109, respectively): ``` dspacetest=# update metadatavalue set metadata_field_id=109 where metadata_field_id=66; UPDATE 40852 ``` - After that an `index-discovery -bf` is required - Start working on metadata migrations, add 25 or so new metadata fields to CGSpace ## 2016-04-07 - Write shell script to do the migration of fields: https://gist.github.com/alanorth/72a70aca856d76f24c127a6e67b3342b - Testing with a few fields it seems to work well: ``` $ ./migrate-fields.sh UPDATE metadatavalue SET metadata_field_id=109 WHERE metadata_field_id=66 UPDATE 40883 UPDATE metadatavalue SET metadata_field_id=202 WHERE metadata_field_id=72 UPDATE 21420 UPDATE metadatavalue SET metadata_field_id=203 WHERE metadata_field_id=76 UPDATE 51258 ``` ## 2016-04-08 - Discuss metadata renaming with Abenet, we decided it's better to start with the center-specific subjects like ILRI, CIFOR, CCAFS, IWMI, and CPWF - I've e-mailed CCAFS and CPWF people to ask them how much time it will take for them to update their systems to cope with this change ## 2016-04-10 - Looking at the DOI issue [reported by Leroy from CIAT a few weeks ago](https://www.yammer.com/dspacedevelopers/#/Threads/show?threadId=678507860) - It seems the `dx.doi.org` URLs are much more proper in our repository! ``` dspacetest=# select count(*) from metadatavalue where metadata_field_id=74 and text_value like 'http://dx.doi.org%'; count ------- 5638 (1 row) dspacetest=# select count(*) from metadatavalue where metadata_field_id=74 and text_value like 'http://doi.org%'; count ------- 3 ``` - I will manually edit the `dc.identifier.doi` in [10568/72509](https://cgspace.cgiar.org/handle/10568/72509?show=full) and tweet the link, then check back in a week to see if the donut gets updated ## 2016-04-11 - The donut is already updated and shows the correct number now - CCAFS people say it will only take them an hour to update their code for the metadata renames, so I proposed we'd do it tentatively on Monday the 18th. ## 2016-04-12 - Looking at quality of WLE data (`cg.subject.iwmi`) in SQL: ``` dspacetest=# select text_value, count(*) from metadatavalue where metadata_field_id=217 group by text_value order by count(*) desc; ``` - Listings and Reports is still not returning reliable data for `dc.type` - I think we need to ask Atmire, as their documentation isn't too clear on the format of the filter configs - Alternatively, I want to see if I move all the data from `dc.type.output` to `dc.type` and then re-index, if it behaves better - Looking at our `input-forms.xml` I see we have two sets of ILRI subjects, but one has a few extra subjects - Remove one set of ILRI subjects and remove duplicate `VALUE CHAINS` from existing list ([#216](https://github.com/ilri/DSpace/pull/216)) - I decided to keep the set of subjects that had `FMD` and `RANGELANDS` added, as it appears to have been requested to have been added, and might be the newer list - I found 226 blank metadatavalues: ``` dspacetest# select * from metadatavalue where resource_type_id=2 and text_value=''; ``` - I think we should delete them and do a full re-index: ``` dspacetest=# delete from metadatavalue where resource_type_id=2 and text_value=''; DELETE 226 ``` - I deleted them on CGSpace but I'll wait to do the re-index as we're going to be doing one in a few days for the metadata changes anyways - In other news, moving the `dc.type.output` to `dc.type` and re-indexing seems to have fixed the Listings and Reports issue from above - Unfortunately this isn't a very good solution, because Listings and Reports config should allow us to filter on `dc.type.*` but the documentation isn't very clear and I couldn't reach Atmire today - We want to do the `dc.type.output` move on CGSpace anyways, but we should wait as it might affect other external people! ## 2016-04-14 - Communicate with Macaroni Bros again about `dc.type` - Help Sisay with some rsync and Linux stuff - Notify CIAT people of metadata changes (I had forgotten them last week) ## 2016-04-15 - DSpace Test had crashed, so I ran all system updates, rebooted, and re-deployed DSpace code ## 2016-04-18 - Talk to CIAT people about their portal again - Start looking more at the fields we want to delete - The following metadata fields have 0 items using them, so we can just remove them from the registry and any references in XMLUI, input forms, etc: - dc.description.abstractother - dc.whatwasknown - dc.whatisnew - dc.description.nationalpartners - dc.peerreviewprocess - cg.species.animal - Deleted! - The following fields have some items using them and I have to decide what to do with them (delete or move): - dc.icsubject.icrafsubject: 6 items, mostly in CPWF collections - dc.type.journal: 11 items, mostly in ILRI collections - dc.publicationcategory: 1 item, in CPWF - dc.GRP: 2 items, CPWF - dc.Species.animal: 6 items, in ILRI and AnGR - cg.livestock.agegroup: 9 items, in ILRI collections - cg.livestock.function: 20 items, mostly in EADD - Test metadata migration on local instance again: ``` $ ./migrate-fields.sh UPDATE metadatavalue SET metadata_field_id=109 WHERE metadata_field_id=66 UPDATE 40885 UPDATE metadatavalue SET metadata_field_id=203 WHERE metadata_field_id=76 UPDATE 51330 UPDATE metadatavalue SET metadata_field_id=208 WHERE metadata_field_id=82 UPDATE 5986 UPDATE metadatavalue SET metadata_field_id=210 WHERE metadata_field_id=88 UPDATE 2456 UPDATE metadatavalue SET metadata_field_id=215 WHERE metadata_field_id=106 UPDATE 3872 UPDATE metadatavalue SET metadata_field_id=217 WHERE metadata_field_id=108 UPDATE 46075 $ JAVA_OPTS="-Xms512m -Xmx512m -Dfile.encoding=UTF-8" ~/dspace/bin/dspace index-discovery -bf ``` - CGSpace was down but I'm not sure why, this was in `catalina.out`: ``` Apr 18, 2016 7:32:26 PM com.sun.jersey.spi.container.ContainerResponse logException SEVERE: Mapped exception to response: 500 (Internal Server Error) javax.ws.rs.WebApplicationException at org.dspace.rest.Resource.processFinally(Resource.java:163) at org.dspace.rest.HandleResource.getObject(HandleResource.java:81) at sun.reflect.GeneratedMethodAccessor198.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185) at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302) at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511) at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381) at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416) ... ``` - Everything else in the system looked normal (50GB disk space available, nothing weird in dmesg, etc) - After restarting Tomcat a few more of these errors were logged but the application was up ## 2016-04-19 - Get handles for items that are using a given metadata field, ie `dc.Species.animal` (105): ``` # select handle from item, handle where handle.resource_id = item.item_id AND item.item_id in (select resource_id from metadatavalue where resource_type_id=2 and metadata_field_id=105); handle ------------- 10568/10298 10568/16413 10568/16774 10568/34487 ``` - Delete metadata values for `dc.GRP` and `dc.icsubject.icrafsubject`: ``` # delete from metadatavalue where resource_type_id=2 and metadata_field_id=96; # delete from metadatavalue where resource_type_id=2 and metadata_field_id=83; ``` - They are old ICRAF fields and we haven't used them since 2011 or so - Also delete them from the metadata registry - CGSpace went down again, `dspace.log` had this: ``` 2016-04-19 15:02:17,025 ERROR org.dspace.storage.rdbms.DatabaseManager @ SQL connection Error - org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object ``` - I restarted Tomcat and PostgreSQL and now it's back up - I bet this is the same crash as yesterday, but I only saw the errors in `catalina.out` - Looks to be related to this, from `dspace.log`: ``` 2016-04-19 15:16:34,670 ERROR org.dspace.rest.Resource @ Something get wrong. Aborting context in finally statement. ``` - We have 18,000 of these errors right now... - Delete a few more old metadata values: `dc.Species.animal`, `dc.type.journal`, and `dc.publicationcategory`: ``` # delete from metadatavalue where resource_type_id=2 and metadata_field_id=105; # delete from metadatavalue where resource_type_id=2 and metadata_field_id=85; # delete from metadatavalue where resource_type_id=2 and metadata_field_id=95; ``` - And then remove them from the metadata registry ## 2016-04-20 - Re-deploy DSpace Test with the new subject and type fields, run all system updates, and reboot the server - Migrate fields and re-deploy CGSpace with the new subject and type fields, run all system updates, and reboot the server - Field migration went well: ``` $ ./migrate-fields.sh UPDATE metadatavalue SET metadata_field_id=109 WHERE metadata_field_id=66 UPDATE 40909 UPDATE metadatavalue SET metadata_field_id=203 WHERE metadata_field_id=76 UPDATE 51419 UPDATE metadatavalue SET metadata_field_id=208 WHERE metadata_field_id=82 UPDATE 5986 UPDATE metadatavalue SET metadata_field_id=210 WHERE metadata_field_id=88 UPDATE 2458 UPDATE metadatavalue SET metadata_field_id=215 WHERE metadata_field_id=106 UPDATE 3872 UPDATE metadatavalue SET metadata_field_id=217 WHERE metadata_field_id=108 UPDATE 46075 ``` - Also, I migrated CGSpace to using the PGDG PostgreSQL repo as the infrastructure playbooks had been using it for a while and it seemed to be working well - Basically, this gives us the ability to use the latest upstream stable 9.3.x release (currently 9.3.12) - Looking into the REST API errors again, it looks like these started appearing a few days ago in the tens of thousands: ``` $ grep -c "Aborting context in finally statement" dspace.log.2016-04-20 21252 ``` - I found a recent discussion on the DSpace mailing list and I've asked for advice there - Looks like this issue was noted and fixed in DSpace 5.5 (we're on 5.1): https://jira.duraspace.org/browse/DS-2936 - I've sent a message to Atmire asking about compatibility with DSpace 5.5 ## 2016-04-21 - Fix a bunch of metadata consistency issues with IITA Journal Articles (Peer review, Formally published, messed up DOIs, etc) - Atmire responded with DSpace 5.5 compatible versions for their modules, so I'll start testing those in a few weeks ## 2016-04-22 - Import 95 records into [CTA's Agrodok collection](https://cgspace.cgiar.org/handle/10568/42219) ## 2016-04-26 - Test embargo during item upload - Seems to be working but the help text is misleading as to the date format - It turns out the `robots.txt` issue we thought we solved last month isn't solved because you can't use wildcards in URL patterns: https://jira.duraspace.org/browse/DS-2962 - Write some nginx rules to add `X-Robots-Tag` HTTP headers to the dynamic requests from `robots.txt` instead - A few URLs to test with: - https://dspacetest.cgiar.org/handle/10568/440/browse?type=bioversity - https://dspacetest.cgiar.org/handle/10568/913/discover - https://dspacetest.cgiar.org/handle/10568/1/search-filter?filtertype_0=country&filter_0=VIETNAM&filter_relational_operator_0=equals&field=country ## 2016-04-27 - I woke up to ten or fifteen "up" and "down" emails from the monitoring website - Looks like the last one was "down" from about four hours ago - I think there must be something with this REST stuff: ``` # grep -c "Aborting context in finally statement" dspace.log.2016-04-* dspace.log.2016-04-01:0 dspace.log.2016-04-02:0 dspace.log.2016-04-03:0 dspace.log.2016-04-04:0 dspace.log.2016-04-05:0 dspace.log.2016-04-06:0 dspace.log.2016-04-07:0 dspace.log.2016-04-08:0 dspace.log.2016-04-09:0 dspace.log.2016-04-10:0 dspace.log.2016-04-11:0 dspace.log.2016-04-12:235 dspace.log.2016-04-13:44 dspace.log.2016-04-14:0 dspace.log.2016-04-15:35 dspace.log.2016-04-16:0 dspace.log.2016-04-17:0 dspace.log.2016-04-18:11942 dspace.log.2016-04-19:28496 dspace.log.2016-04-20:28474 dspace.log.2016-04-21:28654 dspace.log.2016-04-22:28763 dspace.log.2016-04-23:28773 dspace.log.2016-04-24:28775 dspace.log.2016-04-25:28626 dspace.log.2016-04-26:28655 dspace.log.2016-04-27:7271 ``` - I restarted tomcat and it is back up - Add Spanish XMLUI strings so those users see "CGSpace" instead of "DSpace" in the user interface ([#222](https://github.com/ilri/DSpace/pull/222)) - Submit patch to upstream DSpace for the misleading help text in the embargo step of the item submission: https://jira.duraspace.org/browse/DS-3172 - Update infrastructure playbooks for nginx 1.10.x (stable) release: https://github.com/ilri/rmg-ansible-public/issues/32 - Currently running on DSpace Test, we'll give it a few days before we adjust CGSpace - CGSpace down, restarted tomcat and it's back up ## 2016-04-28 - Problems with stability again. I've blocked access to `/rest` for now to see if the number of errors in the log files drop - Later we could maybe start logging access to `/rest` and perhaps whitelist some IPs... ## 2016-04-30 - Logs for today and yesterday have zero references to this REST error, so I'm going to open back up the REST API but log all requests ``` location /rest { access_log /var/log/nginx/rest.log; proxy_pass http://127.0.0.1:8443; } ``` - I will check the logs again in a few days to look for patterns, see who is accessing it, etc