PW data source provides all items, losts, founds, losts and then founds them again on start up. |
||||||||
Issue descriptionVersion: ToT OS: Android What steps will reproduce the problem? (0) Provide 3 different beacons nearby; (1) Kill Chrome; (2) Start Chrome; Note that both beacons and the phone are not moved; What is the expected result? No onLost calls; What happens instead? The log (with my comments are in /* */): < log starts > start I fetched 3 items. /* This is a manual fetch. */ https://play.google.com https://google.com https://abc.xyz ||| OnLost https://play.google.com /* Why? */ I fetched 0 items. ||| OnLost https://google.com I fetched 0 items. ||| OnLost https://abc.xyz I fetched 0 items. ||| OnFound https://google.com I fetched 1 items. https://google.com ||| OnFound https://abc.xyz I fetched 3 items. https://play.google.com https://abc.xyz https://google.com ||| OnFound https://play.google.com I fetched 3 items. https://play.google.com https://abc.xyz https://google.com ||| OnLost https://google.com I fetched 2 items. https://play.google.com https://abc.xyz ||| OnLost https://abc.xyz I fetched 1 items. https://play.google.com ||| OnLost https://play.google.com /* Wait, again? */ I fetched 0 items. ||| OnFound https://play.google.com I fetched 1 items. https://play.google.com ||| OnFound https://google.com I fetched 2 items. https://play.google.com https://google.com ||| OnFound https://abc.xyz I fetched 3 items. /* Finally :) */ https://play.google.com https://abc.xyz https://google.com < log ends > I could reproduce this Lost-Found-Lost situation 3/3 times modulo the order of sites in each block. Is this intended?
,
Nov 22 2016
Here's my first stab: https://codereview.chromium.org/2521333002/ (I'm going to need Matt to look at it since he's more familiar with the data source)
,
Nov 28 2016
Conley, that CL looks like a good change to me, but it looks like there is something more going on than just that. Part of the bug is confusion about onLosts during startup (fixed with your patch), and part of the bug is confusion about "thrashing". It would be useful to have timestamps beside these events. Vitali, do these lost-found-lost happen over time, or almost all at once?
,
Nov 28 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/faed7fd18b306ebc4410e0bd0ae2422ffcec299e commit faed7fd18b306ebc4410e0bd0ae2422ffcec299e Author: cco3 <cco3@chromium.org> Date: Mon Nov 28 20:48:32 2016 Notify PW data source of URLs on first register Currently, when we create the Physical Web data source, we do not populate it with any initial data, which can lead to onLosts occuring when there has not even been an onFound. This change call onFound for currently known URLs when first creating the data source. BUG= 667754 Review-Url: https://codereview.chromium.org/2521333002 Cr-Commit-Position: refs/heads/master@{#434712} [modify] https://crrev.com/faed7fd18b306ebc4410e0bd0ae2422ffcec299e/chrome/android/java/src/org/chromium/chrome/browser/physicalweb/UrlManager.java
,
Nov 29 2016
Michal, sorry for not doing this in the initial post. > do these lost-found-lost happen over time, or almost all at once? Almost all at once. First I receive all 3 urls on startup, but then after 2 seconds, all of them are lost and found in almost no time. I could reproduce this 3/3 times. Log with timestamps: < I killed Clank > < I started Clank > 11-29 07:42:54.250 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(46)] ||| start 11-29 07:42:54.250 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 3 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://play.google.com 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 0 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://google.com 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 0 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://abc.xyz 11-29 07:42:56.319 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 0 11-29 07:42:56.337 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://play.google.com 11-29 07:42:56.338 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 1 11-29 07:42:56.457 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://abc.xyz 11-29 07:42:56.457 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 3 11-29 07:42:56.458 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://google.com 11-29 07:42:56.458 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 3 11-29 07:42:56.461 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://play.google.com 11-29 07:42:56.462 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 2 11-29 07:42:56.464 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://abc.xyz 11-29 07:42:56.464 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 1 11-29 07:42:56.465 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(219)] ||| OnLost = https://google.com 11-29 07:42:56.465 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 0 11-29 07:42:56.554 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://play.google.com 11-29 07:42:56.554 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 1 11-29 07:42:56.577 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://google.com 11-29 07:42:56.578 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 2 11-29 07:42:57.719 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(214)] ||| OnFound = https://abc.xyz 11-29 07:42:57.719 20146 20146 I chromium: [INFO:physical_web_page_suggestions_provider.cc(143)] ||| GetMetadata()->GetSize() = 3
,
Nov 29 2016
Thanks Vitali! Conley: does this have anything to do with us clearing sharedpreferences after a full restart? And/or with re-registering background subscription to Nearby after a full Chrome restart? Vitali: This looks mildly irritating, but not like a blocking issue. We're doing some other more pressing work ATM, so it may take a few weeks to come back to this. Please let us know if it is blocking you!
,
Dec 6 2016
This a launch blocker for us (I have to remove urls from UI when they are lost). I would be grateful if we could have this done well by 6th of January (M57 FF).
,
Dec 21 2016
To reproduce, all you are doing is force stopping and starting? Nothing else? I'm seeing *some* sporadic behavior, but not that much.
,
Dec 22 2016
Yes, force stopping and starting. I have signed debug build. The PW NTP provider is enabled (#enable-ntp-physical-web-page-suggestions) as well as all PW related settings. I am able to reproduce it 3/3 times with ToT at e6b29f780581dedef421548119586efeb5825d2c (see the patch attached, you can apply it using "git apply pw_patch.txt"). The obtained log is 12-22 09:55:20.660 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(61)] ||| Provider start. 12-22 09:55:20.660 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:20.750 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://google.com/ 12-22 09:55:20.750 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:20.750 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://abc.xyz/ 12-22 09:55:20.751 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:20.751 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://play.google.com/ 12-22 09:55:20.751 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:23.298 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://play.google.com/ 12-22 09:55:23.298 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://google.com/ 12-22 09:55:23.299 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://abc.xyz/ 12-22 09:55:23.460 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://abc.xyz/ 12-22 09:55:23.461 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.461 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.0446684 12-22 09:55:23.461 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.465 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.0446684 12-22 09:55:23.466 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:23.466 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://google.com/ 12-22 09:55:23.467 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3 12-22 09:55:23.536 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://play.google.com/ 12-22 09:55:23.536 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.537 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://play.google.com/ estimate = 0.707946 12-22 09:55:23.537 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 1 12-22 09:55:23.537 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://play.google.com/ estimate = 0.707946 12-22 09:55:23.537 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 1 12-22 09:55:23.538 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://abc.xyz/ 12-22 09:55:23.607 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://google.com/ 12-22 09:55:23.608 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(282)] ||| OnLost https://play.google.com/ 12-22 09:55:23.608 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://abc.xyz/ 12-22 09:55:23.608 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 1 12-22 09:55:23.608 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.0446684 12-22 09:55:23.608 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 1 12-22 09:55:23.609 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.0446684 12-22 09:55:23.609 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 1 12-22 09:55:23.615 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://play.google.com/ 12-22 09:55:23.615 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.616 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://play.google.com/ estimate = 0.707946 12-22 09:55:23.616 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.617 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(289)] ||| OnDistanceChanged https://play.google.com/ estimate = 0.707946 12-22 09:55:23.617 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 2 12-22 09:55:23.620 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(277)] ||| OnFound https://google.com/ 12-22 09:55:23.620 9063 9063 I chromium: [INFO:physical_web_page_suggestions_provider.cc(190)] ||| GetMetadata()->GetSize() = 3
,
Jan 5 2017
,
Jan 7 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/91f5b8d2f34faf9c21fb4c08146cb1a7d9ad2144 commit 91f5b8d2f34faf9c21fb4c08146cb1a7d9ad2144 Author: cco3 <cco3@chromium.org> Date: Sat Jan 07 00:24:14 2017 Remove nearby URL cache from the PW UrlManager Given that we can't inspect the status of our Nearby subscription, we have to resubscribe on every startup. That means that there is no point in caching nearby URLs when we will have to repopulate those through the new subscription anyway. Additionally, our current practice is sending noise to listeners (onFound at startup, onLost at cache deletion, onFound at resubscription). This change just removes that cache. BUG= 667754 Review-Url: https://codereview.chromium.org/2606933003 Cr-Commit-Position: refs/heads/master@{#442108} [modify] https://crrev.com/91f5b8d2f34faf9c21fb4c08146cb1a7d9ad2144/chrome/android/java/src/org/chromium/chrome/browser/physicalweb/PhysicalWeb.java [modify] https://crrev.com/91f5b8d2f34faf9c21fb4c08146cb1a7d9ad2144/chrome/android/java/src/org/chromium/chrome/browser/physicalweb/UrlManager.java [modify] https://crrev.com/91f5b8d2f34faf9c21fb4c08146cb1a7d9ad2144/chrome/android/javatests/src/org/chromium/chrome/browser/physicalweb/UrlManagerTest.java
,
Jan 9 2017
Conley, I think this is fixed now?
,
Jan 9 2017
It should be.
,
Jan 12 2017
The issue still exists, but now it is less severe, however still a launch blocker for us. Previously the sequence was <All URLs are available>, OnFound, OnLost, OnFound, OnLost, OnFound. Now it is <No URLs are available>, OnFound, OnLost, OnFound. I would like it to be: <All URLs are available> or <All URLs are available>, OnFound. or <No URLs are available>, OnFound, <LoadingCompleted notification>. Using patch from comment #9, I obtained the following log (start up after killing clank, reproduced 3/3 times): 14:57:17.534 [INFO:physical_web_page_suggestions_provider.cc(64)] ||| Provider start. 14:57:17.534 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 14:57:20.889 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://play.google.com/ 14:57:20.889 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:20.890 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://play.google.com/ estimate = 1.41254 14:57:20.890 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:20.914 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://play.google.com/ estimate = 1.41254 14:57:20.914 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:20.915 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://abc.xyz/ 14:57:20.915 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 14:57:20.916 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.141254 14:57:20.916 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 14:57:20.916 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.141254 14:57:20.917 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:20.917 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://google.com/ 14:57:20.918 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:20.918 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://google.com/ estimate = 0.141254 14:57:20.918 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:20.919 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://google.com/ estimate = 0.141254 14:57:20.919 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:21.039 [INFO:physical_web_page_suggestions_provider.cc(283)] ||| OnLost https://play.google.com/ 14:57:21.041 [INFO:physical_web_page_suggestions_provider.cc(283)] ||| OnLost https://abc.xyz/ 14:57:21.043 [INFO:physical_web_page_suggestions_provider.cc(283)] ||| OnLost https://google.com/ 14:57:21.046 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://google.com/ 14:57:21.046 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:21.046 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://google.com/ estimate = 0.141254 14:57:21.047 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:21.047 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://google.com/ estimate = 0.141254 14:57:21.047 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 14:57:21.047 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://play.google.com/ 14:57:21.048 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 14:57:21.048 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://play.google.com/ estimate = 1.41254 14:57:21.048 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 14:57:21.049 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://play.google.com/ estimate = 1.41254 14:57:21.049 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 14:57:22.389 [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound https://abc.xyz/ 14:57:22.389 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:22.390 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.141254 14:57:22.390 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 14:57:22.391 [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged https://abc.xyz/ estimate = 0.141254 14:57:22.391 [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 Could you have another look please?
,
Jan 12 2017
+ nepper@ & finkm@ who coordinate the launch on our side.
,
Jan 12 2017
Thanks Vitali, I am taking a look.
,
Jan 12 2017
It looks like the Found -> Lost -> Found sequence on startup stems directly from events we get from Nearby api, and thus this won't be easy to resolve. This may possibly be related to the way Nearby loses results during scan windows, or it may be due to our misuse of the API? I know this "flip-flopping" is irritating, but it seems logically consistent. Hopefully this isn't actually a blocker, since its unlikely to cause invalid state, even though it may not be ideal to hop around. Also, and Nearby is updating the way they fire lost events in the near future, so this may just resolve itself in the wild when play services updates. I'll reach out to them for comment. Aside from the startup "flip-flopping", it looks like there are a few small quirks/bugs/races within the transfer of state between Java <-> C++ <-> Zine. Below are some startup logs with my comments to hopefully help piece identify some of the issues. FYI I generated these logs by following these steps: > adb logcat -c > adb logcat | grep -i -e "\|\|\|" -e "physicalweb" -e "BtGatt" -e "BluetoothLeScanner" > logoutput (My comments inline with ###) ================================================================================ ### These logs are for a fresh launch of Chrome, I'll post logs for second launch later ### I also deleted all the BtGatt.GattService etc logs since I don't think they add value and they make this even harder to read. 01-12 10:43:51.766 16155 16155 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:51.766 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(64)] ||| Provider start. 01-12 10:43:51.766 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 01-12 10:43:51.848 16155 16155 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 0 nearby, 2 resolved, and 0 in intersection. ### Notice that we already had 2 saved resolved URLs on startup, presumably from sharedpreferences storage? AFAIK Conley has/is removing this. 01-12 10:43:53.661 16155 16155 D cr_PhysicalWeb: [NearbySubscription.java:43] Nearby background subscribe succeeded 01-12 10:43:53.691 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://mmocny.com -1.000000 1484235833690 false 01-12 10:43:53.691 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.693 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 1 nearby, 2 resolved, and 1 in intersection. ### We found 1 result! Came the exact millisecond of our subscribe, so clearly its from existing Nearby cache. 01-12 10:43:53.695 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound http://mmocny.com/ 01-12 10:43:53.695 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 01-12 10:43:53.696 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://mmocny.com/ estimate = 0.398107 01-12 10:43:53.696 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 ### So far so good! Bit odd that we fire an OnDistanceChanged event after OnFound, but ok.. ### Note: A rapid series of BtGatt.GattService events starts firing now 01-12 10:43:53.739 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://mmocny.com -1.000000 1484235833739 false ### "Found" for an URL we already know to be found. This is presumably just a distance update.. so we should change our logging to make this more obvious. 01-12 10:43:53.740 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.742 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://physical-web.org -1.000000 1484235833742 false 01-12 10:43:53.742 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.747 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://physical-web.org -1.000000 1484235833747 false 01-12 10:43:53.747 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: ### Found second URL (with duplicate event). This time, duplicate came really soon after the first event. 01-12 10:43:53.752 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235833751 false 01-12 10:43:53.752 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.753 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 3 nearby, 2 resolved, and 2 in intersection. 01-12 10:43:53.754 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235833753 false 01-12 10:43:53.754 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: ### Found third URL (with duplicate event) 01-12 10:43:53.756 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: https://pwdemo.org:33336/ -1.000000 1484235833756 false 01-12 10:43:53.757 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.768 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: https://pwdemo.org:33336/ -1.000000 1484235833767 false 01-12 10:43:53.768 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: ### Found fourth URL (with duplicate event). Note: This URL fails to resolve 01-12 10:43:53.770 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235833769 false 01-12 10:43:53.770 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:53.771 16155 16293 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235833771 false 01-12 10:43:53.771 16155 16293 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: ### Found second URL again? Could just be distance updates, but why 2 events back-to-back? ### Looooots of BtGatt.GattService events at this point, sequences finishes about 300ms from when it started. (more events later, but biggest burst was here). 01-12 10:43:54.069 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://mmocny.com/ estimate = 0.398107 01-12 10:43:54.069 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 ### Bug? We're back in C++ now, and get a second OnDistanceChanged event with the same distance estimate, for URL from way up top. Perhaps we always fire distance change events after OnFounds? And then fire another one when the actual distance changes? Odd that the estimate is the same both times. 01-12 10:43:54.072 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound http://goo.gl/IukLV7 01-12 10:43:54.072 16155 16293 D cr_PhysicalWeb: [UrlManager.java:200] URL lost: http://mmocny.com -1.000000 1484235834072 false 01-12 10:43:54.072 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 01-12 10:43:54.073 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 3 nearby, 2 resolved, and 1 in intersection. 01-12 10:43:54.076 16155 16293 D cr_PhysicalWeb: [UrlManager.java:200] URL lost: http://physical-web.org -1.000000 1484235834075 false 01-12 10:43:54.076 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 2 nearby, 2 resolved, and 1 in intersection. 01-12 10:43:54.079 16155 16293 D cr_PhysicalWeb: [UrlManager.java:200] URL lost: http://goo.gl/IukLV7 -1.000000 1484235834078 false 01-12 10:43:54.079 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 1 nearby, 2 resolved, and 0 in intersection. ### Java side we just Lost all our resolved URLs basically at the same time! These losts come only ~400ms after initial found event, which is much less time than we would need to actually lose these for real. 01-12 10:43:54.100 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:54.100 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 ### Bug? Meanwhile in Native, the sequence of events is still valid but reflecting the past. OnFound, GetMetadata, OnDistanceChanged, GetMetadata seems fine, but notice the final size is 0, not 2. Looks like the state of the list changed as we were processing old events (race?) 01-12 10:43:54.100 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:54.100 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 01-12 10:43:54.101 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:54.101 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 01-12 10:43:54.101 16155 16293 D cr_PhysicalWeb: [UrlManager.java:200] URL lost: https://pwdemo.org:33336/ -1.000000 1484235834101 false 01-12 10:43:54.101 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:54.102 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 0 01-12 10:43:54.102 16155 16293 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 0 nearby, 2 resolved, and 0 in intersection. 01-12 10:43:54.107 16155 16293 D cr_PhysicalWeb: [UrlManager.java:200] URL lost: http://goo.gl/IukLV7 -1.000000 1484235834107 false 01-12 10:43:54.115 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(283)] ||| OnLost http://mmocny.com/ 01-12 10:43:54.115 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(283)] ||| OnLost http://goo.gl/IukLV7 ### The above sequence of 3 OnDistanceChanged then 2 OnLosts is just delayed from old Java events. It is odd that Metadata size is already 0 and we are still processing these. We don't get OnFound events for the 2 other URLs we found because Java side hadn't resolved them yet. ### Another series of BtGatt.GattService events starts here (I deleted them) 01-12 10:43:54.128 16155 16155 D cr_PhysicalWeb: [UrlManager.java:363] PWS unresolved: https://pwdemo.org:33336/ 0.199526 1484235833767 false 01-12 10:43:54.128 16155 16155 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 0 nearby, 2 resolved, and 0 in intersection. 01-12 10:43:54.134 16155 16155 D cr_PhysicalWeb: [UrlManager.java:347] PWS resolved: http://physical-web.org ### These are network calls coming in from earlier, but at this point Nearby thinks they are lost. 01-12 10:43:54.842 16155 16307 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://physical-web.org -1.000000 1484235834841 false 01-12 10:43:54.843 16155 16307 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:54.845 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound http://physical-web.org/ 01-12 10:43:54.845 16155 16307 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 1 nearby, 3 resolved, and 1 in intersection. 01-12 10:43:54.846 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 01-12 10:43:54.846 16155 16307 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://physical-web.org -1.000000 1484235834846 false 01-12 10:43:54.846 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://physical-web.org/ estimate = 0.398107 01-12 10:43:54.847 16155 16307 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:54.847 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 01-12 10:43:54.849 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://physical-web.org/ estimate = 0.398107 01-12 10:43:54.850 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 1 ### Starting to find beacons again, events propagating well. 01-12 10:43:55.550 16155 16309 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235835549 false 01-12 10:43:55.551 16155 16309 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:55.553 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound http://goo.gl/IukLV7 01-12 10:43:55.554 16155 16309 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 2 nearby, 3 resolved, and 2 in intersection. 01-12 10:43:55.554 16155 16309 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235835554 false 01-12 10:43:55.556 16155 16309 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:55.560 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 01-12 10:43:55.561 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:55.562 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 01-12 10:43:55.564 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:55.564 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 2 ### Second URL found, sequence of events is familiar 01-12 10:43:56.708 16155 16310 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://mmocny.com -1.000000 1484235836707 false 01-12 10:43:56.709 16155 16310 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:56.711 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(278)] ||| OnFound http://mmocny.com/ 01-12 10:43:56.711 16155 16310 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 3 nearby, 3 resolved, and 3 in intersection. 01-12 10:43:56.712 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 01-12 10:43:56.712 16155 16310 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://mmocny.com -1.000000 1484235836712 false 01-12 10:43:56.713 16155 16310 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:56.714 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://mmocny.com/ estimate = 0.398107 01-12 10:43:56.715 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 01-12 10:43:56.717 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://mmocny.com/ estimate = 0.398107 01-12 10:43:56.718 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 ### Third URL found, sequence of events is familiar 01-12 10:43:57.990 16155 16312 D cr_PhysicalWeb: [UrlManager.java:161] URL found: https://pwdemo.org:33336/ -1.000000 1484235837988 false 01-12 10:43:57.991 16155 16312 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:57.994 16155 16312 D cr_PhysicalWeb: [UrlManager.java:161] URL found: https://pwdemo.org:33336/ -1.000000 1484235837993 false 01-12 10:43:57.995 16155 16312 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:58.238 16155 16155 D cr_PhysicalWeb: [UrlManager.java:363] PWS unresolved: https://pwdemo.org:33336/ 0.199526 1484235837993 false 01-12 10:43:58.240 16155 16155 D cr_PhysicalWeb: [UrlManager.java:241] Get URLs With: 4 nearby, 3 resolved, and 3 in intersection. ### Fourth URL found, but is known unresolved so doesn't propagate 01-12 10:43:59.260 16155 16317 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235839259 false 01-12 10:43:59.260 16155 16317 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:59.261 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:59.262 16155 16317 D cr_PhysicalWeb: [UrlManager.java:161] URL found: http://goo.gl/IukLV7 -1.000000 1484235839261 false 01-12 10:43:59.262 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 01-12 10:43:59.262 16155 16317 D cr_PhysicalWeb: [UrlManager.java:672] Not garbage collecting: 01-12 10:43:59.263 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(290)] ||| OnDistanceChanged http://goo.gl/IukLV7 estimate = 2.81838 01-12 10:43:59.264 16155 16155 I chromium: [INFO:physical_web_page_suggestions_provider.cc(198)] ||| GetMetadata()->GetSize() = 3 ### This time, we get a distance update without a found event, yet we still get 2 events in native? ### Series of BtGatt.GattService events ends. It took quite a while to make sense of the series of events, but I think the few actions items are: - Update logging to make it clear differentiation between founds and distance updates - Review when we fire OnDistanceFound in native, they seem to come in pairs but there are a couple events that seem unexplained - Races between the Metadata list in native and the events that native fires. We seem to fire all old events, even when the list is reflecting a newer reality. May be a problem if you expect to find a result in the list..
,
Jan 12 2017
Initial thoughts: ### Notice that we already had 2 saved resolved URLs on startup, presumably from sharedpreferences storage? AFAIK Conley has/is removing this. I'm not removing the resolved URLs cache; only the cache of what URLs are nearby (and that's already done). ### So far so good! Bit odd that we fire an OnDistanceChanged event after OnFound, but ok.. Expected. OnFound doesn't give us a distance. OnDistanceChanged has to get fired in order for us to have a distance, so it comes right after. ### "Found" for an URL we already know to be found. This is presumably just a distance update.. so we should change our logging to make this more obvious. I can make a fix for this. ### Found second URL again? Could just be distance updates, but why 2 events back-to-back? Yea...that's unexpected. Not sure what's going on there. Going to look into this some more...
,
Jan 12 2017
If the first found doesn't have distance, how come we fire OnDistanceChanged event, and how come it has a distance estimate? Is it possible that its just due to race conditions that we have actually already updated the distance estimate by the time native gets the found event?
,
Jan 12 2017
> If the first found doesn't have distance, how come we fire OnDistanceChanged event To give the distance estimate. Not sure what you are asking. Nearby sends us an onFound event (without a distance estimate), and then they send us an OnDistanceChange event (with an estimate).
,
Jan 12 2017
If so, that explains the Java events, but not the Native events. After every OnFound there is an OnDistanceChanged and it always has an estimate. I would blame races of event delivery, but looking at the very first URL found (@01-12 10:43:53.691) it is followed with an OnDistanceChanged event in native before the second Nearby event. Is it possible that Nearby attaches distance estimate to the first found event in the case of cached results? Is it possible that native shouldn't actually have access to distance after OnFound most of the time, but there are races which made this series of logs happen to work?
,
Jan 23 2017
,
Feb 14 2017
An update from investigation from while ago: Looks like Chrome is doing the right thing, but there is some awkwardness with the Nearby api. We raised the issue but we should follow through with a small reproducing sample so they can better address the issue.
,
Jun 8 2018
|
||||||||
►
Sign in to add a comment |
||||||||
Comment 1 by mmo...@chromium.org
, Nov 22 2016