crash without indication

[caver456]

GUI closes and program appears to end; powershell returns to prompt. This happens at various places:

• after adding one (or more) assignments to incident map:

10:58:18 [sartopo_bg:1458:INFO] newFeatureCallback: class=Assignment  title=  id=20ab6aa8-b1cd-4cbd-ada5-ef1d6015e77d
10:58:18 [sartopo_bg:1125:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
10:58:18 [sartopo_bg:1127:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
Could not parse stylesheet of object QLineEdit(0x3bc0488, name = "debriefLinkLight")
PS C:\Users\caver\Documents\GitHub\plans_console>

Note the sytlesheet parse issue is probably not the cause of the crash, based on subsequent run with more trace lines:

11:03:10 [sartopo_bg:1127:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
11:03:10 [sartopo_bg:1501:INFO] t2
11:03:10 [sartopo_bg:1596:INFO] t3
Could not parse stylesheet of object QLineEdit(0x42fb290, name = "incidentLinkLight")
11:03:10 [sartopo_bg:1598:INFO] t4

and

11:03:15 [sartopo_bg:1127:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
11:03:15 [sartopo_bg:1501:INFO] t2
11:03:15 [sartopo_bg:1596:INFO] t3
11:03:15 [sartopo_bg:1598:INFO] t4
Could not parse stylesheet of object QLineEdit(0x42fb340, name = "debriefLinkLight")
11:03:15 [sartopo_bg:1458:INFO] newFeatureCallback: class=Assignment  title=  id=ce53d8b5-ca64-4948-9aa0-2985b766b73b

• after deleting incident map assignments:

11:04:08 [sartopo_python:433:INFO]   Updating "ids"
11:04:08 [sartopo_python:498:INFO] cleaned up 10 feature(s) from the cache:['bcdc236c-a710-49d5-8a2e-29fadc1c0e48', '46101b0e-493d-404d-b388-9cf8d2bb533c', 'bc699d10-5c6c-4981-8ff2-2437d755960d', '23057119-cec6-4386-b86f-392651aca89d', '3f118c07-f34d-430b-aaa9-2b316ea7051f', '15a6c49c-f6d6-46f5-9659-366f2d781820', 'ce53d8b5-ca64-4948-9aa0-2985b766b73b', '82e1a71f-fc05-483a-b67c-3b97fa500e96', '1a7b2cb5-62d8-42fa-a88d-4ed954f6c2e2', '4f65d1aa-2074-42ce-a918-0bc84c31b710']
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id bcdc236c-a710-49d5-8a2e-29fadc1c0e48 :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 46101b0e-493d-404d-b388-9cf8d2bb533c :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id bc699d10-5c6c-4981-8ff2-2437d755960d :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 23057119-cec6-4386-b86f-392651aca89d :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 3f118c07-f34d-430b-aaa9-2b316ea7051f :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 15a6c49c-f6d6-46f5-9659-366f2d781820 :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id ce53d8b5-ca64-4948-9aa0-2985b766b73b :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 82e1a71f-fc05-483a-b67c-3b97fa500e96 :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 1a7b2cb5-62d8-42fa-a88d-4ed954f6c2e2 :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
11:04:08 [sartopo_bg:1844:INFO] deletedFeatureCallback called for source map feature with id 4f65d1aa-2074-42ce-a918-0bc84c31b710 :
11:04:08 [sartopo_bg:1906:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
PS C:\Users\caver\Documents\GitHub\plans_console>

Note the crash happens after all 10 deletedFeatureCallback calls; maybe this indicates it's happening in the sync thread?

[caver456]

haven't been able to reproduce the crash lately. Using objgraph.show_growth() to identify memory leaks. So far the only giveaway is that every sync call corresponds with 'SplitResult +1'. Even if this is not related to the crash, it would be good to plug the leak.

SplitResult shows up in urllib as an intermedate class and result class for various operations.

Try commenting out various parts of doSync to narrow down what is creating that 'SplitResult +1' entry. Does SplitResult +1 still show up on every sync?

• commenting out everything after rj=self.sendRequest thru but not including self.syncing=False --> NO
• commenting out all of part 2 (if len(rjrsf)>0:) --> YES
• also commenting out all of part 3 --> YES (note that the SplitResult line occurs about 1 second after the start of the doSync command; probably not relevant, since objgraph.show_growth() occurs during tick())
• also commenting out everything before part 2 (after 'if rj and rj['status']=='ok':' - replacing that clause with 'pass' --> NO (these last two appear to be a good dividing line)

the line that makes the difference is self.lastSuccessfulSyncTimeStamp=rj['result']['timestamp']. Comment that line out and the 'SplitResult +1' lines do not happen. Uncomment it and they do. Strange. The only thing that consumes that value is the next sync (inside the sendRequest).

[caver456]

Looks like it is inside self.s.get(url,timeout=timeout):

15:06:24 [sartopo_python:406:INFO] sync
15:06:24 [sartopo_python:621:INFO] start of sendRequest:
15:06:24 [sartopo_python:690:INFO] sendRequest before "self.s.get":
15:06:24 [sartopo_python:693:INFO] sendRequest after "self.s.get":
SplitResult        7        +1
15:06:24 [sartopo_python:738:INFO] sendRequest before "if returnJson":
15:06:24 [sartopo_python:780:INFO] end of sendRequest with returnJson=ALL:
15:06:29 [sartopo_python:406:INFO] sync

Looks googleable.

[caver456]

DIdn't find any reaolutions to this on the web. Will assume it's not really a problem for now, and move on - but should do some long-running big-data profiling before getting too much further along. Here's one reference to someone else that saw the issue, but there was no resolution and no determination of severity: https://github.com/psf/requests/issues/4191#issuecomment-410592568

[caver456]

Note, the +1 doesn't happen if lastSuccessfulSyncTimestamp is never updated, i.e. if the since request is always for 0. Moving on.

[caver456]

Ugh. The crash still happens.

1) start syncing (thru plans console) 2) add several unnamed assignments 3) delete them with bulk ops

Entire log:

PS C:\Users\caver\Documents\GitHub\plans_console> python .\plans_console.py
15:30:29 [plans_console:270:INFO] Plans Console startup at Sat Feb 19 2022 15:30:29
15:30:29 [plans_console:1092:INFO] loading...
15:30:29 [plans_console:341:INFO] args:Namespace(mapID=None, debriefMapID=None, norestore=False, nourl=False)
15:30:30 [plans_console:859:INFO] Get:[{'incidentURL': 'http://localhost:8080/m/RDE', 'debriefURL': 'http://localhost:8080/m/LGA'}, {'csv': 'watched.csv%offset.csv%[]'}, {}, {}]
15:30:30 [plans_console:497:INFO] Creating SartopoSession with domainAndPort=localhost:8080 mapID=RDE
15:30:31 [sartopo_python:341:INFO] This session was requested to use the Fiddler proxy.  Verifying that the proxy host is running...
15:30:33 [sartopo_python:345:WARNING] Fiddler proxy host does not appear to be responding correctly; this session will not use Fiddler proxies.
15:30:33 [sartopo_python:649:INFO] sending post to http://localhost:8080/api/v0/userdata
15:30:33 [sartopo_python:674:INFO] {'map': {'center': [-120, 39], 'zoom': 13}}
15:30:36 [sartopo_python:433:INFO]   Updating "ids"
15:30:36 [plans_console:514:INFO] Successfully connected.
15:30:36 [sartopo_bg:204:INFO] Debrief Map Generator startup at Sat Feb 19 2022 15:30:36
15:30:36 [sartopo_python:649:INFO] sending post to http://localhost:8080/api/v0/userdata
15:30:36 [sartopo_python:674:INFO] {'map': {'center': [-120, 39], 'zoom': 13}}
15:30:40 [sartopo_python:433:INFO]   Updating "ids"
15:30:40 [sartopo_bg:343:INFO] Source map argument = SartopoSession instance: localhost:8080/m/RDE
15:30:40 [sartopo_bg:442:INFO] sts1.apiVersion:1
15:30:40 [sartopo_bg:443:INFO] sts2.apiVersion:1
15:30:40 [sartopo_python:569:INFO] refresh requested: 3672ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
15:30:40 [sartopo_bg:940:INFO] initDmd called
15:30:40 [sartopo_bg:943:INFO] reading correlation file dmg_RDE_LGA.json
15:30:40 [sartopo_bg:945:INFO] {
   "outings": {},
   "corr": {}
}
15:30:40 [sartopo_bg:1459:INFO] newFeatureCallback: class=Marker  title=IC  id=a953f527-8690-4888-8902-dbe79d25cc60
15:30:40 [sartopo_bg:1497:INFO]  no correspondence entry found; adding the feature to the debrief map
15:30:40 [sartopo_bg:1366:INFO] creating marker 'IC' in default folder
15:30:40 [sartopo_python:649:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Marker
15:30:40 [sartopo_python:674:INFO] {'properties': {'class': 'Marker', 'updated': 0, 'marker-color': None, 'marker-symbol': 'cp', 'marker-size': 1, 'marker-rotation': None, 'title': 'IC', 'description': ''}, 'geometry': {'type': 'Point', 'coordinates': [-121.31961822509767, 39.51834388059882]}, 'type': 'Feature'}
15:30:40 [sartopo_python:569:INFO] refresh requested: 3901ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
15:30:40 [sartopo_python:582:INFO] Sartopo syncing initiated.
15:31:05 [sartopo_bg:1459:INFO] newFeatureCallback: class=Assignment  title=  id=6a468db6-2801-4ef5-a307-7e12278f3279
15:31:05 [sartopo_bg:1126:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
15:31:05 [sartopo_bg:1128:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
15:31:10 [sartopo_bg:1459:INFO] newFeatureCallback: class=Assignment  title=  id=8b7c91e7-d6f1-4059-b0b6-308c1c64f698
15:31:10 [sartopo_bg:1126:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
15:31:10 [sartopo_bg:1128:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
15:31:10 [sartopo_bg:1459:INFO] newFeatureCallback: class=Assignment  title=  id=fc949cf6-0e07-4675-acb0-bb34716149d2
15:31:10 [sartopo_bg:1126:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
15:31:10 [sartopo_bg:1128:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
15:31:16 [sartopo_bg:1459:INFO] newFeatureCallback: class=Assignment  title=  id=55663338-b09a-4afa-a328-eca84d23b15b
15:31:16 [sartopo_bg:1126:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
15:31:16 [sartopo_bg:1128:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
15:31:16 [sartopo_bg:1459:INFO] newFeatureCallback: class=Assignment  title=  id=48bfb1e7-8a95-4c96-8393-053d1b264542
15:31:16 [sartopo_bg:1126:INFO] properties:
{
   "creator": "3MA660",
   "previousEfforts": "",
   "description": "",
   "title": " ",
   "operationalPeriodId": "",
   "priority": "LOW",
   "unresponsivePOD": "LOW",
   "transportation": "",
   "gpstype": "TRACK",
   "responsivePOD": "LOW",
   "number": "",
   "primaryFrequency": "",
   "preparedBy": "",
   "teamSize": 0,
   "letter": "",
   "cluePOD": "LOW",
   "preparedOn": 0,
   "class": "Assignment",
   "updated": 0,
   "resourceType": "GROUND",
   "status": "DRAFT",
   "secondaryFrequency": ""
}
15:31:16 [sartopo_bg:1128:INFO] addOuting called for assigment "" that does not have both letter and number; skipping
15:31:47 [sartopo_python:433:INFO]   Updating "ids"
15:31:47 [sartopo_python:498:INFO] cleaned up 5 feature(s) from the cache:['8b7c91e7-d6f1-4059-b0b6-308c1c64f698', '48bfb1e7-8a95-4c96-8393-053d1b264542', 'fc949cf6-0e07-4675-acb0-bb34716149d2', '55663338-b09a-4afa-a328-eca84d23b15b', '6a468db6-2801-4ef5-a307-7e12278f3279']
15:31:47 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 8b7c91e7-d6f1-4059-b0b6-308c1c64f698 :
15:31:47 [sartopo_bg:1903:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
15:31:47 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 48bfb1e7-8a95-4c96-8393-053d1b264542 :
15:31:47 [sartopo_bg:1903:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
15:31:47 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id fc949cf6-0e07-4675-acb0-bb34716149d2 :
15:31:47 [sartopo_bg:1903:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
Could not parse stylesheet of object QLineEdit(0x421c198, name = "incidentLinkLight")
15:31:47 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 55663338-b09a-4afa-a328-eca84d23b15b :
15:31:47 [sartopo_bg:1903:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
15:31:47 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 6a468db6-2801-4ef5-a307-7e12278f3279 :
15:31:47 [sartopo_bg:1903:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

This crash happened on delete of a line which had been imported and cropped as a track, after about 9 minutes of inactivity after restart:

17:29:35 [sartopo_python:433:INFO]   Updating "ids"
17:29:35 [sartopo_python:498:INFO] cleaned up 1 feature(s) from the cache:['8974e0db-3a80-43bd-b3ba-41836a5b9f4b']
17:29:35 [sartopo_bg:483:INFO] t1
17:29:35 [sartopo_bg:485:INFO] t2
17:29:35 [sartopo_bg:487:INFO] t3
17:29:35 [sartopo_bg:489:INFO] t4
17:29:35 [sartopo_bg:492:INFO] t5
17:29:35 [sartopo_bg:494:INFO] t6
17:29:35 [sartopo_bg:496:INFO] t7
17:29:35 [sartopo_bg:498:INFO] t8
17:29:35 [sartopo_bg:500:INFO] t9
17:29:35 [sartopo_bg:1850:INFO] deletedFeatureCallback called for source map feature with id 8974e0db-3a80-43bd-b3ba-41836a5b9f4b :
17:29:35 [sartopo_bg:1860:INFO] deleting corresponding debrief map feature with id c48e8862-7f9c-4889-8861-6af9332808e8
17:29:35 [sartopo_python:559:INFO] refresh requested: 529106ms since last completed sync; longer than syncInterval: syncing now
17:29:35 [sartopo_python:462:INFO]   response contained properties for Shape:AA101b but they matched the cache, so no cache update or callback is performed
17:29:35 [sartopo_python:472:INFO]   response contained geometry for Shape:AA101b but it matched the cache, so no cache update or callback is performed
17:29:35 [sartopo_python:569:INFO] refresh requested: 0ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:29:35 [sartopo_python:649:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/c48e8862-7f9c-4889-8861-6af9332808e8
17:29:37 [sartopo_bg:483:INFO] t1
17:29:37 [sartopo_bg:485:INFO] t2
17:29:37 [sartopo_bg:487:INFO] t3
17:29:37 [sartopo_bg:489:INFO] t4
17:29:37 [sartopo_bg:492:INFO] t5
17:29:37 [sartopo_bg:494:INFO] t6
17:29:37 [sartopo_bg:496:INFO] t7
17:29:37 [sartopo_bg:498:INFO] t8
17:29:37 [sartopo_bg:500:INFO] t9
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

With more trace lines - crash after restart, on delete of unowned line:

05:39:01 [sartopo_python:433:INFO]   Updating "ids"
05:39:01 [sartopo_python:489:INFO] s1
05:39:01 [sartopo_python:494:INFO] s2
05:39:01 [sartopo_python:497:INFO] s3
05:39:01 [sartopo_python:501:INFO] cleaned up 1 feature(s) from the cache:['85bb3417-182b-4714-926f-022069f13c12']
05:39:01 [sartopo_bg:483:INFO] t1
05:39:01 [sartopo_bg:485:INFO] t2
05:39:01 [sartopo_bg:487:INFO] t3
05:39:01 [sartopo_bg:489:INFO] t4
05:39:01 [sartopo_bg:492:INFO] t5
05:39:01 [sartopo_bg:494:INFO] t6
05:39:01 [sartopo_bg:496:INFO] t7
05:39:01 [sartopo_bg:498:INFO] t8
05:39:01 [sartopo_bg:500:INFO] t9
05:39:01 [sartopo_bg:1850:INFO] deletedFeatureCallback called for source map feature with id 85bb3417-182b-4714-926f-022069f13c12 :
05:39:01 [sartopo_bg:1860:INFO] deleting corresponding debrief map feature with id 5be582df-91d2-403e-94a9-58ecfd0b21e3
05:39:01 [sartopo_python:563:INFO] refresh requested: 22198ms since last completed sync; longer than syncInterval: syncing now
05:39:01 [sartopo_python:489:INFO] s1
05:39:01 [sartopo_python:494:INFO] s2
05:39:01 [sartopo_python:497:INFO] s3
05:39:01 [sartopo_python:505:INFO] s4
05:39:01 [sartopo_python:573:INFO] refresh requested: 0ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:01 [sartopo_python:653:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/5be582df-91d2-403e-94a9-58ecfd0b21e3
05:39:03 [sartopo_bg:1912:INFO] source map feature does not have any corresponding feature in debrief map; nothing deleted
05:39:03 [sartopo_bg:483:INFO] t1
05:39:03 [sartopo_bg:485:INFO] t2
05:39:03 [sartopo_bg:487:INFO] t3
05:39:03 [sartopo_bg:489:INFO] t4
05:39:03 [sartopo_bg:492:INFO] t5
05:39:03 [sartopo_bg:494:INFO] t6
05:39:03 [sartopo_bg:496:INFO] t7
05:39:03 [sartopo_bg:498:INFO] t8
05:39:03 [sartopo_bg:500:INFO] t9
05:39:03 [sartopo_python:505:INFO] s4
PS C:\Users\caver\Documents\GitHub\plans_console>

The corresponding code in doSync, in part 3 (cleanup):

            # 3 - cleanup - remove features from the cache whose ids are no longer in cached id list
            #  (ids will be part of the response whenever feature(s) were added or deleted)
            # beforeStr='mapData before cleanup:'+json.dumps(self.mapData,indent=3)
            #  at this point in the code, the deleted feature has been removed from ids but is still part of state-features
            logging.info('s1')
            self.mapIDs=sum(self.mapData['ids'].values(),[])
            mapSFIDsBefore=[f['id'] for f in self.mapData['state']['features']]
            # edit the cache directly: https://stackoverflow.com/a/1157174/3577105
            l1=len(self.mapData['state']['features'])
            logging.info('s2')
            self.mapData['state']['features'][:]=(f for f in self.mapData['state']['features'] if f['id'] in self.mapIDs)
            mapSFIDs=[f['id'] for f in self.mapData['state']['features']]
            logging.info('s3')
            l2=len(self.mapData['state']['features'])
            if l2!=l1:
                deletedIds=list(set(mapSFIDsBefore)-set(mapSFIDs))
                logging.info('cleaned up '+str(l1-l2)+' feature(s) from the cache:'+str(deletedIds))
                if self.deletedFeatureCallback:
                    for did in deletedIds:
                        self.deletedFeatureCallback(did)
            logging.info('s4')

there is a bit of doSync code after part 3. So, the crash doesn't happen during part 3, or during the blink (t1 thru t9 are all in updateLinkLights); add more traces in doSync, before and after part 3 - it could be happening after part 3, or, before part 3 in the subsequent sync, or, somewhere outside of sync

Another key clue from this log: sync is being called from within part3, after the first s3. This might be a/the problem. deletedFeatureCallback is calling sync from its call to refresh. One way to avoid this would be to add as the first lines in doSync to return immediately if self.syncing is True. The large time since last sync reported during refresh is probably misleading, since it only reports time since the last >completed< sync (self.lastSuccessfulSyncTSLocal is set after part 3). Also adding code in refresh to clarify this, and to not attempt to sync-within-sync.

[caver456]

The sync-within-sync still happens. refresh never sees self.syncing as set withing doSync. The doSync run on a timer is inside the sync thread, but the doSync called from refresh is in the main thread. Need to get the two to communicate.

[caver456]

Using globals works, defined at the top level of sartopo_python.py and referenced with the global statement in any functions that need to modify them, but that seems spooky - it would be much better as an instance variable, so that multiple sts sessions could be syncing independently without crosstalk from these shared global variables. But it does work (note s1 thru s4 are the same as before; s1.1 thru s1.5 have been added, and d is the sync depth:

(This also shows that the delete requests are painfully slow - see sartopo_python/#34)

07:44:33 [sartopo_python:429:INFO] s1.1 d=1
07:44:37 [sartopo_python:431:INFO] s1.2
07:44:37 [sartopo_python:440:INFO] s1.3
07:44:37 [sartopo_python:446:INFO] s1.4
07:44:37 [sartopo_python:450:INFO]   Updating "ids"
07:44:37 [sartopo_python:452:INFO] s1.5
07:44:37 [sartopo_python:508:INFO] s1
07:44:37 [sartopo_python:513:INFO] s2
07:44:37 [sartopo_python:516:INFO] s3
07:44:37 [sartopo_python:520:INFO] cleaned up 4 feature(s) from the cache:['c23161bb-4c65-4e77-aa73-f1eeeadc829b', '757c449d-de8c-40a0-97f8-999e2c0ef822', '8a08fc0d-1a1f-40bc-bdcd-4bb039c9e73b', '590fdac9-048c-40fa-98f8-2c1af79abf6d']
07:44:37 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id c23161bb-4c65-4e77-aa73-f1eeeadc829b :
07:44:37 [sartopo_bg:1896:INFO] debrief map outing "AA 101" exists and has no clues or tracks; deleting boundary, folder, and outing database entry now
07:44:37 [sartopo_python:583:INFO] refresh requested (syncDepth=1: 50290ms since last completed sync; but sync is currently in progress; no additional sync will be performed
07:44:37 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/898cf378-95bb-4113-9ca2-42c6c27fc243
07:44:40 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Folder/84956a78-0b51-4782-8a9a-2aac3d234cfb
07:44:43 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 757c449d-de8c-40a0-97f8-999e2c0ef822 :
07:44:43 [sartopo_bg:1896:INFO] debrief map outing "AB 102" exists and has no clues or tracks; deleting boundary, folder, and outing database entry now
07:44:43 [sartopo_python:583:INFO] refresh requested (syncDepth=1: 57250ms since last completed sync; but sync is currently in progress; no additional sync will be performed
07:44:44 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/5d552cac-0de0-4fe1-9e53-eb5e03a93a0d
07:44:46 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Folder/2ff69265-a4a6-457d-8e6e-cf5e3d99c779
Could not parse stylesheet of object QLineEdit(0x41a0130, name = "incidentLinkLight")
07:44:49 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 8a08fc0d-1a1f-40bc-bdcd-4bb039c9e73b :
07:44:49 [sartopo_bg:1896:INFO] debrief map outing "AF 106" exists and has no clues or tracks; deleting boundary, folder, and outing database entry now
07:44:49 [sartopo_python:583:INFO] refresh requested (syncDepth=1: 63168ms since last completed sync; but sync is currently in progress; no additional sync will be performed
07:44:49 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/409331f7-0553-42f1-9561-ed236001ee63
07:44:54 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Folder/b33a3f0d-349d-4402-a7fc-2721f5d73178
07:44:56 [sartopo_bg:1841:INFO] deletedFeatureCallback called for source map feature with id 590fdac9-048c-40fa-98f8-2c1af79abf6d :
07:44:56 [sartopo_bg:1896:INFO] debrief map outing "AC 103" exists and has no clues or tracks; deleting boundary, folder, and outing database entry now
07:44:56 [sartopo_python:583:INFO] refresh requested (syncDepth=1: 69977ms since last completed sync; but sync is currently in progress; no additional sync will be performed
07:44:56 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/841a7bd1-ea75-4c40-9aa0-04e99b149155
07:44:59 [sartopo_python:677:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Folder/645373e3-b1ee-4465-a2ac-c82cedf386dc
07:45:04 [sartopo_python:524:INFO] s4 d=1

[caver456]

Figured out why doSync was self.syncing was >apparently< not getting set and read correctly: it was for different objects (incident map sync, vs debrief map sync). So - confirmed that it was working as expected - the attempted reentrant doSync is blocked for the same map, but is allowed for the different map, i.e. sync debrief map during sync incident map should be allowed.

Thought that made it a lot better - got most of the way through testing - but got a crash again at the end of delete of several lines, mostly corresponding to tracks that were already cropped:

17:15:29 [sartopo_python:592:INFO] Sartopo syncing initiated.
17:17:46 [sartopo_python:438:INFO]   Updating "ids"
17:17:46 [sartopo_python:503:INFO] cleaned up 8 feature(s) from the cache:['f8b4afd0-dfb8-4212-a1b0-deba8e9ccecb', 'b9e69e22-7e0e-42b7-9115-a8d5351fc1dd', '8ae40706-5e23-4b05-b4fe-c06d05385935', '1d773ddf-d632-4159-805b-b9db799dc9cf', '0eb9adab-9115-4c73-93d6-0017fe985a6a', '16c3f1ca-e818-48e0-8b39-c568e5b252cb', '191e4da2-2099-4815-b493-12bc748e41a4', 'e71aa34c-924c-4339-b1e1-a4d5634e8b32']
17:17:46 [sartopo_bg:1849:INFO] deletedFeatureCallback called for source map feature with id f8b4afd0-dfb8-4212-a1b0-deba8e9ccecb :
17:17:46 [sartopo_bg:1859:INFO] deleting corresponding debrief map feature with id cb9229fa-d9f5-4ae6-a38e-857f53dedfcc
17:17:46 [sartopo_python:569:INFO] refresh requested for map LGA: 138525ms since last completed sync; longer than syncInterval: syncing now
17:17:48 [sartopo_python:467:INFO]   response contained properties for Shape:AD104c but they matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:477:INFO]   response contained geometry for Shape:AD104c but it matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:467:INFO]   response contained properties for Shape:AD104b but they matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:477:INFO]   response contained geometry for Shape:AD104b but it matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:467:INFO]   response contained properties for Shape:abcdefg but they matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:477:INFO]   response contained geometry for Shape:abcdefg but it matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:467:INFO]   response contained properties for Shape:AE112d but they matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:477:INFO]   response contained geometry for Shape:AE112d but it matched the cache, so no cache update or callback is performed
17:17:48 [sartopo_python:579:INFO] refresh requested for map LGA: 0ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:48 [sartopo_python:660:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/cb9229fa-d9f5-4ae6-a38e-857f53dedfcc
17:17:48 [sartopo_bg:1849:INFO] deletedFeatureCallback called for source map feature with id b9e69e22-7e0e-42b7-9115-a8d5351fc1dd :
17:17:48 [sartopo_bg:1859:INFO] deleting corresponding debrief map feature with id a1d19d29-9b8e-49a1-8973-3e48a7a0acb6
17:17:48 [sartopo_python:579:INFO] refresh requested for map LGA: 258ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:48 [sartopo_python:579:INFO] refresh requested for map LGA: 259ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:48 [sartopo_python:660:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/a1d19d29-9b8e-49a1-8973-3e48a7a0acb6
17:17:48 [sartopo_bg:1849:INFO] deletedFeatureCallback called for source map feature with id 8ae40706-5e23-4b05-b4fe-c06d05385935 :
17:17:48 [sartopo_bg:1859:INFO] deleting corresponding debrief map feature with id 8f400196-51c9-4cf2-b007-f1ea67f7c7db
17:17:48 [sartopo_python:579:INFO] refresh requested for map LGA: 526ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:48 [sartopo_python:579:INFO] refresh requested for map LGA: 527ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:48 [sartopo_python:660:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/8f400196-51c9-4cf2-b007-f1ea67f7c7db
17:17:49 [sartopo_bg:1849:INFO] deletedFeatureCallback called for source map feature with id 1d773ddf-d632-4159-805b-b9db799dc9cf :
17:17:49 [sartopo_bg:1859:INFO] deleting corresponding debrief map feature with id 60b96b3d-1505-4d6e-a3d2-6d15560f5582
17:17:49 [sartopo_python:579:INFO] refresh requested for map LGA: 785ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:49 [sartopo_python:579:INFO] refresh requested for map LGA: 785ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
17:17:49 [sartopo_python:660:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/60b96b3d-1505-4d6e-a3d2-6d15560f5582
17:17:53 [sartopo_bg:1849:INFO] deletedFeatureCallback called for source map feature with id 0eb9adab-9115-4c73-93d6-0017fe985a6a :
17:17:53 [sartopo_bg:1859:INFO] deleting corresponding debrief map feature with id 424b01b6-a0bf-4f46-b882-71764356e5f6
17:17:53 [sartopo_python:569:INFO] refresh requested for map LGA: 5211ms since last completed sync; longer than syncInterval: syncing now
PS C:\Users\caver\Documents\GitHub\plans_console>

Notice the last refresh request DOES do a sync, so the problem is somewhere in there. Still gotta figure out how to reproduce it.

[caver456]

Here's a crash that does not involve any delete operations at all. Just a rapid sequence of adding unnamed lines (2 vertices each):

19:43:35 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=9d08c2a5-2135-40ce-93ef-3a3fdf90910c
19:43:35 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:35 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:35 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:35 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:35 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
19:43:35 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
19:43:35 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=d735c56b-23f6-4c54-a781-550af49e3c97
19:43:35 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:35 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:35 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:35 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:35 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
19:43:35 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
19:43:35 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=c269239c-c120-4212-8fe2-c5eae0931353
19:43:35 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:35 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:35 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:35 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:35 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
19:43:35 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
19:43:35 [sartopo_python:491:INFO] s2 RDE
19:43:35 [sartopo_python:525:INFO] s3 RDE
19:43:35 [sartopo_python:534:INFO] s4 RDE
19:43:35 [sartopo_python:553:INFO] s5 RDE
19:43:35 [sartopo_python:558:INFO] s6 RDE
19:43:40 [sartopo_python:440:INFO] s1 RDE
19:43:40 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=bbe54a96-0acc-451e-8631-9e3e6a59cac6
19:43:40 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:40 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:40 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:40 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:40 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
19:43:40 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
Could not parse stylesheet of object QLineEdit(0x978b1e0, name = "debriefLinkLight")
19:43:40 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=c2113594-2ad2-4524-85ac-22ee8f610aa6
19:43:40 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:40 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:40 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:40 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:40 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
19:43:41 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
19:43:41 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=a5707c20-2e14-4abb-9a9f-ae990010c62f
19:43:43 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
19:43:43 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
19:43:43 [sartopo_bg:1335:INFO] creating line '' in default folder
19:43:43 [sartopo_python:666:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
19:43:43 [sartopo_python:691:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
PS C:\Users\caver\Documents\GitHub\plans_console>

Notes:

• 9 quick lines were drawn but only six were processed here. Indicates some general sync timing issue. What if the sync from the thread loop is called while the callbacks within the loop within doSync are running? Should probably make the loop actually wait until self.syncing is false.
• 'could not parse stylesheet' shows up again - has not shown up in a while - immediately after refresh is requested but sync is in progress

[caver456]

Doing a lot of rapid actions seems to be a good test.

Added the following code inside _syncLoop:

            syncWaited=0
            while self.syncing and syncWaited<20: # wait for any current callbacks within doSync() to complete, with timeout of 20 sec
                logging.info(' [sync from _syncLoop is waiting for current sync processing to finish...]')
                time.sleep(1)
                syncWaited+=1
            self.doSync()

A large number of rapidly added lines was handled correctly, but that message never showed up in the log; there was no indication in the log that this wait was triggered.
On bulk ops delete of all of those lines (or maybe it was before the delete - not really sure) it crashed with the following:

...
20:00:35 [sartopo_python:440:INFO] s1 RDE
20:00:35 [sartopo_python:491:INFO] s2 RDE
20:00:35 [sartopo_python:525:INFO] s3 RDE
20:00:35 [sartopo_python:534:INFO] s4 RDE
20:00:35 [sartopo_python:553:INFO] s5 RDE
20:00:35 [sartopo_python:558:INFO] s6 RDE
20:00:40 [sartopo_python:440:INFO] s1 RDE
20:00:40 [sartopo_python:491:INFO] s2 RDE
20:00:40 [sartopo_python:525:INFO] s3 RDE
20:00:40 [sartopo_python:534:INFO] s4 RDE
20:00:40 [sartopo_python:553:INFO] s5 RDE
20:00:40 [sartopo_python:558:INFO] s6 RDE
20:00:45 [sartopo_python:440:INFO] s1 RDE
20:00:45 [sartopo_python:491:INFO] s2 RDE
20:00:45 [sartopo_python:525:INFO] s3 RDE
20:00:45 [sartopo_python:534:INFO] s4 RDE
20:00:45 [sartopo_python:553:INFO] s5 RDE
20:00:45 [sartopo_python:558:INFO] s6 RDE
20:01:00 [sartopo_python:2071:CRITICAL] Uncaught exception in Thread-1 (_syncLoop):
Traceback (most recent call last):
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 445, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 440, in _make_request
    httplib_response = conn.getresponse()
  File "C:\Program Files (x86)\Python310-32\lib\http\client.py", line 1368, in getresponse
    response.begin()
  File "C:\Program Files (x86)\Python310-32\lib\http\client.py", line 317, in begin
    version, status, reason = self._read_status()
  File "C:\Program Files (x86)\Python310-32\lib\http\client.py", line 278, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "C:\Program Files (x86)\Python310-32\lib\socket.py", line 705, in readinto
    return self._sock.recv_into(b)
TimeoutError: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\requests\adapters.py", line 439, in send
    resp = conn.urlopen(
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 755, in urlopen
    retries = retries.increment(
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\util\retry.py", line 532, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\packages\six.py", line 770, in reraise
    raise value
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 699, in urlopen
    httplib_response = self._make_request(
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 447, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\connectionpool.py", line 336, in _raise_timeout
    raise ReadTimeoutError(
urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='localhost', port=8080): Read timed out. (read timeout=10)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files (x86)\Python310-32\lib\threading.py", line 1009, in _bootstrap_inner
    self.run()
  File "C:\Program Files (x86)\Python310-32\lib\threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
  File "C:\Users\caver\Documents\GitHub\plans_console\sartopo_python.py", line 628, in _syncLoop
    self.doSync()
  File "C:\Users\caver\Documents\GitHub\plans_console\sartopo_python.py", line 421, in doSync
    rj=self.sendRequest('get','since/'+str(max(0,self.lastSuccessfulSyncTimestamp-500)),None,returnJson='ALL',timeout=self.syncTimeout)
  File "C:\Users\caver\Documents\GitHub\plans_console\sartopo_python.py", line 700, in sendRequest
    r=self.s.get(url,timeout=timeout)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\requests\sessions.py", line 555, in get
    return self.request('GET', url, **kwargs)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\requests\sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\requests\sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
  File "C:\Program Files (x86)\Python310-32\lib\site-packages\requests\adapters.py", line 529, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPConnectionPool(host='localhost', port=8080): Read timed out. (read timeout=10)

(this is similar to the errors that show up when the computer is awakened after sleeping while dmg is running)

after these errors, the GUI is still open and responsive, but:

• the sync blink stopped (incident map light is dark green on plans console and debrief dialog)
• debrief light is dark green on debrief gui, but light green on plans console

So: 1) is this related?? 2) some code should be added to recover - automatically if possible, or manually if needed.

[caver456]

Crash after just adding a few lines, not long after restart, followed by rebuild all (RDE = incident map; LGA = debrief map):

....
20:27:21 [sartopo_python:440:INFO] s1 RDE
20:27:21 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=43d86b10-e1f7-47ea-ace5-a47752fb1d18
20:27:21 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:27:21 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:27:21 [sartopo_bg:1335:INFO] creating line '' in default folder
20:27:21 [sartopo_python:676:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:27:21 [sartopo_python:701:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:27:21 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
20:27:21 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=97434841-c63b-4635-b384-6b0b5eec3068
20:27:21 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:27:21 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:27:21 [sartopo_bg:1335:INFO] creating line '' in default folder
20:27:21 [sartopo_python:676:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:27:21 [sartopo_python:701:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:27:24 [sartopo_python:569:INFO] refresh requested for map RDE: sync already in progress
20:27:24 [sartopo_python:491:INFO] s2 RDE
20:27:24 [sartopo_python:525:INFO] s3 RDE
20:27:24 [sartopo_python:534:INFO] s4 RDE
20:27:24 [sartopo_python:553:INFO] s5 RDE
20:27:24 [sartopo_python:558:INFO] s6 RDE
PS C:\Users\caver\Documents\GitHub\plans_console>

Notes:

• five lines were drawn on the incident map; only the first two were imported - evidently only two were returned in this since request, then this sync call returned gracefully (s6 is the next to last line in doSync, followed by self.syncing=False)

[caver456]

During add of several lines - with more tracing, both in syncLoop (t) and inside doSync (s)

20:39:21 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=9269bbf4-e74a-43e0-a979-f223204d40d5
20:39:21 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:39:21 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:39:21 [sartopo_bg:1335:INFO] creating line '' in default folder
20:39:21 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:39:21 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:39:21 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:39:21 [sartopo_python:491:INFO] s2 RDE
20:39:21 [sartopo_python:525:INFO] s3 RDE
20:39:21 [sartopo_python:534:INFO] s4 RDE
20:39:21 [sartopo_python:553:INFO] s5 RDE
20:39:21 [sartopo_python:558:INFO] s6 RDE
20:39:21 [sartopo_python:560:INFO] s7 RDE
20:39:21 [sartopo_python:637:INFO] t3
20:39:26 [sartopo_python:640:INFO] t4
20:39:26 [sartopo_python:611:INFO] t1
20:39:26 [sartopo_python:626:INFO] t2
20:39:26 [sartopo_python:440:INFO] s1 RDE
20:39:26 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=649e1537-9e7f-48e4-9577-3660ccbbd8ab
20:39:26 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:39:26 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:39:26 [sartopo_bg:1335:INFO] creating line '' in default folder
20:39:26 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:39:26 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:39:27 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:39:27 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=aee38832-a95b-487e-9436-eda245455a57
20:39:27 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:39:27 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:39:27 [sartopo_bg:1335:INFO] creating line '' in default folder
20:39:27 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:39:27 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:39:27 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:39:27 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=49d5ecd3-ea79-4b6a-9da8-e8989ac5e30f
20:39:27 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:39:27 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:39:27 [sartopo_bg:1335:INFO] creating line '' in default folder
20:39:27 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:39:27 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:39:31 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:39:31 [sartopo_bg:1459:INFO] newFeatureCallback: class=Shape  title=  id=876d5863-2e2d-4c66-b207-44867c524f85
20:39:31 [sartopo_bg:1503:INFO]  no correspondence entry found; adding the feature to the debrief map
20:39:31 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:39:31 [sartopo_bg:1335:INFO] creating line '' in default folder
20:39:31 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:39:31 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

crash during bulk ops delete from incident map:

20:48:48 [sartopo_python:440:INFO] s1 LGA
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:468:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:478:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
20:48:48 [sartopo_python:491:INFO] s2 LGA
20:48:48 [sartopo_python:525:INFO] s3 LGA
20:48:48 [sartopo_python:534:INFO] s4 LGA
20:48:48 [sartopo_python:553:INFO] s5 LGA
20:48:48 [sartopo_python:558:INFO] s6 LGA
20:48:48 [sartopo_python:560:INFO] s7 LGA
20:48:48 [sartopo_python:586:INFO] refresh requested for map LGA: 1ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:48 [sartopo_python:681:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/6895c121-f855-4886-b4c4-74a102b6a96d
20:48:49 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id b1c5f40c-7ef4-426f-9947-149e03b48a46 :
20:48:49 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 6ab8fcf5-55f0-4c9f-aef1-fc3a6981c4d7
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 268ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 268ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:681:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/6ab8fcf5-55f0-4c9f-aef1-fc3a6981c4d7
20:48:49 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 3d3711c1-b3eb-4f57-b1d9-445beb0d8a5a :
20:48:49 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 4f05b773-46fc-416d-9d08-61a9f7c660a9
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 532ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 532ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:681:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/4f05b773-46fc-416d-9d08-61a9f7c660a9
Could not parse stylesheet of object QLineEdit(0x45d81a8, name = "debriefLinkLight")
20:48:49 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 003e109d-0d89-4b23-9a5f-7539afea9d18 :
20:48:49 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id d4e8b531-0273-4053-851b-b672cb7dd018
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 801ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:586:INFO] refresh requested for map LGA: 801ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
20:48:49 [sartopo_python:681:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/d4e8b531-0273-4053-851b-b672cb7dd018
Could not parse stylesheet of object QLineEdit(0x45d87d8, name = "incidentLinkLight")
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

This crash makes it look like the requests are just too much. The post request payload never gets logged, which would happen before the request actually gets sent. So it doesn't look like the crash is happening during a request...?

20:52:45 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=48b3426f-53d4-4d04-ac0a-40f32a26ffb3
20:52:45 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
20:52:45 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:52:45 [sartopo_bg:1335:INFO] creating line '' in default folder
20:52:45 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:52:45 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:52:45 [sartopo_bg:1342:INFO] returned from addLine
20:52:45 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:52:45 [sartopo_bg:1357:INFO] done with addShape
20:52:45 [sartopo_bg:1603:INFO] nfcb1
20:52:45 [sartopo_bg:1605:INFO] nfcb2
20:52:45 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=7d70a42c-b608-40ed-832b-36ef8a48f7c2
20:52:45 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
20:52:45 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:52:45 [sartopo_bg:1335:INFO] creating line '' in default folder
20:52:45 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
20:52:45 [sartopo_python:706:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
20:53:08 [sartopo_bg:1342:INFO] returned from addLine
20:53:08 [sartopo_python:570:INFO] refresh requested for map RDE: sync already in progress
20:53:08 [sartopo_bg:1357:INFO] done with addShape
20:53:08 [sartopo_bg:1603:INFO] nfcb1
20:53:08 [sartopo_bg:1605:INFO] nfcb2
20:53:08 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=5da24d9f-1e58-4cfe-ba3a-28fedbe856a7
20:53:08 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
20:53:08 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
20:53:08 [sartopo_bg:1335:INFO] creating line '' in default folder
20:53:08 [sartopo_python:681:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

during bulk ops delete of many lines, with objgraph.show_growth() at the start of sendRequest which shows/implies there's not really any growth during the rapid delete requests:

SplitResult       14        +1
05:38:35 [sartopo_python:442:INFO] s1 RDE
05:38:35 [sartopo_python:493:INFO] s2 RDE
05:38:35 [sartopo_python:527:INFO] s3 RDE
05:38:35 [sartopo_python:536:INFO] s4 RDE
05:38:35 [sartopo_python:555:INFO] s5 RDE
05:38:35 [sartopo_python:560:INFO] s6 RDE
05:38:35 [sartopo_python:562:INFO] s7 RDE
05:38:35 [sartopo_python:639:INFO] t3
05:38:40 [sartopo_python:642:INFO] t4
05:38:40 [sartopo_python:613:INFO] t1
05:38:40 [sartopo_python:628:INFO] t2
SplitResult       15        +1
05:38:48 [sartopo_python:440:INFO]   Updating "ids"
05:38:48 [sartopo_python:442:INFO] s1 RDE
05:38:48 [sartopo_python:493:INFO] s2 RDE
05:38:48 [sartopo_python:507:INFO] cleaned up 30 feature(s) from the cache:['48b3426f-53d4-4d04-ac0a-40f32a26ffb3', '0bc08e2b-a4b1-41c4-a4d0-87a15404be2a', '3b118f7d-15a3-44e3-83f6-afee1e63aa3f', '8d57be52-d960-4307-9b06-b54bcbec6f98', '49f5cbee-ba84-4e3e-aa5a-9ad149d3340a', '985d236a-c8ac-4341-a0c6-736e881476bb', '4d229354-e447-497e-bb5f-a3539109e54f', 'ccc8cb42-03c3-41f5-87b1-4d207fb970b8', 'd3fafb4d-75f0-4a9f-9e3d-c8c0ec0fe8e3', '5da24d9f-1e58-4cfe-ba3a-28fedbe856a7', '94fb7ff1-56b4-4a8b-aafc-8c40dc59e775', '0f33b0d5-030a-482e-aedc-238e757edbfd', '56b8b8ea-43c9-4fb6-a078-dccc1e7181e4', 'bfd943f0-a990-4078-952d-b56e3ea03633', 'd9c95424-fa8d-4972-9ebc-f7a763974dc3', '7d70a42c-b608-40ed-832b-36ef8a48f7c2', '7de1966f-9e52-4d90-a76d-bf2b183005b8', '3bd34883-91a4-4cfd-ae94-4a9697d0d32c', 'c1c85aa8-2190-4b45-bfd6-a8599a8dac48', 'b5f7bd79-fc8b-4c56-881b-50c79a247162', 'dc9dafca-d778-4c79-8bc9-e690c9b66485', 'a3806592-3097-4ef9-8f3c-698753b40927', '1a741edd-6857-4f42-9252-ce1d941c5b89', '86195ec0-5b88-42f2-9fd6-5f741d94a71a', '387b949c-d890-4119-9193-5ce8d3934237', '16e37788-d0c6-4347-8651-aafdba9ccb66', '38d16c4f-f6fe-42c2-8992-f565a4633d95', '02f99bbb-6454-4f9a-bc86-4bc595ebf414', 'f4112a23-9161-4813-b6c6-9168d2b7a858', '8537e385-f1ec-4eed-b948-38e065d388ba']
05:38:48 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 48b3426f-53d4-4d04-ac0a-40f32a26ffb3 :
05:38:48 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 382a8d76-8557-4dd7-ade3-58a32adf1e99
05:38:48 [sartopo_python:578:INFO] refresh requested for map LGA: 56457ms since last completed sync; longer than syncInterval: syncing now
cell               639        +1
SplitResult         16        +1
list_iterator        2        +1
05:38:49 [sartopo_python:442:INFO] s1 LGA
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:470:INFO]   response contained properties for Shape: but they matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:480:INFO]   response contained geometry for Shape: but it matched the cache, so no cache update or callback is performed
05:38:49 [sartopo_python:493:INFO] s2 LGA
05:38:49 [sartopo_python:527:INFO] s3 LGA
05:38:49 [sartopo_python:536:INFO] s4 LGA
05:38:49 [sartopo_python:555:INFO] s5 LGA
05:38:49 [sartopo_python:560:INFO] s6 LGA
05:38:49 [sartopo_python:562:INFO] s7 LGA
05:38:49 [sartopo_python:588:INFO] refresh requested for map LGA: 0ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
SplitResult       17        +1
05:38:49 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/382a8d76-8557-4dd7-ade3-58a32adf1e99
05:38:49 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 0bc08e2b-a4b1-41c4-a4d0-87a15404be2a :
05:38:49 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 2b70f85e-b339-4516-8957-e8e51b91390f
05:38:49 [sartopo_python:588:INFO] refresh requested for map LGA: 312ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:49 [sartopo_python:588:INFO] refresh requested for map LGA: 312ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
SplitResult       18        +1
05:38:49 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/2b70f85e-b339-4516-8957-e8e51b91390f
05:38:50 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 3b118f7d-15a3-44e3-83f6-afee1e63aa3f :
05:38:50 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 7d0ee1ad-53c3-4f3c-8515-ce7b42fefd1c
05:38:50 [sartopo_python:588:INFO] refresh requested for map LGA: 609ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:50 [sartopo_python:588:INFO] refresh requested for map LGA: 609ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
SplitResult       19        +1
05:38:50 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/7d0ee1ad-53c3-4f3c-8515-ce7b42fefd1c
05:38:50 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 8d57be52-d960-4307-9b06-b54bcbec6f98 :
05:38:50 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 1274e531-a1c9-4add-ba36-59aba008c8df
05:38:50 [sartopo_python:588:INFO] refresh requested for map LGA: 912ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:50 [sartopo_python:588:INFO] refresh requested for map LGA: 912ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
SplitResult       20        +1
05:38:50 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/1274e531-a1c9-4add-ba36-59aba008c8df
05:38:52 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 49f5cbee-ba84-4e3e-aa5a-9ad149d3340a :
05:38:52 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 071d9875-b5b4-42fb-961f-74706fc6e52d
05:38:52 [sartopo_python:588:INFO] refresh requested for map LGA: 2862ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:52 [sartopo_python:588:INFO] refresh requested for map LGA: 2862ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:52 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/071d9875-b5b4-42fb-961f-74706fc6e52d
05:38:54 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 985d236a-c8ac-4341-a0c6-736e881476bb :
05:38:54 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 871cab97-b502-44a3-a6ac-56fea7ca9c06
05:38:54 [sartopo_python:588:INFO] refresh requested for map LGA: 4907ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:54 [sartopo_python:588:INFO] refresh requested for map LGA: 4907ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:54 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/871cab97-b502-44a3-a6ac-56fea7ca9c06
Could not parse stylesheet of object QLineEdit(0x38c7c30, name = "incidentLinkLight")
05:38:56 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 4d229354-e447-497e-bb5f-a3539109e54f :
05:38:56 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 8a24fdd5-75e5-42a7-8e14-77d446adb0c2
05:38:56 [sartopo_python:578:INFO] refresh requested for map LGA: 6866ms since last completed sync; longer than syncInterval: syncing now
05:38:59 [sartopo_python:440:INFO]   Updating "ids"
05:38:59 [sartopo_python:442:INFO] s1 LGA
05:38:59 [sartopo_python:493:INFO] s2 LGA
05:38:59 [sartopo_python:507:INFO] cleaned up 6 feature(s) from the cache:['871cab97-b502-44a3-a6ac-56fea7ca9c06', '2b70f85e-b339-4516-8957-e8e51b91390f', '382a8d76-8557-4dd7-ade3-58a32adf1e99', '7d0ee1ad-53c3-4f3c-8515-ce7b42fefd1c', '071d9875-b5b4-42fb-961f-74706fc6e52d', '1274e531-a1c9-4add-ba36-59aba008c8df']
05:38:59 [sartopo_python:527:INFO] s3 LGA
05:38:59 [sartopo_python:536:INFO] s4 LGA
05:38:59 [sartopo_python:555:INFO] s5 LGA
05:38:59 [sartopo_python:560:INFO] s6 LGA
05:38:59 [sartopo_python:562:INFO] s7 LGA
05:38:59 [sartopo_python:588:INFO] refresh requested for map LGA: 1ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:38:59 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/8a24fdd5-75e5-42a7-8e14-77d446adb0c2
05:39:01 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id ccc8cb42-03c3-41f5-87b1-4d207fb970b8 :
05:39:01 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id c5693b0a-afcb-48df-9c2b-a812060c7ecf
05:39:01 [sartopo_python:588:INFO] refresh requested for map LGA: 1937ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:01 [sartopo_python:588:INFO] refresh requested for map LGA: 1937ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:01 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/c5693b0a-afcb-48df-9c2b-a812060c7ecf
05:39:03 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id d3fafb4d-75f0-4a9f-9e3d-c8c0ec0fe8e3 :
05:39:03 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 69ef5846-8cf7-4e7d-89d9-db7a87a9c0d5
05:39:03 [sartopo_python:588:INFO] refresh requested for map LGA: 3888ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:03 [sartopo_python:588:INFO] refresh requested for map LGA: 3889ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:03 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/69ef5846-8cf7-4e7d-89d9-db7a87a9c0d5
05:39:05 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 5da24d9f-1e58-4cfe-ba3a-28fedbe856a7 :
05:39:05 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id 34db1abc-5b2b-4934-86a3-0ca2d6a69875
05:39:05 [sartopo_python:578:INFO] refresh requested for map LGA: 5874ms since last completed sync; longer than syncInterval: syncing now
05:39:09 [sartopo_python:440:INFO]   Updating "ids"
05:39:09 [sartopo_python:442:INFO] s1 LGA
05:39:09 [sartopo_python:493:INFO] s2 LGA
05:39:09 [sartopo_python:507:INFO] cleaned up 3 feature(s) from the cache:['c5693b0a-afcb-48df-9c2b-a812060c7ecf', '69ef5846-8cf7-4e7d-89d9-db7a87a9c0d5', '8a24fdd5-75e5-42a7-8e14-77d446adb0c2']
05:39:09 [sartopo_python:527:INFO] s3 LGA
05:39:09 [sartopo_python:536:INFO] s4 LGA
05:39:09 [sartopo_python:555:INFO] s5 LGA
05:39:09 [sartopo_python:560:INFO] s6 LGA
05:39:09 [sartopo_python:562:INFO] s7 LGA
05:39:09 [sartopo_python:588:INFO] refresh requested for map LGA: 1ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:09 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/34db1abc-5b2b-4934-86a3-0ca2d6a69875
05:39:11 [sartopo_bg:1853:INFO] deletedFeatureCallback called for source map feature with id 94fb7ff1-56b4-4a8b-aafc-8c40dc59e775 :
05:39:11 [sartopo_bg:1863:INFO] deleting corresponding debrief map feature with id b009e9de-3017-4b2f-9579-d413732718b1
05:39:11 [sartopo_python:588:INFO] refresh requested for map LGA: 2164ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:11 [sartopo_python:588:INFO] refresh requested for map LGA: 2165ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
05:39:11 [sartopo_python:685:INFO] sending delete to http://localhost:8080/api/v1/map/LGA/Shape/b009e9de-3017-4b2f-9579-d413732718b1
Could not parse stylesheet of object QLineEdit(0x38c7e40, name = "debriefLinkLight")
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

during import of a json of a bunch of 2-vertex lines, with some memory profiling, which shows memory increase each time with the exception of a drop of a half MB on the fourth or fifth report:

...
05:57:15 [sartopo_python:616:INFO] t1
05:57:15 [sartopo_python:631:INFO] t2
05:57:15 [sartopo_python:649:INFO] RAM:121.33203125MB
05:57:15 [sartopo_python:445:INFO] s1 RDE
05:57:15 [sartopo_python:496:INFO] s2 RDE
05:57:15 [sartopo_python:530:INFO] s3 RDE
05:57:15 [sartopo_python:539:INFO] s4 RDE
05:57:15 [sartopo_python:558:INFO] s5 RDE
05:57:15 [sartopo_python:563:INFO] s6 RDE
05:57:15 [sartopo_python:565:INFO] s7 RDE
05:57:15 [sartopo_python:642:INFO] t3
05:57:20 [sartopo_python:645:INFO] t4
05:57:20 [sartopo_python:616:INFO] t1
05:57:20 [sartopo_python:631:INFO] t2
05:57:20 [sartopo_python:649:INFO] RAM:121.3359375MB
05:57:21 [sartopo_python:445:INFO] s1 RDE
05:57:21 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=c1c85aa8-2190-4b45-bfd6-a8599a8dac48
05:57:21 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:21 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:21 [sartopo_bg:1335:INFO] creating line '' in default folder
list              1042       +25
dict              5196       +13
cell               974        +2
list_iterator        1        +1
05:57:22 [sartopo_python:649:INFO] RAM:121.375MB
05:57:22 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:22 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:22 [sartopo_bg:1342:INFO] returned from addLine
05:57:22 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:22 [sartopo_bg:1357:INFO] done with addShape
05:57:22 [sartopo_bg:1603:INFO] nfcb1
05:57:22 [sartopo_bg:1605:INFO] nfcb2
05:57:22 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=d9c95424-fa8d-4972-9ebc-f7a763974dc3
05:57:22 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:22 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:22 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1047        +5
dict     5201        +5
05:57:22 [sartopo_python:649:INFO] RAM:121.3828125MB
05:57:22 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:22 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:24 [sartopo_bg:1342:INFO] returned from addLine
05:57:24 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:24 [sartopo_bg:1357:INFO] done with addShape
05:57:24 [sartopo_bg:1603:INFO] nfcb1
05:57:24 [sartopo_bg:1605:INFO] nfcb2
05:57:24 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=49f5cbee-ba84-4e3e-aa5a-9ad149d3340a
05:57:24 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:24 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:24 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1051        +4
dict     5203        +2
05:57:24 [sartopo_python:649:INFO] RAM:121.3984375MB
05:57:24 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:24 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:25 [sartopo_bg:1342:INFO] returned from addLine
05:57:25 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:25 [sartopo_bg:1357:INFO] done with addShape
05:57:25 [sartopo_bg:1603:INFO] nfcb1
05:57:25 [sartopo_bg:1605:INFO] nfcb2
05:57:25 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=b5f7bd79-fc8b-4c56-881b-50c79a247162
05:57:25 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:25 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:25 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1055        +4
dict     5205        +2
05:57:26 [sartopo_python:649:INFO] RAM:120.7265625MB
05:57:26 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:26 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:27 [sartopo_bg:1342:INFO] returned from addLine
05:57:27 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:27 [sartopo_bg:1357:INFO] done with addShape
05:57:27 [sartopo_bg:1603:INFO] nfcb1
05:57:27 [sartopo_bg:1605:INFO] nfcb2
05:57:27 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=7de1966f-9e52-4d90-a76d-bf2b183005b8
05:57:27 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:27 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:27 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1059        +4
dict     5207        +2
05:57:27 [sartopo_python:649:INFO] RAM:120.9453125MB
05:57:27 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:27 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:28 [sartopo_bg:1342:INFO] returned from addLine
05:57:28 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:28 [sartopo_bg:1357:INFO] done with addShape
05:57:28 [sartopo_bg:1603:INFO] nfcb1
05:57:28 [sartopo_bg:1605:INFO] nfcb2
05:57:28 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=f4112a23-9161-4813-b6c6-9168d2b7a858
05:57:28 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:28 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:28 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1063        +4
dict     5209        +2
05:57:28 [sartopo_python:649:INFO] RAM:120.96875MB
05:57:28 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:28 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:28 [sartopo_bg:1342:INFO] returned from addLine
05:57:28 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:28 [sartopo_bg:1357:INFO] done with addShape
05:57:28 [sartopo_bg:1603:INFO] nfcb1
05:57:28 [sartopo_bg:1605:INFO] nfcb2
05:57:28 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=0bc08e2b-a4b1-41c4-a4d0-87a15404be2a
05:57:28 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:28 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:28 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1067        +4
dict     5211        +2
05:57:28 [sartopo_python:649:INFO] RAM:120.984375MB
05:57:28 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:28 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "4 points"}}'}
05:57:28 [sartopo_bg:1342:INFO] returned from addLine
05:57:28 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:28 [sartopo_bg:1357:INFO] done with addShape
05:57:28 [sartopo_bg:1603:INFO] nfcb1
05:57:28 [sartopo_bg:1605:INFO] nfcb2
05:57:28 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=8537e385-f1ec-4eed-b948-38e065d388ba
05:57:28 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:28 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:28 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1073        +6
dict     5213        +2
05:57:28 [sartopo_python:649:INFO] RAM:121.01171875MB
05:57:28 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:28 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:28 [sartopo_bg:1342:INFO] returned from addLine
05:57:28 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:28 [sartopo_bg:1357:INFO] done with addShape
05:57:28 [sartopo_bg:1603:INFO] nfcb1
05:57:28 [sartopo_bg:1605:INFO] nfcb2
05:57:28 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=3b118f7d-15a3-44e3-83f6-afee1e63aa3f
05:57:28 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:28 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:28 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1077        +4
dict     5215        +2
05:57:28 [sartopo_python:649:INFO] RAM:121.0234375MB
05:57:28 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:28 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:28 [sartopo_bg:1342:INFO] returned from addLine
05:57:28 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:28 [sartopo_bg:1357:INFO] done with addShape
05:57:28 [sartopo_bg:1603:INFO] nfcb1
05:57:28 [sartopo_bg:1605:INFO] nfcb2
Could not parse stylesheet of object QLineEdit(0x3caf640, name = "incidentLinkLight")
05:57:28 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=1a741edd-6857-4f42-9252-ce1d941c5b89
05:57:28 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:28 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:28 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1081        +4
dict     5217        +2
05:57:28 [sartopo_python:649:INFO] RAM:121.0546875MB
05:57:28 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:28 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:29 [sartopo_bg:1342:INFO] returned from addLine
05:57:29 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:29 [sartopo_bg:1357:INFO] done with addShape
05:57:29 [sartopo_bg:1603:INFO] nfcb1
05:57:29 [sartopo_bg:1605:INFO] nfcb2
05:57:29 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=ccc8cb42-03c3-41f5-87b1-4d207fb970b8
05:57:29 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
05:57:29 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
05:57:29 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1085        +4
dict     5219        +2
05:57:29 [sartopo_python:649:INFO] RAM:121.09765625MB
05:57:29 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
05:57:29 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
05:57:32 [sartopo_bg:1342:INFO] returned from addLine
05:57:32 [sartopo_python:575:INFO] refresh requested for map RDE: sync already in progress
05:57:32 [sartopo_bg:1357:INFO] done with addShape
05:57:32 [sartopo_bg:1603:INFO] nfcb1
05:57:32 [sartopo_bg:1605:INFO] nfcb2
05:57:32 [sartopo_python:496:INFO] s2 RDE
05:57:32 [sartopo_python:530:INFO] s3 RDE
05:57:32 [sartopo_python:539:INFO] s4 RDE
05:57:32 [sartopo_python:558:INFO] s5 RDE
05:57:32 [sartopo_python:563:INFO] s6 RDE
05:57:32 [sartopo_python:565:INFO] s7 RDE
PS C:\Users\caver\Documents\GitHub\plans_console>

[caver456]

Stumped. At least there's now a consistent way to make it crash: 1) start dmg (specify debrief map); 2) import bunch-o-lines.json to incident map. The crash happens after some but not all lines get imported to the debrief map.

Going back to older versions of the plans_console repo (where all work has been going on for a long time including local copies of sartopo_bg.py and sartopo_python.py) in an attempt to find a version that doesn't crash. Went back to 9eb98e6 (Jan 31) and it still crashes in the same manner, with differing number of imported lines before crash - which implies it's not due to the specific data (didn't think it was - just wanted to get some more confirmation).

BUT - interesting note - if bunch-o-lines.json is imported BEFORE sync is begun, there is no crash, consistently. Same for 9eb98e6 and for current code in progress. That's a very good thing and a new lead.

[caver456]

Note that in a successful run (import json was done before sync began) that incident map sync DOES happen during callbacks without incident:

08:59:33 [sartopo_python:649:INFO] RAM:123.22265625MB
08:59:33 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
08:59:33 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
08:59:33 [sartopo_bg:1342:INFO] returned from addLine
08:59:33 [sartopo_python:591:INFO] refresh requested for map RDE: 4844ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
08:59:33 [sartopo_bg:1357:INFO] done with addShape
08:59:33 [sartopo_bg:1603:INFO] nfcb1
08:59:33 [sartopo_bg:1605:INFO] nfcb2
08:59:33 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=387b949c-d890-4119-9193-5ce8d3934237
08:59:33 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
08:59:33 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
08:59:33 [sartopo_bg:1335:INFO] creating line '' in default folder
list     1139        +4
dict     5244        +2
08:59:33 [sartopo_python:649:INFO] RAM:123.22265625MB
08:59:33 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
08:59:33 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
08:59:33 [sartopo_bg:1342:INFO] returned from addLine
08:59:33 [sartopo_python:581:INFO] refresh requested for map RDE: 5056ms since last completed sync; longer than syncInterval: syncing now
list     1142        +3
cell      969        +1
08:59:33 [sartopo_python:649:INFO] RAM:123.22265625MB
08:59:33 [sartopo_python:445:INFO] s1 RDE
08:59:33 [sartopo_python:496:INFO] s2 RDE
08:59:33 [sartopo_python:530:INFO] s3 RDE
08:59:33 [sartopo_python:539:INFO] s4 RDE
08:59:33 [sartopo_python:558:INFO] s5 RDE
08:59:33 [sartopo_python:563:INFO] s6 RDE
08:59:33 [sartopo_python:565:INFO] s7 RDE
08:59:33 [sartopo_bg:1357:INFO] done with addShape
08:59:33 [sartopo_bg:1603:INFO] nfcb1
08:59:33 [sartopo_bg:1605:INFO] nfcb2
08:59:33 [sartopo_bg:1461:INFO] newFeatureCallback: class=Shape  title=  id=8d57be52-d960-4307-9b06-b54bcbec6f98
08:59:33 [sartopo_bg:1505:INFO]  no correspondence entry found; adding the feature to the debrief map
08:59:33 [sartopo_bg:1333:INFO] Newly detected line : name does not appear to indicate association with an assignment
08:59:33 [sartopo_bg:1335:INFO] creating line '' in default folder
dict            5246        +2
list            1143        +1
SplitResult        7        +1
08:59:34 [sartopo_python:649:INFO] RAM:123.22265625MB
08:59:34 [sartopo_python:689:INFO] sending post to http://localhost:8080/api/v1/map/LGA/Shape
08:59:34 [sartopo_python:713:INFO] {'json': '{"properties": {"title": "", "description": "", "stroke-width": 2, "stroke-opacity": 1, "stroke": "#FF0000", "pattern": "solid", "gpstype": "TRACK"}, "geometry": {"type": "LineString", "coordinates": "2 points"}}'}
08:59:34 [sartopo_bg:1342:INFO] returned from addLine
08:59:34 [sartopo_python:591:INFO] refresh requested for map RDE: 216ms since last completed sync; shorter than syncInterval; forceImmediate not specified: not syncing now
08:59:34 [sartopo_bg:1357:INFO] done with addShape

Theory: this is fine because the doSync on the incident map in this case doesn't change the cache since there are no new features. Maybe the problem is the modification of the list of incident map features to process during iteration over that list. We've prevented reentrant doSync calls for the same map (incident map doSync does happen during debrief map doSync) - so - does something in the callbacks modify the incident map cache, or one of the other variables that is used during doSync?

[caver456]

Turns out the one that works (start dmg >after< importing json to incident map) is not calling newFeatureCallback from doSync - it's calling newFeatureCallback from DebriefMapGenerator.init just after the call to initDmd

(but syncing doesn't start til after that initial newFeatureCallback loop - so why did we see incident map sync lines during the initial newFeatureCallback loop??)

But the theory is basically the same - maybe something called by newFeatureCallback is modifying the instance variables that doSync is iterating over.

Looking through the code, newFeatureCallback modifies these instance variables:

• self.orphanTracksDict

and references these instance variables:

• self.dmd
• self.sts1.syncing
• self.sts2.mapData

• and calls these functions:

• self.updateLinkLights (at beginning and at end)
• self.parseTrackName
• self.sts2.getFeature
• self.sts2.editFeature
• self.addOuting
• self.addShape
• self.addMarker
• self.addClue

[caver456]

PROGRESS: Worked on stripping down doSync and newFeatureCallback. ** Got five out of five successful import-bunch-o-lines.json-while-dmg-is-running runs. The most recent change was commenting out the calls to self.updateLinkLights inside newFeatureCallback. Will test some more to confirm that's the culprit.

The most recent clean run showed two doSync calls that had lists of new features to process. The first had 20, the second had 12 (the first two of which were the same as the last two of the previous doSync - not surprising due to the -500ms 'since' offset)

The original post indicates the 'Could not parse stylesheet' lines are not the direct cause of the crash, and those lines don't always appear when there is a crash (they don't get logged - they only go to stdout), but they could be related.

[caver456]

Uncommenting the updateLinkLight calls at the beginning and end of newFeatureCallback led to two out of three runs crashing in the usual manner. So - pretty decent confidence that updateLinkLight is the cause. But why?

Per testing above https://github.com/ncssar/sartopo_bg/issues/14#issuecomment-1046241418 the crash doesn't happen during updateLinkLight, but this indicates that something about updateLinkLight is messing with stuff. It would be nice to uncover a smoking gun.

Next test is to replace all the other things that were pruned out in the course of debugging, and see if it still works.

[caver456]

All other code is replaced (the main changes to track things down were in doSync and newFeatureCallback) so it looks like there is confirmation that updateLinkLights is the culprit even though the crash doesn't occur within that function. It's definitely conceivable some we're futzing with threads and there's probably some interaction with the Qt event loop.

[caver456]

Tried googling 'pyqt thread crash' - the first hit has folks confirming that anything that tries GUI painting from a background thread will probably crash, so the solution is to do some form of slots and signals or shared-variable-passing (like instance variables picked up by main-thread timers) so that the painting always happens in the main thread.

So ultimately the problem here was probably that the sync thread calls doSync which calls newFeatureCallback which calls updateLinkLights. This probably also happens from the other callbacks called by the sync thread - deletedFeatureCallback, geoetryUpdateCallback, propertyUpdateCallback. I kinda knew that, and had previously added the comments below to the start of all callback functions, but I got sloppy and didn't even think about it:

    def propertyUpdateCallback(self,f):
        # this function is probably called from a sync thread:
        #  can't create a timer or do some GUI operations from here, etc.
        ...

Last step before closing this issue: find the right way to have the sync thread cause the link lights to blink as needed. That involves finding all the code inside sync and callbacks that would try to do any GUI painting, and replacing those calls with thread-safe signaling.

[caver456]

The replacement behavior was to use pyqtSignal. Define a wrapper function that can be called from within the sync thread, and an inner function which always runs in the main thread. The wrapper sends a PyQt signal which runs the inner function. The inner function sets style sheets on widgets. The wrapper doesn't do any GUI painting directly, and the thread-safety of slot/signals is well documented. This also required that the main class (DebriefMapGenerator) inherit from QObject, and that its init function be called by super().

The blinking could still be optimized by only sending the signal once-per-sync-that-makes-edits rather than once-per-edit, and also improved to allow a tri-state type of color setting (steady-state=dark-green; active=light-green; or 'as-is') to allow the lights to blink independently. This could probably happen if/when a progress bar is created to show progress during an individual sync that contained n features to be processed. But - this is a complete fix. (Even though the fix is being done in the plans_console repo for now).