House number quest is asked again immediately after solving it

[rhhsm]

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).

Versions affected Android 10, StreetComplete 57.1

[westnordost]

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

[rhhsm]

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]

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]

blocked until new release

[rhhsm]

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]

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

[ratti]

I believe #5569 is not related to this ticket, but just a buggy attribute dependency. I have commented there how I could resolve that issue for me. For reproduction I added a link to another node that still has the issue.

I cannot reopen #5569 , feel free to check that comment: https://github.com/streetcomplete/StreetComplete/issues/5569#issuecomment-2052136668

Let me know if I can support.

[westnordost]

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]

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

[mnalis]

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 (e2621c754ea3da447950d19b1bde72208177656c 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 https://github.com/streetcomplete/StreetComplete/issues/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.

[westnordost]

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]

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]

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]

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]

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]

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

El 27 de diciembre de 2024 8:34:59 CET, Helium314 @.***> escribió:

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.

-- Reply to this email directly or view it on GitHub: https://github.com/streetcomplete/StreetComplete/issues/5545#issuecomment-2563415012 You are receiving this because you modified the open/close state.

Message ID: @.***>

[Helium314]

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]

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]

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]

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

[westnordost]

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]

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]

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 bla	bla 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]

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:

• filtering hidden quests
• filtering visible quests

[westnordost]

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]

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. 🤔