Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Inline-content ads are empty #20658

Closed
stephendonner opened this issue Jan 24, 2022 · 13 comments · Fixed by brave/brave-core#12021
Closed

Inline-content ads are empty #20658

stephendonner opened this issue Jan 24, 2022 · 13 comments · Fixed by brave/brave-core#12021

Comments

@stephendonner
Copy link

Description

Inline-content ads are empty

Steps to reproduce

  1. install 1.36.63
  2. launch Brave
  3. tap through onboarding
  4. restart (to pick up Griffin Brave News seed)
  5. open a new-tab page
  6. tap to Show Brave News
  7. swipe down
  8. look for the BAT-icon-marked ads

Actual result

They are empty, without content.

example example
Screenshot_20220124-121928
mobizen_20220124_122512.mp4

Expected result

Should have a heading/title, source attribution, and of course the larger content image.

Issue reproduces how often

100%

Device details

  • Install type (ARM, x86): arm64
  • Device type (Phone, Tablet, Phablet): Google Pixel XL phone
  • Android version: 9.0

Brave version

1.36.63, Chromium 97.0.5692.99

cc @alexsafe @srirambv @btlechowski @mattmcalister

@stephendonner
Copy link
Author

cc @petemill @tmancey also desktop, same build

desktop-no-ads

@tmancey tmancey self-assigned this Jan 24, 2022
@tmancey tmancey removed their assignment Jan 24, 2022
@stephendonner
Copy link
Author

Feels like this might just be an issue with something in production, server-side?

2022-01-24 14:01:38.488 22564-22564/? V/chromium: [VERBOSE1:inline_content_ad_serving.cc(129)] Serving inline content ad:
      uuid: 65c21264-ea91-4e6c-ab9b-03d8cc728103
      creativeInstanceId: 
      creativeSetId: 
      campaignId: 
      advertiserId: 
      segment: 
      title: 
      description: 
      imageUrl: 
      dimensions: 
      ctaText: 
      targetUrl: 
2022-01-24 14:01:38.488 22564-22564/? V/chromium: [VERBOSE1:inline_content_ad.cc(42)] Failed to fire inline content ad event due to invalid uuid 65c21264-ea91-4e6c-ab9b-03d8cc728103 or creative instance id 
2022-01-24 14:01:38.488 22564-22564/? V/chromium: [VERBOSE1:ads_impl.cc(900)] Failed to fire inline content ad kServed event for uuid 65c21264-ea91-4e6c-ab9b-03d8cc728103 and creative instance id 
2022-01-24 14:01:38.488 22564-22564/? V/chromium: [VERBOSE1:inline_content_ad_serving.cc(98)] Served inline content ad

@tmancey
Copy link
Contributor

tmancey commented Jan 26, 2022

Caused by:

[85514:259:0126/125330.039440:FATAL:brave_news.mojom.cc(2244)] Check failed: !connected. BraveNewsController::GetDisplayAdCallback was destroyed without first either being run or its corresponding binding being closed. It is an error to drop response callbacks which still correspond to an open interface pipe.
0   libbase.dylib                       0x000000010bffa809 base::debug::CollectStackTrace(void**, unsigned long) + 9
1   libbase.dylib                       0x000000010bbe68d3 base::debug::StackTrace::StackTrace() + 19
2   libbase.dylib                       0x000000010bc721d5 logging::LogMessage::~LogMessage() + 1061
3   libbase.dylib                       0x000000010bc74d8e logging::LogMessage::~LogMessage() + 14
4   libchrome_dll.dylib                 0x0000000135017ea1 brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder::OnIsConnectedComplete(bool) + 305
5   libbindings.dylib                   0x0000000109e47c61 mojo::(anonymous namespace)::ResponderThunk::IsConnectedAsync(base::OnceCallback<void (bool)>) + 1265
6   libchrome_dll.dylib                 0x0000000135017829 std::__Cr::unique_ptr<brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder, std::__Cr::default_delete<brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder> >::~unique_ptr() + 425
7   libchrome_dll.dylib                 0x0000000135017d47 base::internal::BindState<void (brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder::*)(mojo::StructPtr<brave_news::mojom::DisplayAd>), std::__Cr::unique_ptr<brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder, std::__Cr::default_delete<brave_news::mojom::BraveNewsController_GetDisplayAd_ProxyToResponder> > >::Destroy(base::internal::BindStateBase const*) + 23
8   libchrome_dll.dylib                 0x000000013d7f8097 _ZN4base8internal9BindStateIZN10brave_news19BraveNewsController12GetDisplayAdENS_12OnceCallbackIFvN4mojo9StructPtrINS2_5mojom9DisplayAdEEEEEEE3$_3JSB_EE7DestroyEPKNS0_13BindStateBaseE + 23
9   libchrome_dll.dylib                 0x0000000136588437 base::internal::BindState<void (brave_ads::AdsServiceImpl::*)(base::OnceCallback<void (bool, std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char> > const&, base::DictionaryValue const&)>, bool, std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char> > const&, std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char> > const&), base::WeakPtr<brave_ads::AdsServiceImpl>, base::OnceCallback<void (bool, std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char> > const&, base::DictionaryValue const&)> >::Destroy(base::internal::BindStateBase const*) + 23
10  libchrome_dll.dylib                 0x0000000135408775 bat_ads::mojom::BatAds_GetInlineContentAd_ForwardToCallback::~BatAds_GetInlineContentAd_ForwardToCallback() + 53
11  libbindings.dylib                   0x0000000109e3c686 std::__Cr::__tree<std::__Cr::__value_type<unsigned long long, std::__Cr::unique_ptr<mojo::MessageReceiver, std::__Cr::default_delete<mojo::MessageReceiver> > >, std::__Cr::__map_value_compare<unsigned long long, std::__Cr::__value_type<unsigned long long, std::__Cr::unique_ptr<mojo::MessageReceiver, std::__Cr::default_delete<mojo::MessageReceiver> > >, std::__Cr::less<unsigned long long>, true>, std::__Cr::allocator<std::__Cr::__value_type<unsigned long long, std::__Cr::unique_ptr<mojo::MessageReceiver, std::__Cr::default_delete<mojo::MessageReceiver> > > > >::destroy(std::__Cr::__tree_node<std::__Cr::__value_type<unsigned long long, std::__Cr::unique_ptr<mojo::MessageReceiver, std::__Cr::default_delete<mojo::MessageReceiver> > >, void*>*) + 166
12  libbindings.dylib                   0x0000000109e36af2 mojo::InterfaceEndpointClient::~InterfaceEndpointClient() + 578
13  libbindings.dylib                   0x0000000109e36cae mojo::InterfaceEndpointClient::~InterfaceEndpointClient() + 14
14  libchrome_dll.dylib                 0x0000000136552f2a brave_ads::AdsServiceImpl::Shutdown() + 858
15  libchrome_dll.dylib                 0x0000000136556121 brave_ads::AdsServiceImpl::MaybeStart(bool) + 673
16  libchrome_dll.dylib                 0x0000000136585648 base::internal::Invoker<base::internal::BindState<void (brave_ads::AdsServiceImpl::*)(bool), base::WeakPtr<brave_ads::AdsServiceImpl>, bool>, void ()>::RunOnce(base::internal::BindStateBase*) + 472
17  libbindings.dylib                   0x0000000109e3aaf8 mojo::InterfaceEndpointClient::NotifyError(absl::optional<mojo::DisconnectReason> const&) + 1048
18  libbindings.dylib                   0x0000000109e6168f mojo::internal::MultiplexRouter::ProcessNotifyErrorTask(mojo::internal::MultiplexRouter::Task*, mojo::internal::MultiplexRouter::ClientCallBehavior, base::SequencedTaskRunner*) + 1679
19  libbindings.dylib                   0x0000000109e5654f mojo::internal::MultiplexRouter::ProcessTasks(mojo::internal::MultiplexRouter::ClientCallBehavior, base::SequencedTaskRunner*) + 1007
20  libbindings.dylib                   0x0000000109e51c99 mojo::internal::MultiplexRouter::OnPipeConnectionError(bool) + 2985
21  libbindings.dylib                   0x0000000109e19d74 mojo::Connector::HandleError(bool, bool) + 1076
22  libbindings.dylib                   0x0000000109e1d85b mojo::Connector::OnWatcherHandleReady(unsigned int) + 235
23  libbindings.dylib                   0x0000000109e1f697 mojo::SimpleWatcher::DiscardReadyState(base::RepeatingCallback<void (unsigned int)> const&, unsigned int, mojo::HandleSignalsState const&) + 311
24  libmojo_public_system_cpp.dylib     0x0000000109f3f00d mojo::SimpleWatcher::OnHandleReady(int, unsigned int, mojo::HandleSignalsState const&) + 1165
25  libmojo_public_system_cpp.dylib     0x0000000109f401c3 base::internal::Invoker<base::internal::BindState<void (mojo::SimpleWatcher::*)(int, unsigned int, mojo::HandleSignalsState const&), base::WeakPtr<mojo::SimpleWatcher>, int, unsigned int, mojo::HandleSignalsState>, void ()>::RunOnce(base::internal::BindStateBase*) + 499
26  libbase.dylib                       0x000000010be5a743 base::TaskAnnotator::RunTaskImpl(base::PendingTask&) + 947
27  libbase.dylib                       0x000000010bedd23a base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl(base::sequence_manager::LazyNow*) + 2506
28  libbase.dylib                       0x000000010bedbe77 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork() + 375
29  libbase.dylib                       0x000000010bede3b2 non-virtual thunk to base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork() + 18
30  libbase.dylib                       0x000000010c06bcd1 base::MessagePumpCFRunLoopBase::RunWork() + 401
31  libbase.dylib                       0x000000010c04372a base::mac::CallWithEHFrame(void () block_pointer) + 10
32  libbase.dylib                       0x000000010c06a2e6 base::MessagePumpCFRunLoopBase::RunDelayedWorkTimer(__CFRunLoopTimer*, void*) + 374
33  CoreFoundation                      0x00007ff81e59d84f __CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__ + 20
34  CoreFoundation                      0x00007ff81e59d33e __CFRunLoopDoTimer + 927
35  CoreFoundation                      0x00007ff81e59ce9d __CFRunLoopDoTimers + 307
36  CoreFoundation                      0x00007ff81e58345f __CFRunLoopRun + 1985
37  CoreFoundation                      0x00007ff81e5825dd CFRunLoopRunSpecific + 563
38  HIToolbox                           0x00007ff8271b54f1 RunCurrentEventLoopInMode + 292
39  HIToolbox                           0x00007ff8271b5247 ReceiveNextEventCommon + 587
40  HIToolbox                           0x00007ff8271b4fe5 _BlockUntilNextEventMatchingListInModeWithFilter + 70
41  AppKit                              0x00007ff820fb1b4c _DPSNextEvent + 886
42  AppKit                              0x00007ff820fb01b8 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 1411
43  libchrome_dll.dylib                 0x0000000135bd8a43 __71-[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:]_block_invoke + 403
44  libbase.dylib                       0x000000010c04372a base::mac::CallWithEHFrame(void () block_pointer) + 10
45  libchrome_dll.dylib                 0x0000000135bd85db -[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 811
46  AppKit                              0x00007ff820fa25a9 -[NSApplication run] + 586
47  libbase.dylib                       0x000000010c06f00b base::MessagePumpNSApplication::DoRun(base::MessagePump::Delegate*) + 987
48  libbase.dylib                       0x000000010c068b39 base::MessagePumpCFRunLoopBase::Run(base::MessagePump::Delegate*) + 521
49  libbase.dylib                       0x000000010bedf1dd base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run(bool, base::TimeDelta) + 1501
50  libbase.dylib                       0x000000010bd96dd9 base::RunLoop::Run(base::Location const&) + 2553
51  libcontent.dylib                    0x000000012a3b8e73 content::BrowserMainLoop::RunMainMessageLoop() + 563
52  libcontent.dylib                    0x000000012a3be11a content::BrowserMainRunnerImpl::Run() + 394
53  libcontent.dylib                    0x000000012a3b19bb content::BrowserMain(content::MainFunctionParams) + 923
54  libcontent.dylib                    0x000000012ceb72f2 content::RunBrowserProcessMain(content::MainFunctionParams, content::ContentMainDelegate*) + 690
55  libcontent.dylib                    0x000000012cebb0ff content::ContentMainRunnerImpl::RunBrowser(content::MainFunctionParams, bool) + 3183
56  libcontent.dylib                    0x000000012ceba207 content::ContentMainRunnerImpl::Run() + 1175
57  libcontent.dylib                    0x000000012ceb3ed9 content::RunContentProcess(content::ContentMainParams, content::ContentMainRunner*) + 1337
58  libcontent.dylib                    0x000000012ceb5fd2 content::ContentMain(content::ContentMainParams) + 242
59  libchrome_dll.dylib                 0x000000013148a3d9 ChromeMain + 585
60  Brave Browser Development           0x0000000109be9b96 main + 518
61  dyld                                0x0000000118f5e4fe start + 462
Task trace:
0   libmojo_public_system_cpp.dylib     0x0000000109f3fc0e mojo::SimpleWatcher::Context::Notify(unsigned int, MojoHandleSignalsState, unsigned int) + 1102
Crash keys:
  "ui_scheduler_async_stack" = "0x109F3FC0E 0x0"
  "num-extensions" = "0"
  "io_scheduler_async_stack" = "0x14F0DBCE5 0x0"
  "switch-17" = "--variations-insecure-server-url"
  "switch-16" = "--lso-url=https://no-thanks.invalid"
  "switch-15" = "--sync-url"
  "switch-14" = "--origin-trial-public-key=bYUKPJoPnCxeNvu72j4EmPuK7tr1PAC7SHh8ld"
  "switch-13" = "--component-updater=url-source=https://go-updater-dev.bravesoftw"
  "switch-12" = "--no-pings"
  "switch-11" = "--enable-dom-distiller"
  "switch-10" = "--disable-domain-reliability"
  "switch-9" = "--disable-client-side-phishing-detection"
  "switch-8" = "--brave-ads-production"
  "switch-7" = "--rewards=staging=false"
  "switch-6" = "--variations-override-country=US"
  "switch-5" = "--variations-server-url=https://variations.bravesoftware.com/see"
  "switch-4" = "--fake-variations-channel=canary"
  "switch-3" = "--use-dev-goupdater-url"
  "switch-2" = "--rewards=staging=false"
  "switch-1" = "--disable-brave-update"
  "num-switches" = "24"
  "osarch" = "x86_64"
  "pid" = "85514"
  "ptype" = "browser"

[0126/125330.638245:WARNING:crash_report_exception_handler.cc(235)] UniversalExceptionRaise: (os/kern) failure (5)

@petemill
Copy link
Member

This seems like 2 separate issues

  1. Getting a blank ad where the fields are blank but the ad itself isn't null (the log of fields with empty entries are coming from an ads library, not brave news)

  2. Crashing because a callback isn't getting called. This looks like it's occuring in the ads library here:


void AdsImpl::GetInlineContentAd(const std::string& dimensions,
                                 GetInlineContentAdCallback callback) {
  if (!IsInitialized()) {
    BLOG(0, "AdsImpl::GetInlineContentAd not connected");
    callback(/* success */ false, dimensions, {});
    return;
  }
  BLOG(0, "AdsImpl::GetInlineContentAd start async");
  inline_content_ad_serving_->MaybeServeAd(
      dimensions, [=](const bool success, const std::string& dimensions,
                      const InlineContentAdInfo& ad) {
                        BLOG(0, "AdsImpl::GetInlineContentAd end async");
        callback(success, dimensions, ad);
      });
}

I had to refresh a few times to get the crash but when I did get the crash I received the "start async" line but not the "end async" line:

[17143:259:0126/162021.666646:ERROR:ads_service_impl.cc(1139)] ads service impl start async
[17143:259:0126/162021.738178:FATAL:brave_news.mojom.cc(2244)] Check failed: !connected. BraveNewsController::GetDisplayAdCallback was destroyed without first either being run or its corresponding binding being closed. It is an error to drop response callbacks which still correspond to an open interface pipe.

@petemill
Copy link
Member

petemill commented Jan 27, 2022

Some more info after 500 refreshes 😊

Maybe it's caused when the ads service restarts whilst already in the middle of a call to get an inline content ad

[18513:259:0126/163351.578573:ERROR:ads_service_impl.cc(1139)] ads service impl start async
[18513:259:0126/163351.717583:VERBOSE1:ads_service_impl.cc(751)] Restarting ads service
[18513:259:0126/163351.717652:FATAL:brave_news.mojom.cc(2244)] Check failed: !connected. BraveNewsController::GetDisplayAdCallback was destroyed without first either being run or its corresponding binding being closed. It is an error to drop response callbacks which still correspond to an open interface pipe.

This is on a profile which has some rewards "issues"

[18513:259:0126/163351.333466:VERBOSE3:client.cc(578)] Successfully loaded client state
[18513:259:0126/163351.333518:VERBOSE3:confirmations_state.cc(72)] Loading confirmations state
[18513:259:0126/163351.334565:INFO:challenge_bypass_ristretto_util.cc(19)] Challenge Bypass Ristretto Error: Failed to decode unblinded token: UnblindedToken must be 96 bytes in length
[18513:259:0126/163351.335192:INFO:confirmations_state.cc(388)] Invalid unblinded token
[18557:259:0126/163351.333942:FATAL:confirmations_state.cc(389)] Check failed: false.

@tmancey
Copy link
Contributor

tmancey commented Jan 28, 2022

This issue only affected nightly and v2 ad serving pipeline which is configured for nightly via griffin

@stephendonner
Copy link
Author

Verified PASSED using Brave 1.37.10, Chromium 98.0.4758.74 on a Google Pixel XL running Android 9.0.

Followed my original steps to reproduce, and confirmed inline-content ads display and work (links, ads redemption).

example example
Screenshot_20220128-225002 Screenshot_20220128-224935

@stephendonner
Copy link
Author

stephendonner commented Jan 29, 2022

Verified PASSED on

Brave 1.37.6 Chromium: 98.0.4758.74 (Official Build) nightly (x86_64)
Revision d0fe1ec4df090cd3eb02b591228505e12ea476e9-refs/branch-heads/4758@{#935}
OS macOS Version 12.3 (Build 21E5196i)

Followed my original steps to reproduce, and confirmed inline-content ads display and work (links, ads redemption).

example example
Screen Shot 2022-01-28 at 11 04 10 PM Screen Shot 2022-01-28 at 11 04 42 PM

Verified PASSED on

Brave 1.37.50 Chromium: 98.0.4758.87 (Official Build) nightly (64-bit)
Revision e4cd00f135fb4d8edc64c8aa6ecbe7cc79ebb3b2-refs/branch-heads/4758@{#1002}
OS Windows 10 Version 21H2 (Build 19044.1526)

Followed my original steps to reproduce, and confirmed inline-content ads display and work (links, ads redemption):

20658-1

@stephendonner
Copy link
Author

This issue only affected nightly and v2 ad serving pipeline which is configured for nightly via griffin

Actually it affects 1.36.82, Chromium 98.0.4758.87.

@tmancey @kjozwiak do we want to uplift this so folks running Brave News via feature flag on 1.36.x can see working inline ads?

@tmancey
Copy link
Contributor

tmancey commented Feb 2, 2022

@stephendonner I would recommend we instead remove the v2 study for beta from griffin. I will raise a PR. @kjozwiak your thoughts? I would rather not uplift any changes for v2 to release or beta until tested in nightly.

@tmancey
Copy link
Contributor

tmancey commented Feb 2, 2022

@stephendonner @kjozwiak griffin PR at brave/brave-variations#214

@stephendonner
Copy link
Author

@stephendonner I would recommend we instead remove the v2 study for beta from griffin. I will raise a PR. @kjozwiak your thoughts? I would rather not uplift any changes for v2 to release or beta until tested in nightly.

Study removal sounds good; just FYI this has been verified on both Android and macOS, nightly builds / master.

@btlechowski
Copy link

Verification passed on

Brave 1.37.83 Chromium: 99.0.4844.51 (Official Build) beta (64-bit)
Revision d537ec02474b5afe23684e7963d538896c63ac77-refs/branch-heads/4844@{#875}
OS Ubuntu 18.04 LTS

Ad serving v1

[8437:8437:0308/003635.670229:VERBOSE1:eligible_inline_content_ads_v1.cc(40)] Get eligible inline content ads:
[8437:8437:0308/003635.687844:VERBOSE1:eligible_inline_content_ads_v1.cc(174)] Get eligible ads for untargeted segment
[8437:8437:0308/003635.694785:VERBOSE2:ad_priority.h(33)] 1 ads with a priority of 1 in bucket 1
[8437:8437:0308/003635.694853:VERBOSE1:eligible_inline_content_ads_v1.cc(195)] 1 eligible ads out of 1 ads for untargeted segment
[8437:8437:0308/003635.694913:VERBOSE1:inline_content_ad_serving.cc(87)] Found 1 eligible ads
[8437:8437:0308/003635.694946:VERBOSE1:inline_content_ad_serving.cc(130)] Serving inline content ad:

image

Ad serving v2

[8099:8099:0308/003402.539292:VERBOSE1:eligible_inline_content_ads_v2.cc(39)] Get eligible inline content ads:
[8099:8099:0308/003402.546823:VERBOSE1:inline_content_ad_serving.cc(87)] Found 1 eligible ads
[8099:8099:0308/003402.547184:VERBOSE1:inline_content_ad_serving.cc(130)] Serving inline content ad:

image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment