Loading...

Type: Task
Resolution: Unresolved
Priority: Critical
Fix Version/s: None
Affects Version/s: None
Component/s: swatch-tally
Labels:
None

Blocked:
False
Blocked Reason:

Hide

None

Show
None
Ready:
False
AssignedTeam:
subs-swatch-thunder
Intelligence Requested:
Market:

SFDC Cases Links:
SFDC Cases Open:
SFDC Cases Counter:

Per Lindsey: Keep this in NEW for now.

We need to fix a test that's failing randomly when it shouldn't.
The test test_verify_deduplication_remittance_different_event_source is experiencing flaky behavior in our ephemeral environment. This test validates that our system correctly deduplicates billable usage when the same host is reported from two different sources (cost-management and rhelemeter) with varying quantities. The test is parameterized to check both scenarios where the first event has a lower quantity than the second, and vice versa.

The failure is happening during the second tally sync operation, after creating the rhelemeter event. This is a critical test because it ensures we're billing customers correctly when we receive duplicate data from multiple sources - we should only charge for the maximum value, not sum them up.

The flaky nature of this test makes it unreliable and can block deployments or cause confusion about whether real bugs exist in the deduplication logic. We need to investigate the root cause and determine the best path forward.

Test:

application = <iqe.base.application.Application object at 0x7fc464501370>
quantities = [5, 15]

    @pytest.mark.ephemeral
    @pytest.mark.ephemeral_only
    @pytest.mark.parametrize("quantities", [[5, 15], [15, 5]])
    def test_verify_deduplication_remittance_different_event_source(application, quantities):
        """Verify dedup in billable usage for rhel payg products
        with same instance-id, timestamp and different event source (cost-management and rhelemeter)
        metadata:
            assignee: aunayak
            negative: false
            importance: high
            requirements: payg_tally
            test_steps:
                1. Reset the account
                2. Create mock offering events using internal api.
                3. Sync hourly tally.
                4. Ensure host's existence
                6. Create a new event from rhelmeter source for the same host
                7. Sync hourly tally
                8. Ensure host's existence
                9. Verify remittance api returns correct usage for all rhel aws products
    
            expected_results:
                1. Remittance value should be correct with host reported from two sources regardless
                   of relative quantities
        """
        application.rhsm_subscriptions.reset_account()
        product_id = "rhel-for-x86-els-payg-addon"
        billing_provider = "aws"
        metric = config_parser.get_swatch_metric_id_from_tag_metrics(product_id=product_id)[0]
        billing_account_id = "test" + fauxfactory.gen_alpha(3).lower()
        customer_id = str(uuid.uuid4())
        instance_name = "testHost" + fauxfactory.gen_alpha(3).lower()
        application.rhsm_subscriptions.create_mock_subscription(
            product_id=product_id,
            billing_provider=billing_provider,
            billing_account_id=billing_account_id,
            customer_id=customer_id,
            start_day=(datetime.date.today() - datetime.timedelta(days=10)).strftime("%Y-%m-%d"),
        )
    
        application.rhsm_subscriptions.rhsm_internal_api.billable_usage.flush_billable_usage_topic()
        # Create a cluster with event-source cost-management
        start_time = today()
        cost_management_data = {
            metric.lower(): quantities[0],
            "billing_provider": billing_provider,
            "billing_account_id": billing_account_id,
            "hours": 1,
            "event_source": "cost-management",
            "instance_uuid": instance_name,
            "start-time": start_time,
        }
        host_instance = application.rhsm_subscriptions.create_mock_payg_cluster(
            product_id=product_id, **cost_management_data
        )
        application.rhsm_subscriptions.sync_tally_hourly(
            product_id=product_id,
            metric_id=metric,
            perform_metering=False,
            wait=True,
            wait_for_remittance=True,
        )
    
        host = application.rhsm_subscriptions.search_system_table(
            product_id=product_id, display_name_contains=host_instance
        )
        assert host
    
        application.rhsm_subscriptions.rhsm_internal_api.billable_usage.flush_billable_usage_topic()
        # Again create another instance with event-source rhel-meter(with other details like instance-uuid, timestamp, etc. are same)
        rhelemeter_data = {
            metric.lower(): quantities[1],
            "billing_provider": billing_provider,
            "billing_account_id": billing_account_id,
            "hours": 1,
            "event_source": "rhelemeter",
            "instance_uuid": instance_name,
            "start-time": start_time,
        }
        host_instance = application.rhsm_subscriptions.create_mock_payg_cluster(
            product_id=product_id, **rhelemeter_data
        )
