search

AtlasOfLivingAustralia / image-service

Image repository and tiling services
https://images.ala.org.au
0 stars 17 forks source link

Unable to persist image from URL while it's valid #73

Closed sadeghim closed 4 years ago

sadeghim commented 5 years ago

Here is the log for biocache-store:

aws-bstore-4b 2019-09-09 13:56:00,709 INFO : [DataLoader] - 20000, >> last key : dr1411|5141336, UUID: , records per sec: 9.803922
aws-bstore-4b 2019-09-09 13:56:01,080 WARN : [RemoteMediaStore] - Unable to persist image from URL. Response code 200.  Image service response body: {"success":false,"message":"Unable to retrieve image from https://static.inaturalist.org/photos/6311697/original.jpg?1487444467"}
aws-bstore-4b 2019-09-09 13:56:01,080 WARN : [DataLoader] - Unable to save file: https://static.inaturalist.org/photos/6311697/original.jpg?1487444467

and the image-service threw these lines at the same time:

2019-09-09 13:56:02.411 ERROR --- [-8080-exec-3809] au.org.ala.images.ImageService           : Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1

org.springframework.orm.hibernate5.HibernateOptimisticLockingFailureException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.springframework.orm.hibernate5.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:283)
    at org.grails.orm.hibernate.GrailsHibernateTemplate.convertHibernateAccessException(GrailsHibernateTemplate.java:724)
    at org.grails.orm.hibernate.GrailsHibernateTemplate.doExecute(GrailsHibernateTemplate.java:303)
    at org.grails.orm.hibernate.GrailsHibernateTemplate.execute(GrailsHibernateTemplate.java:243)
    at org.grails.orm.hibernate.GrailsHibernateTemplate.execute(GrailsHibernateTemplate.java:117)
    at org.grails.orm.hibernate.AbstractHibernateGormInstanceApi.performSave(AbstractHibernateGormInstanceApi.groovy:251)
    at org.grails.orm.hibernate.AbstractHibernateGormInstanceApi.save(AbstractHibernateGormInstanceApi.groovy:168)
    at org.grails.datastore.gorm.GormEntity$Trait$Helper.save(GormEntity.groovy:151)
    at org.grails.datastore.gorm.GormEntity$Trait$Helper$save$11.call(Unknown Source)
    at au.org.ala.images.Image.save(Image.groovy)
    at au.org.ala.images.Image.save(Image.groovy)
    at org.grails.datastore.gorm.GormEntity$save$0.call(Unknown Source)
    at au.org.ala.images.ImageService.storeImageBytes(ImageService.groovy:184)
    at sun.reflect.GeneratedMethodAccessor1058.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrap.invoke(PogoMetaMethodSite.java:190)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)
    at au.org.ala.images.ImageService.storeImageFromUrl(ImageService.groovy:71)
    at au.org.ala.images.ImageService$storeImageFromUrl$22.call(Unknown Source)
    at au.org.ala.images.WebServiceController.uploadImage(WebServiceController.groovy:1428)
    at org.grails.core.DefaultGrailsControllerClass$MethodHandleInvoker.invoke(DefaultGrailsControllerClass.java:223)
    at org.grails.core.DefaultGrailsControllerClass.invoke(DefaultGrailsControllerClass.java:188)
    at org.grails.web.mapping.mvc.UrlMappingsInfoHandlerAdapter.handle(UrlMappingsInfoHandlerAdapter.groovy:90)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:111)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:77)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.jasig.cas.client.util.HttpServletRequestWrapperFilter.doFilter(HttpServletRequestWrapperFilter.java:71)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.jasig.cas.client.validation.AbstractTicketValidationFilter.doFilter(AbstractTicketValidationFilter.java:236)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.jasig.cas.client.session.SingleSignOutFilter.doFilter(SingleSignOutFilter.java:97)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:67)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:96)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:103)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67)
    at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54)
    at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:46)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198)
    at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457)
    at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
    at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
    at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
    at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1295)
    at org.grails.orm.hibernate.AbstractHibernateGormInstanceApi.flushSession(AbstractHibernateGormInstanceApi.groovy:289)
    at sun.reflect.GeneratedMethodAccessor979.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1225)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
    at org.codehaus.groovy.runtime.InvokerHelper.invokePogoMethod(InvokerHelper.java:947)
    at org.codehaus.groovy.runtime.InvokerHelper.invokeMethod(InvokerHelper.java:930)
    at org.codehaus.groovy.runtime.InvokerHelper.invokeMethodSafe(InvokerHelper.java:92)
    at org.grails.orm.hibernate.AbstractHibernateGormInstanceApi$_performSave_closure3.doCall(AbstractHibernateGormInstanceApi.groovy:254)
    at sun.reflect.GeneratedMethodAccessor978.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
    at groovy.lang.Closure.call(Closure.java:418)
    at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
    at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
    at com.sun.proxy.$Proxy136.doInHibernate(Unknown Source)
    at org.grails.orm.hibernate.GrailsHibernateTemplate.doExecute(GrailsHibernateTemplate.java:299)
    ... 86 common frames omitted
