Hide Forgot
Description of problem: run virt-who with libvirt local mode and against stage candlepin, send the json info failed, it will show "RestlibException: Problem updating unit Consumer<id=null, uuid=3c77cf50-1918-47b7-893b-a8f5502540c7, type=null, name=null> " Version-Release number of selected component (if applicable): virt-who-0.17-10.el7.noarch subscription-manager-1.17.10-1.el7.x86_64 python-rhsm-1.17.6-1.el7.x86_64 How reproducible: 50% Steps to Reproduce: 1. register host to stage candlepin 2. run virt-who for libvirt local mode # virt-who -d 2016-08-30 03:38:17,437 [virtwho.init INFO] MainProcess(1170):MainThread @main.py:main:153 - No configurations found, using libvirt as backend 2016-08-30 03:38:17,438 [virtwho.init INFO] MainProcess(1170):MainThread @main.py:main:160 - Using configuration "env/cmdline" ("libvirt" mode) 2016-08-30 03:38:17,438 [virtwho.init INFO] MainProcess(1170):MainThread @main.py:main:162 - Using reporter_id='hp-z220-10.qe.lab.eng.nay.redhat.com-f473adebc5ff4338a9d660b84d08a598' 2016-08-30 03:38:17,439 [virtwho.main DEBUG] MainProcess(1170):MainThread @executor.py:run:171 - Starting infinite loop with 60 seconds interval 2016-08-30 03:38:17,468 [virtwho.env_cmdline DEBUG] Libvirtd-1(1177):MainThread @virt.py:run:364 - Virt backend 'env/cmdline' started 2016-08-30 03:38:17,469 [virtwho.env_cmdline INFO] Libvirtd-1(1177):MainThread @libvirtd.py:_connect:157 - Using libvirt url: "" 2016-08-30 03:38:17,470 [virtwho.env_cmdline DEBUG] Libvirtd-1(1177):MainThread @libvirtd.py:_listDomains:245 - Libvirt domains found: 5e815888-ae08-4de0-831c-de43830adef1 2016-08-30 03:38:17,474 [virtwho.env_cmdline DEBUG] Libvirtd-1(1177):MainThread @virt.py:enqueue:357 - Report for config "env/cmdline" gathered, putting to queue for sending 2016-08-30 03:38:17,485 [virtwho.main DEBUG] MainProcess(1170):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem 2016-08-30 03:38:18,688 [virtwho.main INFO] MainProcess(1170):MainThread @subscriptionmanager.py:sendVirtGuests:153 - Sending update in guests lists for config "env/cmdline": 1 guests found 2016-08-30 03:38:18,688 [virtwho.main DEBUG] MainProcess(1170):MainThread @subscriptionmanager.py:sendVirtGuests:154 - Domain info: [ { "guestId": "5e815888-ae08-4de0-831c-de43830adef1", "state": 1, "attributes": { "active": 1, "virtWhoType": "libvirt" } } ] 2016-08-30 03:38:20,824 [virtwho.main ERROR] MainProcess(1170):MainThread @executor.py:send:156 - Error in communication with subscription manager: Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/virtwho/executor.py", line 137, in send self._sendGuestList(report) File "/usr/lib/python2.7/site-packages/virtwho/executor.py", line 162, in _sendGuestList manager.sendVirtGuests(report, self.options) File "/usr/lib/python2.7/site-packages/virtwho/manager/subscriptionmanager/subscriptionmanager.py", line 158, in sendVirtGuests self.connection.updateConsumer(self.uuid(), guest_uuids=serialized_guests, hypervisor_id=report.hypervisor_id) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 1010, in updateConsumer ret = self.conn.request_put(method, params) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 703, in request_put return self._request("PUT", method, params) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 611, in _request self.validateResponse(result, request_type, handler) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 661, in validateResponse raise RestlibException(response['status'], error_msg, response.get('headers')) RestlibException: Problem updating unit Consumer<id=null, uuid=f975d01c-fbd0-4797-af73-bbeaaa5b340c, type=null, name=null> 2016-08-30 03:38:20,825 [virtwho.main DEBUG] MainProcess(1170):MainThread @executor.py:send_report:108 - Report from "env/cmdline" failed to sent Actual results: failed to send, due to "RestlibException: Problem updating unit Consumer<id=null, uuid=f975d01c-fbd0-4797-af73-bbeaaa5b340c, type=null, name=null>" Expected results: it should be sent normally Additional info:
Sounds like server-side issue to me. Can you please attach logs from the candlepin?
(In reply to Radek Novacek from comment #1) > Sounds like server-side issue to me. Can you please attach logs from the > candlepin? Hi Radek, it's not a satellite bug, it's related with stage candlepin, so we can't fetch the log message. when I use another stage candlepin account testing, the json info can be sent normally, so I agree with you, it seems a candlepin bug
This bug can be reproduced via following steps, I think it's related to virt-who remote libvirt mode. 1, prepare 2 hosts: hp-z220-07, hp-z220-08, configure authorized_keys in hp-z220-08 and copy to hp-z220-07 to enable remote libvirt mode. [root@hp-z220-08 ~]# ssh-keygen [root@hp-z220-08 ~]# ssh-copy-id -i ~/.ssh/id_rsa.pub hp-z220-07 2, register hp-z220-08 to stage candlepin, stop virt-who service and configure remote libvirt mode [root@hp-z220-08 ~]# subscription-manager register [root@hp-z220-08 ~]# systemctl stop virt-who.service [root@hp-z220-08 ~]#cat > /etc/virt-who.d/virt-who <<EOF [libvirt] type=libvirt server=hp-z220-07.qe.lab.eng.nay.redhat.com username=root password= owner=7970632 env=7970632 EOF 3, start virt-who service, check log message as follows, in stage candlepin web page, a hypervisor named "826c4f80-28ee-11e2-b149-b4b52fe0ce88" should be added. [root@hp-z220-08 ~]# cat /var/log/rhsm/rhsm.log 2016-09-01 01:58:25,733 [virtwho.init DEBUG] MainProcess(11029):MainThread @executor.py:__init__:65 - Using config named 'libvirt' 2016-09-01 01:58:25,734 [virtwho.init INFO] MainProcess(11029):MainThread @main.py:main:160 - Using configuration "libvirt" ("libvirt" mode) 2016-09-01 01:58:25,734 [virtwho.init INFO] MainProcess(11029):MainThread @main.py:main:162 - Using reporter_id='hp-z220-08.qe.lab.eng.nay.redhat.com-357d6baee46041ca8e1386179476e20d' 2016-09-01 01:58:25,736 [virtwho.main DEBUG] MainProcess(11029):MainThread @executor.py:run:171 - Starting infinite loop with 60 seconds interval 2016-09-01 01:58:25,768 [virtwho.libvirt DEBUG] Libvirtd-1(11039):MainThread @virt.py:run:364 - Virt backend 'libvirt' started 2016-09-01 01:58:25,769 [virtwho.libvirt INFO] Libvirtd-1(11039):MainThread @libvirtd.py:_get_url:125 - Protocol is not specified in libvirt url, using qemu+ssh:// 2016-09-01 01:58:25,769 [virtwho.libvirt INFO] Libvirtd-1(11039):MainThread @libvirtd.py:_get_url:136 - Libvirt path is not specified in the url, using /system 2016-09-01 01:58:25,769 [virtwho.libvirt INFO] Libvirtd-1(11039):MainThread @libvirtd.py:_connect:157 - Using libvirt url: qemu+ssh://root.lab.eng.nay.redhat.com/system?no_tty=1 2016-09-01 01:58:26,005 [virtwho.libvirt DEBUG] Libvirtd-1(11039):MainThread @libvirtd.py:_listDomains:245 - Libvirt domains found: e6277d3f-705c-4425-91e0-057e5f627215, b6ef25af-b9fa-4f30-9476-66077aae3ced 2016-09-01 01:58:26,006 [virtwho.libvirt DEBUG] Libvirtd-1(11039):MainThread @virt.py:enqueue:357 - Report for config "libvirt" gathered, putting to queue for sending 2016-09-01 01:58:26,019 [virtwho.main DEBUG] MainProcess(11029):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem 2016-09-01 01:58:27,441 [virtwho.main DEBUG] MainProcess(11029):MainThread @subscriptionmanager.py:hypervisorCheckIn:172 - Checking if server has capability 'hypervisor_async' 2016-09-01 01:58:28,859 [virtwho.main DEBUG] MainProcess(11029):MainThread @subscriptionmanager.py:hypervisorCheckIn:184 - Server does not have 'hypervisors_async' capability 2016-09-01 01:58:28,860 [virtwho.main INFO] MainProcess(11029):MainThread @subscriptionmanager.py:hypervisorCheckIn:195 - Sending update in hosts-to-guests mapping for config "libvirt": 1 hypervisors and 2 guests found 2016-09-01 01:58:28,860 [virtwho.main DEBUG] MainProcess(11029):MainThread @subscriptionmanager.py:hypervisorCheckIn:196 - Host-to-guest mapping: { "826c4f80-28ee-11e2-b149-b4b52fe0ce88": [ { "guestId": "e6277d3f-705c-4425-91e0-057e5f627215", "state": 5, "attributes": { "active": 0, "virtWhoType": "libvirt" } }, { "guestId": "b6ef25af-b9fa-4f30-9476-66077aae3ced", "state": 5, "attributes": { "active": 0, "virtWhoType": "libvirt" } } ] } 2016-09-01 01:58:30,092 [virtwho.main DEBUG] MainProcess(11029):MainThread @executor.py:send_report:101 - Report for config "libvirt" sent 4, go to hp-z220-07, register to stage candlepin and start virt-who with libvirt local mode, this bug appears. if remove the hypervisor(826c4f80-28ee-11e2-b149-b4b52fe0ce88) generated in step 3 from stage web ui, the error will disappear. [root@hp-z220-07 ~]# cat /var/log/rhsm/rhsm.log 2016-09-01 01:56:54,971 [virtwho.init INFO] MainProcess(30833):MainThread @main.py:main:153 - No configurations found, using libvirt as backend 2016-09-01 01:56:54,971 [virtwho.init INFO] MainProcess(30833):MainThread @main.py:main:160 - Using configuration "env/cmdline" ("libvirt" mode) 2016-09-01 01:56:54,972 [virtwho.init INFO] MainProcess(30833):MainThread @main.py:main:162 - Using reporter_id='hp-z220-07.qe.lab.eng.nay.redhat.com-00e91b77dc3f4b439ea8e68bb1aa0727' 2016-09-01 01:56:54,973 [virtwho.main DEBUG] MainProcess(30833):MainThread @executor.py:run:171 - Starting infinite loop with 60 seconds interval 2016-09-01 01:56:55,002 [virtwho.env_cmdline DEBUG] Libvirtd-1(30840):MainThread @virt.py:run:364 - Virt backend 'env/cmdline' started 2016-09-01 01:56:55,003 [virtwho.env_cmdline INFO] Libvirtd-1(30840):MainThread @libvirtd.py:_connect:157 - Using libvirt url: "" 2016-09-01 01:56:55,005 [virtwho.env_cmdline DEBUG] Libvirtd-1(30840):MainThread @libvirtd.py:_listDomains:245 - Libvirt domains found: e6277d3f-705c-4425-91e0-057e5f627215, b6ef25af-b9fa-4f30-9476-66077aae3ced 2016-09-01 01:56:55,009 [virtwho.env_cmdline DEBUG] Libvirtd-1(30840):MainThread @virt.py:enqueue:357 - Report for config "env/cmdline" gathered, putting to queue for sending 2016-09-01 01:56:55,019 [virtwho.main DEBUG] MainProcess(30833):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem 2016-09-01 01:56:56,440 [virtwho.main INFO] MainProcess(30833):MainThread @subscriptionmanager.py:sendVirtGuests:153 - Sending update in guests lists for config "env/cmdline": 2 guests found 2016-09-01 01:56:56,440 [virtwho.main DEBUG] MainProcess(30833):MainThread @subscriptionmanager.py:sendVirtGuests:154 - Domain info: [ { "guestId": "b6ef25af-b9fa-4f30-9476-66077aae3ced", "state": 5, "attributes": { "active": 0, "virtWhoType": "libvirt" } }, { "guestId": "e6277d3f-705c-4425-91e0-057e5f627215", "state": 5, "attributes": { "active": 0, "virtWhoType": "libvirt" } } ] 2016-09-01 01:56:58,650 [virtwho.main ERROR] MainProcess(30833):MainThread @executor.py:send:156 - Error in communication with subscription manager: Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/virtwho/executor.py", line 137, in send self._sendGuestList(report) File "/usr/lib/python2.7/site-packages/virtwho/executor.py", line 162, in _sendGuestList manager.sendVirtGuests(report, self.options) File "/usr/lib/python2.7/site-packages/virtwho/manager/subscriptionmanager/subscriptionmanager.py", line 158, in sendVirtGuests self.connection.updateConsumer(self.uuid(), guest_uuids=serialized_guests, hypervisor_id=report.hypervisor_id) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 1010, in updateConsumer ret = self.conn.request_put(method, params) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 703, in request_put return self._request("PUT", method, params) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 611, in _request self.validateResponse(result, request_type, handler) File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 661, in validateResponse raise RestlibException(response['status'], error_msg, response.get('headers')) RestlibException: Problem updating unit Consumer<id=null, uuid=46733c6f-b52d-49a3-be0b-a28a70e48e6b, type=null, name=null>
This looks to be an issue with reporting a hypervisor in both libvirt remote and local modes because they report different uuids. 1) Make sure that libvirt local mode and libvirt remote mode return the same UUID from virt-who 2) Make sure subscription-manager is using the same method as virt-who to get the UUID (Thus ensuring they are the same).
It still exist on RHEL-6.9-20161216.1 against stage candlepin.
It still exist on RHEL-6.9-20170118.0 against stage candlepin. virt-who's version is virt-who-0.18-2.el6.noarch.
I cannot reproduce this bug with current version of virt-who and subscription-manager. Can anybody confirm?
I am able to reproduce this against virt-who master. An alternate way to reproduce can be found below: 0) Start on an unregistered system that has virtual guests (we'll call this HOST) with no prior virt-who configuration (/etc/virt-who.d/ should be empty) 1) Save the following (set owner/env/rhsm* as needed, less the triple quotes) as "remote_libvirt.conf" in your home directory: """ [remote_libvirt] type=libvirt server=qemu:///system owner=admin env=admin rhsm_hostname=localhost rhsm_port=8443 rhsm_username=admin rhsm_password=admin rhsm_prefix=/candlepin """ 2) Save the following as "local_libvirt.conf" (update owner/env/rhsm* as needed) in your home directory: """ [local_libvirt] type=libvirt owner=admin env=admin rhsm_hostname=localhost rhsm_port=8443 rhsm_username=admin rhsm_password=admin rhsm_prefix=/candlepin """ 3) Run virt-who: `virt-who -o -d -c ~/remote_libvirt.conf` 4) Observe that the report appears to have been successful 5) Run virt-who again this time with the local_libvirt configuration: `virt-who -o -d -c ~/local_libvirt.conf` 6) Observe the following line in the output: """ RestlibException: Problem updating unit Consumer [id: null, uuid: c08ec850-01cc-4825-9ccc-ef58c94d4106, consumerType: null, name: null] """ Also, I am moving this issue to 7.5 as this is not a blocking issue for 7.4
Please note there is a missing step in my repro steps above. Step 4 should include the following: Register the system using subscription-manager to the same organization the remote libvirt configuration is pointing to.
I can confirm this behavior. Just note the HOST have to be registered using subscription-manager between step 4 and 5. Otherwise virt-who will not be able to communicate with candlepin server. I run sub-man with following parameters: $ subscription-manager register --username=admin --password=admin --org=admin BTW: this error appeared in candlepin.log file after RestlibException was raised by virt-who: 2017-06-08 11:35:00,053 [thread=QuartzScheduler_Worker-11] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.SweepBarJob 2017-06-08 11:35:00,055 [thread=QuartzScheduler_Worker-11] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Job completed: time=2 2017-06-08 11:36:03,745 [thread=http-bio-8443-exec-7] [req=922b2231-fded-46f0-9e5d-18ab9864a52b, org=, csid=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status/ 2017-06-08 11:36:03,747 [thread=http-bio-8443-exec-7] [req=922b2231-fded-46f0-9e5d-18ab9864a52b, org=, csid=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=2 2017-06-08 11:36:03,778 [thread=http-bio-8443-exec-11] [req=4851a4b0-ff3b-46e3-9b04-8ee915dc840c, org=, csid=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/ 2017-06-08 11:36:03,779 [thread=http-bio-8443-exec-11] [req=4851a4b0-ff3b-46e3-9b04-8ee915dc840c, org=, csid=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=1 2017-06-08 11:36:03,796 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=, csid=] INFO org.candlepin.common.filter.LoggingFilter - Request: verb=PUT, uri=/candlepin/consumers/640029be-435d-4c42-b876-e3e21e25acdb 2017-06-08 11:36:03,906 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=admin, csid=] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 23505 2017-06-08 11:36:03,906 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=admin, csid=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "cp_consumer_hypervisor_ukey" Detail: Key (hypervisor_id, owner_id)=(fb9d1281-53cc-11cb-9a33-8043c5f45d9d, 4028fa7a5c884ac9015c884cfe530004) already exists. 2017-06-08 11:36:03,907 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=admin, csid=] ERROR org.candlepin.resource.ConsumerResource - Problem updating unit: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) ~[hibernate-entitymanager-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) ~[hibernate-entitymanager-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608) ~[hibernate-entitymanager-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1303) ~[hibernate-entitymanager-5.1.1.Final.jar:5.1.1.Final] at org.candlepin.model.AbstractHibernateCurator.flush(AbstractHibernateCurator.java:554) ~[AbstractHibernateCurator.class:na] at org.candlepin.model.AbstractHibernateCurator.save(AbstractHibernateCurator.java:549) ~[AbstractHibernateCurator.class:na] at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58) ~[guice-persist-3.0.jar:na] at org.candlepin.model.ConsumerCurator.update(ConsumerCurator.java:413) ~[ConsumerCurator.class:na] at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58) ~[guice-persist-3.0.jar:na] at org.candlepin.model.ConsumerCurator.update(ConsumerCurator.java:363) ~[ConsumerCurator.class:na] at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58) ~[guice-persist-3.0.jar:na] at org.candlepin.resource.ConsumerResource.updateConsumer(ConsumerResource.java:1030) ~[ConsumerResource.class:na] at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:66) ~[guice-persist-3.0.jar:na] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_131] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_131] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs-3.0.10.Final.jar:na] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs-3.0.10.Final.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) [tomcat-servlet-3.0-api.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:61) [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:112) [candlepin-common-2.0.3.jar:] 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:241) [catalina.jar:7.0.69] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.69] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.69] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.69] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505) [catalina.jar:7.0.69] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169) [catalina.jar:7.0.69] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.69] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) [catalina.jar:7.0.69] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.69] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436) [catalina.jar:7.0.69] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078) [tomcat-coyote.jar:7.0.69] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) [tomcat-coyote.jar:7.0.69] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.69] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.69] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131] Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:112) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2932) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3432) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:582) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:456) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1295) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1300) ~[hibernate-entitymanager-5.1.1.Final.jar:5.1.1.Final] ... 61 common frames omitted Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "cp_consumer_hypervisor_ukey" Detail: Key (hypervisor_id, owner_id)=(fb9d1281-53cc-11cb-9a33-8043c5f45d9d, 4028fa7a5c884ac9015c884cfe530004) already exists. at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102) ~[postgresql-9.0-801.jdbc4.jar:na] at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835) ~[postgresql-9.0-801.jdbc4.jar:na] at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) ~[postgresql-9.0-801.jdbc4.jar:na] at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) ~[postgresql-9.0-801.jdbc4.jar:na] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388) ~[postgresql-9.0-801.jdbc4.jar:na] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334) ~[postgresql-9.0-801.jdbc4.jar:na] at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:384) ~[c3p0-0.9.5.2.jar:0.9.5.2] at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204) ~[hibernate-core-5.1.1.Final.jar:5.1.1.Final] ... 71 common frames omitted 2017-06-08 11:36:03,911 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=admin, csid=] WARN org.candlepin.audit.EventSinkImpl - Rolling back hornetq transaction. 2017-06-08 11:36:03,947 [thread=http-bio-8443-exec-12] [req=11cf3e5e-50d9-4121-aa81-87539793c616, org=admin, csid=] INFO org.candlepin.common.filter.LoggingFilter - Response: status=400, content-type="application/json", time=151 2017-06-08 11:40:00,012 [thread=QuartzScheduler_Worker-10] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.SweepBarJob 2017-06-08 11:40:00,013 [thread=QuartzScheduler_Worker-10] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Job completed: time=1 2017-06-08 11:45:00,053 [thread=QuartzScheduler_Worker-13] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.SweepBarJob 2017-06-08 11:45:00,054 [thread=QuartzScheduler_Worker-13] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Job completed: time=1 2017-06-08 11:50:00,015 [thread=QuartzScheduler_Worker-12] [job=SweepBarJob-b6e994da-452c-455e-9322-a0d7f0a01ffb, org=, csid=] INFO org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.SweepBarJob
Liklely fixed by the solution to BZ 1365248. Needs to be confirmed.
This appears to be fixed in the current build of Candlepin 0.9.54