Data in db is inconsistent. It might happen when candlepin is in the middle of pool refresh.

Actually, I suspect that this inconsistent db is a result of https://bugzilla.redhat.com/show_bug.cgi?id=660516
Therefore... waiting on a fix to #660516 before verifying this bug.

Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Entitlement #8a878c912d7c5c2f012d80fd4a93004c 's endDt[1906385] must equal Subscription #2011-11-01 00:00:00.0 's endDt[Tue Nov 01 23:59:59 EDT 2011]
        at org.fedoraproject.candlepin.controller.PoolManager.generateEntitlementCertificate(PoolManager.java:488)
        at org.fedoraproject.candlepin.controller.PoolManager.addEntitlement(PoolManager.java:449)
        at org.fedoraproject.candlepin.controller.PoolManager.entitleByPool(PoolManager.java:415)

Moving back to ON_DEV since this error is repeat-ably occurring on the DEV2 IT environment.

VERSION...
[root@jsefler-dev2-1 ~]# rpm -q subscription-manager
subscription-manager-0.93.12-1.git.2.397261b.el6.x86_64
[root@jsefler-dev2-1 ~]# curl -k -u candlepin_admin:admin --request GET https://candlepin1.devlab.phx1.redhat.com:443/candlepin/status
{"version":"0.1.28","result":true,"release":"1%{?dist}"}[root@jsefler-dev2-1 ~]# 
# grep hostname /etc/rhsm/rhsm.conf
# Server hostname:
hostname=candlepin1.devlab.phx1.redhat.com
proxy_hostname =



Steps to reproduce:

[root@jsefler-dev2-1 ~]# subscription-manager register --username=xeops --password=redhat
193eff10-f1ea-4f7f-89fc-23f438f682e6 jsefler-dev2-1.usersys.redhat.com
[root@jsefler-dev2-1 ~]# subscription-manager list --available | grep -A3 -B3 8a878c912ccc9e65012ce0410a3d009e
ProductName:       	Red Hat Enterprise MRG Realtime, Standard (unlimited
                        sockets)
ProductId:         	MCT1697RN                
PoolId:            	8a878c912ccc9e65012ce0410a3d009e
Quantity:          	70                       
Expires:           	2011-12-31               

[root@jsefler-dev2-1 ~]# subscription-manager subscribe --pool=8a878c912ccc9e65012ce0410a3d009e
Runtime Error java.lang.IllegalArgumentException: Entitlement #8a878c912d7c5c2f012d85bc624e0091 's endDt[1821752] must equal Subscription #2011-12-31 00:00:00.0 's endDt[Sat Dec 31 23:59:59 EST 2011] at com.google.common.base.Preconditions.checkArgument:111


[root@jsefler-dev2-1 ~]# tail -f /var/log/rhsm/rhsm.log

2011-01-14 13:14:26,411 [INFO] __init__() @connection.py:288 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2011-01-14 13:14:26,411 [INFO] __init__() @connection.py:291 - Connection Established: host: candlepin1.devlab.phx1.redhat.com, port: 443, handler: /candlepin
2011-01-14 13:14:26,502 [INFO] _request() @connection.py:141 - loading ca pem certificates from: /etc/rhsm/ca/
2011-01-14 13:14:26,503 [INFO] _load_ca_certificates() @connection.py:128 - loading ca certificate '/etc/rhsm/ca/candlepin-stage.pem'
2011-01-14 13:14:26,503 [INFO] _load_ca_certificates() @connection.py:128 - loading ca certificate '/etc/rhsm/ca/redhat-uep.pem'
2011-01-14 13:14:26,504 [INFO] _load_ca_certificates() @connection.py:128 - loading ca certificate '/etc/rhsm/ca/fakamai-cp1.pem'
2011-01-14 13:14:26,504 [INFO] _request() @connection.py:143 - work in insecure mode ?:False
2011-01-14 13:14:30,425 [INFO] _request() @connection.py:171 - status code: 500
2011-01-14 13:14:30,426 [ERROR] _do_command() @managercli.py:459 - Runtime Error java.lang.IllegalArgumentException: Entitlement #8a878c912d7c5c2f012d85bc624e0091 's endDt[1821752] must equal Subscription #2011-12-31 00:00:00.0 's endDt[Sat Dec 31 23:59:59 EST 2011] at com.google.common.base.Preconditions.checkArgument:111
Traceback (most recent call last):
  File "/usr/share/rhsm/managercli.py", line 456, in _do_command
    self.cp.bindByEntitlementPool(consumer, pool)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 376, in bindByEntitlementPool
    return self.conn.request_post(method)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 193, in request_post
    return self._request("POST", method, params)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 172, in _request
    self.validateResponse(result)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 187, in validateResponse
    parsed['displayMessage'])
RestlibException: Runtime Error java.lang.IllegalArgumentException: Entitlement #8a878c912d7c5c2f012d85bc624e0091 's endDt[1821752] must equal Subscription #2011-12-31 00:00:00.0 's endDt[Sat Dec 31 23:59:59 EST 2011] at com.google.common.base.Preconditions.checkArgument:111

Also need to fix the String.format(...args) in this message:

Actual output:
Entitlement #8a878c912d7c5c2f012d85bc624e0091 's endDt[1821752] must equal Subscription #2011-12-31 00:00:00.0 's endDt[Sat Dec 31 23:59:59 EST 2011]

Expected output more like this:
Entitlement #8a878c912d7c5c2f012d85bc624e0091's endDt[2011-12-31 00:00:00.0] must
equal Subscription #1821752's endDt[Sat Dec 31 23:59:59 EST 2011]
                    ^^^^^^^ that should probably be a poolid

FYI... zeus may already have a jump on this issue.

refreshing the pools fixes in IT fixes the problem.

After reproducing the error in Comment #5, I looked up the ownerkey for the consumer (registered using xeops credentials) and I refreshed the subscriptions for the owner as follows:

[root@jsefler-dev2-1 ~]# curl -k -u candlepin_admin:admin --request PUT https://candlepin1.devlab.phx1.redhat.com:443/candlepin/owners/4969868/subscriptions
{"id":"refresh_pools_d6052748-a301-4c91-9923-244b533fd6e4","state":"CREATED","startTime":null,"result":null,"finishTime":null,"statusPath":"/jobs/refresh_pools_d6052748-a301-4c91-9923-244b533fd6e4","updated":"2011-01-24T20:42:32.674+0000","created":"2011-01-24T20:42:32.674+0000"}
[root@jsefler-dev2-1 ~]# 
[root@jsefler-dev2-1 ~]# curl -k -u candlepin_admin:admin --request GET https://candlepin1.devlab.phx1.redhat.com:443/candlepin/jobs/refresh_pools_d6052748-a301-4c91-9923-244b533fd6e4
{"id":"refresh_pools_d6052748-a301-4c91-9923-244b533fd6e4","state":"FINISHED","startTime":"2011-01-24T20:42:32.000+0000","result":"Pools refreshed for owner Deutsche Boerse Systems AG","finishTime":"2011-01-24T20:43:25.000+0000","statusPath":"/jobs/refresh_pools_d6052748-a301-4c91-9923-244b533fd6e4","updated":"2011-01-24T20:43:25.000+0000","created":"2011-01-24T20:42:32.000+0000"}

[root@jsefler-dev2-1 ~]# 
[root@jsefler-dev2-1 ~]# subscription-manager register --username=xeops --password=redhat
f03262fe-d79e-4f88-b869-bff9e250dbc3 jsefler-dev2-1.usersys.redhat.com
[root@jsefler-dev2-1 ~]# subscription-manager list --available | grep -A3 -B3 8a878c912ccc9e65012ce0410a3d009e
ProductName:       	Red Hat Enterprise MRG Realtime, Standard (unlimited
                        sockets)
ProductId:         	MCT1697RN                
PoolId:            	8a878c912ccc9e65012ce0410a3d009e
Quantity:          	70                       
Expires:           	2011-12-31               

[root@jsefler-dev2-1 ~]# subscription-manager subscribe --pool=8a878c912ccc9e65012ce0410a3d009e


^^^ SUCCESS!  VERIFIED

[root@jsefler-dev2-1 ~]# openssl x509 -text -in /etc/pki/entitlement/171295902199345162.pem | grep -A1 Validity
        Validity
            Not Before: Jan 24 20:49:58 2011 GMT
[root@jsefler-dev2-1 ~]# openssl x509 -text -in /etc/pki/entitlement/171295902199345162.pem | grep -A2 Validity
        Validity
            Not Before: Jan 24 20:49:58 2011 GMT
            Not After : Jan  1 04:59:59 2012 GMT
[root@jsefler-dev2-1 ~]# openssl x509 -text -in /etc/pki/entitlement/171295902199345162.pem | grep -A1 1.3.6.1.4.1.2312.9.4.6
            1.3.6.1.4.1.2312.9.4.6: 
                ..2010-08-03T04:00:00Z
[root@jsefler-dev2-1 ~]# openssl x509 -text -in /etc/pki/entitlement/171295902199345162.pem | grep -A1 1.3.6.1.4.1.2312.9.4.7
            1.3.6.1.4.1.2312.9.4.7: 
                ..2012-01-01T04:59:59Z
