Listener fails to update some stations

[eyeonus]

For some reason, the database isn't being updated by the listener for some stations when processing the EDDN messages.

First step is to add some debug output to track down the source of the problem.

[eyeonus]

ec2e39a

[eyeonus]

I very much wonder if this has anything to do with https://github.com/eyeonus/Trade-Dangerous/issues/15 ....

[Tromador]

Why would it? We have had this issue singe before the latest 2 ships, no?

Just to note, I was able to use EDMC to make a .prices file for affected stations and import that using 'TD import'. So, taking the listener out of the equation, TD itself worked as expected.

On Fri, 13 Jul 2018, 15:49 Jonathan Jones, notifications@github.com wrote:

I very much wonder if this has anything to do with eyeonus/Trade-Dangerous#15 https://github.com/eyeonus/Trade-Dangerous/issues/15 ....

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/eyeonus/EDDBlink-listener/issues/7#issuecomment-404855840, or mute the thread https://github.com/notifications/unsubscribe-auth/AlJsLPcBztUlP4ZriteKN8Fb45aJ03kQks5uGLNegaJpZM4VL3zU .

[eyeonus]

Yeah, I don't know. Wishful thinking of an exhausted man.

[eyeonus]

I think I figured it out. I have the code only commit changes when there's no queue so as to speed up processing, and I have it close the DB after it finishes processing a message.

But guess what happens when you close the database without commiting? That's right, it discards the changes.

Ugh, I am such an idiot. I already learned that mistake when working on the plugin.

[Tromador]

The only way we'll know is to test, though clearly the commit logic was flawed and it is hard to imagine not losing data prior to this change. Thus unless there is a secondary issue (I truly hope not) then I agree with you that this is likely a fix.

But if you were 100% sure, then you would have closed the ticket.

So, I really think that the only way to be 100% sure is to write a separate audit script that reads the log and checks that the timestamps for all logged stations are sane - otherwise we are relying on catching it out on a station for which we happen to need data.

That in mind, I am going to send a PR to change the behaviour of your recent debug output. It may well help to diagnose if we still have a problem, but the output is vast. Rather than just have 'verbose', have verbose and debug, where debug adds in all that extra output, then I can update the server version of the listener.

[eyeonus]

Sounds good to me. I'm not 100% certain, no, but I want to hold off on making on audit program, mainly because I'd like to not spend all my free time working on this.

That said, if anyone else decides to make an audit program, I'm not going to say no. :)

If we still see this error, I'll worry about an audit program at that point, but if no-one sees this problem, after a week or two I'll consider this matter closed.

[Tromador]

I 100% understand wanting to do something else. Maybe even play the stupid game!

My main concern is that we might not notice, whilst an audit would check a whole raft of data we would otherwise never examine.

[Tromador]

I am really sorry and it pains me to post this.. Market update for HIP 38129/SCHEERBART BASE finished in 2.356 seconds. @ 12:52 my time 14th July

But once again, the data didn't get through. Again it was on a planet. Don't know what else to say.

As before I could export a .prices using EDMC which I could add using trade.py import.

I am hoping you simply made a simple mistake in your earlier fix.

[elite@mort data]$ sqlite3
SQLite version 3.24.0 2018-06-04 19:24:41
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .open TradeDangerous.db
sqlite> SELECT * FROM StationItem WHERE station_id==57218
   ...> ;
57218|1|407|547|3|0|0|0|2018-07-13 06:16:49|0
57218|2|93|0|0|97|49|1|2018-07-13 06:16:49|0
57218|5|273|41|2|0|0|0|2018-07-13 06:16:49|0
57218|6|6829|8|3|0|0|0|2018-07-13 06:16:49|0
57218|7|628|12|2|0|0|0|2018-07-13 06:16:49|0
57218|8|236|53|2|0|0|0|2018-07-13 06:16:49|0
57218|9|1254|531|3|0|0|0|2018-07-13 06:16:49|0
57218|10|10058|45|3|0|0|0|2018-07-13 06:16:49|0
57218|11|5148|4|2|0|0|0|2018-07-13 06:16:49|0
57218|12|473|47|2|0|0|0|2018-07-13 06:16:49|0
57218|14|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|15|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|16|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|17|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|18|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|19|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|20|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|21|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|29|767|88|2|0|0|0|2018-07-13 06:16:49|0
57218|30|693|10|2|0|0|0|2018-07-13 06:16:49|0
57218|31|1772|2905|3|0|0|0|2018-07-13 06:16:49|0
57218|33|4447|41600|3|0|0|0|2018-07-13 06:16:49|0
57218|34|2456|0|1|0|0|0|2018-07-13 06:16:49|0
57218|35|6829|15|3|0|0|0|2018-07-13 06:16:49|0
57218|39|245|0|0|256|27|1|2018-07-13 06:16:49|0
57218|42|9161|0|0|9266|5|2|2018-07-13 06:16:49|0
57218|45|12237|0|0|12377|3|1|2018-07-13 06:16:49|0
57218|47|4144|0|0|4245|18|1|2018-07-13 06:16:49|0
57218|51|97|0|0|148|161|1|2018-07-13 06:16:49|0
57218|52|1987|0|0|2039|39|1|2018-07-13 06:16:49|0
57218|53|947|0|0|987|76|1|2018-07-13 06:16:49|0
57218|54|1453|0|0|1492|59|1|2018-07-13 06:16:49|0
57218|55|1696|0|0|1741|11|1|2018-07-13 06:16:49|0
57218|56|404|0|0|424|125|1|2018-07-13 06:16:49|0
57218|57|254|0|0|274|55|1|2018-07-13 06:16:49|0
57218|58|457|0|0|478|22|1|2018-07-13 06:16:49|0
57218|59|17431|13|2|0|0|0|2018-07-13 06:16:49|0
57218|65|688|431|3|0|0|0|2018-07-13 06:16:49|0
57218|67|1911|64068|3|0|0|0|2018-07-13 06:16:49|0
57218|75|35|0|0|59|3|2|2018-07-13 06:16:49|0
57218|78|2320|170|3|0|0|0|2018-07-13 06:16:49|0
57218|79|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|80|1893|2|2|0|0|0|2018-07-13 06:16:49|0
57218|101|310|18|2|0|0|0|2018-07-13 06:16:49|0
57218|102|543|0|1|0|0|0|2018-07-13 06:16:49|0
57218|103|1595|52|2|0|0|0|2018-07-13 06:16:49|0
57218|104|1558|1|2|0|0|0|2018-07-13 06:16:49|0
57218|105|1052|0|0|1080|20|1|2018-07-13 06:16:49|0
57218|107|405|0|0|423|23|1|2018-07-13 06:16:49|0
57218|108|1700|0|0|1745|85|1|2018-07-13 06:16:49|0
57218|113|543|104|3|0|0|0|2018-07-13 06:16:49|0
57218|116|3000|118|3|0|0|0|2018-07-13 06:16:49|0
57218|118|678|98|2|0|0|0|2018-07-13 06:16:49|0
57218|119|793|26|2|0|0|0|2018-07-13 06:16:49|0
57218|121|3849|0|1|0|0|0|2018-07-13 06:16:49|0
57218|124|6348|10|3|0|0|0|2018-07-13 06:16:49|0
57218|129|2511|44|3|0|0|0|2018-07-13 06:16:49|0
57218|252|978|44|3|0|0|0|2018-07-13 06:16:49|0
57218|254|91|44|3|0|0|0|2018-07-13 06:16:49|0
57218|255|304|44|3|0|0|0|2018-07-13 06:16:49|0
57218|256|250|44|3|0|0|0|2018-07-13 06:16:49|0
57218|257|233|44|3|0|0|0|2018-07-13 06:16:49|0
57218|258|635|44|3|0|0|0|2018-07-13 06:16:49|0
57218|259|747|44|3|0|0|0|2018-07-13 06:16:49|0
57218|260|939|44|3|0|0|0|2018-07-13 06:16:49|0
57218|263|250|44|3|0|0|0|2018-07-13 06:16:49|0
57218|268|2192|44|3|0|0|0|2018-07-13 06:16:49|0
57218|271|12|0|0|63|65|1|2018-07-13 06:16:49|0
57218|276|91325|0|1|0|0|0|2018-07-13 06:16:49|0
57218|282|0|0|0|0|0|0|2018-07-13 06:16:48|0
57218|305|3159|210098|3|0|0|0|2018-07-13 06:16:49|0
57218|307|2304|28|3|0|0|0|2018-07-13 06:16:49|0
57218|308|2745|131|3|0|0|0|2018-07-13 06:16:49|0
57218|310|16490|305|3|0|0|0|2018-07-13 06:16:49|0
57218|313|7890|566|3|0|0|0|2018-07-13 06:16:49|0
57218|314|10449|653|3|0|0|0|2018-07-13 06:16:49|0
57218|316|27726|44|3|0|0|0|2018-07-13 06:16:49|0
57218|321|12862|75|3|0|0|0|2018-07-13 06:16:49|0
57218|322|8771|75|3|0|0|0|2018-07-13 06:16:49|0
57218|323|7736|75|3|0|0|0|2018-07-13 06:16:49|0
57218|324|8771|75|3|0|0|0|2018-07-13 06:16:49|0
57218|325|6034|75|3|0|0|0|2018-07-13 06:16:49|0
57218|326|10614|75|3|0|0|0|2018-07-13 06:16:49|0
57218|327|5308|44|3|0|0|0|2018-07-13 06:16:49|0
57218|328|44336|44|3|0|0|0|2018-07-13 06:16:49|0
57218|330|5658|44|3|0|0|0|2018-07-13 06:16:49|0
sqlite>

[Tromador]

One small thing (I'll post anything I notice at this stage).

I tried to import the prices onto the server, thinking it would get into listings-live. I completely forgot about setting the live field for that to happen, but anyway - my point is that it was different loading into the server DB than my local DB. Dunno if that is relevant, but there it is.

[elite@mort tradedangerous.server]$ ./trade.py import hipprice.prices NOTE: Import complete: 60 updated items over 1 stations in 1 systems

D:\Games\Game Tools\Elite\Trade Dangerous>trade.py import "HIP 38129.Scheerbart Base.2018-07-14T12.55.13.prices" NOTE: Import complete: 9 new and 51 updated items over 1 stations in 1 systems

[eyeonus]

The only thing we can tell for certain from that is that the server already had all 60 items in the DB, whereas the local only had 51 of them.

What was the debug output?

I can have the listener write the messages to file easily enough before I hit the sack. If you don't feel like dusting off your Perl skills, I'll look into writing the audit program after sleep.

[eyeonus]

I definitely recommend against turning debug on on the server, just because all the file writing is sure to slow things down quite a lot.

A note on the commit: It actually creates "debug.txt" in the eddbPath folder, so if self.dataPath = tdb.dataPath / Path("eddb") is altered in the plugin (, which by default is "\<TD>/data/eddb/"), whatever it is altered to is the folder to look in for the debug file.

[Tromador]

I didn't have the server running debug, in the hope it was fixed and I don't run local listener (as then I'm not testing the server).

And I completely agree about NOT running debug at server level. That's why I wanted it as a separate option, so I can continue running the server on verbose.

Venet/Tan Vision - another one, also on planet, but my brain is reeling from today's bout of medication, so trying to think clearly on the subject is a bit beyond me atm.

If you have time after sleep to look into an audit, fine - otherwise I'll try and knock something up in PERL after I too have slept, but can't promise any kind of speed atm, illness and meds rather messing with me.

Any more I find listed here for more testing later (I am routinely checking planetary bases now).

Venet/Tan Vision - Planet Nariyot/Yamamoto Silo - Planet Cubeo/Medupe City - NOT A PLANET (so nevermind that idea) HIP 10785/Gelfand Silo

This last 4 all failed one after another after another. So everywhere I am going isn't getting updated.

Please can you check the whitelisting code?

[Tromador]

Okay my brain is 100% totally fried - forget the whitelisting.

I ran locally and on the server

trade.py import -P eddblink -O clean,fallback

So (should have) identical databases. and then ran the listener on both. Identical code, downloaded today for TD & listener.

Everything should match.

Then I landed on a planet not updated in months (on the grounds nobody else would be interfering with the test).

Sent an update.

Local updated fine Server did not.

This is what I am repeatedly seeing, over and over and over. Local will update, server will not, on identical versions

So - wierd platform specific behaviour? SQLite library version?

I think we need to spend some time together, to look into what the hell is going on.

I did capture a debug from the Server. Which tells me pretty much nothing and also looks identical to a capture I got on the local machine.

Edit: Bunch of noise removed for sake of some kind of brevity.

[eyeonus]

Yeah, those debug messages don't really help at all.

I'm getting rid of them. They're just a bunch of noise.

[Tromador]

Working on KUKI AN/BOKEILI HUB which is presently refusing to update on server (but working fine locally)

Server & Local agree about receiving data per.

KUKI AN/BOKEILI HUB with station_id '43119' updated at 2018-07-15 18:06:00 using E:D Market Connector [Windows]3.0.5.0 ---

Added some debug down to the SQL level per

def db_execute(db, sql_cmd, args = None):
    cur = db.cursor()
    success = False
    result = None

    while go and not success:
        try:
            if args:
                if config['debug']:
                    with debugPath.open('a', encoding = "utf-8") as fh:
                        fh.write("Running SQL Command: " + sql_cmd + " ***\n")
                        fh.write("With args: " + str(args) + " ***\n")
                result = cur.execute(sql_cmd, args)
            else:
                result = cur.execute(sql_cmd)
            success = True
        except sqlite3.OperationalError as e:
                if "locked" not in str(e):
                    success = True
                    raise sqlite3.OperationalError(e)
                else:
                    print("Database is locked, waiting for access.", end = "\r")
                    time.sleep(1)
    return result

Can confirm that listener is producing identical SQL both locally and on server. e.g.

Running SQL Command: INSERT INTO StationItem
                           (station_id, item_id, modified,
                            demand_price, demand_units, demand_level,
                            supply_price, supply_units, supply_level, from_live)
                           VALUES ( ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 ) ***
With args: (43119, 2, '2018-07-15 18:06:00', 93, 1, 0, 97, 18, 1) ***

Not that this should come as a surprise, but when stuff gets into the local DB, but not the server DB, I'm drilling right down to the nuts and bolts.

So I tried manually entering the SQL:

Using the above example we get

INSERT INTO StationItem (station_id, item_id, modified, demand_price, demand_units, demand_level, supply_price, supply_units, supply_level, from_live) VALUES ( 43119, 2, '2018-07-15 18:06:00', 93, 1, 0, 97, 18, 1, 1 );

Which throws: Error: UNIQUE constraint failed: StationItem.station_id, StationItem.item_id

Same error if I run that SQL statement using either the SQLIte3 shell on Linux, or my fancy schmancy DB browser for windows.

Which then looks to me like it should never work and always be caught by the exception. So presumably, I made a mistake in my logic - can someone point out my error, so I can test the SQL correctly on the two platforms and see if there really is a difference.

[eyeonus]

You are correct. When there is already data in the DB for a specific station_id, item_id combo, as in your example, the DB will throw the "UNIQUE constraint failed" sqlite3.IntegrityError.

This is normal expected behavior.

            except sqlite3.IntegrityError:
                try:
                    db_execute(db, """UPDATE StationItem
                                SET modified = ?,
                                 demand_price = ?, demand_units = ?, demand_level = ?,
                                 supply_price = ?, supply_units = ?, supply_level = ?,
                                 from_live = 1
                                WHERE station_id = ? AND item_id = ?""",
                                (modified, 
                                 entry['demand_price'], entry['demand_units'], entry['demand_level'], 
                                 entry['supply_price'], entry['supply_units'], entry['supply_level'],
                                 station_id, entry['item_id']))

It's the UPDATE that isn't working for some reason, not the INSERT.

[eyeonus]

Basically, the code is doing:

try
    INSERT station_data_from_message
except station_data_exists_already:
   try
        UPDATE station_data_with_message
   except error(e)
        print got_error(e)

[Tromador]

I must be missing a step following it through... after failing the INSERT does it get sent back to another function/method with a "FAIL" stamped on it and "Please resend as an UPDATE" such that db_execute can be called twice for a single message?

[eyeonus]

If the INSERT db_execute fails with the sqlite3.IntegrityError exception, which it does whenever trying to insert data for a station item combo that already exists in the DB, the exception is caught by the call, which triggers trying again as an UPDATE.

You'll notice that, for "blank entries", it immediately raises that specific exception and totally skips even trying to INSERT:

            try:
                # Skip inserting blank entries so as to not bloat DB.
                if entry['demand_price'] == 0 and entry['supply_price'] == 0:
                    raise sqlite3.IntegrityError
**INSERT call**
                db_execute(db, """INSERT INTO StationItem
                            (station_id, item_id, modified,
                             demand_price, demand_units, demand_level,
                             supply_price, supply_units, supply_level, from_live)
                            VALUES ( ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 )""",
                            (station_id, entry['item_id'], modified,
                            entry['demand_price'], entry['demand_units'], entry['demand_level'],
                            entry['supply_price'], entry['supply_units'], entry['supply_level']))
**UNIQUE constraint failed**
            except sqlite3.IntegrityError:
                try:
**UPDATE call**
                    db_execute(db, """UPDATE StationItem
                                SET modified = ?,
                                 demand_price = ?, demand_units = ?, demand_level = ?,
                                 supply_price = ?, supply_units = ?, supply_level = ?,
                                 from_live = 1
                                WHERE station_id = ? AND item_id = ?""",
                                (modified, 
                                 entry['demand_price'], entry['demand_units'], entry['demand_level'], 
                                 entry['supply_price'], entry['supply_units'], entry['supply_level'],
                                 station_id, entry['item_id']))
                except sqlite3.IntegrityError as e:
                    if config['verbose']:
                        print("Unable to insert or update: '" + commodity + "' Error: " + str(e))

[eyeonus]

With braces!

            try {
                # Skip inserting blank entries so as to not bloat DB.
                if entry['demand_price'] == 0 and entry['supply_price'] == 0 {
                    raise sqlite3.IntegrityError
                }
                db_execute(db, """INSERT INTO StationItem
                            (station_id, item_id, modified,
                             demand_price, demand_units, demand_level,
                             supply_price, supply_units, supply_level, from_live)
                            VALUES ( ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 )""",
                            (station_id, entry['item_id'], modified,
                            entry['demand_price'], entry['demand_units'], entry['demand_level'],
                            entry['supply_price'], entry['supply_units'], entry['supply_level']))
            } except sqlite3.IntegrityError {
                try {
                    db_execute(db, """UPDATE StationItem
                                SET modified = ?,
                                 demand_price = ?, demand_units = ?, demand_level = ?,
                                 supply_price = ?, supply_units = ?, supply_level = ?,
                                 from_live = 1
                                WHERE station_id = ? AND item_id = ?""",
                                (modified, 
                                 entry['demand_price'], entry['demand_units'], entry['demand_level'], 
                                 entry['supply_price'], entry['supply_units'], entry['supply_level'],
                                 station_id, entry['item_id']))
                } except sqlite3.IntegrityError as e {
                    if config['verbose'] {
                        print("Unable to insert or update: '" + commodity + "' Error: " + str(e))
                    }
                }
            }

[Tromador]

So yes - I'm looking (myopically) in db_execute for this 'if INSERT fails then UPDATE' construct, but it's in a completely different place.

So I need to be testing

Running SQL Command: UPDATE StationItem
                                SET modified = ?,
                                 demand_price = ?, demand_units = ?, demand_level = ?,
                                 supply_price = ?, supply_units = ?, supply_level = ?,
                                 from_live = 1
                                WHERE station_id = ? AND item_id = ? ***
With args: ('2018-07-15 18:06:00', 93, 1, 0, 97, 18, 1, 43119, 2) ***

[eyeonus]

Yes.

All db_execute does is run the passed sql command, retrying if it gets the database is locked error.

Any other errors get passed back to the caller.

[aadler]

@Tromador I note you're using EDMC 3.0.5. The most recent version is 3.1.0 and that has updates for the new ships and such. See https://github.com/Marginal/EDMarketConnector/releases. Could that be related?

[eyeonus]

Highly doubtful.

[Tromador]

No, that won't be it. I get the same result using EDMC, or EDDiscovery. I have been using EDMC for some of my testing as it produces a .prices file, which I can then import outside of the listener to see if TD hates on that data for some other reason (and it doesn't).

[Tromador]

Server has been upgraded. Virtual host is now on new iron with faster cores and more of them. Maybe that will help because of.... something... I'll try to find some testing time now the migration to the new hardware is complete, though I have a big event over the weekend and might end up too hungover to live.

[eyeonus]

Any news on this? I haven't had any time to myself lately, mainly due to my car deciding it didn't want to work, so I haven't done anything with this.

[Tromador]

I have had a busy week too, making sure the hardware migration was done right, hospital appointments and indeed I have a pretty thick head today. I will look into it next week.

One additional difference I have observed: On PC when it runs the plugin to download the latest source files, it seems to back up a lot of messages. After the plugin completes, a whole raft of messages rush through as it catches up. This is (I believe) correct behaviour.

On Linux this does not happen. After the plugin completes there is no sudden rush of queued up information, it simply seems to start listening from that point onwards.

I wonder if there is a difference in how the OS handle threads. Not sure if it is related, mind you.

In any event I will have a prod at it in the next day or so.

[Tromador]

Nah - scratch that. The queue may well be working just fine on Linux... but compare

Server -

Market update for NINHURSAG/DANNY B MATTISSEN finished in 3.186 seconds.
Market update for PROCYON/DAVY DOCK finished in 2.219 seconds.
Market update for ROBIGO/HAUSER'S REACH finished in 2.98 seconds.
Market update for CORNENGU/MARGULIES DOCK finished in 0.719 seconds.
Market update for NLTT 53690/THAGARD TERMINAL finished in 1.45 seconds.
Market update for STF 1774/CHALKER ENTERPRISE finished in 2.961 seconds.
Market update for LACAILLE 9352/GUPTA CITY finished in 3.438 seconds.
Market update for RUNO/BOB PAFFETT finished in 1.885 seconds.

PC

Market update for EURYBIA/AWYRA FLIRBLE finished in 0.534 seconds.
Market update for SHINRARTA DEZHRA/JAMESON MEMORIAL finished in 0.534 seconds.
Market update for ZHANG FEI/SEREBROV HORIZONS finished in 0.009 seconds.
Market update for HIP 85360/MACAN PLATFORM finished in 0.62 seconds.
Market update for HIP 53688/WHITE GATEWAY finished in 0.599 seconds.
Market update for XINCA/FINCH MARKET finished in 0.341 seconds.

Now I know the server hasn't got brand new shiny hardware, but that's a massive difference.

Ah... I have done the obvious test...

PC running in SERVER mode.

Market update for KP TAURI/SPEDDING ORBITAL finished in 3.166 seconds.
Market update for KALVELIS/BEEKMAN GATEWAY finished in 3.404 seconds.
Market update for ERAVATE/CLEVE HUB finished in 3.474 seconds.
Market update for 61 CYGNI/BROGLIE TERMINAL finished in 3.388 seconds.
Market update for CUBEO/CHELOMEY ORBITAL finished in 1.846 seconds.
Market update for FAN YIN/SIMPSON RING finished in 2.41 seconds.
Market update for MUDUSITOQ/DAIMLER GATEWAY finished in 3.031 seconds.
Market update for ERAVATE/CLEVE HUB finished in 3.515 seconds.

[Tromador]

So - some difference on running in server mode is killer.

I thought the only difference was that it called "export" once in a while.

[Tromador]

I tried running the server's listener in 'client' mode. That made it run market updates quicker than my PC and used about 25% of the CPU it does in server mode.

But it didn't make any difference to it ignoring KUKI AN/BOKEILI HUB with station_id '43119' .

[Tromador]

A ton of testing later, I may be at the heart of the matter. Bernd mentioned something about transactions and I had a look at that - this is a copy of my forum post, for reference.

"pysqlite is notorious for implementing weird transactional semantics. By default, pysqlite will open a transaction when you issue your first write query (it does this by examining every query you execute). The transaction will be automatically committed when you either call Connection.commit() or execute any other query that is not a SELECT, INSERT, UPDATE, or DELETE (for example CREATE TABLE or PRAGMA)." [1]

Now it may be that we would be better off managing the transactions ourselves. But I've put a lot of thought into this, so riddle me this:

If there is a problem with transactions, or a funky write-lock, or any other SQLite error you want to come up with - why then is it not random. It picks on stations - KUKI AN/BOKEILI HUB (station_id '43119') is my test case. Almost invariably (emphasis on almost) it will not update when I send a schema (with EDMC or EDDiscovery) , at least on server side, normally that station updates fine via listener on my local PC, but then it seems that other people have their own particular test cases - maybe if I looked hard enough, I could find one my PC hates on. I should probably also test the PC in server mode.

Nevertheless, you got me to thinking about transactions and such, so I put the database into auto-commit mode, changing the connection in tradedb.py to read.

conn = sqlite3.connect(self.dbFilename, isolation_level=None)

And stopping the (now unecessary) db.commits in the listener by altering lines 551 & 687 to read success = True

This had three effects. 1: Completely expected slowing down of the database. Particularly when running in server mode. 2: Trying to read the database, I would frequently get locking problems.

sqlite> SELECT * FROM StationItem WHERE station_id == 43119;
Error: database is locked

3: The problem went away, my bugbear station updated as it should, over and over again.

As another issue - getting back to server mode, something happens speedwise when running in this way as shown above in my previous posting.

For completeness I also ran the "server" in "client" mode. That ran faster than my PC and used about 25% of the CPU time it eats in server mode. Sadly the speed increase did not fix the problem in the same way that running autocommit had done.

So - a lot to think about, but I think that might be a bit of forward progress. We can cure the problem by using autocommit. In server mode the listener runs dog slow (it actually falls way behind in processing, so it can end up being minutes from a schema submission, to it finally getting processed). This slowness is further exacerbated by using autocommit.

Therefore there are two issues that need looking at - 1: Pysqlite and it's funky transactional methods which my testing suggests is the root of missing stations. 2: The listener running horribly horribly horribly in server mode, for which I can see no good reason.

[1] http://charlesleifer.com/blog/going-fast-with-sqlite-and-python/

[Tromador]

You know - as I test this more, it does seem to be dropping less schemas (from my test case) in client mode, where it's running at speed, than in server mode, where it is clunking along. I have to imagine there is some relationship here.

Yup. I can almost turn the problem off and on (again for my test case) by switching between server and client - though it's not 100% even in client mode.

[Tromador]

I've done a bit of database tuning. The pragmas I've chosen aren't especially 'safe' but given it's a server in an airconditioned room with UPS protection, and of course we can easily reconstruct the data, it's a low risk. This has given a bit of a speed up compared with the above, though in server mode it's still taking seconds per market update, as compared to tenths of seconds in client mode.

I've really done all I can do on my own. I'm quite happy to help with any amount of testing, but this is your multithreaded python and you're the only python programmer in the group.

So, realistically at this point I think we do need your input. If you are busy, well then it will just have to wait.

[Tromador]

I think I know what the slowness is though. When that timer routine is counting down 'n' seconds between exports, it's looping (I am guessing here, but it fits the facts) at breakneck speed and laughing maniacally as it eats as much CPU as possible. If I put a 10 second sleep at the top of the loop, then the market updates run at a similar speed as they would in client mode.

And this gives us the same increase in reliability as if I were running in client mode.

[eyeonus]

Making the exporter go to sleep for a second when it's waiting fixes the huge speed difference between server and client mode. See d4374c6.

[eyeonus]

On my PC, running in client mode: Autocommit update:

Market update for KREMAINN/WOHLER TERMINAL finished in 14.086 seconds.
Market update for JUMUZGO/ARTSUTANOV STATION finished in 11.53 seconds.
Market update for IENPALANG/BRUNDAGE CITY finished in 8.443 seconds.

No autocommit:

Market update for AZ CANCRI/FISHER STATION finished in 0.532 seconds.
Market update for LUYTEN 674-15/NOBLEPORT finished in 0.015 seconds.
Market update for ROBIGO/HAUSER'S REACH finished in 0.418 seconds.

[eyeonus]

I think we definitely need to look into the BEGIN ... END block building thing....

[Tromador]

Wait.. hmm...

At the top of TradeDangerous.sql add a couple of pragma so it looks like how I have the server set up, then run clean and see how it performs.

-- -Oliver

PRAGMA foreign_keys=ON;
PRAGMA synchronous=OFF;
PRAGMA temp_store=MEMORY;

BEGIN TRANSACTION;

[eyeonus]

Almost done with the clean run. It's on the live file now.

PRAGMAs added: Autocommit:

Market update for BOLG/MOXON'S MOJO finished in 14.558 seconds.
Market update for TANGAROA/ASYLUM finished in 7.759 seconds.
Market update for LAVE/LAVE STATION finished in 8.173 seconds.

No autocommit:

Market update for ANOTCHADIAE/BUJOLD TERMINAL finished in 0.466 seconds.
Market update for LHS 449/PERRY STATION finished in 0.01 seconds.
Market update for GLIESE 76/THORNE HUB finished in 0.568 seconds.

[Tromador]

This page shows very simply how to make an SQLite transaction. http://www.sqlitetutorial.net/sqlite-transaction/

Now I come to look at it, the database schema that ships with TD is all one transaction.

I suspect it won't end up being that simple - but it's a starting point.

See also https://stackoverflow.com/questions/24374242/python-sqlite-how-to-manually-begin-and-end-transactions

[Tromador]

Read the forum. I like what Bernd proposes. I'd like to test that at least, it's much cleaner.

[aadler]

Did you read the second link I posted? Shows detailed changes of going from 85 inserts/sec to over 70000 inserts/ sec. Not all may be applicable to Python, but blocking the transaction and preparing the call should be.

On Tue, Jul 24, 2018 at 5:48 AM Stefan Morrell notifications@github.com wrote:

Read the forum. I like what Bernd proposes. I'd like to test that at least, it's much cleaner.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/eyeonus/EDDBlink-listener/issues/7#issuecomment-407348121, or mute the thread https://github.com/notifications/unsubscribe-auth/AFVk8a-GkXZrD_Xuln64NugCTj7Fl48gks5uJu1XgaJpZM4VL3zU .

-- Sent from Gmail Mobile

[bgol]

Here would be a replacement for process_messages():

!NOT TESTED!

def process_messages():
    global process_ack
    tdb = tradedb.TradeDB(load=False)
    conn = tdb.getDB()
    # Place the database into autocommit mode to avoid issues with
    # sqlite3 doing automatic transactions.
    conn.isolation_level = None
    curs = conn.cursor()

    # same SQL every time
    updStmt = "UPDATE Station SET system_id = ? WHERE station_id = ?"
    delStmt = "DELETE FROM StationItem WHERE station_id = ?"
    insStmt = (
        "INSERT INTO StationItem("
        " station_id, item_id, modified,"
        " demand_price, demand_units, demand_level,"
        " supply_price, supply_units, supply_level, from_live)"
        " VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, 1)"
    )

    while go:
        # We don't want the threads interfering with each other,
        # so pause this one if either the update checker or
        # listings exporter report that they're active.
        if update_busy or export_busy:
            print("Message processor acknowledging busy signal.")
            process_ack = True
            while (update_busy or export_busy) and go:
                time.sleep(1)
            process_ack = False
            # Just in case we caught the shutdown command while waiting.
            if not go:
                break
            print("Busy signal off, message processor resuming.")

        # Either get the first message in the queue,
        # or go to sleep and wait if there aren't any.
        try:
            entry = q.popleft()
        except IndexError:
            time.sleep(1)
            continue

        # Get the station_id using the system and station names.
        system = entry.system.upper()
        station = entry.station.upper()
        # And the software version used to upload the schema.
        software = entry.software
        swVersion = entry.version

        station_id = station_ids.get(system + "/" + station)
        if not station_id:
            # Mobile stations are stored in the dict a bit differently.
            station_id = station_ids.get("MEGASHIP/" + station)
            system_id = system_ids.get(system)
            if station_id and system_id:
                print("Megaship station, updating system.", end=" ")
                # Update the system the station is in, in case it has changed.
                success = False
                while not success:
                    try:
                        curs.execute("BEGIN IMMEDIATE")
                        success = True
                    except sqlite3.OperationalError:
                        print("Database is locked, waiting for access.", end = "\r")
                        time.sleep(1)
                curs.execute(updStmt, (system_id, station_id))
                conn.commit()
            else:
                if config['verbose']:
                    print("ERROR: Not found in Stations: " + system + "/" + station)
                continue

        modified = entry.timestamp.replace('T',' ').replace('Z','')
        commodities= entry.commodities

        start_update = datetime.datetime.now()
        if config['debug']:
            with debugPath.open('a', encoding = "utf-8") as fh:
                fh.write(system + "/" + station + " with station_id '" + str(station_id) + "' updated at " + modified + " using " + software + swVersion + " ---\n")

        itemList = []
        for commodity in commodities:
            if commodity['sellPrice'] == 0 and commodity['buyPrice'] == 0:
                # Skip blank entries
                continue
            # Get item_id using commodity name from message.
            itemName = db_name.get(commodity['name'].lower())
            if not itemName:
                if config['verbose']:
                    print("Ignoring rare item: " + commodity['name'])
                continue
            # Some items, mostly salvage items, are found in db_name but not in item_ids
            # (This is entirely EDDB.io's fault.)
            item_id = item_ids.get(itemName)
            if not item_id:
                if config['verbose']:
                    print("EDDB.io does not include likely salvage item: '" + itemName + "'")
                continue

            itemList.append((
                station_id, item_id, modified,
                commodity['sellPrice'], commodity['demand'],
                commodity['demandBracket'] if commodity['demandBracket'] != '' else -1,
                commodity['buyPrice'], commodity['stock'],
                commodity['stockBracket'] if commodity['stockBracket'] != '' else -1,
            ))

        success = False
        while not success:
            try:
                curs.execute("BEGIN IMMEDIATE")
                success = True
            except sqlite3.OperationalError:
                print("Database is locked, waiting for access.", end = "\r")
                time.sleep(1)
        curs.execute(delStmt, (station_id,))
        curs.executemany(insStmt, itemList)
        conn.commit()

        if config['verbose']:
            print("Market update for " + system + "/" + station\
                  + " finished in " + str(int((datetime.datetime.now() - start_update).total_seconds() * 1000) / 1000) + " seconds.")
        else:
            print( "Updated " + system + "/" + station)

    print("Shutting down message processor.")

[Tromador]

What is curs = conn.getDB() all about? You never again reference curs and it throws AttributeError: 'sqlite3.Connection' object has no attribute 'getDB'

Did you mean to have curs = conn.cursor() and then where you have conn.execute to have curs.execute ?

Because if you did... and say I presumed you did... and made those changes... and then tested....

Then - it seems to run quite quickly with that code.

[Tromador]

Using Bernd's process_messages(): as corrected by the amateur (*cough* *chuckle*)

D:\Games\Game Tools\Elite\Trade Dangerous>eddblink_listener.py
Starting listener.
Running EDDBlink to perform any needed updates.
NOTE: Import completed.
Press CTRL-C at any time to quit gracefully.
No update, checking again in 1 hour.
Market update for PARUTIS/EVANS PORT finished in 0.606 seconds.
Market update for TANGAROA/ASYLUM finished in 0.591 seconds.
Market update for SHINRARTA DEZHRA/JAMESON MEMORIAL finished in 0.715 seconds.
Market update for TSONDAMA/HEYERDAHL ENTERPRISE finished in 0.692 seconds.
Market update for CEOS/NEW DAWN STATION finished in 0.419 seconds.
Market update for VODYANES/DASSAULT ORBITAL finished in 0.723 seconds.
Market update for IENPALANG/BRUNDAGE CITY finished in 0.443 seconds.
Market update for DAIKU/WRANGEL ORBITAL finished in 0.488 seconds.
Market update for ALRAI/BOUNDS HUB finished in 1.06 seconds.
Market update for ROBIGO/HAUSER'S REACH finished in 0.52 seconds.
Market update for WEN CHER/O'CONNOR INSTALLATION finished in 0.682 seconds.
Market update for EPSILON INDI/MANSFIELD ORBITER finished in 0.46 seconds.

[bgol]

Ups, sorry. As I said not tested. I wanted to use a cursor for the sql and the connection only for the commit. Updated my post accordingly.

Your corrections are the right ones.

[Tromador]

No need to apologise. I totally had fun fixing your mistakes.

...and the other one

print("EDDB.io does not include likely salvage item: '" + name + "'")

should read

print("EDDB.io does not include likely salvage item: '" + itemName + "'")

but after you cut & pasted, you didn't update the variable name.

[Tromador]

Wild - tested on server, check out the speed!

Makes https://github.com/eyeonus/EDDBlink-listener/issues/12 into a non-issue.

I will package this up as a PR to make eyeonus' life easier and he can decide if he wants to use it from there.

Market update for LHS 317/NORTHROP PORT finished in 0.013 seconds.
Market update for IENPALANG/BRUNDAGE CITY finished in 0.004 seconds.
Market update for DANGARLA/SWANSON ENTERPRISE finished in 0.009 seconds.
Market update for CD-53 9442/FOLLAND STATION finished in 0.185 seconds.
Ignoring rare item: KamitraCigars
Market update for KAMITRA/HAMMEL TERMINAL finished in 0.007 seconds.
Market update for MAIA/MAIA POINT finished in 0.01 seconds.
Listings exporter sending busy signal. 2018-07-24 19:31:28.172251
Message processor acknowledging busy signal.
Busy signal acknowledged, getting listings for export.
Exporting 'listings-live.csv'. (Got listings in 0:00:05.122505)
Busy signal off, message processor resuming.
Market update for ADENETS/SABINE GATEWAY finished in 0.014 seconds.
Market update for BINDE/AFANASYEV RING finished in 0.914 seconds.
Market update for ROBIGO/ROBIGO MINES finished in 0.864 seconds.
Export completed in 0:00:14.880630
Market update for DERISO/GILES STATION finished in 0.005 seconds.
Market update for LU VELORUM/MILETUS STATION finished in 0.106 seconds.
Market update for FIRE FADE/TSIOLKOVSKY RING finished in 0.011 seconds.