No valid bids or contextual ads available for scoring

[typerat]

Hi 👋

We're having trouble running a successful auction with bidding logic v3. We copied the file from here and set the appropriate header. The code seems to run, but the result is considered invalid for some reason. Any guidance into the right direction is highly appreciated 🙏

AdSelectionExecutionLogger starts.
Starting filtering and validation.
Asserting package name "com.example.publisher" is valid for uid 10185
Candidate package name "com.example.publisher"
Checking if API is throttled for package: com.example.publisher 
Checking if URI https://4265-1d-48-ae5-e3e.ngrok-free.app/ssp-mock/adl is of prebuilt schema: false
Prebuilt enabled flag: true
Validating decision logic URI
Completed filtering and validation.
Beginning Ad Selection Orchestration
Contextual flow is enabled, filtering contextual ads
Filtering contextual ads in Ad Selection Config
Start the bidding process.
The bidding process start timestamp is 16808023
With number of buyers requested: 4
End the get-buyers-custom-audience process.
The get-buyers-custom-audience process ends at 16808049 with num of buyers fetched 1:
Applying filters to 1 CAs with current time 2023-11-28T07:27:30.859646Z.
Filtering finished. 1 CAs of the original 1 remain. 2 Ads of the original 2 remain.
Starts the run-ad-bidding process.
Entering bidding NO of Ads: 2:, NO of CAs : 1
Created mapping for #1 buyers
Invoking bidding for #1 buyers
Running bid for #1 Custom Audiences for buyer: 4265-1d-48-ae5-e3e.ngrok-free.app
Fetching trusted bidding data for buyer: 4265-1d-48-ae5-e3e.ngrok-free.app
Filtering CA with dev override.
Bidding partition chunk size: 1
Keys are: {"test_key_1":null,"test_key_2":false}
Invoking bidding for CA: 12345
Running Ad Bidding for CA : 12345
Override for app 'com.example.publisher' and key (com.example.client,4265-1d-48-ae5-e3e.ngrok-free.app,12345): is null
Checking if URI https://4265-1d-48-ae5-e3e.ngrok-free.app/bl is of prebuilt schema: false
Prebuilt enabled flag: true
Fetching decision logic from the server with cache enabled is: true
Returning Cached results for Url: https://4265-1d-48-ae5-e3e.ngrok-free.app/bl
Got buyer bidding logic version 3
Fetching trusted bidding Signals from server
End the BiddingProcess with resultCode 0.
Ends of a successful run-ad-bidding process with num of CAs post bidding 0. with end timestamp: 16808331 
Log the AdRunBiddingProcessReportedStats to the AdServicesLog.
Got 1 total bidding outcomes
Got 0 valid bidding outcomes
Received empty list of successful bidding outcomes and contextual ads
Failed to send debug reports
Close failed ad selection and rethrow the RuntimeException java.lang.IllegalStateException: No valid bids or contextual ads available for scoring.
Log the RunAdSelectionProcessReportedStats to the AdServicesLog.
Log RunAdSelectionProcessReportedStats for a failed ad selection run.

[cshmerling]

Would you mind sharing the custom audience you are creating and the ads you are providing?

[typerat]

Hi @cshmerling here's the CA:

{
    "owner": "4265-1d-48-ae5-e3e.ngrok-free.app",
    "buyer": "4265-1d-48-ae5-e3e.ngrok-free.app",
    "name": "12345",
    "trusted_bidding_data": {
        "trusted_bidding_uri": "https://4265-1d-48-ae5-e3e.ngrok-free.app/tbs/get",
        "trusted_bidding_keys": [
            "test_key_1",
            "test_key_2"
        ]
    },
    "user_bidding_signals": {
        "placeholder": true
    },
    "ads": [
        {
            "render_uri": "https://4265-1d-48-ae5-e3e.ngrok-free.app/a/651ab1c46f",
            "metadata": {
                "d": "1000x1000",
                "m": 0
            }
        },
        {
            "render_uri": "https://4265-1d-48-ae5-e3e.ngrok-free.app/a/82938759",
            "metadata": {
                "d": "1000x1000",
                "m": 0
            }
        }
    ],
    "bidding_logic_uri": "https://4265-1d-48-ae5-e3e.ngrok-free.app/bl",
    "daily_update_uri": "https://4265-1d-48-ae5-e3e.ngrok-free.app/du?ca=12345",
    "activation_time": 1701163864000,
    "expiration_time": 1704531202000
}

While looking at it again, I noticed that owner should be the app package. Could that be the problem?

[cshmerling]

Ah, the owner field was removed in an update, and will be implicitly set to the package that is calling the API. Which leads me to the question:

Which version of the SDK are you using, and what emulator/device image are you using? Can just share a screenshot of your SDK Manager a la

Asking because up until this week, I believe the V3 bidding logic was only supported in Developer Preview. This week there was a new Beta released for Android 34 but we've not pushed the sample app updates just yet, so I'm thinking you might be in a weird state with the code you are running + the JavaScript trying to be executed.

[typerat]

Here's the screenshot:

And we're using system-images;android-UpsideDownCakePrivacySandbox;google_apis_playstore;arm64-v8a on an emulated Pixel 7 Pro. I just tried the Pixel 8 Pro, that has a different UI to enable Privacy Sandbox (separate switches for Topics, PAAPI, ARA) - is that the newer version we should be using?

[davidae]

@typerat @cshmerling

I'm experiencing the same issue.

[cshmerling]

@typerat looks like you are using the correct version of the SDK + device images. Unsure of why the 7 Pro and the 8 Pro would have a different consent UI, my only suspicion would be the 7 Pro was created with an older version of the device image.

In any case, @typerat @davidae can you enable verbose logging with

adb shell setprop log.tag.adservices.fledge VERBOSE

run the auction, and look at logcat for any adservices log? There will probably be a lot so feel free to post them here and I can take a look to see if anything stands out.

[typerat]

@cshmerling the logs above were obtained already with verbose logging enabled. Are you looking for something else?

Anyway, we now have a different problem. It seems you were right about the older version on the 7 Pro. I don't know what went wrong there, but I deleted all AVDs and created a new 7 Pro again today - now that one has the new consent UI (three settings) as well. But we can't get much further than that, as it tells us that Custom Audience API is disabled. Is there a new config flag we need to set for it to run again?

Edit: I found some new config flags in this comment. Wanted to try them, but now I'm only getting the old version of Privacy Sandbox regardless of how I create the AVD.

[typerat]

@cshmerling Ok, I now have the new version running on a Pixel 8 Pro, and getting more output (included CA joining this time):

12-12 15:30:32.964 10975 10975 V adservices.fledge: Initializing AdFilteringFeatureFactory with filtering enabled
12-12 15:30:32.968 10975 11177 V adservices.fledge: Entering joinCustomAudience
12-12 15:30:32.969 10975 11177 V adservices.fledge: Running service
12-12 15:30:32.969 10975 10991 V adservices.fledge: Entering doJoinCustomAudience
12-12 15:30:32.969 10975 10991 V adservices.fledge: Validating caller package name.
12-12 15:30:32.969 10975 10991 V adservices.fledge: Asserting package name "com.example.client" is valid for uid 10184
12-12 15:30:32.969 10975 10991 V adservices.fledge: Candidate package name "com.example.client"
12-12 15:30:32.969 10975 10991 V adservices.fledge: Validating API is not throttled.
12-12 15:30:32.969 10975 10991 V adservices.fledge: Checking if API is throttled for package: com.example.client 
12-12 15:30:32.969 10975 10991 V adservices.fledge: Checking caller is in foreground.
12-12 15:30:32.970 10975 10991 V adservices.fledge: Checking ad tech is allowed to use FLEDGE.
12-12 15:30:32.970 10975 10991 V adservices.fledge: Validating caller package is in allow list.
12-12 15:30:32.972 10975 10991 V adservices.fledge: Joining custom audience
12-12 15:30:32.972 10975 10991 V adservices.fledge: Validating CA limits
12-12 15:30:32.974 10975 10991 V adservices.fledge: Validating CA
12-12 15:30:32.976 10975 10991 V adservices.fledge: Inserting CA in the DB
12-12 15:30:32.981 10975 10991 V adservices.fledge: FLEDGE Background Fetch job already scheduled, skipping reschedule
12-12 15:30:33.063 10975 11177 V adservices.fledge: Entering joinCustomAudience
12-12 15:30:33.063 10975 11177 V adservices.fledge: Running service
12-12 15:30:33.063 10975 11049 V adservices.fledge: Entering doJoinCustomAudience
12-12 15:30:33.063 10975 11049 V adservices.fledge: Validating caller package name.
12-12 15:30:33.063 10975 11049 V adservices.fledge: Asserting package name "com.example.client" is valid for uid 10184
12-12 15:30:33.063 10975 11049 V adservices.fledge: Candidate package name "com.example.client"
12-12 15:30:33.063 10975 11049 V adservices.fledge: Validating API is not throttled.
12-12 15:30:33.063 10975 11049 V adservices.fledge: Checking if API is throttled for package: com.example.client 
12-12 15:30:33.063 10975 11049 V adservices.fledge: Checking caller is in foreground.
12-12 15:30:33.064 10975 11049 V adservices.fledge: Checking ad tech is allowed to use FLEDGE.
12-12 15:30:33.065 10975 11049 V adservices.fledge: Validating caller package is in allow list.
12-12 15:30:33.069 10975 11049 V adservices.fledge: Joining custom audience
12-12 15:30:33.069 10975 11049 V adservices.fledge: Validating CA limits
12-12 15:30:33.072 10975 11049 V adservices.fledge: Validating CA
12-12 15:30:33.075 10975 11049 V adservices.fledge: Inserting CA in the DB
12-12 15:30:33.081 10975 11049 V adservices.fledge: FLEDGE Background Fetch job already scheduled, skipping reschedule
12-12 15:30:45.876 10975 11177 V adservices.fledge: AdSelectionExecutionLogger starts.
12-12 15:30:45.881 10975 11097 V adservices.fledge: Starting filtering and validation.
12-12 15:30:45.881 10975 11097 V adservices.fledge: Asserting package name "com.example.publisher" is valid for uid 10185
12-12 15:30:45.881 10975 11097 V adservices.fledge: Candidate package name "com.example.publisher"
12-12 15:30:45.881 10975 11097 V adservices.fledge: Checking if API is throttled for package: com.example.publisher 
12-12 15:30:45.885 10975 11097 V adservices.fledge: Checking if URI https://4099-62-46-219-72.ngrok-free.app/ssp-mock/adl is of prebuilt schema: false
12-12 15:30:45.886 10975 11097 V adservices.fledge: Prebuilt enabled flag: true
12-12 15:30:45.886 10975 11097 V adservices.fledge: Validating decision logic URI
12-12 15:30:45.887 10975 11097 V adservices.fledge: Completed filtering and validation.
12-12 15:30:45.888 10975 11097 V adservices.fledge: Beginning Ad Selection Orchestration
12-12 15:30:45.888 10975 11097 V adservices.fledge: Contextual flow is enabled, filtering contextual ads
12-12 15:30:45.888 10975 11097 V adservices.fledge: Filtering contextual ads in Ad Selection Config
12-12 15:30:45.893 10975 11098 V adservices.fledge: Start the bidding process.
12-12 15:30:45.894 10975 11098 V adservices.fledge: The bidding process start timestamp is 2231829
12-12 15:30:45.894 10975 11098 V adservices.fledge: With number of buyers requested: 4
12-12 15:30:45.898 10975 11098 V adservices.fledge: End the get-buyers-custom-audience process.
12-12 15:30:45.898 10975 11098 V adservices.fledge: The get-buyers-custom-audience process ends at 2231834 with num of buyers fetched 1:
12-12 15:30:45.901 10975 11096 V adservices.fledge: Applying filters to 1 CAs with current time 2023-12-12T14:30:45.900820Z.
12-12 15:30:45.901 10975 11096 V adservices.fledge: Filtering finished. 1 CAs of the original 1 remain. 2 Ads of the original 2 remain.
12-12 15:30:45.901 10975 11096 V adservices.fledge: Starts the run-ad-bidding process.
12-12 15:30:45.902 10975 11096 V adservices.fledge: Entering bidding NO of Ads: 2:, NO of CAs : 1
12-12 15:30:45.903 10975 11096 V adservices.fledge: Created mapping for #1 buyers
12-12 15:30:45.903 10975 11096 V adservices.fledge: Invoking bidding for #1 buyers
12-12 15:30:45.912 10975 11096 V adservices.fledge: Running bid for #1 Custom Audiences for buyer: 4099-62-46-219-72.ngrok-free.app
12-12 15:30:45.912 10975 11096 V adservices.fledge: Fetching trusted bidding data for buyer: 4099-62-46-219-72.ngrok-free.app
12-12 15:30:45.912 10975 11096 V adservices.fledge: Filtering CA with dev override.
12-12 15:30:45.913 10975 11096 V adservices.fledge: Bidding partition chunk size: 1
12-12 15:30:45.967 10975 11097 V adservices.fledge: Keys are: {"3805__spend_adjustment":null,"51187__stop_bidding":false}
12-12 15:30:45.968 10975 10991 V adservices.fledge: Invoking bidding for CA: 51187
12-12 15:30:45.968 10975 10991 V adservices.fledge: Running Ad Bidding for CA : 51187
12-12 15:30:45.971 10975 11049 V adservices.fledge: Override for app 'com.example.publisher' and key (com.example.client,4099-62-46-219-72.ngrok-free.app,51187): is null
12-12 15:30:45.972 10975 11097 V adservices.fledge: Checking if URI https://4099-62-46-219-72.ngrok-free.app/bl#5467 is of prebuilt schema: false
12-12 15:30:45.973 10975 11097 V adservices.fledge: Prebuilt enabled flag: true
12-12 15:30:45.973 10975 11097 V adservices.fledge: Fetching decision logic from the server with cache enabled is: true
12-12 15:30:46.025 10975 11294 V adservices.fledge: Caching results for Url: https://4099-62-46-219-72.ngrok-free.app/bl#5467
12-12 15:30:46.029 10975 11096 V adservices.fledge: Got buyer bidding logic version 3
12-12 15:30:46.029 10975 11096 V adservices.fledge: Fetching trusted bidding Signals from server
12-12 15:30:46.092 10975 11097 V adservices.fledge: End the BiddingProcess with resultCode 0.
12-12 15:30:46.092 10975 11097 V adservices.fledge: Ends of a successful run-ad-bidding process with num of CAs post bidding 0. with end timestamp: 2232027 
12-12 15:30:46.092 10975 11097 V adservices.fledge: Log the AdRunBiddingProcessReportedStats to the AdServicesLog.
12-12 15:30:46.092 10975 11097 V adservices.fledge: Got 1 total bidding outcomes
12-12 15:30:46.092 10975 11097 V adservices.fledge: Got 0 valid bidding outcomes
12-12 15:30:46.092 10975 11097 W adservices.fledge: Received empty list of successful bidding outcomes and contextual ads
12-12 15:30:46.093 10975 11097 V adservices.fledge: Failed to send debug reports
12-12 15:30:46.093 10975 11097 V adservices.fledge: Close failed ad selection and rethrow the RuntimeException java.lang.IllegalStateException: No valid bids or contextual ads available for scoring.
12-12 15:30:46.093 10975 11097 V adservices.fledge: Log the RunAdSelectionProcessReportedStats to the AdServicesLog.
12-12 15:30:46.093 10975 11097 V adservices.fledge: Log RunAdSelectionProcessReportedStats for a failed ad selection run.
12-12 15:30:46.093 10975 11097 E adservices.fledge: Ad Selection failure: 
12-12 15:30:46.093 10975 11097 E adservices.fledge: java.lang.IllegalStateException: No valid bids or contextual ads available for scoring
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.android.adservices.service.adselection.OnDeviceAdSelectionRunner.runAdScoring(OnDeviceAdSelectionRunner.java:339)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.android.adservices.service.adselection.OnDeviceAdSelectionRunner.lambda$orchestrateAdSelection$3(OnDeviceAdSelectionRunner.java:235)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.android.adservices.service.adselection.OnDeviceAdSelectionRunner.$r8$lambda$sno90Tq562UAY___vPHJDn685dQ(OnDeviceAdSelectionRunner.java:0)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.android.adservices.service.adselection.OnDeviceAdSelectionRunner$$ExternalSyntheticLambda6.apply(R8$$SyntheticClass:0)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:221)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.google.common.util.concurrent.AbstractTransformFuture$AsyncTransformFuture.doTransform(AbstractTransformFuture.java:208)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:122)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
12-12 15:30:46.093 10975 11097 E adservices.fledge:     at java.lang.Thread.run(Thread.java:1012)
12-12 15:30:46.093 10975 11097 V adservices.fledge: Ad Selection failed with overall latency 220 in ms
12-12 15:30:46.096 11064 11298 E Publisher - Ad Selection:  at android.adservices.common.AdServicesStatusUtils.asException(AdServicesStatusUtils.java:203)
12-12 15:30:46.096 11064 11298 E Publisher - Ad Selection:  at android.adservices.common.AdServicesStatusUtils.asException(AdServicesStatusUtils.java:210)
12-12 15:30:46.096 11064 11298 E Publisher - Ad Selection:  at android.adservices.adselection.AdSelectionManager$3.lambda$onFailure$1(AdSelectionManager.java:317)
12-12 15:30:46.096 11064 11298 E Publisher - Ad Selection:  at android.adservices.adselection.AdSelectionManager$3$$ExternalSyntheticLambda1.run(Unknown Source:4)
12-12 15:30:55.918 10975 11125 V adservices.fledge: Total tasks: #1, cancelled incomplete tasks: #0

Is it possible that Filtering CA with dev override. is excluding the CA from the results?

[typerat]

I just found the error. The bidding logic was trying to access a field that wasn't available. The field userBiddingSignals of the custom_audience argument is apparently breaking with the convention of using camel_case for field names.

But my real question is: Can we please get some proper logs out of the auction? The message Got 1 total bidding outcomes is highly misleading when the code isn't even executed properly. At least something along the lines of error executing bidding logic would have saved us several weeks of aimless debugging.

[cshmerling]

I'm glad you were able to sort things out.

I am collecting a lot of instances like this and other GitHub issues showing that developers cannot debug simple issues like this with the existing logs. Will bring this back to the team and see what we can do. I can't promise any timelines, but it should not take X number of weeks of guess and check debugging to figure out simple issues like this.

[typerat]

One more question: Is there a way to disable caching of the bidding logic (for testing)?

[cshmerling]

There is a flag you can use to turn off caching- fledge_http_cache_enable_js_caching

So the command should be

adb shell device_config put adservices fledge_http_cache_enable_js_caching false

[cshmerling]

Marking this as resolved as it seems the questions were addressed.