[root@jsefler-dev2-1 ~]# 

^^^ ALSO VERIFIED JESUS'S FIX IN Comment #9 RESULTS IN A SUBSCRIPTION THAT ENDS AT ONE TICK BEFORE MIDNIGHT (local time to the candlepin server - EST), HENCE THE END DATES IN THE CERT ARE AT 2012-01-01T04:59:59Z (GMT).  MOREOVER, THE START DATE IS ON THE FIRST TICK OF THE DAY EST, HENCE 2010-08-03T04:00:00Z (GMT)


CANDLEPIN/RHSM VERSIONS...
[root@jsefler-dev2-1 ~]# rpm -q subscription-manager
subscription-manager-0.93.14-1.git.6.0632b6a.el6.x86_64
[root@jsefler-dev2-1 ~]# curl -k -u candlepin_admin:admin --request GET https://candlepin1.devlab.phx1.redhat.com:443/candlepin/status
{"version":"0.1.28","result":true,"release":"1%{?dist}"}[root@jsefler-dev2-1 ~]# 
[root@jsefler-dev2-1 ~]# 
[root@jsefler-dev2-1 ~]# grep hostname /etc/rhsm/rhsm.conf
# Server hostname:
hostname=candlepin1.devlab.phx1.redhat.com
proxy_hostname =


moving to VERIFIED

