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

House number quest is asked again immediately after solving it #5545

Closed
rhhsm opened this issue Mar 21, 2024 · 26 comments · Fixed by #6111
Closed

House number quest is asked again immediately after solving it #5545

rhhsm opened this issue Mar 21, 2024 · 26 comments · Fixed by #6111
Assignees
Labels

Comments

@rhhsm
Copy link

rhhsm commented Mar 21, 2024

I hope what I saw today is not another case of #4258, but I was asked to solve a house number quest several times again after solving it during a quest update download. See screen shot (note it's asking for the house number of the apartment building with house number 4, i.e. the number is already known). Restarting the app made the quest go away. Maybe #5473 was not a complete solution?

Edit: I noticed in the history of the object here https://www.openstreetmap.org/way/1135323961/history that each time I answered the house number quest again, a new edit was made to the object. The house number quest was preceded with an "Is this building still under construction?" quest, which I answered with Yes. That answer apparently resulted in the activation of the house number quest, but not in an edit to the object (it's still under construction on the map).

Screenshot_20240321-161338

Versions affected
Android 10, StreetComplete 57.1

@rhhsm rhhsm added the bug label Mar 21, 2024
@westnordost
Copy link
Member

Uff. Oh no. Can you add the logs for time when this happened?

@rhhsm
Copy link
Author

rhhsm commented Mar 22, 2024

2024-03-21T16 0.txt
I hope this helps. The screenshot is from 16.13 so it must have happened in the few minutes before. There was another building under construction just east of the one I mentioned above that I deleted this morning because it doesn't exist (Way: 1135323962). Let me know if you need more help.

@westnordost
Copy link
Member

Summary:

  1. 16:11:37.937 - Download starts
  2. 16:11:40.290 - You answered MarkCompletedBuildingConstruction for way#1135323961, AddHousenumber, AddBuildingLevels, AddRoofShape are created and persisted
  3. 16:11:56.182 - Download finished, data is persisted, quests are created and persisted
  4. 16:11:56.459 - Second download starts
  5. 16:11:57.365 - Something triggers checking which quests apply for way#1135323961. AddHousenumber, AddBuildingLevels, AddRoofShape are created again.
  6. 16:12:11.892 - Download finished, data is persisted. Quests are created.
  7. 16:12:12.644 - You answered AddHousenumber for way#1135323961
  8. 16:12:13.719 - Persisted created quests from download
  9. 16:12:13.979 - Persisted quest creation after answering AddHousenumber quest
  10. 16:12:13.905 - You answered AddHousenumber for way#1135323961
  11. 16:12:14.347 - You answered AddHousenumber for way#1135323961
  12. 16:12:19.514 - You answered AddHousenumber for way#1135323961
  13. 16:12:31.249 - You answered AddHousenumber for way#1135323961
  14. 16:13:22.186 - You answered AddHousenumber for way#1135323961

Observations:

  • It looks like the actual problem occured after the download. Could point 8 and 9 have triggered this behavior? (= quests from download have been persisted and after that quest created as consequence of the answered quests are persisted)

Takeaways for now:

  • Copying the log from the log viewer should also include the log level for easier browsing
  • Creating/removing edits should be logged, too. Otherwise it is very difficult to divine what edits the user actually did
  • the "fetched x elements in y ms" log could probably be removed. It's clear that it is fast on any subsequent fetch since the cache has been implemented

@westnordost
Copy link
Member

westnordost commented Apr 5, 2024

blocked until new release

@westnordost westnordost added the blocked blocked by another issue label Apr 5, 2024
@rhhsm
Copy link
Author

rhhsm commented Apr 11, 2024

Had another case with a kerb height quest today https://www.openstreetmap.org/node/9480862703/history (happened while updating quests). Do you wan the log?

@westnordost
Copy link
Member

No. Next version will have some more logging, so maybe that will give a hint where this issue comes from.

@ratti

This comment was marked as resolved.

@westnordost westnordost removed the blocked blocked by another issue label Apr 28, 2024
@westnordost
Copy link
Member

