New Brave Ads catalog not pulled every 2 hours - follow up to 3520

[LaurenWags]

Description

Found while testing #3520

While testing I have not been getting a new Ads catalog every two hours. Others have not experienced this (@kjozwiak @tmancey ). I wonder if it's because when my computer sleeps it's turning off hard disks and this is possibly disrupting things.

Steps to Reproduce

Still TBD. I'm testing different scenarios/builds and will add notes as comments to this issue. Once steps are found, I'll put them here.

Actual result:

Catalog not downloaded every 2 hours

Expected result:

Catalog downloaded every 2 hours

Reproduces how often:

reproduces easily for me, not for others.

Brave version (brave://version info)

Experienced with the following versions:

Brave	0.63.45 Chromium: 74.0.3729.75 (Official Build) beta(64-bit)
Revision	fdb7915642fef8cf997beac2554709d148e3c187-refs/branch-heads/3729@{#754}
OS	Mac OS X

Brave	0.65.67 Chromium: 74.0.3729.75 (Official Build) nightly(64-bit)
Revision	fdb7915642fef8cf997beac2554709d148e3c187-refs/branch-heads/3729@{#754}
OS	Mac OS X

Version/Channel Information:

• Can you reproduce this issue with the current release? n/a
• Can you reproduce this issue with the beta channel? yes
• Can you reproduce this issue with the dev channel? unsure
• 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:

[LaurenWags]

Brave	0.66.9 Chromium: 74.0.3729.91 (Official Build) nightly(64-bit)
Revision	03844ed83e02b8add3f4b9cb859a7108d55b2e4d-refs/branch-heads/3729@{#860}
OS	Mac OS X

Reproduced the issue with above build. STR:

1. Clean install above build.
2. Launch with /Applications/Brave\ Browser\ Nightly.app/Contents/MacOS/Brave\ Browser\ Nightly --enable-logging=stderr --vmodule=brave_ads=3 --log-level=3 --brave-ads-debug
3. Enable Rewards
4. Let computer go idle/go to sleep. Wait about 30 minutes.
5. Come back, wake computer.
   --> No new catalog, no mention of 'Start collecting activity' in terminal aside from the initial ones.

4161.txt

[kjozwiak]

Went through the following last night which appeared to be working:

• installed 0.63.46 Chromium: 74.0.3729.91 and enabled BR/Ads
• once enabled, put my macOS 10.14.4 x64 to sleep for ~45mins
• woke up the machine and left it running during the night, had several catalog.json download pings:

[42668:775:0423/064444.786486:INFO:ads_serve.cc(64)] Successfully downloaded catalog
[42668:775:0423/064444.786959:INFO:ads_serve.cc(137)] Parsing catalog
[42668:775:0423/064444.791233:INFO:catalog.cc(37)] Successfully loaded catalog
[42668:775:0423/064444.791461:INFO:ads_serve.cc(143)] Catalog parsed
[42668:775:0423/064444.791643:WARNING:ads_serve.cc(151)] Catalog id c1843c587d9dce273a163a64499b274b6f2b697e matches current catalog id c1843c587d9dce273a163a64499b274b6f2b697e

@LaurenWags as per our discussion, can you try the following whenever you have some time?

• install the latest version of Brave and enable BR/Ads
• put the machine to sleep for a few hours (maybe ~2-3hrs)
• wake up the machine and leave Brave running

Are you getting pings after ~2hrs once the machine woke up?

[LaurenWags]

Ran the following test:

• on both Release (0.63.48) and Nightly (0.66.21) launched with --enable-logging=stderr --log-level=2 --vmodule=brave_ads=3 --brave-ads-debug with clean profiles and enabled Rewards.
• didn't navigate to any sites
• let these both sit overnight (my computer went to sleep).
• In the morning, 15 minutes after waking (and every 15 minutes thereafter) Nightly pulled a catalog (this is because --brave-ads-debug shortens the time from 2hr to 15 minutes).
• For release, 2 hours after waking, Release did pull a new catalog.

Seems like it is working in that after being asleep, the machine did eventually pull a new catalog. However, my concern is that after being asleep for over 2 hours, neither pulled a new catalog on waking up. If a user does the following

• Has Brave running (actively or in the background)
• Lets computer sleep for over two hours
• Wakes computer (Brave is still running)
• Uses computer for less than 2 hours
• Lets computer sleep for some time over two hours (basically repeats the cycle)
  Their catalog will be out of date until the machine is active for over two hours with Brave running or they restart Brave, whatever comes first.

[tmancey]

@LaurenWags Totally agree, does this also happen on Ledger?

[LaurenWags]

@tmancey I'm unsure what your question means. Could you provide a bit more detail?

[tmancey]

@LaurenWags I have spoken with @NejcZdovc and Ledger also has timers which trigger after a specified amount of time, so it is likely that Ledger is also affected when the device goes to sleep. I will discuss solutions with @NejcZdovc

[tmancey]

cc @LaurenWags @btlechowski this was due to the use of OneShotTimer. We should use WallClockTimer which runs after a delay based on usual time, while OneShotTimer runs after a delay according to TimeTicks which may freeze on some platforms when power suspends (i.e. desktop falls asleep). On platforms where TimeTicks don't freeze, the WallClockTimer has the same behavior as OneShotTimer.

[LaurenWags]

Verified with

Brave | 1.41.77 Chromium: 103.0.5060.53 (Official Build) beta (x86_64)
-- | --
Revision | a1711811edd74ff1cf2150f36ffa3b0dae40b17f-refs/branch-heads/5060@{#853}
OS | macOS Version 12.4 (Build 21F79)

Initial catalog request/response:

[52889:259:0627/090545.107687:VERBOSE1:catalog.cc(70)] Catalog
[52889:259:0627/090545.107713:VERBOSE2:catalog.cc(71)] GET /v9/catalog
[52889:259:0627/090545.107734:VERBOSE6:catalog.cc(77)] URL Request:
  URL: https://static.ads.brave.com/v9/catalog
  Method: kGet
...........
[52889:259:0627/090545.183408:VERBOSE1:catalog.cc(86)] OnCatalog
[52889:259:0627/090545.183967:VERBOSE7:catalog.cc(88)] URL Response:
  URL: https://static.ads.brave.com/v9/catalog
  Response Status Code: 200
  Response: {"ping":7200000,"version":9,"campaigns":[{"ptr":0.9983993079500545,"endAt":"202........
[52889:259:0627/090545.186689:VERBOSE1:catalog.cc(107)] Successfully fetched catalog
[52889:259:0627/090545.186712:VERBOSE1:catalog.cc(109)] Parsing catalog
[52889:259:0627/090545.224778:VERBOSE1:catalog.cc(150)] Fetch catalog in 1 hour, 28 minutes, 28 seconds at 10:34:13.224

Let computer sleep for ~2hr (past the Fetch catalog in 1 hour, 28 minutes, 28 seconds at 10:34:13.224 time from above logs).

Confirmed on computer wake a new catalog was fetched:

[52889:259:0627/110936.640074:VERBOSE1:catalog.cc(70)] Catalog
[52889:259:0627/110936.640102:VERBOSE2:catalog.cc(71)] GET /v9/catalog
[52889:259:0627/110936.640123:VERBOSE6:catalog.cc(77)] URL Request:
  URL: https://static.ads.brave.com/v9/catalog
  Method: kGet
............
[52889:259:0627/110938.885588:VERBOSE1:catalog.cc(86)] OnCatalog
[52889:259:0627/110938.885957:VERBOSE7:catalog.cc(88)] URL Response:
  URL: https://static.ads.brave.com/v9/catalog
  Response Status Code: 200
  Response: {"ping":7200000,"version":9,"campaigns":[{"ptr":1,"endAt":"2022-07-11T22:59:00.000Z","start..........
[52889:259:0627/110938.890382:VERBOSE1:catalog.cc(107)] Successfully fetched catalog
[52889:259:0627/110938.890405:VERBOSE1:catalog.cc(109)] Parsing catalog
[52889:259:0627/110938.934311:VERBOSE1:catalog.cc(150)] Fetch catalog in 1 hour, 44 minutes, 26 seconds at 12:54:04.933