From 3c60d3b1ca492ba77d64111f0378892acaadf36b Mon Sep 17 00:00:00 2001 From: Mike Bayer Date: Sun, 31 Aug 2014 15:22:00 -0400 Subject: [PATCH] - A new style of warning can be emitted which will "filter" up to N occurrences of a parameterized string. This allows parameterized warnings that can refer to their arguments to be delivered a fixed number of times until allowing Python warning filters to squelch them, and prevents memory from growing unbounded within Python's warning registries. fixes #3178 --- doc/build/changelog/changelog_10.rst | 15 +++ doc/build/changelog/migration_10.rst | 49 +++++++ lib/sqlalchemy/orm/loading.py | 9 +- lib/sqlalchemy/orm/mapper.py | 9 +- lib/sqlalchemy/orm/persistence.py | 3 +- lib/sqlalchemy/sql/schema.py | 8 +- lib/sqlalchemy/sql/sqltypes.py | 12 +- lib/sqlalchemy/testing/__init__.py | 2 +- lib/sqlalchemy/testing/assertions.py | 129 +++++++++---------- lib/sqlalchemy/testing/plugin/plugin_base.py | 4 +- lib/sqlalchemy/testing/warnings.py | 42 ++---- lib/sqlalchemy/util/__init__.py | 3 +- lib/sqlalchemy/util/deprecations.py | 2 +- lib/sqlalchemy/util/langhelpers.py | 51 ++++++-- test/aaa_profiling/test_memusage.py | 14 ++ test/orm/test_session.py | 1 + test/sql/test_defaults.py | 5 +- 17 files changed, 226 insertions(+), 132 deletions(-) diff --git a/doc/build/changelog/changelog_10.rst b/doc/build/changelog/changelog_10.rst index 5f12cc9693..7594c7c323 100644 --- a/doc/build/changelog/changelog_10.rst +++ b/doc/build/changelog/changelog_10.rst @@ -21,6 +21,21 @@ series as well. For changes that are specific to 1.0 with an emphasis on compatibility concerns, see :doc:`/changelog/migration_10`. + .. change:: + :tags: feature, engine + :tickets: 3178 + + A new style of warning can be emitted which will "filter" up to + N occurrences of a parameterized string. This allows parameterized + warnings that can refer to their arguments to be delivered a fixed + number of times until allowing Python warning filters to squelch them, + and prevents memory from growing unbounded within Python's + warning registries. + + .. seealso:: + + :ref:`feature_3178` + .. change:: :tags: feature, orm diff --git a/doc/build/changelog/migration_10.rst b/doc/build/changelog/migration_10.rst index 533682ebc4..a3f0748abb 100644 --- a/doc/build/changelog/migration_10.rst +++ b/doc/build/changelog/migration_10.rst @@ -459,6 +459,55 @@ object totally smokes both namedtuple and KeyedTuple:: :ticket:`3176` +.. _feature_3178: + +New systems to safely emit parameterized warnings +------------------------------------------------- + +For a long time, there has been a restriction that warning messages could not +refer to data elements, such that a particular function might emit an +infinite number of unique warnings. The key place this occurs is in the +``Unicode type received non-unicode bind param value`` warning. Placing +the data value in this message would mean that the Python ``__warningregistry__`` +for that module, or in some cases the Python-global ``warnings.onceregistry``, +would grow unbounded, as in most warning scenarios, one of these two collections +is populated with every distinct warning message. + +The change here is that by using a special ``string`` type that purposely +changes how the string is hashed, we can control that a large number of +parameterized messages are hashed only on a small set of possible hash +values, such that a warning such as ``Unicode type received non-unicode +bind param value`` can be tailored to be emitted only a specific number +of times; beyond that, the Python warnings registry will begin recording +them as duplicates. + +To illustrate, the following test script will show only ten warnings being +emitted for ten of the parameter sets, out of a total of 1000: + + from sqlalchemy import create_engine, Unicode, select, cast + import random + import warnings + + e = create_engine("sqlite://") + + # Use the "once" filter (which is also the default for Python + # warnings). Exactly ten of these warnings will + # be emitted; beyond that, the Python warnings registry will accumulate + # new values as dupes of one of the ten existing. + warnings.filterwarnings("once") + + for i in range(1000): + e.execute(select([cast( + ('foo_%d' % random.randint(0, 1000000)).encode('ascii'), Unicode)])) + +The format of the warning here is:: + + /path/lib/sqlalchemy/sql/sqltypes.py:186: SAWarning: Unicode type received + non-unicode bind param value 'foo_4852'. (this warning may be + suppressed after 10 occurrences) + + +:ticket:`3178` .. _feature_2963: diff --git a/lib/sqlalchemy/orm/loading.py b/lib/sqlalchemy/orm/loading.py index a40f13fae8..380afcdc72 100644 --- a/lib/sqlalchemy/orm/loading.py +++ b/lib/sqlalchemy/orm/loading.py @@ -562,10 +562,11 @@ def load_scalar_attributes(mapper, state, attribute_names): if (_none_set.issubset(identity_key) and not mapper.allow_partial_pks) or \ _none_set.issuperset(identity_key): - util.warn("Instance %s to be refreshed doesn't " - "contain a full primary key - can't be refreshed " - "(and shouldn't be expired, either)." - % state_str(state)) + util.warn_limited( + "Instance %s to be refreshed doesn't " + "contain a full primary key - can't be refreshed " + "(and shouldn't be expired, either).", + state_str(state)) return result = load_on_ident( diff --git a/lib/sqlalchemy/orm/mapper.py b/lib/sqlalchemy/orm/mapper.py index 539867f2e8..cd735c8656 100644 --- a/lib/sqlalchemy/orm/mapper.py +++ b/lib/sqlalchemy/orm/mapper.py @@ -1452,13 +1452,12 @@ class Mapper(InspectionAttr): if polymorphic_key in dict_ and \ dict_[polymorphic_key] not in \ mapper._acceptable_polymorphic_identities: - util.warn( + util.warn_limited( "Flushing object %s with " "incompatible polymorphic identity %r; the " - "object may not refresh and/or load correctly" % ( - state_str(state), - dict_[polymorphic_key] - ) + "object may not refresh and/or load correctly", + state_str(state), + dict_[polymorphic_key] ) self._set_polymorphic_identity = _set_polymorphic_identity diff --git a/lib/sqlalchemy/orm/persistence.py b/lib/sqlalchemy/orm/persistence.py index 511a9cef0f..dd9df4a661 100644 --- a/lib/sqlalchemy/orm/persistence.py +++ b/lib/sqlalchemy/orm/persistence.py @@ -554,8 +554,7 @@ def _emit_update_statements(base_mapper, uowtransaction, elif needs_version_id: util.warn("Dialect %s does not support updated rowcount " "- versioning cannot be verified." % - c.dialect.dialect_description, - stacklevel=12) + c.dialect.dialect_description) def _emit_insert_statements(base_mapper, uowtransaction, diff --git a/lib/sqlalchemy/sql/schema.py b/lib/sqlalchemy/sql/schema.py index c8e815d244..8225a35334 100644 --- a/lib/sqlalchemy/sql/schema.py +++ b/lib/sqlalchemy/sql/schema.py @@ -1124,8 +1124,12 @@ class Column(SchemaItem, ColumnClause): else: if getattr(self.type, '_warn_on_bytestring', False): if isinstance(self.default, util.binary_type): - util.warn("Unicode column received non-unicode " - "default value.") + util.warn( + "Unicode column '%s' has non-unicode " + "default value %r specified." % ( + self.key, + self.default + )) args.append(ColumnDefault(self.default)) if self.server_default is not None: diff --git a/lib/sqlalchemy/sql/sqltypes.py b/lib/sqlalchemy/sql/sqltypes.py index a7f25bbfa4..4de4885c6d 100644 --- a/lib/sqlalchemy/sql/sqltypes.py +++ b/lib/sqlalchemy/sql/sqltypes.py @@ -180,8 +180,10 @@ class String(Concatenable, TypeEngine): if self._warn_on_bytestring: def process(value): if isinstance(value, util.binary_type): - util.warn("Unicode type received non-unicode" - "bind param value.") + util.warn_limited( + "Unicode type received non-unicode " + "bind param value %r.", + util.ellipses_string(value)) return value return process else: @@ -194,8 +196,10 @@ class String(Concatenable, TypeEngine): if isinstance(value, util.text_type): return encoder(value, self.unicode_error)[0] elif warn_on_bytestring and value is not None: - util.warn("Unicode type received non-unicode bind " - "param value") + util.warn_limited( + "Unicode type received non-unicode bind " + "param value %r.", + util.ellipses_string(value)) return value return process else: diff --git a/lib/sqlalchemy/testing/__init__.py b/lib/sqlalchemy/testing/__init__.py index 8f8f56412e..e53fb28b13 100644 --- a/lib/sqlalchemy/testing/__init__.py +++ b/lib/sqlalchemy/testing/__init__.py @@ -6,7 +6,7 @@ # the MIT License: http://www.opensource.org/licenses/mit-license.php -from .warnings import testing_warn, assert_warnings, resetwarnings +from .warnings import assert_warnings from . import config diff --git a/lib/sqlalchemy/testing/assertions.py b/lib/sqlalchemy/testing/assertions.py index 79411af7e9..dbe365ad5c 100644 --- a/lib/sqlalchemy/testing/assertions.py +++ b/lib/sqlalchemy/testing/assertions.py @@ -9,79 +9,79 @@ from __future__ import absolute_import from . import util as testutil from sqlalchemy import pool, orm, util -from sqlalchemy.engine import default, create_engine, url -from sqlalchemy import exc as sa_exc +from sqlalchemy.engine import default, url from sqlalchemy.util import decorator from sqlalchemy import types as sqltypes, schema import warnings import re -from .warnings import resetwarnings from .exclusions import db_spec, _is_excluded from . import assertsql from . import config -import itertools from .util import fail import contextlib +from . import mock -def emits_warning(*messages): - """Mark a test as emitting a warning. +def expect_warnings(*messages): + """Context manager which expects one or more warnings. + + With no arguments, squelches all SAWarnings emitted via + sqlalchemy.util.warn and sqlalchemy.util.warn_limited. Otherwise + pass string expressions that will match selected warnings via regex; + all non-matching warnings are sent through. + + Note that the test suite sets SAWarning warnings to raise exceptions. + + """ + return _expect_warnings( + "sqlalchemy.util.deprecations.warnings.warn", messages) + + +@contextlib.contextmanager +def expect_warnings_on(db, *messages): + """Context manager which expects one or more warnings on specific + dialects. - With no arguments, squelches all SAWarning failures. Or pass one or more - strings; these will be matched to the root of the warning description by - warnings.filterwarnings(). """ - # TODO: it would be nice to assert that a named warning was - # emitted. should work with some monkeypatching of warnings, - # and may work on non-CPython if they keep to the spirit of - # warnings.showwarning's docstring. - # - update: jython looks ok, it uses cpython's module + spec = db_spec(db) + + if isinstance(db, util.string_types) and not spec(config._current): + yield + elif not _is_excluded(*db): + yield + else: + with expect_warnings(*messages): + yield + + +def emits_warning(*messages): + """Decorator form of expect_warnings().""" @decorator def decorate(fn, *args, **kw): - # todo: should probably be strict about this, too - filters = [dict(action='ignore', - category=sa_exc.SAPendingDeprecationWarning)] - if not messages: - filters.append(dict(action='ignore', - category=sa_exc.SAWarning)) - else: - filters.extend(dict(action='ignore', - message=message, - category=sa_exc.SAWarning) - for message in messages) - for f in filters: - warnings.filterwarnings(**f) - try: + with expect_warnings(*messages): return fn(*args, **kw) - finally: - resetwarnings() + return decorate -def emits_warning_on(db, *warnings): +def expect_deprecated(*messages): + return _expect_warnings( + "sqlalchemy.util.deprecations.warnings.warn", messages) + + +def emits_warning_on(db, *messages): """Mark a test as emitting a warning on a specific dialect. With no arguments, squelches all SAWarning failures. Or pass one or more strings; these will be matched to the root of the warning description by warnings.filterwarnings(). """ - spec = db_spec(db) - @decorator def decorate(fn, *args, **kw): - if isinstance(db, util.string_types): - if not spec(config._current): - return fn(*args, **kw) - else: - wrapped = emits_warning(*warnings)(fn) - return wrapped(*args, **kw) - else: - if not _is_excluded(*db): - return fn(*args, **kw) - else: - wrapped = emits_warning(*warnings)(fn) - return wrapped(*args, **kw) + with expect_warnings_on(db, *messages): + return fn(*args, **kw) + return decorate @@ -105,29 +105,24 @@ def uses_deprecated(*messages): @contextlib.contextmanager -def expect_deprecated(*messages): - # todo: should probably be strict about this, too - filters = [dict(action='ignore', - category=sa_exc.SAPendingDeprecationWarning)] - if not messages: - filters.append(dict(action='ignore', - category=sa_exc.SADeprecationWarning)) - else: - filters.extend( - [dict(action='ignore', - message=message, - category=sa_exc.SADeprecationWarning) - for message in - [(m.startswith('//') and - ('Call to deprecated function ' + m[2:]) or m) - for m in messages]]) - - for f in filters: - warnings.filterwarnings(**f) - try: +def _expect_warnings(to_patch, messages): + + filters = [re.compile(msg, re.I) for msg in messages] + + real_warn = warnings.warn + + def our_warn(msg, exception, *arg, **kw): + if not filters: + return + + for filter_ in filters: + if filter_.match(msg): + break + else: + real_warn(msg, exception, *arg, **kw) + + with mock.patch(to_patch, our_warn): yield - finally: - resetwarnings() def global_cleanup_assertions(): diff --git a/lib/sqlalchemy/testing/plugin/plugin_base.py b/lib/sqlalchemy/testing/plugin/plugin_base.py index c02f0556b5..7ba31d3e36 100644 --- a/lib/sqlalchemy/testing/plugin/plugin_base.py +++ b/lib/sqlalchemy/testing/plugin/plugin_base.py @@ -181,7 +181,7 @@ def post_begin(): from sqlalchemy.testing import fixtures, engines, exclusions, \ assertions, warnings, profiling, config from sqlalchemy import util - + warnings.setup_filters() def _log(opt_str, value, parser): global logging @@ -491,13 +491,11 @@ def before_test(test, test_module_name, test_class, test_name): id_ = "%s.%s.%s" % (test_module_name, name, test_name) - warnings.resetwarnings() profiling._current_test = id_ def after_test(test): engines.testing_reaper._after_test_ctx() - warnings.resetwarnings() def _possible_configs_for_cls(cls, reasons=None): diff --git a/lib/sqlalchemy/testing/warnings.py b/lib/sqlalchemy/testing/warnings.py index b3314de6e9..47f1e14041 100644 --- a/lib/sqlalchemy/testing/warnings.py +++ b/lib/sqlalchemy/testing/warnings.py @@ -9,25 +9,11 @@ from __future__ import absolute_import import warnings from .. import exc as sa_exc -from .. import util import re -def testing_warn(msg, stacklevel=3): - """Replaces sqlalchemy.util.warn during tests.""" - - filename = "sqlalchemy.testing.warnings" - lineno = 1 - if isinstance(msg, util.string_types): - warnings.warn_explicit(msg, sa_exc.SAWarning, filename, lineno) - else: - warnings.warn_explicit(msg, filename, lineno) - - -def resetwarnings(): - """Reset warning behavior to testing defaults.""" - - util.warn = util.langhelpers.warn = testing_warn +def setup_filters(): + """Set global warning behavior for the test suite.""" warnings.filterwarnings('ignore', category=sa_exc.SAPendingDeprecationWarning) @@ -35,24 +21,20 @@ def resetwarnings(): warnings.filterwarnings('error', category=sa_exc.SAWarning) -def assert_warnings(fn, warnings, regex=False): +def assert_warnings(fn, warning_msgs, regex=False): """Assert that each of the given warnings are emitted by fn.""" - from .assertions import eq_, emits_warning + from .assertions import eq_ - canary = [] - orig_warn = util.warn + with warnings.catch_warnings(record=True) as log: + # ensure that nothing is going into __warningregistry__ + warnings.filterwarnings("always") - def capture_warnings(*args, **kw): - orig_warn(*args, **kw) - popwarn = warnings.pop(0) - canary.append(popwarn) + result = fn() + for warning in log: + popwarn = warning_msgs.pop(0) if regex: - assert re.match(popwarn, args[0]) + assert re.match(popwarn, str(warning.message)) else: - eq_(args[0], popwarn) - util.warn = util.langhelpers.warn = capture_warnings - - result = emits_warning()(fn)() - assert canary, "No warning was emitted" + eq_(popwarn, str(warning.message)) return result diff --git a/lib/sqlalchemy/util/__init__.py b/lib/sqlalchemy/util/__init__.py index b92beac965..c963b18c33 100644 --- a/lib/sqlalchemy/util/__init__.py +++ b/lib/sqlalchemy/util/__init__.py @@ -34,7 +34,8 @@ from .langhelpers import iterate_attributes, class_hierarchy, \ classproperty, set_creation_order, warn_exception, warn, NoneType,\ constructor_copy, methods_equivalent, chop_traceback, asint,\ generic_repr, counter, PluginLoader, hybridmethod, safe_reraise,\ - get_callable_argspec, only_once, attrsetter + get_callable_argspec, only_once, attrsetter, ellipses_string, \ + warn_limited from .deprecations import warn_deprecated, warn_pending_deprecation, \ deprecated, pending_deprecation, inject_docstring_text diff --git a/lib/sqlalchemy/util/deprecations.py b/lib/sqlalchemy/util/deprecations.py index d48efbaaab..124f304fc5 100644 --- a/lib/sqlalchemy/util/deprecations.py +++ b/lib/sqlalchemy/util/deprecations.py @@ -102,7 +102,7 @@ def _decorate_with_warning(func, wtype, message, docstring_header=None): @decorator def warned(fn, *args, **kwargs): - warnings.warn(wtype(message), stacklevel=3) + warnings.warn(message, wtype, stacklevel=3) return fn(*args, **kwargs) doc = func.__doc__ is not None and func.__doc__ or '' diff --git a/lib/sqlalchemy/util/langhelpers.py b/lib/sqlalchemy/util/langhelpers.py index f0dd7a08e5..c260e0931b 100644 --- a/lib/sqlalchemy/util/langhelpers.py +++ b/lib/sqlalchemy/util/langhelpers.py @@ -1189,24 +1189,55 @@ def warn_exception(func, *args, **kwargs): warn("%s('%s') ignored" % sys.exc_info()[0:2]) -def warn(msg, stacklevel=3): +def ellipses_string(value, len_=25): + if len(value) > len_: + return "%s..." % value[0:len_] + else: + return value + + +class _hash_limit_string(compat.text_type): + """A string subclass that can only be hashed on a maximum amount + of unique values. + + This is used for warnings so that we can send out parameterized warnings + without the __warningregistry__ of the module, or the non-overridable + "once" registry within warnings.py, overloading memory, + + + """ + def __new__(cls, value, args, num): + interpolated = value % args + \ + (" (this warning may be suppressed after %d occurrences)" % num) + self = super(_hash_limit_string, cls).__new__(cls, interpolated) + self._hash = hash("%s_%d" % (value, hash(interpolated) % num)) + return self + + def __hash__(self): + return self._hash + + def __eq__(self, other): + return hash(self) == hash(other) + + +def warn(msg): """Issue a warning. If msg is a string, :class:`.exc.SAWarning` is used as the category. - .. note:: + """ + warnings.warn(msg, exc.SAWarning, stacklevel=2) + - This function is swapped out when the test suite - runs, with a compatible version that uses - warnings.warn_explicit, so that the warnings registry can - be controlled. +def warn_limited(msg, *args): + """Issue a warning with a paramterized string, limiting the number + of registrations. """ - if isinstance(msg, compat.string_types): - warnings.warn(msg, exc.SAWarning, stacklevel=stacklevel) - else: - warnings.warn(msg, stacklevel=stacklevel) + if args: + msg = _hash_limit_string(msg, args, 10) + warnings.warn(msg, exc.SAWarning, stacklevel=2) def only_once(fn): diff --git a/test/aaa_profiling/test_memusage.py b/test/aaa_profiling/test_memusage.py index d1d3b385ae..d4ed1fe2ef 100644 --- a/test/aaa_profiling/test_memusage.py +++ b/test/aaa_profiling/test_memusage.py @@ -17,7 +17,9 @@ from sqlalchemy.testing.util import gc_collect import decimal import gc from sqlalchemy.testing import fixtures +from sqlalchemy import util import weakref +import itertools class A(fixtures.ComparableEntity): @@ -376,6 +378,18 @@ class MemUsageTest(EnsureZeroed): finally: metadata.drop_all() + def test_warnings_util(self): + counter = itertools.count() + import warnings + warnings.filterwarnings("ignore", "memusage warning.*") + + @profile_memory() + def go(): + util.warn_limited( + "memusage warning, param1: %s, param2: %s", + next(counter), next(counter)) + go() + def test_mapper_reset(self): metadata = MetaData(self.engine) diff --git a/test/orm/test_session.py b/test/orm/test_session.py index 186b7a781a..74a7a7442b 100644 --- a/test/orm/test_session.py +++ b/test/orm/test_session.py @@ -838,6 +838,7 @@ class SessionStateTest(_fixtures.FixtureTest): def test_extra_dirty_state_post_flush_state(self): s, a1, a2 = self._test_extra_dirty_state() canary = [] + @event.listens_for(s, "after_flush_postexec") def e(sess, ctx): canary.append(bool(sess.identity_map._modified)) diff --git a/test/sql/test_defaults.py b/test/sql/test_defaults.py index 7688aba40d..3ba2318b4c 100644 --- a/test/sql/test_defaults.py +++ b/test/sql/test_defaults.py @@ -1272,8 +1272,9 @@ class UnicodeDefaultsTest(fixtures.TestBase): default = b('foo') assert_raises_message( sa.exc.SAWarning, - "Unicode column received non-unicode default value.", + "Unicode column 'foobar' has non-unicode " + "default value 'foo' specified.", Column, - Unicode(32), + "foobar", Unicode(32), default=default ) -- 2.47.3