(In reply to comment #6)
> Also need to fix the String.format(...args) in this message:
> 
> Actual output:
> Entitlement #8a878c912d7c5c2f012d85bc624e0091 's endDt[1821752] must equal
> Subscription #2011-12-31 00:00:00.0 's endDt[Sat Dec 31 23:59:59 EST 2011]
> 
> Expected output more like this:
> Entitlement #8a878c912d7c5c2f012d85bc624e0091's endDt[2011-12-31 00:00:00.0]
> must
> equal Subscription #1821752's endDt[Sat Dec 31 23:59:59 EST 2011]
>                     ^^^^^^^ that should probably be a poolid


VERIFIED fix was put in the code at...
[root@jsefler-f12-candlepin candlepin]# view ./proxy/src/main/java/org/fedoraproject/candlepin/service/impl/DefaultEntitlementCertServiceAdapter.java

     94         Preconditions
     95             .checkArgument(
     96                 entitlement.getEndDate().getTime() == sub.getEndDate().getTime(),
     97                 "Entitlement #%s 's endDt[%s] must equal Subscription #%s 's endDt[%s]",
     98                 entitlement.getId(), entitlement.getEndDate(), sub.getId(),
     99                 sub.getEndDate());


[root@jsefler-f12-candlepin candlepin]# git show-ref master
c3c7c53ac977aad5b72dd14888a0b5d577334198 refs/heads/master
c3c7c53ac977aad5b72dd14888a0b5d577334198 refs/remotes/origin/master

*** Bug 670184 has been marked as a duplicate of this bug. ***

Just ran into this again today.

[root@candlepin-fte ~]# rpm -qa | grep candlepin
candlepin-jboss-0.2.5-1.el5
candlepin-it-jars-0.2.2-6


Refresh pool cleaned it up; was this bad legacy data, or did the fix not make it into the branch for rhel6.1 beta?


Candlepin's server.log output below:

2011-02-11 15:51:22,672 INFO  [STDOUT] Feb 11 15:51:22 [http-10.7.13.77-8080-1] DEBUG org.fedoraproject.candlepin.service.impl.DefaultEntitlementCertServiceAdapter - Generating entitlement cert for:
2011-02-11 15:51:22,673 INFO  [STDOUT] Feb 11 15:51:22 [http-10.7.13.77-8080-1] DEBUG org.fedoraproject.candlepin.service.impl.DefaultEntitlementCertServiceAdapter -    consumer: 58191d60-b038-4440-87d0-acfd69f9a140
2011-02-11 15:51:22,673 INFO  [STDOUT] Feb 11 15:51:22 [http-10.7.13.77-8080-1] DEBUG org.fedoraproject.candlepin.service.impl.DefaultEntitlementCertServiceAdapter -    product: SER0232US
2011-02-11 15:51:22,673 INFO  [STDOUT] Feb 11 15:51:22 [http-10.7.13.77-8080-1] DEBUG org.fedoraproject.candlepin.service.impl.DefaultEntitlementCertServiceAdapter - entitlement's endDt == subs endDt? 2011-05-04 00:00:00.0 == Wed May 04 23:59:59 EDT 2011 ?
2011-02-11 15:51:23,190 INFO  [STDOUT] Feb 11 15:51:23 [http-10.7.13.77-8080-1] ERROR org.fedoraproject.candlepin.exceptions.CandlepinExceptionMapper - Runtime exception:
org.jboss.resteasy.spi.ApplicationException: java.lang.RuntimeException: java.lang.IllegalArgumentException: Entitlement #8a878dcd2e167259012e167e07b30003 's endDt[2011-05-04 00:00:00.0] must equal Subscription #1748720 's endDt[Wed May 04 23:59:59 EDT 2011]
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:248)
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:216)
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:205)
	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:489)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:466)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:120)
	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:200)
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:48)
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:43)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:216)
	at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:141)
	at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:93)
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:63)
	at org.fedoraproject.candlepin.servlet.filter.logging.LoggingFilter.doFilter(LoggingFilter.java:55)
	at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:129)
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:59)
	at com.wideplay.warp.persist.PersistenceFilter$3.run(PersistenceFilter.java:141)
	at com.wideplay.warp.persist.internal.Lifecycles.failEarlyAndLeaveNoOneBehind(Lifecycles.java:29)
	at com.wideplay.warp.persist.PersistenceFilter.doFilter(PersistenceFilter.java:155)
	at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:129)
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:59)
	at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:122)
	at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:110)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:173)
	at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182)
	at com.redhat.www.valve.ConfigValve.invoke(ConfigValve.java:79)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
	at com.redhat.www.valve.UTF8Valve.invoke(UTF8Valve.java:36)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
	at org.jboss.web.tomcat.service.sso.ClusteredSingleSignOn.invoke(ClusteredSingleSignOn.java:638)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
	at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Entitlement #8a878dcd2e167259012e167e07b30003 's endDt[2011-05-04 00:00:00.0] must equal Subscription #1748720 's endDt[Wed May 04 23:59:59 EDT 2011]
	at org.fedoraproject.candlepin.controller.PoolManager.generateEntitlementCertificate(PoolManager.java:522)
	at org.fedoraproject.candlepin.controller.PoolManager.addEntitlement(PoolManager.java:479)
	at org.fedoraproject.candlepin.controller.PoolManager.entitleByPool(PoolManager.java:446)
	at org.fedoraproject.candlepin.controller.PoolManager$$EnhancerByGuice$$edcfc41d.CGLIB$entitleByPool$5(<generated>)
	at org.fedoraproject.candlepin.controller.PoolManager$$EnhancerByGuice$$edcfc41d$$FastClassByGuice$$965807eb.invoke(<generated>)
	at com.google.inject.internal.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
	at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:64)
	at com.wideplay.warp.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:68)
	at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:64)
	at com.google.inject.InterceptorStackCallback.intercept(InterceptorStackCallback.java:44)
	at org.fedoraproject.candlepin.controller.PoolManager$$EnhancerByGuice$$edcfc41d.entitleByPool(<generated>)
	at org.fedoraproject.candlepin.resource.ConsumerResource.createEntitlementByPool(ConsumerResource.java:485)
	at org.fedoraproject.candlepin.resource.ConsumerResource.bindByPool(ConsumerResource.java:572)
	at org.fedoraproject.candlepin.resource.ConsumerResource.bind(ConsumerResource.java:623)
	at org.fedoraproject.candlepin.resource.ConsumerResource$$EnhancerByGuice$$4ecbf523.CGLIB$bind$2(<generated>)
	at org.fedoraproject.candlepin.resource.ConsumerResource$$EnhancerByGuice$$4ecbf523$$FastClassByGuice$$a3771abc.invoke(<generated>)
	at com.google.inject.internal.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
	at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:64)
	at org.fedoraproject.candlepin.auth.interceptor.SecurityInterceptor.invoke(SecurityInterceptor.java:91)
	at com.google.inject.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:64)
	at com.google.inject.InterceptorStackCallback.intercept(InterceptorStackCallback.java:44)
	at org.fedoraproject.candlepin.resource.ConsumerResource$$EnhancerByGuice$$4ecbf523.bind(<generated>)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
	... 42 more
Caused by: java.lang.IllegalArgumentException: Entitlement #8a878dcd2e167259012e167e07b30003 's endDt[2011-05-04 00:00:00.0] must equal Subscription #1748720 's endDt[Wed May 04 23:59:59 EDT 2011]
	at com.google.common.base.Preconditions.checkArgument(Preconditions.java:111)
	at org.fedoraproject.candlepin.service.impl.DefaultEntitlementCertServiceAdapter.generateEntitlementCert(DefaultEntitlementCertServiceAdapter.java:99)
	at org.fedoraproject.candlepin.controller.PoolManager.generateEntitlementCertificate(PoolManager.java:519)
	... 68 more

We believe bad legacy data.