StaleDataError on UPDATE for a DATETIME field on multiple consecutive requests

[Dumitru Gîra]

I have encountered a very strange behaviour and I don't know where to look further.

I have a small API https://pastebin.com/qW01jNz8 with 2 endpoints: one to update the name (VARCHAR) and one to update the last_login (DATETIME).

If I make 10 consecutive requests to /update-string - everything works as expected.

If I make 10 consecutive requests to /update-datetime - the first request works and other 9 fail with sqlalchemy.orm.exc.StaleDataError.

NOTE: putting a time.sleep(1) after every request does not raise the error

Consecutive requests are being made using the simple snippet

import requests
for i in range(10):
    r = requests.put('http://0.0.0.0:8080/update-datetime')

    print(r.text, r.code)

The source code and the logs are in above link and for the reference I am using:

- MySQL 8.0, but the same happens with 5.7

- mysqldb connector, but the same happens with pymysql

- SQLAlchemy==1.4.49

Is this related to MySQL and specifically to date/time related fields (as the same happens with TIMESTAMP) or can it be something from SQLAlchemy side?

Any directions would be highly appreciated.

Kind regards,

Dumitru

[Mike Bayer]

a stale data error with date/time fields is usually a mismatch between the date/time value you have locally and the one that's in the database,. assuming you are using the datetime column as a "version_id" in your mapping.     Issues like strings vs. datetimes and/or microseconds portions being present or non-present are the most common.

would need to see SQL debug logging to have more insight / confirm that's the problem.

--

SQLAlchemy -

The Python SQL Toolkit and Object Relational Mapper

 

http://www.sqlalchemy.org/

 

To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.

---

You received this message because you are subscribed to the Google Groups "sqlalchemy" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy/e53169bd-617f-41f3-b9d3-8002ea75496an%40googlegroups.com.

[Dumitru Gîra]

Hi Mike,

thanks for the quick response.

These would be the debug logs for

import requests
for i in range(2):

    r = requests.put('http://0.0.0.0:8080/update-datetime')

    print(r.text, r.code)

2023-09-01 16:06:20,711 INFO sqlalchemy.engine.Engine SELECT DATABASE()
2023-09-01 16:06:20,711 INFO sqlalchemy.engine.Engine [raw sql] ()
2023-09-01 16:06:20,713 DEBUG sqlalchemy.engine.Engine Col ('DATABASE()',)
2023-09-01 16:06:20,713 DEBUG sqlalchemy.engine.Engine Row ('dbname',)
2023-09-01 16:06:20,714 INFO sqlalchemy.engine.Engine SELECT @@sql_mode
2023-09-01 16:06:20,714 INFO sqlalchemy.engine.Engine [raw sql] ()
2023-09-01 16:06:20,715 DEBUG sqlalchemy.engine.Engine Col ('@@sql_mode',)
2023-09-01 16:06:20,715 DEBUG sqlalchemy.engine.Engine Row ('ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION',)
2023-09-01 16:06:20,716 INFO sqlalchemy.engine.Engine SELECT @@lower_case_table_names
2023-09-01 16:06:20,716 INFO sqlalchemy.engine.Engine [raw sql] ()
2023-09-01 16:06:20,717 DEBUG sqlalchemy.engine.Engine Col ('@@lower_case_table_names',)
2023-09-01 16:06:20,717 DEBUG sqlalchemy.engine.Engine Row (0,)
2023-09-01 16:06:20,717 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2023-09-01 16:06:20,719 INFO sqlalchemy.engine.Engine SELECT foo.id AS foo_id, foo.last_login AS foo_last_login, foo.name AS foo_name
FROM foo
WHERE foo.id = %s
 LIMIT %s
2023-09-01 16:06:20,719 INFO sqlalchemy.engine.Engine [generated in 0.00016s] (1, 1)
2023-09-01 16:06:20,720 DEBUG sqlalchemy.engine.Engine Col ('foo_id', 'foo_last_login', 'foo_name')
2023-09-01 16:06:20,720 DEBUG sqlalchemy.engine.Engine Row (1, datetime.datetime(2023, 9, 1, 16, 6, 12), '2023-09-01 15:50:46.029445')
2023-09-01 16:06:20,722 INFO sqlalchemy.engine.Engine UPDATE foo SET last_login=%s WHERE foo.id = %s
2023-09-01 16:06:20,722 INFO sqlalchemy.engine.Engine [generated in 0.00014s] (datetime.datetime(2023, 9, 1, 16, 6, 20, 721146), 1)
2023-09-01 16:06:20,723 INFO sqlalchemy.engine.Engine COMMIT
192.168.0.1 - - [01/Sep/2023 16:06:20] "PUT /update-datetime HTTP/1.1" 200 -
2023-09-01 16:06:20,733 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2023-09-01 16:06:20,733 INFO sqlalchemy.engine.Engine SELECT foo.id AS foo_id, foo.last_login AS foo_last_login, foo.name AS foo_name
FROM foo
WHERE foo.id = %s
 LIMIT %s
2023-09-01 16:06:20,733 INFO sqlalchemy.engine.Engine [cached since 0.01402s ago] (1, 1)
2023-09-01 16:06:20,734 DEBUG sqlalchemy.engine.Engine Col ('foo_id', 'foo_last_login', 'foo_name')
2023-09-01 16:06:20,735 DEBUG sqlalchemy.engine.Engine Row (1, datetime.datetime(2023, 9, 1, 16, 6, 21), '2023-09-01 15:50:46.029445')
2023-09-01 16:06:20,736 INFO sqlalchemy.engine.Engine UPDATE foo SET last_login=%s WHERE foo.id = %s
2023-09-01 16:06:20,736 INFO sqlalchemy.engine.Engine [cached since 0.01399s ago] (datetime.datetime(2023, 9, 1, 16, 6, 20, 735704), 1)
2023-09-01 16:06:20,737 INFO sqlalchemy.engine.Engine ROLLBACK
192.168.0.1 - - [01/Sep/2023 16:06:20] "PUT /update-datetime HTTP/1.1" 500 -
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2548, in __call__
    return self.wsgi_app(environ, start_response)
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2528, in wsgi_app
    response = self.handle_exception(e)
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2525, in wsgi_app
    response = self.full_dispatch_request()
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1822, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1820, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1796, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/usr/src/app/sqa.py", line 69, in update_datetime
    db_session.commit()
  File "<string>", line 2, in commit
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 1454, in commit
    self._transaction.commit(_to_root=self.future)
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 832, in commit
    self._prepare_impl()
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 811, in _prepare_impl
    self.session.flush()
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 3449, in flush
    self._flush(objects)
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 3589, in _flush
    transaction.rollback(_capture_exception=True)
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 70, in __exit__
    compat.raise_(
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 211, in raise_
    raise exception
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 3549, in _flush
    flush_context.execute()
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/unitofwork.py", line 456, in execute
    rec.execute(self)
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/unitofwork.py", line 630, in execute
    util.preloaded.orm_persistence.save_obj(
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 237, in save_obj
    _emit_update_statements(
  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1035, in _emit_update_statements
    raise orm_exc.StaleDataError(
sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'foo' expected to update 1 row(s); 0 were matched.

[Mike Bayer]

unless the row is being deleted, this would possibly be a driver bug.  the pymysql driver should work pretty well whereas mysql-connector I would stay away from.    I would need more detail to reproduce beyond that, the SQL statement has nohting wrong with it.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy/5eeecabd-1451-4db5-9fc7-0558024c5932n%40googlegroups.com.

[Dumitru Gîra]

Okay, I guess I figured out why this happens. We are using the mysql+mysqldb dialect and we were explicitly setting 'client_flag': 0 which by default is set to 2 in SQLAlchemy, thus disabling CLIENT_FLAGS.FOUND_ROWS. Removing 'client_flag': 0 or setting it to 'client_flag': 2 makes everything to work as expected.

What I don't understand, is why the disabled FOUND_ROWS causes StaleDatError when the row was actually updated in the database? Could it be because of a very small difference between the previous datetime/timestamp and the update one?

[Mike Bayer]

if the two values are the same, then it will report zero rows matched.   re: "very small difference" the MySQL field is likely not storing the microseconds portion of the timestamp so if you run several operations in succession the timestamps are very likely identical.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy/40684c83-f33e-46c9-bc5b-067e84e04a30n%40googlegroups.com.