17103
Reporter: trobertson
Type: Feedback
Summary: "dataset_occurrence_download" violates foreign key constraint
Priority: Blocker
Resolution: WontFix
Status: Closed
Created: 2015-02-05 21:27:57.56
Updated: 2015-03-02 14:36:49.877
Resolved: 2015-03-02 14:36:49.853
Description: Live registry logs showing concerning WARN statement
{code}
WARN [2015-02-05 20:10:25,652+0100] [qtp1876233337-94] org.eclipse.jetty.servlet.ServletHandler: /occurrence/download/dataset
org.apache.ibatis.exceptions.PersistenceException:
### Error updating database. Cause: org.postgresql.util.PSQLException: ERROR: insert or update on table "dataset_occurrence_download" violates foreign key constraint "dataset_occurrence_download_download_key_fkey"
Detail: Key (download_key)=(0000292-150204170955391) is not present in table "occurrence_download".
### The error may involve org.gbif.registry.persistence.mapper.DatasetOccurrenceDownloadMapper.create-Inline
### The error occurred while setting parameters
### SQL: INSERT INTO dataset_occurrence_download(download_key,dataset_key,dataset_title,dataset_doi,dataset_citation,number_records) VALUES( ?, ?, ?, ?, ?, ? )
### Cause: org.postgresql.util.PSQLException: ERROR: insert or update on table "dataset_occurrence_download" violates foreign key constraint "dataset_occurrence_download_download_key_fkey"
Detail: Key (download_key)=(0000292-150204170955391) is not present in table "occurrence_download".
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:26) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:154) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:141) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at sun.reflect.GeneratedMethodAccessor548.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
at org.apache.ibatis.session.SqlSessionManager$SqlSessionInterceptor.invoke(SqlSessionManager.java:285) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.proxy.$Proxy44.insert(Unknown Source) ~[na:na]
at org.apache.ibatis.session.SqlSessionManager.insert(SqlSessionManager.java:198) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:51) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.proxy.$Proxy130.create(Unknown Source) ~[na:na]
at org.gbif.registry.ws.resources.DatasetOccurrenceDownloadUsageResource.create(DatasetOccurrenceDownloadUsageResource.java:63) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.apache.bval.guice.ValidateMethodInterceptor.invoke(ValidateMethodInterceptor.java:92) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at sun.reflect.GeneratedMethodAccessor546.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$VoidOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:167) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1556) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.gbif.registry.ws.filter.StaticContentFilter.doFilter(StaticContentFilter.java:52) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1548) ~[registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:524) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:568) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1110) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:453) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:183) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1044) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:199) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.Server.handle(Server.java:459) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:280) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:229) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536) [registry-ws-2.20.jar:2.21-SNAPSHOT]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
{code}]]>
Author: trobertson@gbif.org
Comment: Other than the actual issue, this looks like ERROR level logging, not WARN
Created: 2015-02-05 21:33:46.869
Updated: 2015-02-05 21:33:46.869
Author: fmendez@gbif.org
Comment: the download '0000292-15020417095539' doesn't exist in pg1.gbif.org/prod_b_registry...which makes everything even more serious
Created: 2015-02-05 21:38:18.524
Updated: 2015-02-05 21:38:18.524
Author: mdoering@gbif.org
Comment: I think that was me causing the problem when I replaced the registry last night. It was down for 10 seconds and I immediately saw those logs firing up. Guess it missed the actual download write so subsequent usages failed. Should not be a code bug
Created: 2015-02-06 08:29:31.323
Updated: 2015-02-06 08:29:31.323
Author: mdoering@gbif.org
Comment: Changing the logging from WARN to ERROR for ibatis exceptions is not that straight forward as it is handled by the jetty container. Maybe @Fede has some insights how to change the log level for exceptions logged by our jetty jars? Maybe we can also catch log and rethrow all of them in jersey...
Created: 2015-02-06 10:25:27.187
Updated: 2015-02-06 10:25:27.187
Author: mdoering@gbif.org
Created: 2015-02-06 10:31:20.363
Updated: 2015-02-06 10:31:20.363
All logged PersistenceExceptions come from one download that tried to write to registry the usages at 20:10
Thats the time I just restarted registry (around 20:0x). so apart from warn logging level we can close this issue
Author: trobertson@gbif.org
Comment: Occurred due to service error
Created: 2015-03-02 14:36:49.874
Updated: 2015-03-02 14:36:49.874