SAWarning: Evaluating non-mapped column expression 'id' onto ORM instances; this is a deprecated use case. Please make use of the actual mapped columns in ORM-evaluated UPDATE / DELETE expressions.

[Matt Riedemann]

This is split off from bug 1813147 but py35 unit test jobs have a ton of these SAWarnings (at least in nova):

http://logs.openstack.org/58/632158/1/check/cross-nova-py35/afe0282/job-output.txt#_2019-01-22_00_10_44_708744

There are 866 hits of that SAWarning in that single run which causes intermittent issues with the stestr subunit parser.

Here is an example of a stacktrace from nova master:

nova.tests.unit.api.openstack.compute.test_hosts.HostTestCaseV21.test_show_works_correctly
------------------------------------------------------------------------------------------

Captured pythonlogging:
~~~~~~~~~~~~~~~~~~~~~~~
    b'2019-01-31 17:48:15,014 INFO [248_add_expire_reservations_index] Skipped adding reservations_deleted_expire_idx because an equivalent index already exists.'
    b''

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    b'Traceback (most recent call last):'
    b' File "/home/osboxes/git/nova/nova/tests/unit/api/openstack/compute/test_hosts.py", line 410, in test_show_works_correctly'
    b" db.instance_destroy(ctxt, i_ref1['uuid'])"
    b' File "/home/osboxes/git/nova/nova/db/api.py", line 753, in instance_destroy'
    b' return IMPL.instance_destroy(context, instance_uuid, constraint)'
    b' File "/home/osboxes/git/nova/nova/db/sqlalchemy/api.py", line 170, in wrapper'
    b' return f(*args, **kwargs)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/oslo_db/api.py", line 154, in wrapper'
    b' ectxt.value = e.inner_exc'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/oslo_utils/excutils.py", line 220, in __exit__'
    b' self.force_reraise()'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/oslo_utils/excutils.py", line 196, in force_reraise'
    b' six.reraise(self.type_, self.value, self.tb)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/six.py", line 693, in reraise'
    b' raise value'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/oslo_db/api.py", line 142, in wrapper'
    b' return f(*args, **kwargs)'
    b' File "/home/osboxes/git/nova/nova/db/sqlalchemy/api.py", line 227, in wrapped'
    b' return f(context, *args, **kwargs)'
    b' File "/home/osboxes/git/nova/nova/db/sqlalchemy/api.py", line 1797, in instance_destroy'
    b' count = query.soft_delete()'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/oslo_db/sqlalchemy/orm.py", line 32, in soft_delete'
    b' synchronize_session=synchronize_session)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 3486, in update'
    b' update_op.exec_()'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 1334, in exec_'
    b' self._do_pre_synchronize()'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 1405, in _do_pre_synchronize'
    b' self._additional_evaluators(evaluator_compiler)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 1543, in _additional_evaluators'
    b' expression._literal_as_binds(value))'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/evaluator.py", line 39, in process'
    b' return meth(clause)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/orm/evaluator.py", line 71, in visit_column'
    b' "UPDATE / DELETE expressions." % clause)'
    b' File "/home/osboxes/git/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/util/langhelpers.py", line 1312, in warn'
    b' warnings.warn(msg, exc.SAWarning, stacklevel=2)'
    b"sqlalchemy.exc.SAWarning: Evaluating non-mapped column expression 'updated_at' onto ORM instances; this is a deprecated use case. Please make use of the actual mapped columns in ORM-evaluated UPDATE / DELETE expressions."
    b''

It seems the problem stems from this code:

https://github.com/openstack/oslo.db/blob/4.43.0/oslo_db/sqlalchemy/orm.py#L28

I'm not really sure how to fix that though, will need help from Mike Bayer.

[Mike Bayer (zzzeek)]

so this is a bug in oslo.db, for which soft_delete() should not be written that way, since it is wrong.

The immediate mitigation is to pass in synchronize_session=False so that the ORM evaluator isn't pulled in, which is the element that has to make a guess when those non-mapped columns are passed in.

longer term, the method in oslo.db needs to be fixed. issue with the correct code is added in https://bugs.launchpad.net/oslo.db/+bug/1814199.

[Mike Bayer (zzzeek)]

however I forgot to note, it's not safe to set synchronize_session=False unless you are sure the entities that are currently in the Session don't matter to subsequent operations, which I think is the case with the persistence pattern used by Nova (e.g. things are passed around as dictionaries and converted to ORM objects only for SQL operations).