Brave-browser: Ad notification timeout timers are not cancelled if a Brave Ad is clicked

[tmancey]

Description

Ad notification timeout timers are not cancelled if an ad is clicked

Steps to Reproduce

1. Click an ad notification (before it times out)

Actual result:

Ad notification 120 second timeout timer is not stopped

Expected result:

Ad notification 120 second timeout timer should be stopped

Reproduces how often:

Easily reproduced

Brave version (brave://version info)

Version/Channel Information:

• Can you reproduce this issue with the current release? Yes
• Can you reproduce this issue with the beta channel? Yes
• Can you reproduce this issue with the dev channel? Yes
• Can you reproduce this issue with the nightly channel? Yes

Other Additional Information:

• Does the issue resolve itself when disabling Brave Shields? N/A
• Does the issue resolve itself when disabling Brave Rewards? N/A
• Is the issue reproducible on the latest version of Chrome? N/A

Miscellaneous Information:

This is not a critical issue as when an ad event for timeouts was triggered we already had defensive code in place, however, we should fix this so that the timer is not using unecessary resources

[GeetaSarvadnya]

Verification passed on

Brave | 1.9.52 Chromium: 81.0.4044.129 (Official Build) dev (64-bit)
-- | --
Revision | 3d71af9f5704a40b85806f4d08925db24605ba25-refs/branch-heads/4044@{#979}
OS | Windows 10 OS Version 1803 (Build 17134.1006)

Need clarification for few checks

• Verified the test plan from https://github.com/brave/brave-core/pull/5230

1. Ensured that Timeout ad notification with uuid appeared in the console log when an ad notification appears ( don't click/view/dismiss the ad).

[15876:16664:0504/220739.704:INFO:ads_service_impl.cc(1928)] Timeout ad notification with uuid 2d4c0d78-4be2-4ed5-97fe-0247eafade2e in 120 seconds
[15876:16664:0504/220739.704:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-04T22:07:39Z"},"data":{"type":"notify","timestamp":"2020-05-04T22:07:39Z","eventType":"generated","classifications":["arts & entertainment"],"adCatalog":"b2054163-9998-4b88-aa0c-9939f55d414a","targetUrl":"https://travala.com/"}}
[15876:16664:0504/220739.704:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-04T22:07:39Z","creativeInstanceId":"ed8bf723-1346-48ce-8635-5d86b7b4ebf1","confirmationType":"view"}}
[2676:4056:0504/220739.704:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: ed8bf723-1346-48ce-8635-5d86b7b4ebf1
  creativeSetId: b2054163-9998-4b88-aa0c-9939f55d414a
  category: arts & entertainment
  targetUrl: https://travala.com/
  geoTarget: US
  confirmationType: view

1. ensured Cancelled timeout for ad notification with uuid appeared in the console log when clicking an ad notification

[2832:18556:0504/182108.768:INFO:ads_service_impl.cc(836)] Cancelled timeout for ad notification with uuid f9382126-cab5-4f0f-9b52-152ac3f65636

1. ensured Cancelled timeout for ad notification with uuid appeared in the console log when dismissing an ad notification

[18796:2132:0504/184630.376:INFO:ads_service_impl.cc(804)] Cancelled timeout for ad notification with uuid 631d357b-04db-4dcd-b0e7-f5d0a83c6c35
[14660:8036:0504/184630.376:INFO:ad_notifications.cc(307)] Saving notifications state
[18796:2132:0504/184630.376:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-04T18:46:30Z"},"data":{"type":"notify","timestamp":"2020-05-04T18:46:30Z","eventType":"dismissed","classifications":["arts & entertainment"],"adCatalog":"b2054163-9998-4b88-aa0c-9939f55d414a","targetUrl":"https://travala.com/"}}
[18796:2132:0504/184630.376:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-04T18:46:30Z","creativeInstanceId":"ce170650-5eee-44b6-ba98-1890208c6453","confirmationType":"dismiss"}}
[16268:8184:0504/184630.376:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: ce170650-5eee-44b6-ba98-1890208c6453
  creativeSetId: b2054163-9998-4b88-aa0c-9939f55d414a
  category: arts & entertainment
  targetUrl: https://travala.com/
  geoTarget: US
  confirmationType: dismiss

1. ensure Timed out ad notification with uuid appears in the console log when an ad notification times out (After receiving an ad wait for 120 secs to auto dismiss the notification)

[12976:17584:0504/190759.852:INFO:ads_service_impl.cc(1928)] Timeout ad notification with uuid 4adc217c-08f4-4bf3-a80f-769502c4ac3e in 120 seconds
[12976:17584:0504/190759.853:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-04T19:07:59Z"},"data":{"type":"notify","timestamp":"2020-05-04T19:07:59Z","eventType":"generated","classifications":["technology & computing"],"adCatalog":"c7f96341-726f-4e5d-9494-5686db89664b","targetUrl":"https://travala.com/"}}
[12976:17584:0504/190759.853:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-04T19:07:59Z","creativeInstanceId":"55505284-68c0-4442-a3d3-2ce3c42b5937","confirmationType":"view"}}
[12360:12600:0504/190759.853:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: 55505284-68c0-4442-a3d3-2ce3c42b5937
  creativeSetId: c7f96341-726f-4e5d-9494-5686db89664b
  category: technology & computing
  targetUrl: https://travala.com/
  geoTarget: US
  confirmationType: view

1. ensured Timed out ad notification with uuid does not appear in the console log if the user clicks and ad notification

[3060:14548:0504/203130.303:INFO:ads_service_impl.cc(1928)] Timeout ad notification with uuid 9cb4bb52-bce0-4314-b59c-b4d44d3a598e in 120 seconds
[3060:14548:0504/203130.303:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-04T20:31:30Z"},"data":{"type":"notify","timestamp":"2020-05-04T20:31:30Z","eventType":"generated","classifications":["technology & computing"],"adCatalog":"c7f96341-726f-4e5d-9494-5686db89664b","targetUrl":"https://travala.com/"}}
[3060:14548:0504/203130.303:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-04T20:31:30Z","creativeInstanceId":"9c57d4ba-c518-4f12-a156-8d682bc2d44d","confirmationType":"view"}}
[16564:13504:0504/203130.303:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: 9c57d4ba-c518-4f12-a156-8d682bc2d44d
  creativeSetId: c7f96341-726f-4e5d-9494-5686db89664b
  category: technology & computing
  targetUrl: https://travala.com/
  geoTarget: US
  confirmationType: view

1. ensured Timed out ad notification with uuid does not appear in the console log if the user dismisses an ad notification

[5548:5560:0504/193144.809:INFO:ads_service_impl.cc(804)] Cancelled timeout for ad notification with uuid 47da8e92-7f01-43c3-ad0a-138cb5cab561
[11680:17952:0504/193144.809:INFO:ad_notifications.cc(307)] Saving notifications state
[5548:5560:0504/193144.810:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-04T19:31:44Z"},"data":{"type":"notify","timestamp":"2020-05-04T19:31:44Z","eventType":"dismissed","classifications":["technology & computing"],"adCatalog":"c7f96341-726f-4e5d-9494-5686db89664b","targetUrl":"https://travala.com/"}}
[5548:5560:0504/193144.810:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-04T19:31:44Z","creativeInstanceId":"914d40b8-031c-486b-b0f3-8300f2c11601","confirmationType":"dismiss"}}
[17132:10952:0504/193144.810:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: 914d40b8-031c-486b-b0f3-8300f2c11601
  creativeSetId: c7f96341-726f-4e5d-9494-5686db89664b
  category: technology & computing
  targetUrl: https://travala.com/
  geoTarget: US
  confirmationType: dismiss

---

Verification passed on

Brave | 1.9.66 Chromium: 81.0.4044.138 (Official Build) dev (64-bit)
-- | --
Revision | 8c6c7ba89cc9453625af54f11fd83179e23450fa-refs/branch-heads/4044@{#999}
OS | Ubuntu 18.04 LTS

Verified the test plan from https://github.com/brave/brave-core/pull/5230

1. Verified Timeout ad notification with uuid appears in the console log when an ad notification appears

[3362:3362:0515/061803.508254:INFO:ads_service_impl.cc(1928)] Timeout ad notification with uuid 803eb1bb-8150-4c14-9c31-3a1e006cf416 in 120 seconds

1. Verified Cancelled timeout for ad notification with uuid appears in the console log when clicking an ad notification

[4501:4501:0515/062444.036029:INFO:ads_service_impl.cc(836)] Cancelled timeout for ad notification with uuid 49ff572c-61f5-4ed3-9f40-a071d51605a5

1. Verified Cancelled timeout for ad notification with uuid appears in the console log when dismissing an ad notification

[4941:4941:0515/062703.252392:INFO:ads_service_impl.cc(804)] Cancelled timeout for ad notification with uuid 8b0ae5a5-e49a-45ff-ade3-285063df88e8
[4941:4941:0515/062703.253601:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-15T06:27:03Z","creativeInstanceId":"174d8aed-aad0-47e4-9754-e813084861c4","confirmationType":"dismiss"}}

1. Verified Timed out ad notification with uuid appears in the console log when an ad notification times out

[5359:5359:0515/063356.788418:INFO:ads_service_impl.cc(806)] Timed out ad notification with uuid 2296de34-97e5-4484-a5b6-40c772e2024d
[5391:1:0515/063356.788918:INFO:ad_notifications.cc(307)] Saving notifications state
[5359:5359:0515/063356.789220:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-15T06:33:56Z"},"data":{"type":"notify","timestamp":"2020-05-15T06:33:56Z","eventType":"timed out","classifications":["untargeted"],"adCatalog":"330eaa49-ca57-454c-b461-93d8df728469","targetUrl":"https://batcommunity.org?brave=house"}}

1. Verified Timed out ad notification with uuid does not appear in the console log if the user clicks an ad notification
2. Verified Timed out ad notification with uuid does not appear in the console log if the user dismisses an ad notification

---

Verification passed with

Brave | 1.9.70 Chromium: 81.0.4044.138 (Official Build) (64-bit)
-- | --
Revision | 8c6c7ba89cc9453625af54f11fd83179e23450fa-refs/branch-heads/4044@{#999}
OS | macOS Version 10.14.6 (Build 18G3020)

• Verified test plan from https://github.com/brave/brave-core/pull/5230

1. Confirmed that Timeout ad notification with uuid... appeared in the console log when an ad notification appears (don't click/view/dismiss the ad).

[16169:775:0518/100600.685333:INFO:ads_service_impl.cc(1928)] Timeout ad notification with uuid 9b0a50e4-6435-467a-8446-fcb27854bd37 in 120 seconds
[16169:775:0518/100600.686167:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-18T10:06:00Z"},"data":{"type":"notify","timestamp":"2020-05-18T10:06:00Z","eventType":"generated","classifications":["untargeted"],"adCatalog":"f228782f-e210-4b18-8438-6e89a6a11813","targetUrl":"https://sellbrite.grsm.io/bravebrowser"}}
[16169:775:0518/100600.686427:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-18T10:06:00Z","creativeInstanceId":"fdac6da8-ec2c-412b-983e-d1f11f5d27b1","confirmationType":"view"}}
[16177:775:0518/100600.686627:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: fdac6da8-ec2c-412b-983e-d1f11f5d27b1
  creativeSetId: f228782f-e210-4b18-8438-6e89a6a11813
  category: untargeted
  targetUrl: https://sellbrite.grsm.io/bravebrowser
  geoTarget: US
  confirmationType: view

1. Confirmed Cancelled timeout for ad notification with uuid... appeared in the console log when clicking an ad notification

[16256:775:0518/112453.633797:INFO:ads_service_impl.cc(836)] Cancelled timeout for ad notification with uuid a7fa0826-71f6-409d-a0a0-34ba7aebcddb
[16256:775:0518/112453.633852:INFO:ads_service_impl.cc(844)] View ad notification with uuid a7fa0826-71f6-409d-a0a0-34ba7aebcddb
[16269:775:0518/112453.634306:INFO:ad_notifications.cc(307)] Saving notifications state
[16269:775:0518/112453.636293:INFO:ads_impl.cc(463)] OnTabUpdated.IsFocused for tab id: 7
[16269:775:0518/112453.641420:INFO:ads_impl.cc(475)] OnTabUpdated.IsBlurred for tab id: 5
[16261:775:0518/112453.665122:VERBOSE1:gles2_cmd_decoder.cc(3859)] GL_EXT_packed_depth_stencil supported.
[16270:775:0518/112453.665248:ERROR:paint_controller.cc(561)] PaintController::FinishCycle() completed
[16256:775:0518/112453.715221:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-18T11:24:53Z"},"data":{"type":"notify","timestamp":"2020-05-18T11:24:53Z","eventType":"clicked","classifications":["untargeted"],"adCatalog":"82c21de1-16ae-4921-86dd-d9b8b10bc558","targetUrl":"https://weekinethereumnews.com/"}}
[16256:775:0518/112453.715276:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-18T11:24:53Z","creativeInstanceId":"9963cb71-310e-4a65-a761-0d0d7b3537c6","confirmationType":"click"}}
[16256:775:0518/112453.715372:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"focus","timestamp":"2020-05-18T11:24:53Z","tabId":7}}
[16256:775:0518/112453.715406:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"blur","timestamp":"2020-05-18T11:24:53Z","tabId":5}}
[16268:775:0518/112453.715464:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: 9963cb71-310e-4a65-a761-0d0d7b3537c6
  creativeSetId: 82c21de1-16ae-4921-86dd-d9b8b10bc558
  category: untargeted
  targetUrl: https://weekinethereumnews.com/
  geoTarget: US
  confirmationType: click

1. Confirmed Cancelled timeout for ad notification with uuid... appeared in the console log when dismissing an ad notification

[16237:775:0518/105831.284290:INFO:ads_service_impl.cc(804)] Cancelled timeout for ad notification with uuid 5fc6b637-1fe7-4da9-966d-f3cb686eb1d3
[16246:775:0518/105831.284488:INFO:ad_notifications.cc(307)] Saving notifications state
[16237:775:0518/105831.285397:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"restart","timestamp":"2020-05-18T10:58:31Z"},"data":{"type":"notify","timestamp":"2020-05-18T10:58:31Z","eventType":"dismissed","classifications":["untargeted"],"adCatalog":"69cf860f-4e39-4725-aefc-0d41a27a84b8","targetUrl":"https://protonvpn.com/brave"}}
[16237:775:0518/105831.285686:INFO:ads_service_impl.cc(2095)] AdsService Event Log: {"data":{"type":"confirmation","timestamp":"2020-05-18T10:58:31Z","creativeInstanceId":"6722ccfb-b513-4249-8574-5c6c785da341","confirmationType":"dismiss"}}
[16245:775:0518/105831.285893:INFO:confirmations_impl.cc(1146)] Confirm ad:
  creativeInstanceId: 6722ccfb-b513-4249-8574-5c6c785da341
  creativeSetId: 69cf860f-4e39-4725-aefc-0d41a27a84b8
  category: untargeted
  targetUrl: https://protonvpn.com/brave
  geoTarget: US
  confirmationType: dismiss

1. Confirmed Timed out ad notification with uuid... appeared in the console log when an ad notification times out (After receiving an ad wait for 120 secs to auto dismiss the notification)

[16169:775:0518/100800.689034:INFO:ads_service_impl.cc(806)] Timed out ad notification with uuid 9b0a50e4-6435-467a-8446-fcb27854bd37
[16178:775:0518/100800.689198:INFO:ad_notifications.cc(307)] Saving notifications state

1. Confirmed Timed out ad notification with uuid... did not appear in the console log when I clicked an ad notification.

2. Confirmed Timed out ad notification with uuid... did not appear in the console log when I dismissed an ad notification

[GeetaSarvadnya]

@tmancey Need clarification on scenarios 5th and 6th from the test plan https://github.com/brave/brave-core/pull/5230

Scenario 5: when the user clicks on Ad, we are getting Timed out ad notification with uuid in the logs. But the scenario says it should not. Shared logs in DM
Scenario 6: when the user dismiss an Ad, we are getting Timed out ad notification with uuid in the logs. But the scenario says it should not. Shared logs in DM

[LaurenWags]

Marking as QA/Blocked as @GeetaSarvadnya is still pending answers from https://github.com/brave/brave-browser/issues/9154#issuecomment-623580902.

[tmancey]

@GeetaSarvadnya I have searched your logs and Timed out ad notification with uuid do not appear for #5 and #6. After checking your comments you were searching for timeout and not timed out :-)

[LaurenWags]

Thanks for the clarification @tmancey 😄