Not pulling route as it changes, not closing process when closed

[Rhaedas]

The second part is like it was doing with 1.0, I can close the window but the two processes remain in Task Manager usually until I kill them. I can open and close and get a whole bunch of EDScouts in the manager.

The first - Version 1.1 was pulling perfectly, I could change a route in the map and would see the update right away. With 1.2 it doesn't show activity if it's up and running. If I close it (and that's where I noticed the process problem) and reopen it will usually pull the route I had last plotted. A few time it pulled up several previous routes, cleared, and finally showed the last one. So it's not tracking the json file as well as it was before I guess.

[joncage]

The nav route is in one file and the journal in another. In 1.1 I was relying on the navroute file changing to trigger sending to the GUI. In 1.2 I shuffled things around so it's just watching for the journal changing and using that as the trigger to read the navroute.

I have pretty fast SSDs on my machine so maybe the nav route file is sometimes changing after the journal or something and so it's picking up earlier routes etc.

Annoyingly, that was working really reliably on my machine. Perhaps I need to revert and use the nav file watcher again.

The startup picking up current state was something that needed work previously but I can take a look at that.

[joncage]

How long do you leave it after closing the scout? I've noticed it takes ~5-10s or so for it to close on my machine but it does shutdown and disappear eventually.

[Rhaedas]

If I open the program and then close it, yes it behaves fine. The persistence is from if I open it more than one time, only the last one gets removed. I know that wouldn't be a normal behavior of a user, I had just been opening it a few times to see if I could trigger it to refresh and I guess they were within that 5 sec period before it disappeared. Maybe there's something in a python library to check if an instance is already running?

As for the rest, I'll keep messing with it when I can. Any idea when the journal gets updated? All I'm doing is starting the game and jumping into the galaxy map to tag various stars for a route. Maybe doing just that in the station doesn't trigger anything but the nav file.

[joncage]

The persistence is from if I open it more than one time, only the last one gets removed.

Gotcha. I've dug into the source of flaskwebgui and I can see it uses a local file that sets a timestamp every time something is received from the browser. When that hasn't happened for 10s it closes the main Python instance. Since all instances use the local folder, that explains why having multiple copies open causes all of them to stay open because the common file is still being updated.

I can see a few options to fix this:

1. Fix the library so that it uses a temp file.
2. Check for existing scouts on startup and kill them off when it's launched.

As for the journal file, I thought it happened as soon as you make a change in the game (certainly seems pretty instant on my machine).

Every time you either select a destination or a new navroute in the glaxy map, it should plot it. One caveat to that is that it is polling EDSM for each system so it's possible that's slowing things down if your internet connection isn't the fastest. That lookup could potentially be done in a background thread but would require some more effort to sort it out.

I'm wondering if the multiple instances could be to blame for the odd behaviour with routes being plotted / replotted.

[joncage]

I tried some experiments to kill off earlier scouts looking at their PID's but that doesn't seem to solve the issue; something is still staying open so looks like we need some open-module-surgery on flaskwebgui

[Rhaedas]

More evidence for you to work with. I wanted to see when the journal file was being updated, so I had it open in Notepad++ while I mapped things. It changes with each plot, so that logic is sound. But EDScout still wasn't doing anything, until I clicked on the Notepad++ prompt to update the file loaded. Suddenly it worked for that route. Did this many times. Then I tried it with just File Explorer - I mapped something in the game, waited for a while and EDScout didn't do anything. I opened File Explorer, went to where the journal is, literally just clicked on the file name and suddenly EDScout came to life. So it's not triggering with just the update itself for some reason, but works fine once it gets flagged by whatever other programs might do when accessing the file.

[Rhaedas]

I don't know a lot about python, but I ran across a constructor in wxPython that seems simple, so if it can't be used a a library, maybe something similar is out there.

https://wxpython.org/Phoenix/docs/html/wx.SingleInstanceChecker.html

[joncage]

Give this a shot: https://github.com/joncage/ed-scout/releases/tag/v1.2.2 (should detect and kill off older instances).

Interesting behaviour you're seeing; There is one difference in my journal-watcher vs the nav-route-watcher and that's that I initally had issues where (as it's a busy file) i'd only get half an update now and then. To counter it, I just aborted if we had an incomplete entry so that the next write-trigger starts a complete read. Maybe on a slower disk if there's a lot of activity, this is preventing it from ever completing and I need a smarter strategy.

Could be there's something odd in Windows or the Python watchdog lib I'm using to watch for changes.

[Rhaedas]

On the instances - it worked in that running it a few times only shows one process, but it still has multiple windows. Closing each of them doesn't do anything until the last. When I get it to work, it plots in all of them, so they are views of the same instance. Example

I doubt it's a speed thing, as I'm running on a new build with a brand new SSD, nothing else going on. Any reason not to use the Nav file? It's pretty basic, it only has the current route plotted with nothing else.

Just an update, I've played through charting a trip and following through it. It functions as intended as long as I access the journal file with something else between trips, such as clicking on the file name in File Manager. If I make two jumps it is static until I do that, and then it cycles through both those locations like it should have done while I did them.

[joncage]

Cheers for the feedback - very useful!

On the instances

So it turns out that the chrome instance it launches for the GUI aspect appears in device manager as 'chrome.exe' and is (as far as I can see) indistinguishable from any other chrome instances you might have open. So even though EDS now kills off the duplicate back-ends, the GUI elements remain. I do have a theory about how I might get around that (i.e. get the I to do a heartbeat to ping the packend and via javascript, kill the window if we get no response) but it'll take a bit more hacking.

I'm running on a new build with a brand new SSD, nothing else going on.

Okay, probably a red-herring on that front then :)

Any reason not to use the Nav file?

It still uses the nav file in the latest version. The difference is that instead of watching the navfile for changes (as well as the journal), it just watches the journal file and when it sees a { "event":"NavRoute" } entry, goes and reads the navroute file. This meant (1) I only needed one thing watching the filesystem (2) I avoided some complications where some bits of the journal update were being posted to the GUI before or during the navroute being sent though.

I'll generate some diagnostic builds / tools to add some more info to try and get to the bottom of this. I have some thoughts about how we might get it to re-read the file every (say) 250ms even if windows doesn't proactively tell us the file has change as a backup but would be cool if we could work out why it's pretty instant on my machine but takes another program fiddling with the file to spot it otherwise.

[joncage]

When you get some time, can you try:

1. Download & extract EDScout.zip
2. Run EDScout.exe -log_level 0
3. Run Elite
4. Plot a nav-route.
5. Stick a copy of the resulting log in here.

This is what I got from running it:

EDScout.log

This is a diagnostic build that should show a bit more of what's going on behind the scenes. Just workign on another adjustment that will show what happens to the nav file.

[joncage]

Next up try the same with this: EDScout-WithNavWatching.zip

..for which I get: EDScout.log

Looks like the nav route is written a few 10s of ms before the journal is updated.

[Rhaedas]

EDScout.log

Got this from a clean run. I noticed it mentioning an old process it killed, but I had nothing in my Task Manager at the time. This log generated when I plotted the course, but there is no activity on EDScout itself.

EDScout.log

And here is the log after I just click on the journal file name in File Explorer.

[joncage]

Looks like the backend is working but the web page has an issue potentially.

Try this if you can:

1. Close all the scouts
2. Run the scout again.
3. Open chrome and connect to http://127.0.0.1:5000/
4. Open developer tools:
   
5. Plot a route
6. Check the console for errors:
   
7. Copy-paste the console output here.

[Rhaedas]

Here's the run from the second version.

EDScout.log

Same as before.

I did the same as before to get it to do something, but it didn't write anything new to the log, plus wrote the path twice (cleared it and redid it). Weird.

Going to try your next suggestion.

[Rhaedas]

Going to try again, but in the middle of doing all that with Chrome, I plotted a course and got nothing on either console or EDScout. Then the game crashed and I got a mauve adder error. Coincidence probably, but interestingly I found this in Chrome after the crash.

{data: {…}}data: {type: "NewRoute"}__proto__: Object (index):244 Clearing (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 14574, id64: 7266682348953, name: "Nakako", url: "https://www.edsm.net/en/system/bodies/id/14574/name/Nakako", …} (index):87 Setting current (index):78 NodeList [] (index):234 {bodyId: 1251263, bodyName: "Nakako 6", distance: 91, valueMax: 353177} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 592, id64: 1183230005962, name: "Kocab", url: "https://www.edsm.net/en/system/bodies/id/592/name/Kocab", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 2675, id64: 1075612502371, name: "HIP 68796", url: "https://www.edsm.net/en/system/bodies/id/2675/name/HIP+68796", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 2095, id64: 1183230038730, name: "HIP 66267", url: "https://www.edsm.net/en/system/bodies/id/2095/name/HIP+66267", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 81333, id64: 669612647825, name: "Col 285 Sector KE-D b14-0", url: "https://www.edsm.net/en/system/bodies/id/81333/name/Col+285+Sector+KE-D+b14-0", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 2001617, id64: 2868635903369, name: "Col 285 Sector GY-E b13-1", url: "https://www.edsm.net/en/system/bodies/id/2001617/name/Col+285+Sector+GY-E+b13-1", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 2567351, id64: 7266414044553, name: "Col 285 Sector DD-F b13-3", url: "https://www.edsm.net/en/system/bodies/id/2567351/name/Col+285+Sector+DD-F+b13-3", …} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 10035, id64: 1900246223203, name: "HIP 57532", url: "https://www.edsm.net/en/system/bodies/id/10035/name/HIP+57532", …} (index):234 {bodyId: 26163984, bodyName: "HIP 57532 5", distance: 372, valueMax: 635006} (index):234 {bodyId: 26163990, bodyName: "HIP 57532 6", distance: 467, valueMax: 632269} (index):241 {data: {…}} (index):268 Processing system report {type: "System-NavRoute", id: 13906, id64: 663295641955, name: "HIP 58924", url: "https://www.edsm.net/en/system/bodies/id/13906/name/HIP+58924", …} (index):241 {data: {…}} (index):120 Setting target system (index):241 {data: {…}} (index):268 Processing system report {type: "System-FSDTarget", id: 592, id64: 1183230005962, name: "Kocab", url: "https://www.edsm.net/en/system/bodies/id/592/name/Kocab", …} (index):241 {data: {…}}

[Rhaedas]

Okay, second run, this is what I get in the console after a plot:

{data: {…}} data: {timestamp: "2020-08-16T00:22:49Z", event: "Fileheader", part: 1, language: "English\UK", gameversion: "Fleet Carriers Update - Patch 4", …} __proto__: Object (index):241 {data: {…}} data: {timestamp: "2020-08-16T00:23:26Z", event: "Friends", Status: "Online", Name: "Ageudum", type: "JournalEntry"} __proto__: Object

No change in EDScout, it's still waiting.

Let me know if you need the whole thing expanded out or a particular section.

Going back to the early logs, it looks like the journal hook is working right, it detects the early parts of the file size changes when the game starts, but then something is not letting it see the plot changes until something else touches the file.

[joncage]

Okay, second run, this is what I get in the console after a plot

I take it chrome didn't display anything either when you plotted that out?

[Rhaedas]

Okay, second run, this is what I get in the console after a plot

I take it chrome didn't display anything either when you plotted that out?

Both Chrome and EDScout show the same thing, "waiting for nav data..."

[joncage]

Very strange. We'remissing something obvious here is my feeling. From the logs above it looks like at least some of the time, the back end is correctly picking up the changes and the front end is receiving them but the page isn't being redrawn :-/

If you have time, might be worth logging off / back on or rebooting then try running this (before firing up elite):
EDScout-WithNavWatch-DiagnosticBuild.zip ...just to get a bit more debug and to be 100% sure we only have one instance going.

[Rhaedas]

Will do, going to do a clean start. For what it's worth, I went back and retried version 1.0.0 just to make sure nothing change here. I know it worked a bit differently, just had to make. It works fine still.

No change.
Log under Documents only has these three lines added:

2020-08-15 20:43:29.194 - EDScoutWebUI-EDScout - INFO - ED Scout Starting 2020-08-15 20:43:29.358 - EDScoutWebUI-EDScout - INFO - Looking for HUD overrides in C:\Users\GHH\AppData\Local\Frontier Developments\Elite Dangerous\Options\Graphics\GraphicsConfigurationOverride.xml 2020-08-15 20:43:30.620 - EDScoutWebUI-EDScout - INFO - Background thread launched and awaiting data..

Any other log areas to look at?

[Rhaedas]

New results - I went and closed the game and still had EDScout open. It showed the route. Going to try and duplicate it.

Confirmed. Ran the stock 1.2.2 and it hangs, but the minute the game ends it plots the route (twice). Why mine and not yours (or others) is the question.

[joncage]

Do you have the scout-logs from that last experiment?

I'm going to try and add some code to just read the file size every 100ms and see if that prompts the file system to report the changes properly. It's a bit hacky but it could work based.on some of the observations we've seen here..

[joncage]

EDScout.log

And here is the log after I just click on the journal file name in File Explorer.

This is interesting:

2020-08-15 19:44:22.411 - EDScoutWebUI-EDScout - INFO - ED Scout Starting
...
2020-08-15 19:45:20.350 - JournalInterface-JournalInterface - DEBUG - Journal created: C:\Users\GHH\Saved Games\Frontier Developments\Elite Dangerous\Journal.200815194520.01.log

2020-08-15 19:45:20.351 - JournalInterface-JournalInterface - DEBUG - Journal change: C:\Users\GHH\Saved Games\Frontier Developments\Elite Dangerous\Journal.200815194520.01.log
2020-08-15 19:45:46.205 - JournalInterface-JournalInterface - DEBUG - C:\Users\GHH\Saved Games\Frontier Developments\Elite Dangerous\Journal.200815194520.01.log - Size change: 170 to 333
2020-08-15 19:45:46.206 - JournalInterface-JournalInterface - DEBUG - Found 2 new entries

2020-08-15 19:45:58.495 - JournalInterface-JournalInterface - DEBUG - Journal change: C:\Users\GHH\Saved Games\Frontier Developments\Elite Dangerous\Journal.200815194520.01.log
2020-08-15 19:45:58.496 - JournalInterface-JournalInterface - DEBUG - Found 1 new entries

2020-08-15 19:53:16.025 - JournalInterface-JournalInterface - DEBUG - Journal change: C:\Users\GHH\Saved Games\Frontier Developments\Elite Dangerous\Journal.200815194520.01.log
2020-08-15 19:53:16.028 - JournalInterface-JournalInterface - DEBUG - Found 23 new entries

Note the 23 new entries bit. Inside that we're seeing:

2020-08-15 19:53:16.026 - New journal entry detected: { "timestamp":"2020-08-15T23:45:58Z", "event":"Commander", "FID":"F51848", "Name":"Rhaedas" }
...
2020-08-15 19:53:16.027 - New journal entry detected: { "timestamp":"2020-08-15T23:45:58Z", "event":"Rank", "Combat":4, "Trade":8, "Explore":5, "Empire":0, "Federation":0, "CQC":0 }
...
2020-08-15 19:53:16.028 - New journal entry detected: { "timestamp":"2020-08-15T23:46:26Z", "event":"NavRoute" }
...
2020-08-15 19:53:16.028 - New journal entry detected: { "timestamp":"2020-08-15T23:53:03Z"

Note that the scount is just doing one update there at a single timestamp vs lots of updates from elite.

So this further confirms that something is caching file system updates to the journal.

[joncage]

Give this a shot:

EDScout-DiagnosticBuild-025f8c56eb866bcae4700b4a5d85e3aaad66808c.zip

It has a little timer that checks the journal size every 100ms; I'm hoping that will be enough to kick your machine into spotting updates to the journal file. Note that it needs to be run AFTER Elite has been started so it picks up the latest journal file.

If this works, I'll package it up into a proper version and tidy things up a bit. Would be good to understand why it's different still though.

[Rhaedas]

Ran Elite then the new one. Got this in the command window:

`default_config_file=C:\Users\GHH\AppData\Local\Frontier Developments\Elite Dangerous\Options\Graphics\GraphicsConfigurationOverride.xml
Exception in thread Thread-4:
Traceback (most recent call last):
File "threading.py", line 917, in _bootstrap_inner
File "watchdog\observers\api.py", line 203, in run
File "watchdog\observers\api.py", line 376, in dispatch_events
File "watchdog\events.py", line 452, in dispatch
File "watchdog\events.py", line 336, in dispatch
File "EDScoutCore\JournalInterface.py", line 123, in on_modified
File "EDScoutCore\EDScout.py", line 94, in on_journal_change
AttributeError: 'EDScout' object has no attribute 'journalChangeIdentifier'

and this in the log:

2020-08-16 11:49:44.351 - EDScoutWebUI-EDScout - INFO - ED Scout v1.2.2-025f8c56eb866bcae4700b4a5d85e3aaad66808c Starting 2020-08-16 11:49:44.533 - EDScoutWebUI-EDScout - INFO - Looking for HUD overrides in C:\Users\GHH\AppData\Local\Frontier Developments\Elite Dangerous\Options\Graphics\GraphicsConfigurationOverride.xml 2020-08-16 11:49:45.660 - EDScoutWebUI-EDScout - INFO - Background thread launched and awaiting data..

[Rhaedas]

I've pulled from the journal before myself to check for updates for something I did for Voice Attack (reading NPC messages). My methodology was more brute force, I'd have VA check the size every half second or something to see if anything was new, and then look backwards through the file for a NPC chat statement. If it didn't match what I had done previously, then the loop would start over, if new VA would say it in a random voice.

This is a bit different, but since all you're looking for is a plotted route to work with, why not just do all this with the navroute file. Store the timestamp for the route creation, and when it changes you know you have a new route.

Totally just a suggestion. Nothing wrong with taking the journal approach, but it does seem like that added complexity is throwing some obstacles, at least for my system.

[joncage]

There is a way to switch the watchdog to polling (brute force) so that's an option certainly.

I want to use the journal because I'm working on some updates that use the FSS as you're doing it to highlight which planets are worth most money and any that haven't been mapped yet etc. ...just using the navroute file was easier I agree 😉

[joncage]

One more to try:

EDScout-DiagnosticBuild-9b3984ff6a311068b13a468e3cad6ff333a69879.zip

...and if that doesn't work, try running it a second time as follows:

EDScout.exe -force_polling

...which will engage a more brute-force polling approach.

[Rhaedas]

That version worked right away. I ran Elite, then ran it. The second I popped into the galaxy map it started mapping the route I had last done, and my changes also get mapped. Once you get the next version packaged, I'll start testing the other factors of it. I have to finish my HOTAS setup anyway, and it gives me a good reason to do that.

[joncage]

That version worked right away.

Excellent! Was that with or without the -force_polling?

[Rhaedas]

That version worked right away.

Excellent! Was that with or without the -force_polling?

Without, just ran the extracted code as-is.

[joncage]

I'll try and get a new release out tonight which will include some extra logging that'll help me implement the next stage of you're prepared to help pass on some logs from it? 😊

[Rhaedas]

Will do. Suggestion - have log names also have initial timestamps in their name for each session, so it doesn't become one long file. Also, have the log directory in the same directory as the exe? Don't know if there's a benefit to putting it in Documents.

[joncage]

Have log names also have initial timestamps in their name for each session.

Excellent suggetsion - will do! o7

The advantage of having it in your user area is you don't have to worry about permissions but probably appdata would be a more appropriate location. Will take a look at that too.

[joncage]

v1.2.3 released here: https://github.com/joncage/ed-scout/releases/tag/v1.2.3

Give it a shot :)

[Rhaedas]

Ran EDScout first just to test if that would be an issue, it waited for the game properly. Plotted a number of routes, no issues. Followed the last route for a few jumps to make sure it was tracking, no issues. Then had to get some fuel, so I parked.

So until I get out of the bubble, all looks well now. One UI suggestion - the route is printed between two lines, and for long ones it's not obvious when the route is done. Either don't print the bottom line until the plot is finished to indicate it's done, or alternatively have the last star, the destination be labeled like you label the current location in its own heading.

Here's my log for the run, fwiw:

EDScout-2020-08-17-23-10-30.log

So time to move to the other stuff for 1.3, make it prettier, more features, etc.