>       application.rhsm_subscriptions.sync_tally_hourly(
            product_id=product_id,
            metric_id=metric,
            perform_metering=False,
            wait=True,
            wait_for_remittance=quantities[0] < quantities[1],
            expected_remittance_status="succeeded",
            expected_remittance_value=max(quantities),
            expected_tally_increase=False,
        )

Output:

--------------------------------- Captured Log ---------------------------------
2025-11-24 06:59:49 INFO Using random seed value for random generation: 1959
2025-11-24 06:59:49 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 06:59:49 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 06:59:49 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 06:59:49 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 06:59:51 INFO Requesting DELETE http://swatch-contracts-service:8000/api/swatch-contracts/internal/rpc/reset/18939574
2025-11-24 06:59:51 INFO DELETE request response url: http://swatch-contracts-service:8000/api/swatch-contracts/internal/rpc/reset/18939574, status_code: 204
2025-11-24 06:59:51 INFO Trace log using : 00-7af32889a82f617812c010918a83c566-cb9d0062071285c2-01  
2025-11-24 06:59:51 INFO Not valid JSON output. Returning plain text message.
2025-11-24 06:59:51 INFO The action 'delete all data (contracts and subscriptions) for organization 18939574' succeeded with: <Response [204]>
2025-11-24 06:59:51 INFO Requesting DELETE http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/remittance/18939574
2025-11-24 06:59:51 INFO DELETE request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/remittance/18939574, status_code: 200
2025-11-24 06:59:51 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 06:59:51 INFO Remittances for organization 18939574 deleted.
2025-11-24 06:59:51 INFO Requesting DELETE http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/18939574
2025-11-24 06:59:51 INFO DELETE request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/18939574, status_code: 200
2025-11-24 06:59:51 INFO Trace log using : 00-c4d67c5419128e0f10d1721f49c6c59e-9218d69b8411483f-00  
2025-11-24 06:59:51 INFO Reset moto b'{"status": "ok"}'
2025-11-24 06:59:51 INFO SKUs for rhel-for-x86-els-payg-addon : ['RH02985HR']
2025-11-24 06:59:51 INFO Requesting PUT http://swatch-contracts-service:8000/api/swatch-contracts/internal/rpc/offerings/sync/RH02985HR
2025-11-24 06:59:51 INFO PUT request response url: http://swatch-contracts-service:8000/api/swatch-contracts/internal/rpc/offerings/sync/RH02985HR, status_code: 200
2025-11-24 06:59:51 INFO Trace log using : 00-b788f9ba1811f2ddaf955a1a9ea94b84-07b4ffa3216abd58-01  
2025-11-24 06:59:51 INFO Offering RH02985HR synced.
2025-11-24 06:59:51 INFO Requesting POST http://swatch-contracts-service:8000/api/swatch-contracts/internal/subscriptions?reconcileCapacity=true
2025-11-24 06:59:51 INFO POST request response url: http://swatch-contracts-service:8000/api/swatch-contracts/internal/subscriptions?reconcileCapacity=true, status_code: 200
2025-11-24 06:59:51 INFO Trace log using : 00-a7ab161d52885802216803507ce498c4-b64d7881d246eee8-01  
2025-11-24 06:59:51 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 06:59:51 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 06:59:51 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 06:59:51 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 06:59:53 INFO Adding payg events of org 18939574 ...
2025-11-24 06:59:53 INFO Requesting POST http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events
2025-11-24 06:59:53 INFO POST request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events, status_code: 200
2025-11-24 06:59:53 INFO Trace log using : 00-4a48c4ee1405beefe6bbd2f8c1f04851-41ef8c1215608708-00  
2025-11-24 06:59:53 INFO Requesting GET http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574
2025-11-24 06:59:53 INFO GET request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574?begin=2025-11-24T05%3A00%3A00Z&end=2025-11-24T06%3A00%3A00Z, status_code: 200
2025-11-24 06:59:53 INFO Trace log using : 00-016ab3418c4f675fb84bb4e0e881630c-3f532a3e6d660d6c-00  
2025-11-24 06:59:53 INFO Found events after saving: []
2025-11-24 06:59:54 INFO Requesting GET http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574
2025-11-24 06:59:54 INFO GET request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574?begin=2025-11-24T05%3A00%3A00Z&end=2025-11-24T06%3A00%3A00Z, status_code: 200
2025-11-24 06:59:54 INFO Trace log using : 00-f818eab2880e69f6a090d287f36e0ccf-aa85f24576901bc7-00  
2025-11-24 06:59:54 INFO Found events after saving: [
    {
        "billing_account_id": "testiem",
        "billing_provider": "aws",
        "cloud_provider": "AWS",
        "conversion": false,
        "display_name": "automation__cluster_testHostbfa",
        "event_id": "3c16aea7-a909-4e6c-8845-3e62a496a8fb",
        "event_source": "cost-management",
        "event_type": "vCPUs",
        "expiration": "2025-11-24T06:00:00Z",
        "hardware_type": "Cloud",
        "instance_id": "testHostbfa",
        "isHypervisor": false,
        "isUnmappedGuest": false,
        "isVirtual": false,
        "measurements": [
            {
                "metric_id": "vCPUs",
                "value": 5.0
            }
        ],
        "org_id": "18939574",
        "product_ids": [
            "204"
        ],
        "product_tag": [
            "rhel-for-x86-els-payg-addon"
        ],
        "record_date": "2025-11-24T06:59:53.958879383Z",
        "service_type": "RHEL System",
        "sla": "Premium",
        "timestamp": "2025-11-24T05:00:00Z",
        "usage": "Production"
    }
]
2025-11-24 06:59:54 INFO [{'event_source': 'cost-management', 'event_type': 'vCPUs', 'org_id': '18939574', 'instance_id': 'testHostbfa', 'timestamp': '2025-11-24T05:00:00Z', 'expiration': '2025-11-24T06:00:00Z', 'display_name': 'automation__cluster_testHostbfa', 'measurements': [{'value': 5, 'metric_id': 'vCPUs'}], 'sla': 'Premium', 'service_type': 'RHEL System', 'product_ids': ['204'], 'usage': 'Production', 'cloud_provider': 'AWS', 'hardware_type': 'Cloud', 'billing_provider': 'aws', 'billing_account_id': 'testiem'}]
2025-11-24 06:59:54 INFO rhel-for-x86-els-payg-addon PAYG Cluster testHostbfa created successfully!!
2025-11-24 06:59:54 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T03:00:00+00:00'), ('ending', '2025-11-24T10:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 06:59:54 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 06:59:54 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 06:59:54 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 06:59:54 INFO Requesting POST http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/tally/hourly
2025-11-24 06:59:54 INFO POST request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/tally/hourly?org=18939574&start=2025-11-24T03%3A00%3A00Z&end=2025-11-24T10%3A00%3A00Z, status_code: 204
2025-11-24 06:59:54 INFO Trace log using : 00-c9c26bf68f3d3c8e5948a0c1c64d23d9-dfedfe2a9d2b8ac9-00  
2025-11-24 06:59:54 INFO Not valid JSON output. Returning plain text message.
2025-11-24 06:59:54 INFO Tally synced from 2025-11-24T03:00:00Z to 2025-11-24T10:00:00Z.
2025-11-24 06:59:54 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T03:00:00+00:00'), ('ending', '2025-11-24T10:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 06:59:54 INFO Waiting for hourly tally sync completion...
2025-11-24 07:00:09 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T03:00:00+00:00'), ('ending', '2025-11-24T10:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 07:00:09 INFO Tally updated with increased value......
2025-11-24 07:00:09 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:09 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:09 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:09 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:11 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:11 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:11 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:11 INFO The action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value 'None', status 'None', and '{}'' succeeded with: [{'orgId': '18939574', 'productId': 'rhel-for-x86-els-payg-addon', 'metricId': 'vCPUs', 'billingProvider': 'aws', 'billingAccountId': 'testiem', 'remittedValue': 5.0, 'accumulationPeriod': '2025-11', 'remittanceDate': '2025-11-24T06:59:54.572398Z', 'remittanceStatus': 'succeeded', 'remittanceErrorCode': 'null'}]
2025-11-24 07:00:11 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/instances/products/rhel-for-x86-els-payg-addon with query params [('limit', 100), ('offset', 0), ('display_name_contains', 'testHostbfa')] and x-rh-insights-request-id=None
2025-11-24 07:00:11 INFO Found 1 hosts:
[{'id': '9324c8a6-6b23-409c-94a2-d4beea37893b', 'instance_id': 'testHostbfa', 'display_name': 'automation__cluster_testHostbfa', 'billing_provider': 'aws', 'billing_account_id': 'testiem', 'measurements': [5.0], 'last_seen': datetime.datetime(2025, 11, 24, 5, 0, tzinfo=tzlocal()), 'last_applied_event_record_date': datetime.datetime(2025, 11, 24, 6, 59, 53, 958879, tzinfo=tzlocal()), 'number_of_guests': 0, 'category': 'cloud', 'cloud_provider': 'aws', '_labeled_measurements': {'vCPUs': 5.0}}]
2025-11-24 07:00:11 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:11 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:11 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:11 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:13 INFO Adding payg events of org 18939574 ...
2025-11-24 07:00:13 INFO Requesting POST http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events
2025-11-24 07:00:13 INFO POST request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events, status_code: 200
2025-11-24 07:00:13 INFO Trace log using : 00-bd05616f2418e384c2790b6d022ce65e-413d04ef00a9cdc0-00  
2025-11-24 07:00:13 INFO Requesting GET http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574
2025-11-24 07:00:13 INFO GET request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574?begin=2025-11-24T06%3A00%3A00Z&end=2025-11-24T07%3A00%3A00Z, status_code: 200
2025-11-24 07:00:13 INFO Trace log using : 00-22fa784ad8835f1e78cbbfd114fdc054-6755a4a216c38be9-00  
2025-11-24 07:00:13 INFO Found events after saving: []
2025-11-24 07:00:14 INFO Requesting GET http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574
2025-11-24 07:00:14 INFO GET request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/rpc/tally/events/18939574?begin=2025-11-24T06%3A00%3A00Z&end=2025-11-24T07%3A00%3A00Z, status_code: 200
2025-11-24 07:00:14 INFO Trace log using : 00-ce60d0047cb3fdf6d73ebe3fc2fcfdc5-309207d3f0d94c32-00  
2025-11-24 07:00:14 INFO Found events after saving: [
    {
        "billing_account_id": "testiem",
        "billing_provider": "aws",
        "conversion": false,
        "display_name": "automation__cluster_testHostbfa",
        "event_id": "f4ecbe4b-7819-4c6a-8e48-8e8caf40ef51",
        "event_source": "rhelemeter",
        "event_type": "vCPUs",
        "expiration": "2025-11-24T07:00:00Z",
        "instance_id": "testHostbfa",
        "isHypervisor": false,
        "isUnmappedGuest": false,
        "isVirtual": false,
        "measurements": [
            {
                "metric_id": "vCPUs",
                "value": 15.0
            }
        ],
        "org_id": "18939574",
        "product_ids": [
            "204"
        ],
        "product_tag": [
            "rhel-for-x86-els-payg-addon"
        ],
        "record_date": "2025-11-24T07:00:13.609382538Z",
        "service_type": "RHEL System",
        "sla": "Premium",
        "timestamp": "2025-11-24T06:00:00Z"
    }
]
2025-11-24 07:00:14 INFO [{'event_source': 'rhelemeter', 'event_type': 'vCPUs', 'org_id': '18939574', 'instance_id': 'testHostbfa', 'timestamp': '2025-11-24T06:00:00Z', 'expiration': '2025-11-24T07:00:00Z', 'display_name': 'automation__cluster_testHostbfa', 'measurements': [{'value': 15, 'metric_id': 'vCPUs'}], 'sla': 'Premium', 'service_type': 'RHEL System', 'product_ids': ['204'], 'billing_provider': 'aws', 'billing_account_id': 'testiem'}]
2025-11-24 07:00:14 INFO rhel-for-x86-els-payg-addon PAYG Cluster testHostbfa created successfully!!
2025-11-24 07:00:14 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T04:00:00+00:00'), ('ending', '2025-11-24T11:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 07:00:14 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:14 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:14 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:14 INFO Requesting POST http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/tally/hourly
2025-11-24 07:00:14 INFO POST request response url: http://swatch-tally-service:8000/api/rhsm-subscriptions/v1/internal/tally/hourly?org=18939574&start=2025-11-24T04%3A00%3A00Z&end=2025-11-24T11%3A00%3A00Z, status_code: 204
2025-11-24 07:00:14 INFO Trace log using : 00-56d06bcc9ae9ab444518a31aaa85e893-63990dc3fbb3a2ad-00  
2025-11-24 07:00:14 INFO Not valid JSON output. Returning plain text message.
2025-11-24 07:00:14 INFO Tally synced from 2025-11-24T04:00:00Z to 2025-11-24T11:00:00Z.
2025-11-24 07:00:14 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T04:00:00+00:00'), ('ending', '2025-11-24T11:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 07:00:14 INFO Waiting for hourly tally sync completion...
2025-11-24 07:00:29 INFO REST: GET http://swatch-api-nginx-proxy.ephemeral-fchaeb.svc:8000/api/rhsm-subscriptions/v1/tally/products/rhel-for-x86-els-payg-addon/vCPUs with query params [('billing_account_id', '_ANY'), ('billing_provider', '_ANY'), ('granularity', 'Hourly'), ('beginning', '2025-11-24T04:00:00+00:00'), ('ending', '2025-11-24T11:00:00+00:00')] and x-rh-insights-request-id=None
2025-11-24 07:00:29 INFO Tally updated with increased value......
2025-11-24 07:00:29 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:29 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:29 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:29 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:31 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:31 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:31 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:31 WARNING Action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}'' failed with error 'New remittance records do not match expected sum of 15. Found 20.0
assert 20.0 == 15'. Retrying...
2025-11-24 07:00:36 WARNING Retrying 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}''...
2025-11-24 07:00:36 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:36 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:36 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:36 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:38 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:38 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:38 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:38 WARNING Action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}'' failed with error 'New remittance records do not match expected sum of 15. Found 20.0
assert 20.0 == 15'. Retrying...
2025-11-24 07:00:43 WARNING Retrying 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}''...
2025-11-24 07:00:43 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:43 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:43 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:43 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:45 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:45 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:45 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:45 WARNING Action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}'' failed with error 'New remittance records do not match expected sum of 15. Found 20.0
assert 20.0 == 15'. Retrying...
2025-11-24 07:00:50 WARNING Retrying 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}''...
2025-11-24 07:00:50 INFO Flushing usage messages off from billable usage kafka topic
2025-11-24 07:00:50 INFO Requesting PUT http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush
2025-11-24 07:00:50 INFO PUT request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/rpc/topics/flush, status_code: 200
2025-11-24 07:00:50 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:52 INFO Requesting GET http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs
2025-11-24 07:00:52 INFO GET request response url: http://swatch-billable-usage-service:8000/api/swatch-billable-usage/internal/remittance/accountRemittances?productId=rhel-for-x86-els-payg-addon&orgId=18939574&metricId=vCPUs, status_code: 200
2025-11-24 07:00:52 INFO Trace log using : 00-00000000000000000000000000000000-0000000000000000-00  
2025-11-24 07:00:52 WARNING Action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}'' failed with error 'New remittance records do not match expected sum of 15. Found 20.0
assert 20.0 == 15'. Retrying...
2025-11-24 07:00:53 WARNING Execution of job "fetch_and_load_features (trigger: interval[0:00:01], next run at: 2025-11-24 07:00:53 UTC)" skipped: maximum number of running instances reached (1)
2025-11-24 07:00:57 ERROR The action 'wait for remittances for 'rhel-for-x86-els-payg-addon', 'vCPUs', expected value '15', status 'succeeded', and '{}'' was not completed within the timeout period. Last result was '[{'orgId': '18939574', 'productId': 'rhel-for-x86-els-payg-addon', 'metricId': 'vCPUs', 'billingProvider': 'aws', 'billingAccountId': 'testiem', 'remittedValue': 20.0, 'accumulationPeriod': '2025-11', 'remittanceDate': '2025-11-24T07:00:14.204422Z', 'remittanceStatus': 'succeeded', 'remittanceErrorCode': 'null'}]'. 
2025-11-24 07:00:57 INFO select version()
2025-11-24 07:00:57 INFO [raw sql] {}
2025-11-24 07:00:57 INFO select current_schema()
2025-11-24 07:00:57 INFO [raw sql] {}
2025-11-24 07:00:57 INFO show standard_conforming_strings
2025-11-24 07:00:57 INFO [raw sql] {}
2025-11-24 07:00:57 INFO BEGIN (implicit)
2025-11-24 07:00:57 INFO select * from events where org_id=%(org_id)s
2025-11-24 07:00:57 INFO [generated in 0.00020s] {'org_id': '18939574'}
2025-11-24 07:00:57 INFO Event record: {'event_id': UUID('3c16aea7-a909-4e6c-8845-3e62a496a8fb'), 'timestamp': datetime.datetime(2025, 11, 24, 5, 0, tzinfo=datetime.timezone.utc), 'data': {'sla': 'Premium', 'usage': 'Production', 'org_id': '18939574', 'event_id': '3c16aea7-a909-4e6c-8845-3e62a496a8fb', 'isVirtual': False, 'timestamp': '2025-11-24T05:00:00Z', 'conversion': False, 'event_type': 'vCPUs', 'expiration': '2025-11-24T06:00:00Z', 'instance_id': 'testHostbfa', 'product_ids': ['204'], 'product_tag': ['rhel-for-x86-els-payg-addon'], 'record_date': '2025-11-24T06:59:53.958879383Z', 'display_name': 'automation__cluster_testHostbfa', 'event_source': 'cost-management', 'isHypervisor': False, 'measurements': [{'value': 5.0, 'metric_id': 'vCPUs'}], 'service_type': 'RHEL System', 'hardware_type': 'Cloud', 'cloud_provider': 'AWS', 'isUnmappedGuest': False, 'billing_provider': 'aws', 'billing_account_id': 'testiem'}, 'event_type': 'vCPUs', 'event_source': 'cost-management', 'instance_id': 'testHostbfa', 'org_id': '18939574', 'metering_batch_id': None, 'record_date': datetime.datetime(2025, 11, 24, 6, 59, 53, 958879, tzinfo=datetime.timezone.utc)}
2025-11-24 07:00:57 INFO Event record: {'event_id': UUID('f4ecbe4b-7819-4c6a-8e48-8e8caf40ef51'), 'timestamp': datetime.datetime(2025, 11, 24, 6, 0, tzinfo=datetime.timezone.utc), 'data': {'sla': 'Premium', 'org_id': '18939574', 'event_id': 'f4ecbe4b-7819-4c6a-8e48-8e8caf40ef51', 'isVirtual': False, 'timestamp': '2025-11-24T06:00:00Z', 'conversion': False, 'event_type': 'vCPUs', 'expiration': '2025-11-24T07:00:00Z', 'instance_id': 'testHostbfa', 'product_ids': ['204'], 'product_tag': ['rhel-for-x86-els-payg-addon'], 'record_date': '2025-11-24T07:00:13.609382538Z', 'display_name': 'automation__cluster_testHostbfa', 'event_source': 'rhelemeter', 'isHypervisor': False, 'measurements': [{'value': 15.0, 'metric_id': 'vCPUs'}], 'service_type': 'RHEL System', 'isUnmappedGuest': False, 'billing_provider': 'aws', 'billing_account_id': 'testiem'}, 'event_type': 'vCPUs', 'event_source': 'rhelemeter', 'instance_id': 'testHostbfa', 'org_id': '18939574', 'metering_batch_id': None, 'record_date': datetime.datetime(2025, 11, 24, 7, 0, 13, 609383, tzinfo=datetime.timezone.utc)}
2025-11-24 07:00:57 INFO select s.*,m.* from tally_snapshots s  inner join tally_measurements m on s.id=m.snapshot_id  where s.org_id=%(org_id)s and s.granularity='HOURLY' and m.measurement_type != 'TOTAL' and s.sla != '_ANY'  and s.usage != '_ANY' and s.billing_provider != '_ANY' and s.billing_account_id != '_ANY' 
2025-11-24 07:00:57 INFO [generated in 0.00021s] {'org_id': '18939574'}
2025-11-24 07:00:57 INFO Tally snapshot record: {'id': UUID('217f64f6-787f-41f0-8244-b10539c2cf24'), 'product_id': 'rhel-for-x86-els-payg-addon', 'granularity': 'HOURLY', 'org_id': '18939574', 'snapshot_date': datetime.datetime(2025, 11, 24, 5, 0, tzinfo=datetime.timezone.utc), 'unit_of_measure': None, 'sla': 'Premium', 'usage': 'Production', 'billing_provider': 'aws', 'billing_account_id': 'testiem', 'snapshot_id': UUID('217f64f6-787f-41f0-8244-b10539c2cf24'), 'measurement_type': 'AWS', 'metric_id': 'VCPUS', 'value': 5.0}
2025-11-24 07:00:57 INFO Tally snapshot record: {'id': UUID('8f0a8ed3-cadd-4dc9-91d1-c26f0117939b'), 'product_id': 'rhel-for-x86-els-payg-addon', 'granularity': 'HOURLY', 'org_id': '18939574', 'snapshot_date': datetime.datetime(2025, 11, 24, 6, 0, tzinfo=datetime.timezone.utc), 'unit_of_measure': None, 'sla': 'Premium', 'usage': 'Production', 'billing_provider': 'aws', 'billing_account_id': 'testiem', 'snapshot_id': UUID('8f0a8ed3-cadd-4dc9-91d1-c26f0117939b'), 'measurement_type': 'PHYSICAL', 'metric_id': 'VCPUS', 'value': 15.0}
2025-11-24 07:00:57 INFO select * from billable_usage_remittance where org_id=%(org_id)s
2025-11-24 07:00:57 INFO [generated in 0.00020s] {'org_id': '18939574'}
2025-11-24 07:00:57 INFO Remittance record: {'account_number': None, 'org_id': '18939574', 'product_id': 'rhel-for-x86-els-payg-addon', 'metric_id': 'vCPUs', 'accumulation_period': '2025-11', 'sla': 'Premium', 'usage': 'Production', 'billing_provider': 'aws', 'billing_account_id': 'testiem', 'remitted_pending_value': 5.0, 'remittance_pending_date': datetime.datetime(2025, 11, 24, 6, 59, 54, 572398, tzinfo=datetime.timezone.utc), 'retry_after': None, 'tally_id': UUID('217f64f6-787f-41f0-8244-b10539c2cf24'), 'uuid': UUID('32adb5e0-10b9-4de7-8be5-0efb1b2a85d4'), 'billed_on': datetime.datetime(2025, 11, 24, 7, 0, 2, 693205, tzinfo=datetime.timezone.utc), 'error_code': None, 'status': 'succeeded', 'updated_at': datetime.datetime(2025, 11, 24, 7, 0, 2, 702788)}
2025-11-24 07:00:57 INFO Remittance record: {'account_number': None, 'org_id': '18939574', 'product_id': 'rhel-for-x86-els-payg-addon', 'metric_id': 'vCPUs', 'accumulation_period': '2025-11', 'sla': 'Premium', 'usage': 'Production', 'billing_provider': 'aws', 'billing_account_id': 'testiem', 'remitted_pending_value': 15.0, 'remittance_pending_date': datetime.datetime(2025, 11, 24, 7, 0, 14, 204422, tzinfo=datetime.timezone.utc), 'retry_after': None, 'tally_id': UUID('8f0a8ed3-cadd-4dc9-91d1-c26f0117939b'), 'uuid': UUID('b3156d03-1242-4d13-b4b8-8a9ea0122717'), 'billed_on': datetime.datetime(2025, 11, 24, 7, 0, 29, 935168, tzinfo=datetime.timezone.utc), 'error_code': None, 'status': 'succeeded', 'updated_at': datetime.datetime(2025, 11, 24, 7, 0, 29, 946857)}
--------------------------------- Captured Out ---------------------------------
2025-11-24 07:00:57,287 INFO sqlalchemy.engine.Engine select version()
2025-11-24 07:00:57,287 INFO sqlalchemy.engine.Engine [raw sql] {}
2025-11-24 07:00:57,288 INFO sqlalchemy.engine.Engine select current_schema()
2025-11-24 07:00:57,288 INFO sqlalchemy.engine.Engine [raw sql] {}
2025-11-24 07:00:57,289 INFO sqlalchemy.engine.Engine show standard_conforming_strings
2025-11-24 07:00:57,289 INFO sqlalchemy.engine.Engine [raw sql] {}
2025-11-24 07:00:57,290 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2025-11-24 07:00:57,290 INFO sqlalchemy.engine.Engine select * from events where org_id=%(org_id)s
2025-11-24 07:00:57,291 INFO sqlalchemy.engine.Engine [generated in 0.00020s] {'org_id': '18939574'}
2025-11-24 07:00:57,293 INFO sqlalchemy.engine.Engine select s.*,m.* from tally_snapshots s  inner join tally_measurements m on s.id=m.snapshot_id  where s.org_id=%(org_id)s and s.granularity='HOURLY' and m.measurement_type != 'TOTAL' and s.sla != '_ANY'  and s.usage != '_ANY' and s.billing_provider != '_ANY' and s.billing_account_id != '_ANY' 
2025-11-24 07:00:57,293 INFO sqlalchemy.engine.Engine [generated in 0.00021s] {'org_id': '18939574'}
2025-11-24 07:00:57,295 INFO sqlalchemy.engine.Engine select * from billable_usage_remittance where org_id=%(org_id)s
2025-11-24 07:00:57,295 INFO sqlalchemy.engine.Engine [generated in 0.00020s] {'org_id': '18939574'}

Acceptance Criteria

Investigate why the test fails intermittently (timing issues, environment dependencies, race conditions, etc.)
Determine whether the issue is in the test implementation or reveals an actual product bug
Evaluate if this test would be more stable as a component test in swatch-tally rather than an integration test
Either fix the flaky behavior to make the test reliable, or migrate it to a component test in swatch-tally

mentioned on

Merge request - SWATCH-4286: Mark test_verify_deduplication_remittance_different_event_source...

Details

Description

Acceptance Criteria

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates