Bid response times are sometimes wrong

[troels-jakobsen]

In addBidResponse() the bid response time is calculated as:

bid.timeToRespond = bid.responseTimestamp - bid.requestTimestamp;

... where bid.responseTimestamp is just set to Date.now(), and bid.requestTimestamp is found using getBidSetForBidder().

However, for some reason getBidSetForBidder() is sometimes unable to find the relevant bid and therefore returns an empty bid having requestTimestamp = 0. This results in bid.timeToRespond becoming the same as Date.now().

For instance, in my GA log for Sep 14 2016 I have a total response time = 1473859474633 for 1 bid.
Sep 14 2016 is (roughly) the same as new Date(1473859474633).
Likewise, for Sep 13 2016 I have a total response time = 17685185954321.
This is 12 occurrences of Sep 13 2016 dates.

The problem occurs with all of my adapters (adform, rubicon, pubmatic), using prebid 0.12.

[mkendall07]

@troels-jakobsen
Are you seeing inconsistent behavior from the same adapters? Meaning sometimes the bid is found and sometimes it's not?
Do you have an example page we can look at? Also what percentages of bids are not found?

[mkendall07]

@troels-jakobsen
This should be resolved when #509 is complete for all bidders.

[dugwood]

@mkendall07 @troels-jakobsen I have the same issue (I'm trying to fix many things, but it's getting harder and harder!).

In fact, when you have no bids at all (or if you set them to 0 with a floor price setting), then markComplete isn't fired... and all bids are kept.

Then when you hit requestTimestamp: getBidSetForBidder(bid.bidderCode).start, the test is only made on the bidderCode, in the order of bids. So you end up with the first bid run for this bidder, and so you mostly hit timeout.

@mkendall07 why do we keep all bids after the timeout expired or all bids are back? I don't understand this scenario, as every auction is separated from the other (auctionRunning set to true).
Why don't we clear the _bidsRequested and _bidsReceived completely?

[dugwood]

In fact I think there's a missing piece here: when a bid comes back from a bidder, we don't have anything to match it against the _bidsRequested.

Suppose you send out an auction, and a bidder doesn't answer in time, there's the timeout. Then the second auction starts... and the bidder finally answers: how can we know the bid is associated with the first auction and not the second? We just can't use bidderCode (can be in both auctions), adId can be a random value, and... that's all we have!
We should send out the requestId, which creates a uniqueness for each auction, and ask the adapter to send it back to addBidResponse (or to the bid object).

If we add the requestId, then we can ignore timed-out bids, we can then totally remove markComplete and removeComplete (which are not working correctly in my tests), and then change auctionRunning to auctionId which would create the requestId globally.

Can you just confirm me that Prebid never launches more than one auction at a time? If so, there's a lot of work to do (every adapter must be fixed!), but that would be far more easier in the future.

[dugwood]

Another option (but requestId should be the way to go, including for people who reload ads in the same zone), is to create separate _bidsRequested for each adUnitCode. So that we can find the real number of bids, depending on adUnitCodes.
So the auctionRunning will be set along with all adUnitCodes, and the final callback will look for adUnits that match the global adUnitCodes variable. If the same adUnitCode is used for another auction, the _bidsRequested will be deleted on this very code, and only this one.

I'll give it a try in 8 hours or so...

[dugwood]

Hooray! Build successful. #700

[dugwood]

#729 should fix this, as #700 was aborted (with very good reasons).

[mkendall07]

@dugwood
Appreciate the bug catches and PRs. We've been slowly working through a refactor that would allow having some semblance of concurrent auctions, but it has caused a lot of side effects that we cannot effectively handle due to missing identifiers on bids. We are most likely going to scrap the idea of multiple auctions for now and come back to it later (after we fixed the bugs).

[dugwood]

@mkendall07 the single auction seems good to me (had a lot of timeouts with multiple auctions from multiple bidders at the same time, along with all the images & static stuff loading on the page).
I didn't catch all the scenario while fixing things in #700, that's why I ended up on minor changes with @protonate review.
I must stress out the fact that I'm working with Criteo, and they only run one request for all adUnits, where some other run one (and sometimes 3 or 4!) requests per adUnit. So this is critical that auction is run alone, with as many adUnits as possible, for the bidders that do a great work of combining requests. This should almost be a negative score for those who run too many requests for one auction...

[protonate]

#736 will return the relevant bid by matching bidder and ad unit code. Please let us know if this resolves the issue you are seeing. If it is not resolved reopen ticket with additional info.