Bug 2030265
| Summary: | EntitlementChanged notification comes too early, GetStatus returns old data | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 8 | Reporter: | Marius Vollmer <mvollmer> |
| Component: | subscription-manager | Assignee: | candlepin-bugs |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Red Hat subscription-manager QE Team <rhsm-qe> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 8.6 | CC: | mpitt, ptoscano, redakkan, wpoteat |
| Target Milestone: | rc | Keywords: | Regression, Triaged |
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2022-02-03 05:54:30 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
Can we get a debug level capture of the rhsm.log while this process is happening, please? Thanks I can no longer reproduce this bug with subscription-manager-1.28.25-1.el8.x86_64. Now the GetStatus calls return with { ..., "valid": true }, as expected.
I am afraid we have to either accept that this is mysteriously fixed, or have a long careful look at the code with the hope of finding some race condition.
Our automatic tracker confirms that this wasn't seen any more in the last 3 weeks [1], since Jan 13. This coincides with our rhel-8-6 refresh in [2], which updated (amongst other things) subscription-manager (1.28.24-1.el8 -> 1.28.25-1.el8) subscription-manager-cockpit (1.28.24-1.el8 -> 1.28.25-1.el8) subscription-manager-rhsm-certificates (1.28.24-1.el8 -> 1.28.25-1.el8) So let's close this for now, so some change fixed this. If we see it again, I'll reopen. [1] https://github.com/cockpit-project/bots/pull/2888 [2] https://github.com/cockpit-project/bots/pull/2794 This looks similar: https://bugzilla.redhat.com/show_bug.cgi?id=2067129 |
Description of problem: This is about the /com/redhat/RHSM1/Entitlement object of the com.redhat.RHSM1 D-Bus service. Cockpit monitors the entitlement status by calling GetStatus initially and in response to the EntitlementChanged signal. Recently, calling GetStatus right after receiving the signal will return the old, stale data, instead of the expected current status. Version-Release number of selected component (if applicable): subscription-manager-1.28.24-1.el8.x86_64 How reproducible: Always Steps to Reproduce: 1. Open Cockpit and go to "Subscriptions" page 2. busctl monitor 3. subscription-manager --register ...; subscription-manager attach --auto Actual results: ‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=60 Timestamp="Wed 2021-12-08 09:21:00.135422 UTC" Sender=:1.60 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=EntitlementChanged UniqueName=:1.60 MESSAGE "" { }; ‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=61 Timestamp="Wed 2021-12-08 09:21:00.135464 UTC" Sender=:1.60 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=EntitlementChanged UniqueName=:1.60 MESSAGE "" { }; ‣ Type=method_call Endian=l Flags=4 Version=1 Priority=0 Cookie=38 Timestamp="Wed 2021-12-08 09:21:00.168711 UTC" Sender=:1.55 Destination=com.redhat.RHSM1 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=GetStatus UniqueName=:1.55 MESSAGE "ss" { STRING ""; STRING ""; }; ‣ Type=method_call Endian=l Flags=4 Version=1 Priority=0 Cookie=39 Timestamp="Wed 2021-12-08 09:21:00.168748 UTC" Sender=:1.55 Destination=com.redhat.RHSM1 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=GetStatus UniqueName=:1.55 MESSAGE "ss" { STRING ""; STRING ""; }; ‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=62 ReplyCookie=38 Timestamp="Wed 2021-12-08 09:21:00.168761 UTC" Sender=:1.60 Destination=:1.55 UniqueName=:1.60 MESSAGE "s" { STRING "{"status": "Unknown", "status_id": "unknown", "reasons": {}, "reason_ids": {}, "valid": false}"; }; ‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=63 ReplyCookie=39 Timestamp="Wed 2021-12-08 09:21:00.168771 UTC" Sender=:1.60 Destination=:1.55 UniqueName=:1.60 MESSAGE "s" { STRING "{"status": "Unknown", "status_id": "unknown", "reasons": {}, "reason_ids": {}, "valid": false}"; }; There are two EntitlementChanged signals, resulting in two GetStatus calls, and both calls return "valid": "false". A little while later, with no intervening EntitlementChanged signals, GetStatus returns the expected values: # busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Entitlement com.redhat.RHSM1.Entitlement GetStatus ss "" "" s "{\"status\": \"Current\", \"status_id\": \"valid\", \"reasons\": {}, \"reason_ids\": {}, \"valid\": true}" Expected results: With subscription-manager-1.28.21-3.el8.x86_64 in RHEL 8.5: ‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=63 Timestamp="Wed 2021-12-08 10:15:26.036652 UTC" Sender=:1.61 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=EntitlementChanged UniqueName=:1.61 MESSAGE "" { }; ‣ Type=method_call Endian=l Flags=4 Version=1 Priority=0 Cookie=38 Timestamp="Wed 2021-12-08 10:15:26.088188 UTC" Sender=:1.56 Destination=com.redhat.RHSM1 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=GetStatus UniqueName=:1.56 MESSAGE "ss" { STRING ""; STRING ""; }; ‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=64 Timestamp="Wed 2021-12-08 10:15:26.219226 UTC" Sender=:1.61 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=EntitlementChanged UniqueName=:1.61 MESSAGE "" { }; ‣ Type=method_call Endian=l Flags=4 Version=1 Priority=0 Cookie=39 Timestamp="Wed 2021-12-08 10:15:26.222655 UTC" Sender=:1.56 Destination=com.redhat.RHSM1 Path=/com/redhat/RHSM1/Entitlement Interface=com.redhat.RHSM1.Entitlement Member=GetStatus UniqueName=:1.56 MESSAGE "ss" { STRING ""; STRING ""; }; ‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=65 ReplyCookie=38 Timestamp="Wed 2021-12-08 10:15:26.277442 UTC" Sender=:1.61 Destination=:1.56 UniqueName=:1.61 MESSAGE "s" { STRING "{"status": "Current", "status_id": "valid", "reasons": {}, "reason_ids": {}, "valid": true}"; }; ‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=68 ReplyCookie=39 Timestamp="Wed 2021-12-08 10:15:26.804878 UTC" Sender=:1.61 Destination=:1.56 UniqueName=:1.61 MESSAGE "s" { STRING "{"status": "Current", "status_id": "valid", "reasons": {}, "reason_ids": {}, "valid": true}"; }; There are two signals, and GeStatus returns the expected values right away. Additional info: