Update to fix CONSTRAINT_4 error for spawnpoint table

[Kneckter]

Description

RM tries to write DB records with a 'latest_seen=3600' instead of 3599 like the constraint allows for. Changing the Check statement to '=<3600' allows for these records to be written instead of throwing "InternalError(4025, u'CONSTRAINT CONSTRAINT_4 failed for rocketmapdbadmin.spawnpoint')".

Note that this code change will not update existing DBs and will only apply the new constraint to maps that run the -cd flag.

An FAQ can be added if anyone wants to run the mysql commands to update their DB. The following commands should allow anyone to do it:

mysql -u rocketmapuser -p

USE 'rocketmapdb';
ALTER TABLE spawnpoint DROP CONSTRAINT CONSTRAINT_4;
ALTER TABLE spawnpoint ADD CONSTRAINT CONSTRAINT_4 CHECK (`latest_seen` <= 3600);

Motivation and Context

This error kept occurring on my map and many others. Most have seen this as a resource issue and the only solution was to decrease step size and run a -cd. Search the discord channels, there are 6 pages of results but no real solutions. If this is implemented, people will be able to run their large steps without having to restart a DB if they run into a constraint issue.

How Has This Been Tested?

Using Ubuntu 17.04 with the GUI desktop installed. Running a speedscan with an -st 200 geofenced to 36723 steps with 600 workers and 10 DB threads.

I have not tested the python code change, only the DB constraint commands.

I have been running this -st 200 with 50K spawnpoints started to get error 4025 when I hit about 75%. I pulled up HeidiSQL to see what was being written. Since I have spawnpoints with 'latest_seen=3599' and saw that RM wanted to write one with 'latest_seen=3600', I changed the constraint on the spawnpoints table with the above commands. Since then, I have not received the error and completed the initial scan. There are about 150 spawnpoints that have 'latest_seen=3600'.

As my TTH search got smaller, so did the total 'latest_seen=3600' DB records. I was down to 26 after a night so this change should not cause any issues with searching.

Screenshots (if appropriate):

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to change)

Checklist:

• My code follows the code style of this project.
• My change requires a change to the documentation.
• I have updated the documentation accordingly.

[dongemus]

I wanted to try this, I am using MariaDB on windows and getting this error.
MariaDB [rocketmapdb]> ALTER TABLE spawnpoint DROP CONSTRAINT CONSTRAINT_4;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'CONSTRAINT CONSTRAINT_4' at line 1

This seems to be the right syntax, not sure why it isn't working.

[Kneckter]

@dongemus what version of mariadb are you running? I am on 10.2.11. It should say it when you log into mysql or you can run the below from the command prompt.

mysql --version

Can you run these mysql commands for mariadb to see if your constraints are listed?

SELECT CONSTRAINT_NAME, TABLE_NAME, CONSTRAINT_TYPE FROM information_schema.TABLE_CONSTRAINTS WHERE TABLE_NAME = 'spawnpoint';

[dongemus]

Thanks, I run 3 machines. I was trying it on the one that was on 10.1.28 and it showed

| CONSTRAINT_NAME | TABLE_NAME | CONSTRAINT_TYPE |
+-----------------+------------+-----------------+
| PRIMARY         | spawnpoint | PRIMARY KEY

However, when I tried it on the machines running 10.2.8 and 10.2.9 it did show the CONSTRAINTs and the original commands worked. Looking forward to seeing the results!
I will update MariaDB on the first machine later and try that one as well

[Kneckter]

@dongemus Yes, you got the right results. Before MariaDB 10.2.1, constraint expressions were accepted in syntax, but ignored. So you would not show any on that one server.

I updated my original comment to note that as my TTH search got smaller, so did the total 'latest_seen=3600' DB records. I was down to 26 after the night so this change should not cause any issues with searching.

[sebastienvercammen]

👍 Good catch. @Kneckter

We've added this PR near the top of our todo list, but one thing it's missing is DB migration code to execute the change on old databases.

Keep in mind the RM team is enjoying their holidays at the moment, so don't worry if it doesn't get done before New Year's. ❤️

[friscoMad]

But there is no reason to store 3600 it should store 0 instead the problem is in the code trying to store 3600

[Kneckter]

@friscoMad constraint 3 sets the latest seen to be >= 0 and constraint 4 sets it to be less than 3600. So it already stores 0 to 3599. Why shouldn't it store a 3600? Those spawn points exist and will be checked again for a TTH.

[friscoMad]

earliest_unseen and latest_seen are the seconds from the hour when the spawn was present or not, this is to identify the type of spawn and the timing, so the value should always be from 0 to 3599, 3600 is the same as 0, but I am not sure why we are trying to store 3600 as I tried to locate where it is being set and it seems that the value always come from date_secs in util.py and that function should only return values from 0 to 3599 (unles a leap second occurs but I don't expect that to be the issue) so I must have skip some branch of code that leads to this situation. I will give it another try.

[friscoMad]

Can you check in your logs with the issue if this line appears with 3600?
log.info('1x60: appear %d, despawn %d, duration: %d min.',
I don't expect it to be there but who knows, if possible also provide the lines above the error to see how it was trying to calculate the tth so we can center the search.

[Kneckter]

I no longer have that log file but I saw someone post the logs in the help channel:

2017-12-04 16:57:27,934 [   search-worker-6][        search][    INFO] Scanning step 1146 for a band.
2017-12-04 16:57:28,700 [   search-worker-5][        search][    INFO] Scanning step 1095 for a band.
2017-12-04 16:57:28,809 [   search-worker-6][        models][    INFO] Parsing found Pokemon: 0 (0 filtered), nearby: 1, pokestops: 0, gyms: 0, raids: 0.
2017-12-04 16:57:28,888 [   search-worker-5][        models][    INFO] 1x60: appear 0, despawn 3600, duration: 0 min.
2017-12-04 16:57:28,888 [   search-worker-5][        models][    INFO] Parsing found Pokemon: 0 (1 filtered), nearby: 2, pokestops: 0, gyms: 0, raids: 0.
2017-12-04 16:57:28,903 [      db-updater-0][        models][ WARNING] InternalError(4025, u'CONSTRAINT CONSTRAINT_4 failed for rocketmaplewiston.spawnpoint')... Retrying...
2017-12-04 16:57:29,918 [      db-updater-0][        models][ WARNING] InternalError(4025, u'CONSTRAINT CONSTRAINT_4 failed for rocketmaplewiston.spawnpoint')... Retrying...
2017-12-04 16:57:30,121 [   search-worker-4][        search][    INFO] Scanning step 446 for a band.
2017-12-04 16:57:30,496 [   search-worker-4][        models][    INFO] 1x60: appear 656, despawn 2000, duration: 22 min.
2017-12-04 16:57:30,496 [   search-worker-4][        models][    INFO] Parsing found Pokemon: 0 (1 filtered), nearby: 1, pokestops: 0, gyms: 0, raids: 0.
2017-12-04 16:57:30,934 [      db-updater-0][        models][ WARNING] InternalError(4025, u'CONSTRAINT CONSTRAINT_4 failed for rocketmaplewiston.spawnpoint')... Retrying...

I can try recreating the constraint error over the weekend if you need more logs.

[sebastienvercammen]

#2423 has been closed for now. After investigating the scheduler, it seems 3600 is meant to be an appropriate value, so it might be the constraint that needs to be updated.

The code is clear on requiring 3600 for latest_seen, here are some snippets:

// [0, 3600] --> (0 - 3600) % 3600 == 0, so tth_range = '0'.
// If we return [0, 0] we lose the duration of the spawn and we can't know the difference with our default values.
tth_range = str(int(round(
    ((sp['earliest_unseen'] - sp['latest_seen']) % 3600) /
    60.0)))

// Code expects the above to have a valid result 0.
tth_ranges['0'] = tth_ranges.get('0', 0) - self.tth_found

But it also has code requiring 0 == 0. We're still investigating.

Edit: With the investigation finished, we've agreed (on Discord) to use the range [0, 3600] but to apply modulo when comparing the values. Also not to apply it as (a - b) % 3600 since python uses the least residue as modulo instead of the remainder as many are used to and it can return unexpected results with negative numbers.

We're not sure whether there are ever any negative numbers, but we preferred to make sure.

[jaake77]

Attempt just now. Fresh develop, pulled pr2416, ran an instance with -cd, ran a server only instance, fired up my main chunk, error and python crash, fired up a tiny test st4 and it works. Odd.
EDIT** Not rebased to develop. I reverted and will test after work.

[pogo-excalibur]

@Kneckter A DB migration to run the commands in the PR details would be great.

[Kneckter]

Hello @pogo-excalibur , you are talking about the python code for applying this to existing DBs? I have an idea about that but I am not sure how to rebase the file since I never use github. In the latest version of RM the DB was updated to version 21. So the code would look like this:

db_schema_version = 22
...
    if old_ver < 22:
        # Drop and add CONSTRAINT_2 with the <= fix.
        db.execute_sql('ALTER TABLE `spawnpoint` '
                       'DROP CONSTRAINT CONSTRAINT_2;')
        db.execute_sql('ALTER TABLE `spawnpoint` '
                       'ADD CONSTRAINT CONSTRAINT_2 CHECK (`earliest_unseen` <= 3600);')

        # Drop and add CONSTRAINT_4 with the <= fix.
        db.execute_sql('ALTER TABLE `spawnpoint` '
                       'DROP CONSTRAINT CONSTRAINT_4;')
        db.execute_sql('ALTER TABLE `spawnpoint` '
                       'ADD CONSTRAINT CONSTRAINT_4 CHECK (`latest_seen` <= 3600);')

I have not tested this out yet but I can give it a shot later.

[pogo-excalibur]

@Kneckter 👍 That looks about right. Having that in will make it easier to test this.

[Kneckter]

I rebased the code and added the DB migration. It worked on my test setup without an error.

2018-01-09 00:44:22,123 [        MainThread][     runserver][    INFO] No file "custom.css" found, using default settings.
2018-01-09 00:44:22,123 [        MainThread][     runserver][    INFO] No file "custom.js" found, using default settings.
2018-01-09 00:44:22,392 [        MainThread][     runserver][    INFO] Parsed location is: 41.3249/-75.7803/215.1194 (lat/lng/alt)
2018-01-09 00:44:22,395 [        MainThread][           app][    INFO] Retrieving blacklist...
2018-01-09 00:44:22,979 [        MainThread][        models][    INFO] Connecting to MySQL database on 127.0.0.1:3306...
2018-01-09 00:44:22,984 [        MainThread][        models][    INFO] Detected database version 21, updating to 22...
2018-01-09 00:44:23,899 [        MainThread][        models][    INFO] Schema upgrade complete.
2018-01-09 00:44:23,937 [        MainThread][     runserver][    INFO] Webhook disabled.

Let me know if I messed something up with the rebase or the commit.

[Kneckter]

Fell asleep before Travis finished lol. I used too long of lines since I'm not used to python. Updated my code and retested it on my small setup to ensure it still applied the changes.

[jaake77]

Been running for 2 hours no issues on my main setup. Someone else will need to review the code as I'm not an expert.

[jaake77]

Ran 12+ hours yesterday without issues, ran a -cd and restarted this morning. Been going good for 2 more hours.

[Kneckter]

@jaake77 thanks for running the test! Has your TTH scan completed? The last half of the TTH scan is usually when the u'CONSTRAINT error came up.

If it has not completed, will you check to see if it stored any 3600s with this mysql command:

SELECT * FROM `rocketmapdb`.`spawnpoint` WHERE latest_seen>='3600' ORDER BY `latest_seen` DESC LIMIT 10;

If it displays some records then you shouldn't expect any error by the time the TTH finishes.

[jaake77]

SELECT * FROM `rocketmapdb`.`spawnpoint` WHERE latest_seen>='3600' ORDER BY `latest_seen` DESC LIMIT 10; /* Affected rows: 0 Found rows: 0 Warnings: 0 Duration for 1 query: 0.000 sec. */

[Kneckter]

Looking good, it must have found TTHs for the ones you had. I ran two new areas last night and had no constraint errors. There are about 8 3600s in my spawnpoints right now.

[jaake77]

Tests good. Did both with an existing DB and a -cd fresh one. Thanks for your work. Someone else needs to review code. Let me know if there are changes and you need more testing.

[fosJoddie]

No errors in console, spheal of approval!