Since v57.2 we have some additional logging in place. This might help finding the issue. So when this bug appears again, I'd appreciate if you posted the log here.

@westnordost westnordost added the feedback required more info is needed, issue will be likely closed if it is not provided label Oct 14, 2024
@westnordost
Copy link
Member

Can be reopened when it happens again. In that case, we need the log, as I added additional logging over six month ago.

@mnalis
Copy link
Member

mnalis commented Nov 27, 2024

Well, I think it probably still happens. My case is from SCEE 58.2 with extra SCEE quest, but it should have #5473 alleged fix (e2621c7 mentioned there should be present from v57.0-beta1 onwards AFAICT); yet the issue still happens.

(Un)fortunately it happens rather rarely (I notice it maybe once in a few months), so I don't have example from pure SC (as I mostly use SCEE nowadays)... It just so happens I had one of those today; here is example changeset 159639189 in which node 12377419129 has multiple answers for same quest v3-v6 -- it was offered even more times, but I gave up on answering the same quest)

While I have problems easily sharing logs (due to #5561 and me having some ~3500+ loglines today), I've manually limited the results in several time ranges and concatenated them, so hopefully I've managed to extract all related logs.

Here are the those logs (as mentioned, SCEE 58.2, but hopefully it still helps) that probably relate to the issue:
scee_duplicate_BenchMaterial_quest_20241126.txt

I'm suspecting it happened between timestamps 16:19-16:24.

@mnalis mnalis reopened this Nov 27, 2024
@westnordost
Copy link
Member

westnordost commented Nov 27, 2024

Do you have auto-sync on or did all that happen offline (i.e. can't be a result of something going wrong during upload)? Cause, I don't see node 12377419129 mentioned in the log.

@mnalis
Copy link
Member

mnalis commented Nov 27, 2024

Do you have auto-sync on or did all that happen offline (i.e. can't be a result of something going wrong during upload)?

No, I have Upload answers automatically = Off in settings. But mobile internet was mostly enabled so it could've being auto-downloading (or manually downloading) new areas (probably weren't downloading stuff though, as I was not moving much as I was adding dozen details in that park, but I can't guarantee that part. Definitely no uploads were being done at the time, though).

Cause, I don't see node 12377419129 mentioned in the log.

  • That bench was manually created by me in Things overlay just seconds (or minutes at most) before (see version 1 "Survey small map features"),
  • then backrest quest was solved in version 2 (which didn't repeat)
  • and then material quest was repeated several times afterwards (versions 3,4,5,6)

So I would expect that node to be one with "anonymous" negative numbers, as it didn't get official number 12377419129 until dozen hours later when I got home and uploaded all few hundred quests via WiFi.

@riQQ
Copy link
Collaborator

riQQ commented Nov 27, 2024

The relevant node in the logs is NODE#-2209.
The line [ElementEditsController] Add AddBenchMaterial for NODE#-2209 occurs 4 times, matching the 4 node versions V3-V6 created for this.

Logs
2024-11-26T16:21:40.263: W [OsmAvatarsDownload] Unable to download avatar for user id 172435
...
2024-11-26T16:21:41.254: I [AbstractOverlayForm] solve ThingsOverlay for null, extra: false
2024-11-26T16:21:41.256: D [ElementEditsController] Add ThingsOverlay for 
2024-11-26T16:21:41.262: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:21:41.265: D [OsmQuestController] Created AddBenchBackrest for NODE#-2209
2024-11-26T16:21:41.265: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:21:41.265: D [OsmQuestController] Created AddBenchMaterial for NODE#-2209
2024-11-26T16:21:41.268: I [OsmQuestController] Created 3 quests for 1 updated elements in 7ms
2024-11-26T16:21:41.268: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchBackrest), OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial), OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: []
2024-11-26T16:21:41.269: I [OsmQuestController] Persisted 3 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:21:41.269: I [EditHistoryController] history: add edit ThingsOverlay for []
2024-11-26T16:21:41.270: I [MainFragment] edited: ThingsOverlay
2024-11-26T16:21:41.271: I [MainFragment] closeBottomSheet while showing null
2024-11-26T16:21:42.804: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchBackrest)
2024-11-26T16:21:43.035: I [MapDataDownload] Downloaded 22796 nodes, 3506 ways and 41 relations in 34.2s
2024-11-26T16:21:43.580: I [AbstractOsmQuestForm] solve AddBenchBackrest for NODE#-2209, extra: false, in TagEditor: false
2024-11-26T16:21:43.581: D [ElementEditsController] Add AddBenchBackrest for NODE#-2209
2024-11-26T16:21:43.825: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:21:43.828: D [OsmQuestController] Created AddBenchMaterial for NODE#-2209
2024-11-26T16:21:43.828: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:21:43.828: I [OsmQuestController] Created 2 quests for 1 updated elements in 3ms
2024-11-26T16:21:43.829: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial), OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchBackrest)]
2024-11-26T16:21:43.829: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchBackrest)
2024-11-26T16:21:43.832: I [EditHistoryController] history: add edit AddBenchBackrest for [NODE#-2209]
2024-11-26T16:21:43.832: I [OsmQuestController] Persisted 2 new and removed 1 already resolved quests in 0.0s
2024-11-26T16:21:43.833: I [MainFragment] edited: AddBenchBackrest
2024-11-26T16:21:43.835: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:21:43.835: I [MainFragment] closeBottomSheet while showing null
2024-11-26T16:21:43.946: D [OsmQuestController] AddPlaceName: Found 34 quests in 9ms
...
2024-11-26T16:21:44.301: D [OsmQuestController] AddSuspectedOneway: Found 0 quests in 361ms
2024-11-26T16:21:44.301: I [OsmQuestController] Created 11374 quests for bbox in 0.4s
2024-11-26T16:21:45.178: I [AbstractOsmQuestForm] solve AddBenchMaterial for NODE#-2209, extra: false, in TagEditor: false
2024-11-26T16:21:45.179: D [ElementEditsController] Add AddBenchMaterial for NODE#-2209
2024-11-26T16:21:45.231: I [OsmQuestController] Persisted 11374 new and removed 0 already resolved quests in 0.7s
2024-11-26T16:21:45.235: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:21:45.235: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:21:45.236: I [OsmQuestController] Created 1 quests for 1 updated elements in 1ms
2024-11-26T16:21:45.236: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)]
2024-11-26T16:21:45.236: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:21:45.239: I [OsmQuestController] Persisted 1 new and removed 1 already resolved quests in 0.0s
2024-11-26T16:21:45.239: I [EditHistoryController] history: add edit AddBenchMaterial for [NODE#-2209]
2024-11-26T16:21:45.241: I [MainFragment] edited: AddBenchMaterial
2024-11-26T16:21:45.243: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:21:45.243: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:21:45.246: I [VisibleQuestsSource] added 6486, deleted 0
2024-11-26T16:21:45.248: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:21:45.250: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:21:45.251: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: []
2024-11-26T16:21:45.251: I [OsmQuestController] Created 1 quests for 1 updated elements in 2ms
2024-11-26T16:21:45.251: I [OsmQuestController] Persisted 1 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:21:45.254: D [OsmoseDao] downloading for bbox: BoundingBox(min=LatLon(latitude=45.80712702143074, longitude=15.948044889356089), max=LatLon(latitude=45.815014199341924, longitude=15.95936035183956)) using request https://osmose.openstreetmap.fr/api/0.3/issues.csv?zoom=16&item=xxxx&level=1&limit=500&bbox=15.948044889356089%2C45.80712702143074%2C15.95936035183956%2C45.815014199341924
2024-11-26T16:21:46.679: D [OsmoseDao] got 11 problems
2024-11-26T16:21:47.038: I [MapDataController] Persisted 26826 and deleted 0 elements and geometries in 4.0s
2024-11-26T16:21:47.038: I [VisibleQuestsSource] added [ExternalSourceQuestKey(id=a79503ca-c962-3482-a897-b5791ec1d922, source=osmose), ExternalSourceQuestKey(id=78249614-0fb3-bf43-e040-2a4aea097ca2, source=osmose), ExternalSourceQuestKey(id=dd0fd317-40c6-7bf4-965c-06e2d876ecb7, source=osmose)], deleted: []
2024-11-26T16:21:47.040: I [Download] Finished download (1.6 km², bbox: 45.8058285,15.9466553,45.8173151,15.9631348) in 38.2s
2024-11-26T16:21:47.040: I [QuestAutoSyncer] Checking whether to automatically download new quests at 45.8110708,15.9537022
2024-11-26T16:21:47.044: I [QuestAutoSyncer] All downloaded in radius of 438 meters around user (9 tiles)
2024-11-26T16:21:49.334: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSurface)
2024-11-26T16:21:50.762: I [AbstractOsmQuestForm] solve AddPathSurface for WAY#1217985917, extra: false, in TagEditor: false
2024-11-26T16:21:50.763: D [ElementEditsController] Add AddPathSurface for WAY#1217985917
2024-11-26T16:21:50.770: I [MapDataWithEditsSource] updated: [WAY#1217985917], deleted: []
2024-11-26T16:21:50.774: D [OsmQuestController] Created AddPathSmoothness for WAY#1217985917
2024-11-26T16:21:50.774: D [OsmQuestController] Created AddWayLit for WAY#1217985917
2024-11-26T16:21:50.774: D [OsmQuestController] Created AddFootwayWidth for WAY#1217985917
2024-11-26T16:21:50.776: I [OsmQuestController] Created 3 quests for 1 updated elements in 7ms
2024-11-26T16:21:50.776: I [VisibleQuestsSource] added [OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSmoothness), OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddWayLit)], deleted: [OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSurface)]
2024-11-26T16:21:50.777: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSurface)
2024-11-26T16:21:50.781: I [OsmQuestController] Persisted 3 new and removed 1 already resolved quests in 0.0s
2024-11-26T16:21:50.781: I [EditHistoryController] history: add edit AddPathSurface for [WAY#1217985917]
2024-11-26T16:21:50.782: I [MainFragment] edited: AddPathSurface
2024-11-26T16:21:50.786: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSmoothness)
2024-11-26T16:21:50.792: I [MainFragment] closeBottomSheet while showing null
2024-11-26T16:21:59.154: I [AbstractOsmQuestForm] solve AddPathSmoothness for WAY#1217985917, extra: false, in TagEditor: false
2024-11-26T16:21:59.156: D [ElementEditsController] Add AddPathSmoothness for WAY#1217985917
2024-11-26T16:21:59.163: I [MapDataWithEditsSource] updated: [WAY#1217985917], deleted: []
2024-11-26T16:21:59.166: D [OsmQuestController] Created AddWayLit for WAY#1217985917
2024-11-26T16:21:59.167: D [OsmQuestController] Created AddFootwayWidth for WAY#1217985917
2024-11-26T16:21:59.167: I [OsmQuestController] Created 2 quests for 1 updated elements in 5ms
2024-11-26T16:21:59.167: I [VisibleQuestsSource] added [OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddWayLit)], deleted: [OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSmoothness)]
2024-11-26T16:21:59.168: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddPathSmoothness)
2024-11-26T16:21:59.172: I [OsmQuestController] Persisted 2 new and removed 1 already resolved quests in 0.0s
2024-11-26T16:21:59.172: I [EditHistoryController] history: add edit AddPathSmoothness for [WAY#1217985917]
2024-11-26T16:21:59.172: I [MainFragment] edited: AddPathSmoothness
2024-11-26T16:21:59.176: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddWayLit)
2024-11-26T16:21:59.176: I [MainFragment] closeBottomSheet while showing null
2024-11-26T16:22:05.581: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=WAY, elementId=1217985917, questTypeName=AddWayLit)
2024-11-26T16:22:07.462: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:08.838: I [AbstractOsmQuestForm] solve AddBenchMaterial for NODE#-2209, extra: false, in TagEditor: false
2024-11-26T16:22:08.840: D [ElementEditsController] Add AddBenchMaterial for NODE#-2209
2024-11-26T16:22:08.847: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:22:08.852: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:22:08.852: I [OsmQuestController] Created 1 quests for 1 updated elements in 6ms
2024-11-26T16:22:08.852: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: []
2024-11-26T16:22:08.854: I [OsmQuestController] Persisted 1 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:22:08.854: I [EditHistoryController] history: add edit AddBenchMaterial for [NODE#-2209]
2024-11-26T16:22:08.855: I [MainFragment] edited: AddBenchMaterial
2024-11-26T16:22:08.857: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:08.857: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:10.820: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:12.076: I [AbstractOsmQuestForm] solve AddBenchMaterial for NODE#-2209, extra: false, in TagEditor: false
2024-11-26T16:22:12.077: D [ElementEditsController] Add AddBenchMaterial for NODE#-2209
2024-11-26T16:22:12.085: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:22:12.093: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:22:12.093: I [OsmQuestController] Created 1 quests for 1 updated elements in 8ms
2024-11-26T16:22:12.093: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: []
2024-11-26T16:22:12.095: I [OsmQuestController] Persisted 1 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:22:12.095: I [EditHistoryController] history: add edit AddBenchMaterial for [NODE#-2209]
2024-11-26T16:22:12.096: I [MainFragment] edited: AddBenchMaterial
2024-11-26T16:22:12.097: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:12.098: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:15.558: I [Download] Starting download (0.2 km², bbox: 45.8096576,15.9521484,45.8134865,15.9576416)
2024-11-26T16:22:15.562: V [MapTilesDownload] Tile 0/0/0 in cache
2024-11-26T16:22:15.562: V [MapTilesDownload] Tile 13/4459/2920 in cache
2024-11-26T16:22:15.563: V [MapTilesDownload] Tile 10/557/365 in cache
2024-11-26T16:22:15.563: V [MapTilesDownload] Tile 12/2229/1460 in cache
2024-11-26T16:22:15.568: V [MapTilesDownload] Tile 14/8918/5841 in cache
2024-11-26T16:22:15.568: V [MapTilesDownload] Tile 16/35672/23364 in cache
2024-11-26T16:22:15.569: V [MapTilesDownload] Tile 15/17836/11682 in cache
2024-11-26T16:22:15.569: V [MapTilesDownload] Tile 3/4/2 in cache
2024-11-26T16:22:15.569: V [MapTilesDownload] Tile 7/69/45 in cache
2024-11-26T16:22:15.571: V [MapTilesDownload] Tile 5/17/11 in cache
2024-11-26T16:22:15.571: V [MapTilesDownload] Tile 1/1/0 in cache
2024-11-26T16:22:15.571: V [MapTilesDownload] Tile 11/1114/730 in cache
2024-11-26T16:22:15.572: V [MapTilesDownload] Tile 8/139/91 in cache
2024-11-26T16:22:15.572: V [MapTilesDownload] Tile 2/2/1 in cache
2024-11-26T16:22:15.573: V [MapTilesDownload] Tile 6/34/22 in cache
2024-11-26T16:22:15.573: V [MapTilesDownload] Tile 4/8/5 in cache
2024-11-26T16:22:15.573: V [MapTilesDownload] Tile 9/278/182 in cache
2024-11-26T16:22:15.573: I [MapTilesDownload] Downloaded 17 tiles (0kB downloaded, 697kB already cached) in 0.0s
2024-11-26T16:22:15.823: I [NotesDownload] Downloaded 0 notes in 0.3s
2024-11-26T16:22:15.828: I [NoteController] Persisted 0 and deleted 0 notes in 0.0s
2024-11-26T16:22:16.016: I [MapDataDownload] Downloaded 3431 nodes, 451 ways and 8 relations in 0.5s
2024-11-26T16:22:16.064: D [OsmQuestController] AddHousenumber: Found 6 quests in 2ms
...
2024-11-26T16:22:16.326: I [OsmQuestController] Created 1611 quests for bbox in 0.3s
2024-11-26T16:22:16.384: I [OsmQuestController] Persisted 1611 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:22:16.386: I [VisibleQuestsSource] added 890, deleted 0
2024-11-26T16:22:16.398: D [OsmoseDao] downloading for bbox: BoundingBox(min=LatLon(latitude=45.80965764997508, longitude=15.9521484375), max=LatLon(latitude=45.81348649679971, longitude=15.9576416015615)) using request https://osmose.openstreetmap.fr/api/0.3/issues.csv?zoom=16&item=xxxx&level=1&limit=500&bbox=15.9521484375%2C45.80965764997508%2C15.9576416015615%2C45.81348649679971
2024-11-26T16:22:16.549: I [MapDataController] Persisted 4372 and deleted 0 elements and geometries in 0.5s
2024-11-26T16:22:17.724: D [OsmoseDao] got 3 problems
2024-11-26T16:22:17.731: I [VisibleQuestsSource] added [ExternalSourceQuestKey(id=78249614-0fb3-bf43-e040-2a4aea097ca2, source=osmose)], deleted: []
2024-11-26T16:22:17.732: I [Download] Finished download (0.2 km², bbox: 45.8096576,15.9521484,45.8134865,15.9576416) in 2.2s
2024-11-26T16:22:17.734: I [QuestAutoSyncer] Checking whether to automatically download new quests at 45.8110708,15.9537022
2024-11-26T16:22:17.740: I [QuestAutoSyncer] All downloaded in radius of 438 meters around user (9 tiles)
2024-11-26T16:22:19.077: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:20.352: I [AbstractOsmQuestForm] solve AddBenchMaterial for NODE#-2209, extra: false, in TagEditor: false
2024-11-26T16:22:20.353: D [ElementEditsController] Add AddBenchMaterial for NODE#-2209
2024-11-26T16:22:20.360: I [MapDataWithEditsSource] updated: [NODE#-2209], deleted: []
2024-11-26T16:22:20.365: D [OsmQuestController] Created ShowSeating for NODE#-2209
2024-11-26T16:22:20.366: I [OsmQuestController] Created 1 quests for 1 updated elements in 6ms
2024-11-26T16:22:20.366: I [VisibleQuestsSource] added [OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=ShowSeating)], deleted: []
2024-11-26T16:22:20.367: I [OsmQuestController] Persisted 1 new and removed 0 already resolved quests in 0.0s
2024-11-26T16:22:20.367: I [EditHistoryController] history: add edit AddBenchMaterial for [NODE#-2209]
2024-11-26T16:22:20.368: I [MainFragment] edited: AddBenchMaterial
2024-11-26T16:22:20.370: I [MainFragment] showQuestDetails for OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:20.370: I [MainFragment] closeBottomSheet while showing OsmQuestKey(elementType=NODE, elementId=-2209, questTypeName=AddBenchMaterial)
2024-11-26T16:22:30.431: I [AbstractOverlayForm] solve ThingsOverlay for null, extra: false
2024-11-26T16:22:30.432: D [ElementEditsController] Add ThingsOverlay for 
2024-11-26T16:22:30.439: I [MapDataWithEditsSource] updated: [NODE#-2210], deleted: []

@Helium314
Copy link
Collaborator

I'll go through this log in the next few days, but note that SCEE has some code changes that might introduce this bug. So maybe this doesn't concern SC.

@Helium314
Copy link
Collaborator

What I read from the log (in order):

  1. quests from a download are created while the quest form is open
  2. the quest is solved
  3. the quests from download are persisted in DB
  4. new quests for bench are created
  5. visible quests source gets a new quest for bench, and one to delete (in SCEE this can happen before 6., in SC it cannot)
  6. bench quests are persisted in DB (including the deletion)
  7. visible quests source gets new quests from downloaded area (which I assume includes the bench quest)

Looke very much like the download completes and persists quests before the single edit, but is overtaken by the single edit somewhere on the way to VisibleQuestsSource.updateVisibleQuests. This can happen in OsmQuestController.onUpdated (filtering quests hidden by notes), and in VisibleQuestsSource.osmQuestSourceListener.onUpdated (filtering invisible quests).
It's not explicitly in the log, but I'm fairly certain that the download (mapDataSourceListener.onReplacedForBBox) called OsmQuestController.onUpdated just a few ms before the single edit (mapDataSourceListener.onUpdated).

SCEE is more susceptible to this issue, but as far as I understand it can occur in both SCEE and SC.

@westnordost
Copy link
Member

westnordost commented Dec 27, 2024 via email

@Helium314
Copy link
Collaborator

hmm, does that explain why it also persists? I.e. the quest wont go away even after solving it multiple times.

I think so. The quest is not in the database, so it's not in previousQuests, which means it will not be in obsoleteQuestKeys and thus will not be forwarded to VisibleQuestsSource in deletedKeys.
In general, if a quest is not in the database, solving it will not trigger removal.

@mnalis
Copy link
Member

mnalis commented Dec 27, 2024

Thanks a lot for the investigation @Helium314 !

Looke very much like the download completes and persists quests before the single edit, but is overtaken by the single edit somewhere on the way to VisibleQuestsSource.updateVisibleQuests. This can happen in OsmQuestController.onUpdated (filtering quests hidden by notes), and in VisibleQuestsSource.osmQuestSourceListener.onUpdated (filtering invisible quests).

So, if I'm getting this correctly, if one were to add artificial delays (e.g. Thread.sleep(1000)?) in OsmQuestController.onUpdated and VisibleQuestsSource.osmQuestSourceListener.onUpdated (along with some extra logging), one should be able to make debug build where this bug is much easier to reproduce (so can be used to test eventual solutions)?

Helium314 added a commit that referenced this issue Jan 19, 2025
description in linked issue
@Helium314
Copy link
Collaborator

I added a test that reproduces what I think is happening.
In the test, first onReplacedForBBox is called (what a download would do), then onUpdated is called (what solving a quest would do).

  • Case 1: just run it -> test fails
    createQuestsForBBox is slow enough that the call to mapDataListener.onUpdated finishes first.
    The result is the same as the problem @mnalis reported, but in the provided log createQuestsForBBox was already done, so we have a slightly different situation.
  • Case 2: uncomment the delay (line 405) -> test passes
    The delay is long enough for onReplacedForBBox to call osmQuestController.onUpdated before mapDataListener.onUpdated starts (note that with a shorter delay the test result is more or less random, depends on the system running the test)
  • Case 3: uncomment the delay, and add a delay in osmQuestController.onUpdated -> test fails
    The added delay is for simulating the additional time for filtering by hidden quests / blacklisted positions. I used runBlocking { delay(added.size * 10L) }.
    The delay is long enough so the second call to osmQuestController.onUpdated finishes first, result is the same as in Case 1. This is what I suspect happed to @mnalis above.

@Helium314
Copy link
Collaborator

Without proper investigation: maybe the solution could be similar to MapDataWithEditsSource.updatesWhileReplacingBBox

@westnordost
Copy link
Member

westnordost commented Jan 22, 2025

Thank you for this test case! Unfortunately, after having a long look at it, I didn't follow, the test case doesn't help me understand the cause.

I would like to avoid a solution like updatesWhileReplacingBBox because it is somewhat complex. Couldn't more aggressive synchronized help?

TBH I still don't quite understand the flow after an hour or so of looking at it and where exactly the race condition is located. I mean, there are synchronized sections in the OsmQuestController.
Also, any edit done while new data in a bbox is being persisted AND any subsequent updates called through the MapDataWithEditsSource.Listener.onReplacedForBBox will be replayed on top of the new data.
If you understand where exactly is the issue, would you mind showing the two race conditioning threads in a more graphic manner? (e.g. a table with two columns showing the order of the functions called)

@Helium314
Copy link
Collaborator

I would like to avoid a solution like updatesWhileReplacingBBox because it is somewhat complex. Couldn't more aggressive synchronized help?

Yes, that could definitely solve the issue. The drawback would be less responsive UI when solving quests while quests are created / persisted (bottom sheet is closed only after quest edit is persisted, and if that needs to wait for onReplacedForBbox it might take a few seconds).

TBH I still don't quite understand the flow after an hour or so of looking at it and where exactly the race condition is located. I mean, there are synchronized sections in the OsmQuestController.

Calls to mapDataSourceListener.onUpdated and mapDataSourceListener.onReplacedForBbox should call onUpdated in the same order they are called, and onUpdated needs to call listeners in the same order it is called.

If you understand where exactly is the issue, would you mind showing the two race conditioning threads in a more graphic manner? (e.g. a table with two columns showing the order of the functions called)

I'll try.

download mnalis
starts looks for important quests to solve
finishes (including persisting OSM data) opens AddBenchMaterial
creates quests looks at quest form
finishes creating quests still looks at quest form
persists quest to DB solves AddBenchMaterial
persisted quests waits for quest form to close
"slowly" crawling around somewhere in onUpdated, which is called right after quests are persisted creates and persists new quests for that bench and calls onUpdated, which promptly finishes and thus VisibleQuestsSource removes AddBenchMaterial
finishes onUpdated, so quests from download are shown waits
finished sees AddBenchMaterial popping up again

Key points:

  • quests created form download include that AddBenchMaterial quest, because the quest wasn't solved when quest creation started
  • AddBenchMaterial is solved after quests from download are created, but VisibleQuestsSource is informed about solved quests before being informed about quests created from download
    • so AddBenchMaterial is first removed from visible quests, but re-added as part of quests from download
  • solution: functions in mapDataSourceListener should call VisibleQuestsSource.onUpdated in the order they are called (actually the also need to wait for VisibleQuestsSource.onUpdated to return to be really safe)

@westnordost
Copy link
Member

Thank you, will look at it again more closely tomorrow! Hopefully I can then come out with a proper and more concrete suggestion or solution. Could you update the table to show exactly the order of things where it matters? E.g.

A takes an action that takes some time to complete...B takes action an finishes earlier
bla blabla bla

After all, nothing really happens in parallel, and that one task "reingrätschen" into another while that one is still executing is the prime reason for any race condition. It would be most graphic to see clearly depicted in that table, where that happens.

@Helium314
Copy link
Collaborator

download mnalis
starts -
finishes (including persisting OSM data) -
_ opens AddBenchMaterial
creates quests for downloaded area (includes AddBenchMaterial for the element mnalis is looking at) -
finishes creating quests -
persisting quest to DB solves AddBenchMaterial
calls onUpdated after persisting quests -
_ creates new quests for that bench
_ persists new quests for that bench to DB / removes old one
_ calls onUpdated
_ finishes onUpdated and thus VisibleQuestsSource has already removed the solved AddBenchMaterial quest
finishes onUpdated, so quests from download are shown (including that specifc AddBenchMaterial quest) -
_ sees AddBenchMaterial popping up again

In my understanding there are 2 sections where a small (single element) onUpdated can overtake a larger one (11k quests), simply because the execution time should scale linearly with the number of quests:

@westnordost
Copy link
Member

Now I understand, yes, now I can follow!

I agree that there are two points where one thread could overtake the other, the first being much more likely than the second.

@westnordost westnordost removed the feedback required more info is needed, issue will be likely closed if it is not provided label Jan 27, 2025
@westnordost westnordost self-assigned this Jan 27, 2025
@westnordost
Copy link
Member

While looking at the code, it's somewhat odd that OsmQuestSource does not include all the OSM quests, but only those that are not hidden by the user. I.e. OsmQuestController also manages OsmQuestsHiddenDao.

It seems to me on first glance that it would make more sense to have another QuestsHiddenController that would manage both OsmQuestsHiddenDao and OsmNoteQuestsHiddenDao rather than to have the logic whether a quest is hidden or not be scattered between two classes (OsmQuestController and VisibleQuestsSource).

On the other hand, OsmQuestsHidden* classes kind of belong to the osmquests package from the data point of view. 🤔

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants