2030265 – EntitlementChanged notification comes too early, GetStatus returns old data

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 2030265 - EntitlementChanged notification comes too early, GetStatus returns old data

Summary: EntitlementChanged notification comes too early, GetStatus returns old data

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Red Hat Enterprise Linux 8
Classification:	Red Hat
Component:	subscription-manager
Sub Component:
Version:	8.6
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	candlepin-bugs
QA Contact:	Red Hat subscription-manager QE Team
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2021-12-08 11:00 UTC by Marius Vollmer
Modified:	2022-03-25 10:20 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2022-02-03 05:54:30 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	cockpit-project bots issues 2701	0	None	closed	rhel-8-6: org.redhat.RHSM1 sends EntitlementChanged notification too early	2022-02-03 07:23:03 UTC
Red Hat Issue Tracker	RHELPLAN-105140	0	None	None	None	2021-12-08 11:02:02 UTC

Description Marius Vollmer 2021-12-08 11:00:57 UTC

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:

Comment 1 William Poteat 2022-01-14 21:08:12 UTC

Can we get a debug level capture of the rhsm.log while this process is happening, please?
Thanks

Comment 2 Marius Vollmer 2022-02-01 14:44:40 UTC

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.

Comment 3 Martin Pitt 2022-02-03 05:54:30 UTC

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

Comment 4 Marius Vollmer 2022-03-25 10:20:48 UTC

This looks similar: https://bugzilla.redhat.com/show_bug.cgi?id=2067129

Note You need to log in before you can comment on or make changes to this bug.