Description of problem: Product Create scarcely fails with InvalidFormatException com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-04-14T00:03:03.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-04-14T00:03:03.1000-04:00': Can not parse date "2016-04-14T00:03:03.1000-04:00": not compatible with any of standard forms ("yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd")) There is a problem with ss.SSS par of Date value Actions::Candlepin::Product::Create (preceding action) has ss.SSS = 03.970 While Actions::Candlepin::Product::CreateUnlimitedSubscription (failed action) has ss.SSS = 03.1000 !!! (=04.000) It doesn't match ss.SSS patern so it couldn't be deserialized, it came out of json, the source of error could be here... Version-Release number of selected component (if applicable): @Sat6.2.0-Beta-Snap8 candlepin-common-1.0.22-1.el6.noarch candlepin-selinux-0.9.54.4-1.el6.noarch candlepin-0.9.54.4-1.el6.noarch (resteasy-jaxrs-2.3.7.Final.jar) How reproducible: scarcely Steps to Reproduce: 1. repeatedly create products (theoretically with 2000 created products you can hit it once, you have to target last 1/2 milisecond in a second for higher chance Actual results: Date value cannot be deserialized Expected results: Date values are successfully deserialized Additional info: I know the chance to reproduce is low but still there is a flaw somewhere in implementation that should be hunted down
/var/log/candlepin/error.log: 2016-04-14 00:03:04,043 [thread=http-8443-4] [req=dfe09fff-10a3-4635-bdec-7bdce3045b1a, org=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-04-14T00:03:03.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-04-14T00:03:03.1000-04:00': Can not parse date "2016-04-14T00:03:03.1000-04:00": not compatible with any of standard forms ("yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd")) at [Source: org.candlepin.common.filter.TeeHttpServletRequest$1@570d8872; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription["startDate"]) at com.fasterxml.jackson.databind.exc.InvalidFormatException.from:55 org.jboss.resteasy.spi.ReaderException: com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-04-14T00:03:03.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-04-14T00:03:03.1000-04:00': Can not parse date "2016-04-14T00:03:03.1000-04:00": not compatible with any of standard forms ("yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd")) at [Source: org.candlepin.common.filter.TeeHttpServletRequest$1@570d8872; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription["startDate"]) at org.jboss.resteasy.core.MessageBodyParameterInjector.inject(MessageBodyParameterInjector.java:202) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.MethodInjectorImpl.injectArguments(MethodInjectorImpl.java:136) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.candlepin.resteasy.interceptor.AuthInterceptor.getArguments(AuthInterceptor.java:431) ~[AuthInterceptor.class:na] at org.candlepin.resteasy.interceptor.AuthInterceptor.preProcess(AuthInterceptor.java:211) ~[AuthInterceptor.class:na] at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:252) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:227) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:216) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:542) [resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:524) [resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:126) [resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.7.Final.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) [tomcat6-servlet-2.5-api-6.0.24.jar:na] at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62) [guice-servlet-3.0.jar:na] at org.candlepin.servlet.filter.EventFilter.doFilter(EventFilter.java:63) [EventFilter.class:na] at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na] at org.candlepin.servlet.filter.ContentTypeHackFilter.doFilter(ContentTypeHackFilter.java:58) [ContentTypeHackFilter.class:na] at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na] at org.candlepin.common.filter.LoggingFilter.doFilter(LoggingFilter.java:90) [candlepin-common-1.0.23.jar:na] at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na] at org.candlepin.servlet.filter.CandlepinPersistFilter.doFilter(CandlepinPersistFilter.java:48) [CandlepinPersistFilter.class:na] at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na] at org.candlepin.servlet.filter.CandlepinScopeFilter.doFilter(CandlepinScopeFilter.java:68) [CandlepinScopeFilter.class:na] at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118) [guice-servlet-3.0.jar:na] at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113) [guice-servlet-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina-6.0.24.jar:na] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.24.jar:na] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) [catalina-6.0.24.jar:na] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina-6.0.24.jar:na] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina-6.0.24.jar:na] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [catalina-6.0.24.jar:na] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina-6.0.24.jar:na] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:299) [catalina-6.0.24.jar:na] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857) [tomcat-coyote-6.0.24.jar:na] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588) [tomcat-coyote-6.0.24.jar:na] at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) [tomcat-coyote-6.0.24.jar:na] at java.lang.Thread.run(Thread.java:745) [na:1.7.0_99] Caused by: com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-04-14T00:03:03.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-04-14T00:03:03.1000-04:00': Can not parse date "2016-04-14T00:03:03.1000-04:00": not compatible with any of standard forms ("yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd")) at [Source: org.candlepin.common.filter.TeeHttpServletRequest$1@570d8872; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription["startDate"]) at com.fasterxml.jackson.databind.exc.InvalidFormatException.from(InvalidFormatException.java:55) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.DeserializationContext.weirdStringException(DeserializationContext.java:742) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.std.StdDeserializer._parseDate(StdDeserializer.java:619) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.std.DateDeserializers$DateBasedDeserializer._parseDate(DateDeserializers.java:166) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.std.DateDeserializers$DateDeserializer.deserialize(DateDeserializers.java:260) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.std.DateDeserializers$DateDeserializer.deserialize(DateDeserializers.java:241) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:525) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.impl.MethodProperty.deserializeAndSet(MethodProperty.java:99) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:242) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:118) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.ObjectReader._bind(ObjectReader.java:1233) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:677) ~[jackson-databind-2.3.0.jar:2.3.0] at com.fasterxml.jackson.jaxrs.base.ProviderBase.readFrom(ProviderBase.java:764) ~[jackson-jaxrs-base-2.3.0.jar:2.3.0] at org.jboss.resteasy.core.interception.MessageBodyReaderContextImpl.proceed(MessageBodyReaderContextImpl.java:105) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.plugins.interceptors.encoding.GZIPDecodingInterceptor.read(GZIPDecodingInterceptor.java:63) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.interception.MessageBodyReaderContextImpl.proceed(MessageBodyReaderContextImpl.java:108) ~[resteasy-jaxrs-2.3.7.Final.jar:na] at org.jboss.resteasy.core.MessageBodyParameterInjector.inject(MessageBodyParameterInjector.java:169) ~[resteasy-jaxrs-2.3.7.Final.jar:na] ... 46 common frames omitted
Dynflow Console 3: Actions::Candlepin::Product::Create (success) [ 0.05s / 0.05s ] 5: Actions::Candlepin::Product::CreateUnlimitedSubscription (error) [ 0.05s / 0.05s ] Skip Started at: 2016-04-14 04:03:03 UTC Ended at: 2016-04-14 04:03:04 UTC Real time: 0.05s Execution time (excluding suspended state): 0.05s Input: --- owner_key: 3ZqjnOZgbF product_id: '1460606583970' remote_user: admin remote_cp_user: admin locale: en Output: --- {} Error: Katello::Errors::CandlepinError Runtime Error com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-04-14T00:03:03.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-04-14T00:03:03.1000-04:00': Can not parse date "2016-04-14T00:03:03.1000-04:00": not compatible with any of standard forms ("yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd")) at [Source: org.candlepin.common.filter.TeeHttpServletRequest$1@570d8872; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription["startDate"]) at com.fasterxml.jackson.databind.exc.InvalidFormatException.from:55 --- - "/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.17/app/lib/actions/middleware/propagate_candlepin_errors.rb:21:in `rescue in propagate_candlepin_errors'" - "/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.17/app/lib/actions/middleware/propagate_candlepin_errors.rb:19:in `propagate_candlepin_errors'" - "/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.17/app/lib/actions/middleware/propagate_candlepin_errors.rb:9:in `run'" - "/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.10/lib/dynflow/middleware/stack.rb:22:in `call'" - "/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.10/lib/dynflow/middleware/stack.rb:26:in `pass'" - "/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.10/lib/dynflow/middleware.rb:17:in
Created attachment 1147606 [details] foreman debug
Hi Lukas, When you encounter this error, are you able to recover from it? E.g. can the task be resumed and product created? Also, based on the behavior described, are you primarily seeing this when doing performance testing, automated testing...etc? Thanks!
Hi Brad, Yes I'm able to recover form it ... still we have wrong date being sent on dynflow (that candlepin fails on) I was only looking into a single automation run results, with 2375 product creations overall there were 20 or so failures and the only one was really really interesting (this one)
The date format requested '2016-04-14T00:03:03.1000-04:00' is not in the acceptable list: "yyyy-MM-dd'T'HH:mm:ss.SSSZ", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'", "EEE, dd MMM yyyy HH:mm:ss zzz", "yyyy-MM-dd"
If candlepin received such a badly formatted data then who is to blame? So that we can switch this bz to relevant component? Dynflow?
I don't know if this would be an issue in the test script, Dynflow, or an API layer in between. If you can source where the '-4:00' got added to the time requested that would be the component where the error occurred.
Barnaby, I concur,... Actually "-4:00" (=Z) is not an issue, but "03.1000" (ss.SSS) definitely is. You cant have "1000" for .SSS fraction 2016-04-14T00:03:03.1000-04:00 ----
Reassigning and Reopening now with proper component.
Moving 6.2 bugs out to sat-backlog.
Hit the bug again on sat6.2.3-3.0 during product create task. 2016-10-22 16:15:41 - nailgun.client - WARNING - Received HTTP 500 response: {"displayMessage":"Task cdf62d39-fb7c-42fd-9596-1fd20e27cf6d: Katello::Errors::CandlepinError: Runtime Error com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-10-22T16:15:40.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-10-22T16:15:40.1000-04:00': Can not parse date \"2016-10-22T16:15:40.1000-04:00\": not compatible with any of standard forms (\"yyyy-MM-dd'T'HH:mm:ss.SSSZ\", \"yyyy-MM-dd'T'HH:mm:ss.SSS'Z'\", \"EEE, dd MMM yyyy HH:mm:ss zzz\", \"yyyy-MM-dd\"))\n at [Source: org.jboss.resteasy.core.interception.MessageBodyReaderContextImpl$InputStreamWrapper@3dd28f21; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription[\"startDate\"]) at com.fasterxml.jackson.databind.exc.InvalidFormatException.from:55","errors":["Task cdf62d39-fb7c-42fd-9596-1fd20e27cf6d: Katello::Errors::CandlepinError: Runtime Error com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-10-22T16:15:40.1000-04:00': not a valid representation (error: Failed to parse Date value '2016-10-22T16:15:40.1000-04:00': Can not parse date \"2016-10-22T16:15:40.1000-04:00\": not compatible with any of standard forms (\"yyyy-MM-dd'T'HH:mm:ss.SSSZ\", \"yyyy-MM-dd'T'HH:mm:ss.SSS'Z'\", \"EEE, dd MMM yyyy HH:mm:ss zzz\", \"yyyy-MM-dd\"))\n at [Source: org.jboss.resteasy.core.interception.MessageBodyReaderContextImpl$InputStreamWrapper@3dd28f21; line: 1, column: 2] (through reference chain: org.candlepin.model.Subscription[\"startDate\"]) at com.fasterxml.jackson.databind.exc.InvalidFormatException.from:55"]}
and again for 6.2.5 snap3: Task ada1816d-d5a2-4b95-b7ce-1173e9d8bbbb: Katello::Errors::CandlepinError: Runtime Error com.fasterxml.jackson.databind.exc.InvalidFormatException: Can not construct instance of java.util.Date from String value '2016-12-03T21:54:33.1000-05:00': not a valid representation
Created redmine issue http://projects.theforeman.org/issues/18437 from this bug
Let me answer with PR to Katello: https://github.com/Katello/katello/pull/6594, explanation in http://projects.theforeman.org/issues/18437
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/18437 has been resolved.
VERIFIED. @satellite-6.3.0-15.0.beta.el7sat.noarch tfm-rubygem-katello-3.4.1-1.el7sat.noarch by following manual reproducer: 1. Create 2000 products # for i in {1..2000}; do hammer product create --name "product$i" --organization-id 1 ; done 2. Check tasks page for failed product creations by filter "state = paused" REPRO: Product Create product 'product1775'; organization 'Default Organization' Product Create product 'product338'; organization 'Default Organization' vs. FIX: no paused (=failed) tasks >>> product creation no longer fails due to InvalidFormatException
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHSA-2018:0336