djtfmartin commented 5 years ago

I haven't successfully reproduced locally, but I think this is happening because the image in question is referenced by 3 records in succession, so the request to store the same image comes in 3 times.

The actual image is persisted and stored, and its the subsequent (multi-threaded) requests to store the same image are failing. So i think more synchronisation is needed for this particular scenario.

So its not a widespread issue, but its an issue nonetheless.

djtfmartin commented 5 years ago

Fixed in 1.0.9

sadeghim commented 4 years ago

Test fails on biocahe-dev with version:

gitCommitSummary = 6344e7c
gitCommitID = 6344e7ccd0993401622763d13d19739a75cc78a2
gitCommitterEmail = noreply@github.com
Manifest-Version = 1.0
Implementation-Title = Biocache
Comment = Manages the loading, processing, sampling and indexing of occurrence records.
Implementation-Vendor = Atlas of Living Australia
Implementation-Vendor-Id = au.org.ala
gitCommitter = GitHub
Created-By = Apache Maven 3.6.0
gitCommitAuthor = Doug Palmer
Implementation-Version = 6344e7ccd0993401622763d13d19739a75cc78a2
sha1 = 6344e7ccd0993401622763d13d19739a75cc78a2
Built-By = travis
buildTimestamp = 2019-11-05T22:17:54Z
Build-Jdk = 1.8.0_222

And image-service of:

Git commit date/time 2019-10-29T04:41:57+1100
d1104cbb199637468a85564cc85f081a9887350d d1104cbb199637468a85564cc85f081a9887350d
Git commit short ID d1104cb
HEAD HEAD
Grails Environment production
App version 1.0.13-SNAPSHOT
Grails version 3.3.9
JVM Version 1.8.0_222
ansell commented 4 years ago

Just to clarify, Mahmoud and I have been testing biocache-store on nci-sandbox-dev with it linked to nci-image-service (images-dev). nci-sandbox-dev is the current defacto biocache-dev server at this point because the sandbox tool allows us to pull in all of the components for a full stack easily

djtfmartin commented 4 years ago

Its deployed on images-dev for testing. Ive tested from biocache-dev. Issue was cause by the introduction of updating licencing here:

https://github.com/AtlasOfLivingAustralia/image-service/commit/39a5d17e1dcaac14e9d59b5d7f890f48c057b9c6

As before, the issue is only happening when the image in question is referenced by 2 or more records in succession, so the request to store the same image comes in 2 times.

I believe this is fixed.

ansell commented 4 years ago

@djtfmartin What is the exact test sequence and file data that you used?

djtfmartin commented 4 years ago

thanks @ansell. Tested using image-dev and nci-sandbox-dev for running biocache-cli. Deployed image-service SNAPSHOT from develop branch using ansible.

  1. Clean images-dev first (DB & indexes)

    • Clear postgres DB using psql> truncate image cascade;
    • Reinitialise indexes through image service /admin console.

  2. Loaded data using a snapshot @sadeghim had on nci-sandbox-dev using the following command.

sudo -u tomcat7 biocache load-dwca --local /home/sad036/dr1411-20191105-030138.dwca.zip -b true dr1411

Monitored logs and killed the job before completion to due to space constraints on image-dev.

Also tested locally using a DWCA with the same multimedia item referenced by 100s of records.

djtfmartin commented 4 years ago

Tried to re-run on nci-sandbox-dev but getting a NPE possibly due to some of the commits referenced here:

https://github.com/AtlasOfLivingAustralia/biocache-store/issues/350

djtfmartin commented 4 years ago

Ignore previous comment. The NPE was misleading - the argument should be an expanded archive directory.

To test run on nci-sandbox-dev

sudo -u tomcat7 biocache load-dwca --local /data/biocache-load/dr1411-20191105-030138  -b true dr1411 -t 8
ansell commented 4 years ago

Thanks, I was having the same issue with the unexpanded archives and resorted to copying the entire prod collectory database to test to get them into nectar-collections-test. After that I still had to touch the archive on nci-upload to bump its timestamp to get it to work for each successive test. I will work through that sequence today to verify this and the fix for AtlasOfLivingAustralia/biocache-store#350

In the biocache-store case I was generating my archives using the rowType from the Darwin Core Text Guide, http://rs.tdwg.org/dwc/xsd/simpledarwincore/SimpleDarwinRecord. That rowType has worked for me for the past 3 years for non-media archives, but it appears that it is the cause of my issues (as Doug identified last week) so I will switch to using the one that biocache-store explicitly supports for media archives.