diff --git a/doc/OnlineDocs/modeling_extensions/pysp.rst b/doc/OnlineDocs/modeling_extensions/pysp.rst index cb582798f88..a90ad5e6f61 100644 --- a/doc/OnlineDocs/modeling_extensions/pysp.rst +++ b/doc/OnlineDocs/modeling_extensions/pysp.rst @@ -987,46 +987,48 @@ empty will alert the SMPS conversion routines that all variables appearing in the single active model objective expression should be considered to have stochastic coefficients. -*Annotating Constraint Stages* - -Annotating the model with constraint stages is sometimes necessary to -identify to the SMPS routines that certain constraints belong in the -second time-stage even though they lack references to any second-stage -variables. Annotation of constraint stages is achieved using the -**ConstraintStageAnnotation** annotation type. If this annotation -is added to the model, it is assumed that it will be fully populated -with explicit stage assignments for every constraint in the model. The -``declare`` method should be called giving a ``Constraint`` or ``Block`` -as the first argument and a positive integer as the second argument (1 -signifies the first time stage). Example: - -.. testcode:: - - model.IDX = pyo.RangeSet(5) - - # declare the annotation - model.constraint_stage = annotations.ConstraintStageAnnotation() - - # all constraints on this Block are first-stage - model.B = pyo.Block() - # ... - model.constraint_stage.declare(model.B, 1) - - # all indices of this indexed constraint are first-stage - def C1_rule(m, i): - return p*m.x <= q*i - model.C1 = pyo.Constraint(model.IDX, rule=C1_rule) - model.constraint_stage.declare(model.C1, 1) - - # all but one index in this indexed constraint are second-stage - def C2_rule(m, i): - return p*m.x <= q*i - model.C2 = pyo.Constraint(model.IDX, rule=C2_rule) - for index in model.C2: - if index == 3: - model.constraint_stage.declare(model.C2[index], 1) - else: - model.constraint_stage.declare(model.C2[index], 2) +.. # Commenting out documentation of deprecated functionality + + *Annotating Constraint Stages* + + Annotating the model with constraint stages is sometimes necessary to + identify to the SMPS routines that certain constraints belong in the + second time-stage even though they lack references to any second-stage + variables. Annotation of constraint stages is achieved using the + **ConstraintStageAnnotation** annotation type. If this annotation + is added to the model, it is assumed that it will be fully populated + with explicit stage assignments for every constraint in the model. The + ``declare`` method should be called giving a ``Constraint`` or ``Block`` + as the first argument and a positive integer as the second argument (1 + signifies the first time stage). Example: + + .. testcode:: + + model.IDX = pyo.RangeSet(5) + + # declare the annotation + model.constraint_stage = annotations.ConstraintStageAnnotation() + + # all constraints on this Block are first-stage + model.B = pyo.Block() + # ... + model.constraint_stage.declare(model.B, 1) + + # all indices of this indexed constraint are first-stage + def C1_rule(m, i): + return p*m.x <= q*i + model.C1 = pyo.Constraint(model.IDX, rule=C1_rule) + model.constraint_stage.declare(model.C1, 1) + + # all but one index in this indexed constraint are second-stage + def C2_rule(m, i): + return p*m.x <= q*i + model.C2 = pyo.Constraint(model.IDX, rule=C2_rule) + for index in model.C2: + if index == 3: + model.constraint_stage.declare(model.C2[index], 1) + else: + model.constraint_stage.declare(model.C2[index], 2) .. _Edge-Cases: diff --git a/pyomo/bilevel/plugins/transform.py b/pyomo/bilevel/plugins/transform.py index 811ad0b2bd1..9c31a9a4ee3 100644 --- a/pyomo/bilevel/plugins/transform.py +++ b/pyomo/bilevel/plugins/transform.py @@ -10,8 +10,6 @@ from pyomo.core.base import Transformation, Var, ComponentUID from pyomo.bilevel import SubModel -import logging -logger = logging.getLogger('pyomo.core') class Base_BilevelTransformation(Transformation): diff --git a/pyomo/common/log.py b/pyomo/common/log.py index bb30bd59a28..be482688f81 100644 --- a/pyomo/common/log.py +++ b/pyomo/common/log.py @@ -23,34 +23,82 @@ import sys import textwrap +from pyomo.common.deprecation import deprecated from pyomo.common.fileutils import PYOMO_ROOT_DIR -_indention = re.compile('\s*') -_status_re = re.compile('^\[\s*[A-Za-z0-9\.]+\s*\]') +_indentation_re = re.compile(r'\s*') +_bullet_re = re.compile(r'(?:[-*] +)|(\[\s*[A-Za-z0-9\.]+\s*\] +)') +_bullet_char = '-*[' +_DEBUG = logging.DEBUG +_NOTSET = logging.NOTSET +if not __debug__: + def is_debug_set(logger): + return False +elif hasattr(getattr(logging.getLogger(), 'manager', None), 'disable'): + # This works for CPython and PyPy, but relies on a manager attribute + # to get the current value of the logging.disabled() flag + # (technically not included in the official logging documentation) + def is_debug_set(logger): + """A variant of Logger.isEnableFor that returns False if NOTSET -class LogHandler(logging.Handler): + The implementation of logging.Logger.isEnableFor() returns True + if the effective level of the logger is NOTSET. This variant + only returns True if the effective level of the logger is NOTSET + < level <= DEBUG. This is used in Pyomo to detect if the user + explicitly requested DEBUG output. - def __init__( self, base='', stream=None, - level=logging.NOTSET, verbosity=None ): - logging.Handler.__init__(self, level=level) + This implementation mimics the core functionality of + isEnabledFor() by directly querying the (undocumented) 'manager' + attribute to get the current value for logging.disabled() - if verbosity is None: - verbosity = lambda: True - if stream is None: - stream = sys.stdout + """ + if logger.manager.disable >= _DEBUG: + return False + _level = logger.getEffectiveLevel() + # Filter out NOTSET and higher levels + return _NOTSET < _level <= _DEBUG +else: + # This is inefficient (it indirectly checks effective level twice), + # but is included for [as yet unknown] platforms that ONLY implement + # the API documented in the logging library + def is_debug_set(logger): + if not logger.isEnabledFor(_DEBUG): + return False + return logger.getEffectiveLevel() > _NOTSET - self.verbosity = verbosity - self.stream = stream - self.basepath = base - # Public attributes (because embedded constants in functions are evil) - self.wrap = 78 - self.initial_indent = '' - self.subsequent_indent = ' '*4 +class WrappingFormatter(logging.Formatter): + _flag = "<>" - def emit(self, record): - level = record.levelname + def __init__(self, **kwds): + if 'fmt' not in kwds: + if kwds.get('style', '%') == '%': + kwds['fmt'] = '%(levelname)s: %(message)s' + elif kwds['style'] == '{': + kwds['fmt'] = '{levelname}: {message}' + elif kwds['style'] == '$': + kwds['fmt'] = '$levelname: $message' + else: + raise ValueError('unrecognized style flag "%s"' + % (kwds['style'],)) + self._wrapper = textwrap.TextWrapper(width=kwds.pop('wrap', 78)) + self.hang = kwds.pop('hang', ' '*4) + self.basepath = kwds.pop('base', None) + super(WrappingFormatter, self).__init__(**kwds) + + def format(self, record): + _orig = {k:getattr(record, k) for k in ('msg', 'args', 'pathname')} msg = record.getMessage() + record.msg = self._flag + record.args = None + if self.basepath and record.pathname.startswith(self.basepath): + record.pathname = '[base]' + record.pathname[len(self.basepath):] + try: + raw_msg = super(WrappingFormatter, self).format(record) + finally: + for k,v in _orig.items(): + setattr(record, k, v) + # Most of the messages are either unformatted long lines or # triple-quote blocks of text. In the latter case, if the text # starts on the same line as the triple-quote, then it is almost @@ -58,11 +106,11 @@ def emit(self, record): # cause dedent to get confused and not strip any leading # whitespace. This attempts to work around that case: # - #if not ( msg.startswith('\n') or _indention.match(msg).group() ): + #if not (_msg.startswith('\n') or _indentation_re.match(_msg).group()): # # copy the indention for the second line to the first: - # lines = msg.splitlines() + # lines = _msg.splitlines() # if len(lines) > 1: - # msg = _indention.match(lines[1]).group() + msg + # _msg = _indentation_re.match(lines[1]).group() + _msg # # The problem with the above logic is that users may want a # simple introductory line followed by an intented line (our @@ -70,105 +118,154 @@ def emit(self, record): # extra blank line to the output. In contrast, it is possible # for the user to fix the scenario above that motivated this # code by just indenting their first line correctly. + msg = textwrap.dedent(msg).strip() + + # Split the formatted log message (that currently has _flag in + # lieu of the actual message content) into lines, then + # recombine, substituting and wrapping any lines that contain + # _flag. + return '\n'.join( + self._wrap_msg(l, msg) if self._flag in l else l + for l in raw_msg.splitlines() + ) - # TBD: dedent does not convert \t to ' '*8. Should we do that? - msg = textwrap.dedent(msg) + def _wrap_msg(self, l, msg): + indent = _indentation_re.match(l).group() + return self._wrap(l.strip().replace(self._flag, msg), indent) + def _wrap(self, msg, base_indent): # As textwrap only works on single paragraphs, we need to break # up the incoming message into paragraphs before we pass it to # textwrap. paragraphs = [] - indent = _indention.match(msg).group() - par_lines = [] - for line in msg.splitlines(): - leading = _indention.match(line).group() + verbatim = False + for line in msg.rstrip().splitlines(): + leading = _indentation_re.match(line).group() content = line.strip() if not content: - paragraphs.append((indent, par_lines)) - par_lines = [] - # Blank lines reset the indentation level - indent = None - elif indent == leading: - # Catch things like bulleted lists and '[FAIL]' - if len(content) > 1 and par_lines and ( - (content[1] == ' ' and content[0] in '-* ') or - (content[0] == '[' and _status_re.match(content))): - paragraphs.append((indent, par_lines)) - par_lines = [] - par_lines.append( content ) + paragraphs.append((None, None)) + elif content == '```': + verbatim ^= True + elif verbatim: + paragraphs.append((None, line)) else: - paragraphs.append((indent, par_lines)) - par_lines = [ content ] - indent = leading - # Collect the final paragraph - if par_lines: - paragraphs.append((indent, par_lines)) - - # Skip any leading/trailing blank lines - while paragraphs and not paragraphs[-1][1]: - paragraphs.pop() - while paragraphs and not paragraphs[0][1]: - paragraphs.pop(0) + matchBullet = _bullet_re.match(content) + if matchBullet: + paragraphs.append( + (leading + ' '*len(matchBullet.group()), [content])) + elif paragraphs and paragraphs[-1][0] == leading: + paragraphs[-1][1].append( content ) + else: + paragraphs.append((leading, [content])) - if self.verbosity(): - # - # If verbosity is on, the first logged line is the file, - # line, and function name that called the logger. The first - # line of the message is actually the second line of the - # output (and so is indented/wrapped the same as the rest of - # the message) - # - filename = record.pathname # file path - lineno = record.lineno - try: - function = record.funcName - except AttributeError: - function = '(unknown)' - if self.basepath and filename.startswith(self.basepath): - filename = '[base]' + filename[len(self.basepath):] - - self.stream.write( - '%s: "%s", %d, %s\n' % - ( level, filename, lineno, function.strip(), )) - else: - # - # If verbosity is off, prepend the log level name to the - # beginning of the message and format the line without the - # 'subsequent' indentation of the remainder of the message - # - if paragraphs: - firstPar = ' '.join(paragraphs.pop(0)[1]).strip() - if level: - firstPar = ('%s: %s' % (level, firstPar)) + base_indent = (self.hang or '') + base_indent + + for i, (indent, par) in enumerate(paragraphs): + if indent is None: + if par is None: + paragraphs[i] = '' + else: + paragraphs[i] = base_indent + par + continue + + par_indent = base_indent + indent + self._wrapper.subsequent_indent = par_indent + if not i and self.hang: + self._wrapper.initial_indent = par_indent[len(self.hang):] else: - firstPar = level - self.stream.write( '%s\n' % ( - textwrap.fill( firstPar, - width=self.wrap, - initial_indent=self.initial_indent, - subsequent_indent=self.subsequent_indent ), )) - for indent, par in paragraphs: - if not indent: - indent = '' + self._wrapper.initial_indent = par_indent + # Bulleted lists get indented with a hanging indent - if par and len(par[0]) > 1 and par[0][0] in '-*': - hang = ' '*4 - else: - hang = '' - self.stream.write( '%s\n' % ( - textwrap.fill( - ' '.join(par), - width=self.wrap, - initial_indent=self.subsequent_indent+indent, - subsequent_indent=self.subsequent_indent+indent+hang ), )) + bullet = _bullet_re.match(par[0]) + if bullet: + self._wrapper.initial_indent = par_indent[:-len(bullet.group())] -# -# Set up the root Pyomo namespace logger -# -_logger = logging.getLogger('pyomo') -_logger.addHandler( LogHandler( - PYOMO_ROOT_DIR, verbosity=lambda: _logger.isEnabledFor(logging.DEBUG) )) -_logger.setLevel(logging.WARNING) + paragraphs[i] = self._wrapper.fill(' '.join(par)) + return '\n'.join(paragraphs) + + +class LegacyPyomoFormatter(logging.Formatter): + """This mocks up the legacy Pyomo log formating. + + This formatter takes a callback function (`verbosity`) that will be + called for each message. Based on the result, one of two formatting + templates will be used. + + """ + def __init__(self, **kwds): + if 'fmt' in kwds: + raise ValueError( + "'fmt' is not a valid option for the LegacyFormatter") + if 'style' in kwds: + raise ValueError( + "'style' is not a valid option for the LegacyFormatter") + + self.verbosity = kwds.pop('verbosity', lambda: True) + self.standard_formatter = WrappingFormatter(**kwds) + self.verbose_formatter = WrappingFormatter( + fmt='%(levelname)s: "%(pathname)s", %(lineno)d, %(funcName)s\n' + ' %(message)s', + hang=False, + **kwds + ) + super(LegacyPyomoFormatter, self).__init__() + + def format(self, record): + if self.verbosity(): + return self.verbose_formatter.format(record) + else: + return self.standard_formatter.format(record) + + +class StdoutHandler(logging.StreamHandler): + """A logging handler that emits to the current value of sys.stdout""" + + def flush(self): + self.stream = sys.stdout + super(StdoutHandler, self).flush() + + def emit(self, record): + self.stream = sys.stdout + super(StdoutHandler, self).emit(record) + + +class _GlobalLogFilter(object): + def __init__(self): + self.logger = logging.getLogger() + + def filter(self, record): + return not self.logger.handlers + + +# This mocks up the historical Pyomo logging system, which uses a +# different formatter based on if the main pyomo logger is enabled for +# debugging. It has been updated to suppress output if any handlers +# have been defined at the root level. +_pyomoLogger = logging.getLogger('pyomo') +_handler = StdoutHandler() +_handler.setFormatter(LegacyPyomoFormatter( + base=PYOMO_ROOT_DIR, + verbosity=lambda: _pyomoLogger.isEnabledFor(logging.DEBUG), +)) +_handler.addFilter(_GlobalLogFilter()) +_pyomoLogger.addHandler(_handler) + + +class LogHandler(logging.StreamHandler): + @deprecated('The pyomo.common.log.LogHandler class has been deprecated ' + 'in favor of standard Handlers from the Python logging module ' + 'combined with the pyomo.common.log.WrappingFormatter.', + version='TBD') + def __init__(self, base='', stream=None, + level=logging.NOTSET, verbosity=None): + super(LogHandler, self).__init__(stream) + self.setLevel(level), + if verbosity is None: + verbosity = lambda: True + self.setFormatter(LegacyPyomoFormatter( + base=base, + verbosity=verbosity, + )) class LoggingIntercept(object): diff --git a/pyomo/common/tests/test_log.py b/pyomo/common/tests/test_log.py index 4552345f0ba..88a6be965b2 100644 --- a/pyomo/common/tests/test_log.py +++ b/pyomo/common/tests/test_log.py @@ -19,16 +19,18 @@ import logging import os from inspect import currentframe, getframeinfo -from six import StringIO +from six import StringIO, PY2 import pyutilib.th as unittest -from pyomo.common.log import LogHandler +from pyomo.common.log import ( + LoggingIntercept, WrappingFormatter, LegacyPyomoFormatter, LogHandler, +) logger = logging.getLogger('pyomo.common.log.testing') filename = getframeinfo(currentframe()).filename -class TestLogging(unittest.TestCase): +class TestLegacyLogHandler(unittest.TestCase): def setUp(self): self.stream = StringIO() @@ -37,10 +39,14 @@ def tearDown(self): def test_simple_log(self): # Testing positional base, configurable verbosity - self.handler = LogHandler( - os.path.dirname(__file__), - stream = self.stream, - verbosity=lambda: logger.isEnabledFor(logging.DEBUG)) + log = StringIO() + with LoggingIntercept(log): + self.handler = LogHandler( + os.path.dirname(__file__), + stream = self.stream, + verbosity=lambda: logger.isEnabledFor(logging.DEBUG) + ) + self.assertIn('LogHandler class has been deprecated', log.getvalue()) logger.addHandler(self.handler) logger.setLevel(logging.WARNING) @@ -57,11 +63,99 @@ def test_simple_log(self): ' (warn)\n' % (os.path.sep, lineno,) self.assertEqual(self.stream.getvalue(), ans) + def test_default_verbosity(self): + # Testing positional base, configurable verbosity + log = StringIO() + with LoggingIntercept(log): + self.handler = LogHandler( + os.path.dirname(__file__), + stream = self.stream, + ) + self.assertIn('LogHandler class has been deprecated', log.getvalue()) + logger.addHandler(self.handler) + + logger.setLevel(logging.WARNING) + logger.warn("(warn)") + lineno = getframeinfo(currentframe()).lineno - 1 + ans = 'WARNING: "[base]%stest_log.py", %d, test_default_verbosity\n' \ + ' (warn)\n' % (os.path.sep, lineno,) + self.assertEqual(self.stream.getvalue(), ans) + + +class TestWrappingFormatter(unittest.TestCase): + def setUp(self): + self.stream = StringIO() + self.handler = logging.StreamHandler(self.stream) + logger.addHandler(self.handler) + + def tearDown(self): + logger.removeHandler(self.handler) + + @unittest.skipIf(PY2, "style added in Python 3.2") + def test_style_options(self): + ans = '' + + self.handler.setFormatter(WrappingFormatter(style='%')) + logger.warn("(warn)") + ans += "WARNING: (warn)\n" + self.assertEqual(self.stream.getvalue(), ans) + + self.handler.setFormatter(WrappingFormatter(style='$')) + logger.warn("(warn)") + ans += "WARNING: (warn)\n" + self.assertEqual(self.stream.getvalue(), ans) + + self.handler.setFormatter(WrappingFormatter(style='{')) + logger.warn("(warn)") + ans += "WARNING: (warn)\n" + self.assertEqual(self.stream.getvalue(), ans) + + with self.assertRaisesRegex(ValueError, 'unrecognized style flag "s"'): + WrappingFormatter(style='s') + +class TestLegacyPyomoFormatter(unittest.TestCase): + def setUp(self): + self.stream = StringIO() + self.handler = logging.StreamHandler(self.stream) + logger.addHandler(self.handler) + + def tearDown(self): + logger.removeHandler(self.handler) + + def test_unallowed_options(self): + with self.assertRaisesRegex( + ValueError, "'fmt' is not a valid option"): + LegacyPyomoFormatter(fmt='%(message)') + + with self.assertRaisesRegex( + ValueError, "'style' is not a valid option"): + LegacyPyomoFormatter(style='%') + + def test_simple_log(self): + # Testing positional base, configurable verbosity + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG) + )) + + logger.setLevel(logging.WARNING) + logger.info("(info)") + self.assertEqual(self.stream.getvalue(), "") + logger.warn("(warn)") + ans = "WARNING: (warn)\n" + self.assertEqual(self.stream.getvalue(), ans) + + logger.setLevel(logging.DEBUG) + logger.warn("(warn)") + lineno = getframeinfo(currentframe()).lineno - 1 + ans += 'WARNING: "[base]%stest_log.py", %d, test_simple_log\n' \ + ' (warn)\n' % (os.path.sep, lineno,) + self.assertEqual(self.stream.getvalue(), ans) + def test_alternate_base(self): - self.handler = LogHandler( + self.handler.setFormatter(LegacyPyomoFormatter( base = 'log_config', - stream = self.stream) - logger.addHandler(self.handler) + )) logger.setLevel(logging.WARNING) logger.info("(info)") @@ -73,9 +167,7 @@ def test_alternate_base(self): self.assertEqual(self.stream.getvalue(), ans) def test_no_base(self): - self.handler = LogHandler( - stream = self.stream) - logger.addHandler(self.handler) + self.handler.setFormatter(LegacyPyomoFormatter()) logger.setLevel(logging.WARNING) logger.info("(info)") @@ -87,34 +179,50 @@ def test_no_base(self): self.assertEqual(self.stream.getvalue(), ans) def test_no_message(self): - self.handler = LogHandler( - os.path.dirname(__file__), - stream = self.stream, - verbosity=lambda: logger.isEnabledFor(logging.DEBUG)) - logger.addHandler(self.handler) + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG) + )) logger.setLevel(logging.WARNING) logger.info("") self.assertEqual(self.stream.getvalue(), "") logger.warn("") - ans = "WARNING\n" + ans = "WARNING:\n" self.assertEqual(self.stream.getvalue(), ans) logger.setLevel(logging.DEBUG) logger.warn("") lineno = getframeinfo(currentframe()).lineno - 1 - ans += 'WARNING: "[base]%stest_log.py", %d, test_no_message\n' \ + ans += 'WARNING: "[base]%stest_log.py", %d, test_no_message\n\n' \ % (os.path.sep, lineno,) self.assertEqual(self.stream.getvalue(), ans) + def test_blank_lines(self): + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG), + )) + + logger.setLevel(logging.WARNING) + logger.warn("\n\nthis is a message.\n\n\n") + ans = "WARNING: this is a message.\n" + self.assertEqual(self.stream.getvalue(), ans) + + logger.setLevel(logging.DEBUG) + logger.warn("\n\nthis is a message.\n\n\n") + lineno = getframeinfo(currentframe()).lineno - 1 + ans += 'WARNING: "[base]%stest_log.py", %d, test_blank_lines\n' \ + " this is a message.\n" % (os.path.sep, lineno) + self.assertEqual(self.stream.getvalue(), ans) + def test_numbered_level(self): testname ='test_numbered_level' - self.handler = LogHandler( - os.path.dirname(__file__), - stream = self.stream, - verbosity=lambda: logger.isEnabledFor(logging.DEBUG)) - logger.addHandler(self.handler) + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG), + )) logger.setLevel(logging.WARNING) logger.log(45, "(hi)") @@ -122,7 +230,7 @@ def test_numbered_level(self): self.assertEqual(self.stream.getvalue(), ans) logger.log(45, "") - ans += "Level 45\n" + ans += "Level 45:\n" self.assertEqual(self.stream.getvalue(), ans) logger.setLevel(logging.DEBUG) @@ -134,24 +242,25 @@ def test_numbered_level(self): logger.log(45, "") lineno = getframeinfo(currentframe()).lineno - 1 - ans += 'Level 45: "[base]%stest_log.py", %d, %s\n' \ + ans += 'Level 45: "[base]%stest_log.py", %d, %s\n\n' \ % (os.path.sep, lineno, testname) self.assertEqual(self.stream.getvalue(), ans) def test_long_messages(self): - self.handler = LogHandler( - os.path.dirname(__file__), - stream = self.stream, - verbosity=lambda: logger.isEnabledFor(logging.DEBUG)) - logger.addHandler(self.handler) + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG) + )) - msg = ("This is a long message\n\n" + msg = ("This is a long message\n" + "\n" "With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2 ") logger.setLevel(logging.WARNING) logger.warn(msg) - ans = ( "WARNING: This is a long message\n\n" + ans = ( "WARNING: This is a long message\n" + "\n" " With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2\n" ) @@ -161,7 +270,8 @@ def test_long_messages(self): logger.info(msg) lineno = getframeinfo(currentframe()).lineno - 1 ans += ( 'INFO: "[base]%stest_log.py", %d, test_long_messages\n' - " This is a long message\n\n" + " This is a long message\n" + "\n" " With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2\n" % (os.path.sep, lineno,)) @@ -171,17 +281,19 @@ def test_long_messages(self): msg += "\n" logger.setLevel(logging.WARNING) logger.warn(msg) - ans += ( "WARNING: This is a long message\n\n" - " With some kind of internal formatting\n" - " - including a bulleted list\n" - " - list 2\n" ) + ans += ( "WARNING: This is a long message\n" + "\n" + " With some kind of internal formatting\n" + " - including a bulleted list\n" + " - list 2\n" ) self.assertEqual(self.stream.getvalue(), ans) logger.setLevel(logging.DEBUG) logger.info(msg) lineno = getframeinfo(currentframe()).lineno - 1 ans += ( 'INFO: "[base]%stest_log.py", %d, test_long_messages\n' - " This is a long message\n\n" + " This is a long message\n" + "\n" " With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2\n" % (os.path.sep, lineno,)) @@ -191,7 +303,8 @@ def test_long_messages(self): msg = "\n" + msg + "\n\n" logger.setLevel(logging.WARNING) logger.warn(msg) - ans += ( "WARNING: This is a long message\n\n" + ans += ( "WARNING: This is a long message\n" + "\n" " With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2\n" ) @@ -201,8 +314,52 @@ def test_long_messages(self): logger.info(msg) lineno = getframeinfo(currentframe()).lineno - 1 ans += ( 'INFO: "[base]%stest_log.py", %d, test_long_messages\n' - " This is a long message\n\n" + " This is a long message\n" + "\n" " With some kind of internal formatting\n" " - including a bulleted list\n" " - list 2\n" % (os.path.sep, lineno,)) self.assertEqual(self.stream.getvalue(), ans) + + def test_verbatim(self): + self.handler.setFormatter(LegacyPyomoFormatter( + base=os.path.dirname(__file__), + verbosity=lambda: logger.isEnabledFor(logging.DEBUG) + )) + + msg = ( + "This is a long message\n" + "\n" + " ```\n" + "With some \n" + "internal\n" + "verbatim \n" + " - including a\n" + " long list\n" + " - and a short list \n" + " ```\n" + "\n" + "And some \n" + "internal\n" + "non-verbatim \n" + " - including a\n" + " long list\n" + " - and a short list \n" + ) + logger.setLevel(logging.WARNING) + logger.warn(msg) + ans = ( + "WARNING: This is a long message\n" + "\n" + " With some \n" + " internal\n" + " verbatim \n" + " - including a\n" + " long list\n" + " - and a short list \n" + "\n" + " And some internal non-verbatim\n" + " - including a long list\n" + " - and a short list\n" + ) + self.assertEqual(self.stream.getvalue(), ans) diff --git a/pyomo/contrib/fbbt/tests/test_fbbt.py b/pyomo/contrib/fbbt/tests/test_fbbt.py index 0f7fe1b140b..3fb6a271eac 100644 --- a/pyomo/contrib/fbbt/tests/test_fbbt.py +++ b/pyomo/contrib/fbbt/tests/test_fbbt.py @@ -12,12 +12,12 @@ import pyomo.environ as pyo from pyomo.contrib.fbbt.fbbt import fbbt, compute_bounds_on_expr from pyomo.common.dependencies import numpy as np, numpy_available +from pyomo.common.log import LoggingIntercept from pyomo.common.errors import InfeasibleConstraintException from pyomo.core.expr.numeric_expr import (ProductExpression, UnaryFunctionExpression) import math -import logging -import io +from six import StringIO class DummyExpr(ProductExpression): @@ -727,7 +727,6 @@ def test_inf_bounds_on_expr(self): self.assertEqual(lb, None) self.assertEqual(ub, None) - @unittest.skip('This test passes locally, but not on travis or appveyor. I will add an issue.') def test_skip_unknown_expression1(self): m = pyo.ConcreteModel() @@ -735,25 +734,17 @@ def test_skip_unknown_expression1(self): m.y = pyo.Var() expr = DummyExpr([m.x, m.y]) m.c = pyo.Constraint(expr=expr == 1) - logging_io = io.StringIO() - handler = logging.StreamHandler(stream=logging_io) - handler.setLevel(logging.WARNING) - logger = logging.getLogger('pyomo.contrib.fbbt.fbbt') - logger.addHandler(handler) - new_bounds = fbbt(m) - handler.flush() + + OUT = StringIO() + with LoggingIntercept(OUT, 'pyomo.contrib.fbbt.fbbt'): + new_bounds = fbbt(m) + self.assertEqual(pyo.value(m.x.lb), 1) self.assertEqual(pyo.value(m.x.ub), 1) self.assertEqual(pyo.value(m.y.lb), None) self.assertEqual(pyo.value(m.y.ub), None) - a = "Unsupported expression type for FBBT" - b = logging_io.getvalue() - a = a.strip() - b = b.strip() - self.assertTrue(b.startswith(a)) - logger.removeHandler(handler) - - @unittest.skip('This test passes locally, but not on travis or appveyor. I will add an issue.') + self.assertIn("Unsupported expression type for FBBT", OUT.getvalue()) + def test_skip_unknown_expression2(self): def dummy_unary_expr(x): return 0.5*x @@ -762,21 +753,14 @@ def dummy_unary_expr(x): m.x = pyo.Var(bounds=(0,4)) expr = UnaryFunctionExpression((m.x,), name='dummy_unary_expr', fcn=dummy_unary_expr) m.c = pyo.Constraint(expr=expr == 1) - logging_io = io.StringIO() - handler = logging.StreamHandler(stream=logging_io) - handler.setLevel(logging.WARNING) - logger = logging.getLogger('pyomo.contrib.fbbt.fbbt') - logger.addHandler(handler) - new_bounds = fbbt(m) - handler.flush() + + OUT = StringIO() + with LoggingIntercept(OUT, 'pyomo.contrib.fbbt.fbbt'): + new_bounds = fbbt(m) + self.assertEqual(pyo.value(m.x.lb), 0) self.assertEqual(pyo.value(m.x.ub), 4) - a = "Unsupported expression type for FBBT" - b = logging_io.getvalue() - a = a.strip() - b = b.strip() - self.assertTrue(b.startswith(a)) - logger.removeHandler(handler) + self.assertIn("Unsupported expression type for FBBT", OUT.getvalue()) def test_compute_expr_bounds(self): m = pyo.ConcreteModel() diff --git a/pyomo/contrib/fme/fourier_motzkin_elimination.py b/pyomo/contrib/fme/fourier_motzkin_elimination.py index 63baaaa1a9e..a2e5f5bcd8a 100644 --- a/pyomo/contrib/fme/fourier_motzkin_elimination.py +++ b/pyomo/contrib/fme/fourier_motzkin_elimination.py @@ -189,7 +189,7 @@ def __init__(self): super(Fourier_Motzkin_Elimination_Transformation, self).__init__() def _apply_to(self, instance, **kwds): - log_level = logger.getEffectiveLevel() + log_level = logger.level try: assert not NAME_BUFFER config = self.CONFIG(kwds.pop('options', {})) diff --git a/pyomo/contrib/gdpopt/util.py b/pyomo/contrib/gdpopt/util.py index 0334d6349a6..29d4cf75e8d 100644 --- a/pyomo/contrib/gdpopt/util.py +++ b/pyomo/contrib/gdpopt/util.py @@ -437,7 +437,7 @@ def get_main_elapsed_time(timing_data_obj): version='5.6.9') @contextmanager def restore_logger_level(logger): - old_logger_level = logger.getEffectiveLevel() + old_logger_level = logger.level yield logger.setLevel(old_logger_level) @@ -445,9 +445,9 @@ def restore_logger_level(logger): @contextmanager def lower_logger_level_to(logger, level=None): """Increases logger verbosity by lowering reporting level.""" - old_logger_level = logger.getEffectiveLevel() - if level is not None and old_logger_level > level: + if level is not None and logger.getEffectiveLevel() > level: # If logger level is higher (less verbose), decrease it + old_logger_level = logger.level logger.setLevel(level) yield logger.setLevel(old_logger_level) diff --git a/pyomo/contrib/pynumero/interfaces/external_grey_box.py b/pyomo/contrib/pynumero/interfaces/external_grey_box.py index 80c72394215..0a9fc052785 100644 --- a/pyomo/contrib/pynumero/interfaces/external_grey_box.py +++ b/pyomo/contrib/pynumero/interfaces/external_grey_box.py @@ -12,6 +12,7 @@ import numpy as np from scipy.sparse import coo_matrix +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base import Var, Constraint, value from pyomo.core.base.block import _BlockData, Block, declare_custom_block @@ -260,7 +261,7 @@ def construct(self, data=None): # Do not set the constructed flag - Block.construct() will do that timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing external grey box model %s" % (self.name)) diff --git a/pyomo/core/base/PyomoModel.py b/pyomo/core/base/PyomoModel.py index bfb42353a53..bd6d410922b 100644 --- a/pyomo/core/base/PyomoModel.py +++ b/pyomo/core/base/PyomoModel.py @@ -22,6 +22,7 @@ from pyomo.common.dependencies import pympler, pympler_available from pyomo.common.deprecation import deprecated, deprecation_warning from pyomo.common.gc_manager import PauseGC +from pyomo.common.log import is_debug_set from pyomo.common.plugin import ExtensionPoint from pyomo.core.expr import expr_common @@ -870,7 +871,8 @@ def _initialize_component(self, modeldata, namespaces, component_name, profile_m if data is not None: break - if __debug__ and logger.isEnabledFor(logging.DEBUG): + generate_debug_messages = is_debug_set(logger) + if generate_debug_messages: _blockName = "Model" if self.parent_block() is None \ else "Block '%s'" % self.name logger.debug( "Constructing %s '%s' on %s from data=%s", @@ -886,11 +888,11 @@ def _initialize_component(self, modeldata, namespaces, component_name, profile_m type(err).__name__, err ) raise - if __debug__ and logger.isEnabledFor(logging.DEBUG): - _out = StringIO() - declaration.pprint(ostream=_out) - logger.debug("Constructed component '%s':\n %s" - % ( declaration.name, _out.getvalue())) + if generate_debug_messages: + _out = StringIO() + declaration.pprint(ostream=_out) + logger.debug("Constructed component '%s':\n %s" + % ( declaration.name, _out.getvalue())) if profile_memory >= 2 and pympler_available: mem_used = pympler.muppy.get_size(pympler.muppy.get_objects()) diff --git a/pyomo/core/base/action.py b/pyomo/core/base/action.py index 5b8b404998b..511f26a6fbc 100644 --- a/pyomo/core/base/action.py +++ b/pyomo/core/base/action.py @@ -13,6 +13,7 @@ import logging import types +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory from pyomo.core.base.indexed_component import IndexedComponent @@ -48,7 +49,7 @@ def _pprint(self): def construct(self, data=None): """ Apply the rule to construct values in this set """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Constructing Action, name="+self.name) # if self._constructed: #pragma:nocover diff --git a/pyomo/core/base/alias.py b/pyomo/core/base/alias.py index f7e69cccbd1..8aaae761ba7 100644 --- a/pyomo/core/base/alias.py +++ b/pyomo/core/base/alias.py @@ -11,6 +11,7 @@ import weakref import logging +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.component import Component, ComponentData @@ -88,14 +89,13 @@ def aliased_object(self, value): # def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover try: name = str(self.name) except: name = type(self) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("Constructing Alias, name=%s, " - "from data=%s", name, str(data)) + logger.debug("Constructing Alias, name=%s, " + "from data=%s", name, str(data)) if self._constructed: return timer = ConstructionTimer(self) diff --git a/pyomo/core/base/block.py b/pyomo/core/base/block.py index 394885462ef..cbad9419234 100644 --- a/pyomo/core/base/block.py +++ b/pyomo/core/base/block.py @@ -28,6 +28,7 @@ from pyomo.common.collections import ComponentMap, Mapping from pyomo.common.deprecation import deprecated, deprecation_warning +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory from pyomo.core.base.component import ( @@ -1063,7 +1064,8 @@ def add_component(self, name, val): data = data.get(name, None) else: data = None - if __debug__ and logger.isEnabledFor(logging.DEBUG): + generate_debug_messages = is_debug_set(logger) + if generate_debug_messages: # This is tricky: If we are in the middle of # constructing an indexed block, the block component # already has _constructed=True. Now, if the @@ -1081,7 +1083,7 @@ def add_component(self, name, val): _blockName = "Block '%s[...]'" \ % self.parent_component().name logger.debug("Constructing %s '%s' on %s from data=%s", - val.__class__.__name__, val.name, + val.__class__.__name__, name, _blockName, str(data)) try: val.construct(data) @@ -1092,11 +1094,11 @@ def add_component(self, name, val): str(val.name), str(data).strip(), type(err).__name__, err) raise - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if generate_debug_messages: if _blockName[-1] == "'": - _blockName = _blockName[:-1] + '.' + val.name + "'" + _blockName = _blockName[:-1] + '.' + name + "'" else: - _blockName = "'" + _blockName + '.' + val.name + "'" + _blockName = "'" + _blockName + '.' + name + "'" _out = StringIO() val.pprint(ostream=_out) logger.debug("Constructed component '%s':\n%s" @@ -1813,7 +1815,7 @@ def solver_capability(x): return True self.solutions = ModelSolutions(self) self.solutions.add_symbol_map(smap) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug( "Writing model '%s' to file '%s' with format %s", self.name, @@ -1917,7 +1919,7 @@ def construct(self, data=None): """ Initialize the block """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing %s '%s', from data=%s", self.__class__.__name__, self.name, str(data)) if self._constructed: diff --git a/pyomo/core/base/boolean_var.py b/pyomo/core/base/boolean_var.py index d47e617b858..2b7c79806e6 100644 --- a/pyomo/core/base/boolean_var.py +++ b/pyomo/core/base/boolean_var.py @@ -4,6 +4,7 @@ import logging from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.expr.boolean_value import BooleanValue from pyomo.core.expr.numvalue import value @@ -324,15 +325,14 @@ def set_values(self, new_values, valid=False): def construct(self, data=None): """Construct this component.""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover try: name = str(self.name) except: name = type(self) - if logger.isEnabledFor(logging.DEBUG): - logger.debug( - "Constructing Variable, name=%s, from data=%s" - % (name, str(data))) + logger.debug( + "Constructing Variable, name=%s, from data=%s" + % (name, str(data))) if self._constructed: return @@ -558,7 +558,7 @@ def __init__(self, **kwds): def construct(self, data=None): """Construct this component.""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing variable list %s", self.name) # We need to ensure that the indices needed for initialization are diff --git a/pyomo/core/base/check.py b/pyomo/core/base/check.py index 7ae1693105c..6051f0e613b 100644 --- a/pyomo/core/base/check.py +++ b/pyomo/core/base/check.py @@ -13,6 +13,7 @@ import logging import types +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory from pyomo.core.base.indexed_component import IndexedComponent @@ -47,7 +48,7 @@ def _pprint(self): def construct(self, data=None): """ Apply the rule to construct values in this set """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Constructing Check, name="+self.name) # if self._constructed: #pragma:nocover diff --git a/pyomo/core/base/connector.py b/pyomo/core/base/connector.py index b4a145e3a7a..e2c7348fadb 100644 --- a/pyomo/core/base/connector.py +++ b/pyomo/core/base/connector.py @@ -16,8 +16,9 @@ from weakref import ref as weakref_ref from pyomo.common import deprecated -from pyomo.common.timing import ConstructionTimer +from pyomo.common.log import is_debug_set from pyomo.common.plugin import Plugin, implements +from pyomo.common.timing import ConstructionTimer from pyomo.core.base.component import ComponentData from pyomo.core.base.indexed_component import IndexedComponent @@ -171,7 +172,7 @@ def _getitem_when_not_present(self, idx): def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug( "Constructing Connector, name=%s, from data=%s" % (self.name, data) ) if self._constructed: diff --git a/pyomo/core/base/constraint.py b/pyomo/core/base/constraint.py index 415c03a549d..f7d9e7d4ca5 100644 --- a/pyomo/core/base/constraint.py +++ b/pyomo/core/base/constraint.py @@ -18,6 +18,7 @@ from weakref import ref as weakref_ref import pyutilib.math +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.expr import logical_expr from pyomo.core.expr.numvalue import (ZeroConstant, @@ -797,7 +798,7 @@ def construct(self, data=None): self._constructed=True timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing constraint %s" % (self.name)) @@ -1076,9 +1077,7 @@ def construct(self, data=None): return self._constructed=True - generate_debug_messages = \ - __debug__ and logger.isEnabledFor(logging.DEBUG) - if generate_debug_messages: + if is_debug_set(logger): logger.debug("Constructing constraint list %s" % (self.name)) diff --git a/pyomo/core/base/expression.py b/pyomo/core/base/expression.py index e6c543e36b6..5b82d3bb0ad 100644 --- a/pyomo/core/base/expression.py +++ b/pyomo/core/base/expression.py @@ -14,6 +14,7 @@ import logging from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.common.deprecation import deprecated from pyomo.common.timing import ConstructionTimer @@ -360,7 +361,7 @@ def _getitem_when_not_present(self, index): def construct(self, data=None): """ Apply the rule to construct values in this set """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug( "Constructing Expression, name=%s, from data=%s" % (self.name, str(data))) diff --git a/pyomo/core/base/logical_constraint.py b/pyomo/core/base/logical_constraint.py index cf96a5c89b3..e708b9400b9 100644 --- a/pyomo/core/base/logical_constraint.py +++ b/pyomo/core/base/logical_constraint.py @@ -16,6 +16,7 @@ from weakref import ref as weakref_ref import pyutilib.math +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.constraint import Constraint from pyomo.core.expr import logical_expr @@ -280,7 +281,7 @@ def construct(self, data=None): """ Construct the expression(s) for this logical constraint. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing logical constraint %s" % self.name) if self._constructed: return @@ -537,8 +538,7 @@ def construct(self, data=None): """ Construct the expression(s) for this logical constraint. """ - generate_debug_messages = \ - __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("Constructing logical constraint list %s" % self.name) diff --git a/pyomo/core/base/matrix_constraint.py b/pyomo/core/base/matrix_constraint.py index 0159331aead..838b7e5e9d9 100644 --- a/pyomo/core/base/matrix_constraint.py +++ b/pyomo/core/base/matrix_constraint.py @@ -20,6 +20,7 @@ from pyomo.core.base.constraint import (IndexedConstraint, _ConstraintData) from pyomo.common.gc_manager import PauseGC +from pyomo.common.log import is_debug_set import six from six.moves import xrange @@ -353,7 +354,7 @@ def __init__(self, A_data, A_indices, A_indptr, lb, ub, x): def construct(self, data=None): """Construct the expression(s) for this constraint.""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing constraint %s" % (self.name)) if self._constructed: diff --git a/pyomo/core/base/objective.py b/pyomo/core/base/objective.py index c7cc21e40ed..86638de8f57 100644 --- a/pyomo/core/base/objective.py +++ b/pyomo/core/base/objective.py @@ -21,6 +21,7 @@ from weakref import ref as weakref_ref import inspect +from pyomo.common.log import is_debug_set from pyomo.common.deprecation import deprecated from pyomo.common.timing import ConstructionTimer from pyomo.core.expr.numvalue import value @@ -320,7 +321,7 @@ def construct(self, data=None): """ Construct the expression(s) for this objective. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug( "Constructing objective %s" % (self.name)) if self._constructed: @@ -624,8 +625,7 @@ def construct(self, data=None): """ Construct the expression(s) for this objective. """ - generate_debug_messages = \ - __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug( "Constructing objective %s" % (self.name)) diff --git a/pyomo/core/base/param.py b/pyomo/core/base/param.py index 177de9fbe94..527734dd894 100644 --- a/pyomo/core/base/param.py +++ b/pyomo/core/base/param.py @@ -16,6 +16,7 @@ from weakref import ref as weakref_ref from pyomo.common.deprecation import deprecation_warning +from pyomo.common.log import is_debug_set from pyomo.common.modeling import NoArgumentGiven from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory @@ -870,7 +871,7 @@ def construct(self, data=None): constructed. We throw an exception if a user tries to use an uninitialized Param. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Constructing Param, name=%s, from data=%s" % ( self.name, str(data) )) # diff --git a/pyomo/core/base/piecewise.py b/pyomo/core/base/piecewise.py index c9977a05dcc..d483de629a1 100644 --- a/pyomo/core/base/piecewise.py +++ b/pyomo/core/base/piecewise.py @@ -47,6 +47,7 @@ from pyutilib.misc import flatten_tuple +from pyomo.common.log import is_debug_set from pyomo.common.deprecation import deprecation_warning from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory @@ -1173,8 +1174,7 @@ def construct(self, *args, **kwds): """ A quick hack to call add after data has been loaded. """ - generate_debug_messages \ - = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if self._constructed: return diff --git a/pyomo/core/base/set.py b/pyomo/core/base/set.py index dd00789a628..1af02d8077d 100644 --- a/pyomo/core/base/set.py +++ b/pyomo/core/base/set.py @@ -21,6 +21,7 @@ from pyomo.common.deprecation import deprecated, deprecation_warning from pyomo.common.errors import DeveloperError, PyomoException +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.expr.numvalue import ( native_types, native_numeric_types, as_numeric, value, @@ -1977,7 +1978,7 @@ def construct(self, data=None): if self._constructed: return timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing Set, name=%s, from data=%r" % (self.name, data)) self._constructed = True @@ -2293,7 +2294,7 @@ def construct(self, data=None): if self._constructed: return timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing SetOf, name=%s, from data=%r" % (self.name, data)) self._constructed = True @@ -2706,7 +2707,7 @@ def construct(self, data=None): if self._constructed: return timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing RangeSet, name=%s, from data=%r" % (self.name, data)) if data is not None: @@ -2959,7 +2960,7 @@ def construct(self, data=None): if self._constructed: return timer = ConstructionTimer(self) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing SetOperator, name=%s, from data=%r" % (self.name, data)) for s in self._sets: diff --git a/pyomo/core/base/sos.py b/pyomo/core/base/sos.py index 5ac761f0506..1d1837dc60c 100644 --- a/pyomo/core/base/sos.py +++ b/pyomo/core/base/sos.py @@ -15,6 +15,7 @@ import six from six.moves import zip, xrange +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.misc import apply_indexed_rule from pyomo.core.base.plugin import ModelComponentFactory @@ -218,8 +219,7 @@ def construct(self, data=None): Construct this component """ assert data is None # because I don't know why it's an argument - generate_debug_messages \ - = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if self._constructed is True: #pragma:nocover return diff --git a/pyomo/core/base/suffix.py b/pyomo/core/base/suffix.py index 9c6d9134f2b..183fdb13893 100644 --- a/pyomo/core/base/suffix.py +++ b/pyomo/core/base/suffix.py @@ -15,6 +15,7 @@ import logging from pyomo.common.collections import ComponentMap +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.base.plugin import ModelComponentFactory from pyomo.core.base.component import ActiveComponent @@ -212,7 +213,7 @@ def construct(self, data=None): """ Constructs this component, applying rule if it exists. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing suffix %s", self.name) if self._constructed is True: diff --git a/pyomo/core/base/var.py b/pyomo/core/base/var.py index 29470d6ed4b..c8f1e638638 100644 --- a/pyomo/core/base/var.py +++ b/pyomo/core/base/var.py @@ -13,6 +13,7 @@ import logging from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.common.modeling import NoArgumentGiven from pyomo.common.timing import ConstructionTimer from pyomo.core.base.numvalue import NumericValue, value, is_fixed @@ -588,17 +589,16 @@ def get_units(self): def construct(self, data=None): """Construct this component.""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover try: name = str(self.name) except: # Some Var components don't have a name yet, so just use # the type name = type(self) - if logger.isEnabledFor(logging.DEBUG): - logger.debug( - "Constructing Variable, name=%s, from data=%s" - % (name, str(data))) + logger.debug( + "Constructing Variable, name=%s, from data=%s" + % (name, str(data))) if self._constructed: return @@ -990,7 +990,7 @@ def __init__(self, **kwds): def construct(self, data=None): """Construct this component.""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing variable list %s", self.name) if self._constructed: diff --git a/pyomo/core/beta/dict_objects.py b/pyomo/core/beta/dict_objects.py index 0fccba8e54a..a00c81f79e2 100644 --- a/pyomo/core/beta/dict_objects.py +++ b/pyomo/core/beta/dict_objects.py @@ -13,6 +13,7 @@ import logging from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.core.base.set_types import Any from pyomo.core.base.var import (IndexedVar, _VarData) @@ -54,7 +55,7 @@ def __init__(self, interface_datatype, *args): self.update(args[0]) def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug( #pragma:nocover "Constructing ComponentDict object, name=%s, from data=%s" % (self.name, str(data))) diff --git a/pyomo/core/beta/list_objects.py b/pyomo/core/beta/list_objects.py index 1d936f87b69..90ca3ac9158 100644 --- a/pyomo/core/beta/list_objects.py +++ b/pyomo/core/beta/list_objects.py @@ -13,6 +13,7 @@ import logging from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.core.base.set_types import Any from pyomo.core.base.var import (IndexedVar, _VarData) @@ -53,7 +54,7 @@ def __init__(self, interface_datatype, *args): self.append(item) def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug( #pragma:nocover "Constructing ComponentList object, name=%s, from data=%s" % (self.name, str(data))) diff --git a/pyomo/core/plugins/transform/expand_connectors.py b/pyomo/core/plugins/transform/expand_connectors.py index c606e59b90b..6894308a9ac 100644 --- a/pyomo/core/plugins/transform/expand_connectors.py +++ b/pyomo/core/plugins/transform/expand_connectors.py @@ -14,6 +14,7 @@ from six import next, iteritems, itervalues from pyomo.common.collections import ComponentMap, ComponentSet +from pyomo.common.log import is_debug_set from pyomo.core.expr import current as EXPR from pyomo.core.base import Transformation, TransformationFactory, Connector, Constraint, \ ConstraintList, Var, SortComponents @@ -25,7 +26,7 @@ class ExpandConnectors(Transformation): def _apply_to(self, instance, **kwds): - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Calling ConnectorExpander") connectorsFound = False @@ -35,7 +36,7 @@ def _apply_to(self, instance, **kwds): if not connectorsFound: return - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug(" Connectors found!") self._name_buffer = {} diff --git a/pyomo/dataportal/DataPortal.py b/pyomo/dataportal/DataPortal.py index a3dd7641045..24306720529 100644 --- a/pyomo/dataportal/DataPortal.py +++ b/pyomo/dataportal/DataPortal.py @@ -11,6 +11,7 @@ __all__ = ['DataPortal'] import logging +from pyomo.common.log import is_debug_set from pyomo.dataportal.factory import DataManagerFactory, UnknownDataManager logger = logging.getLogger('pyomo.core') @@ -124,7 +125,7 @@ def load(self, **kwds): Other keyword arguments are passed to the :func:`connect()` method. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Loading data...") # # Process arguments @@ -158,7 +159,7 @@ def load(self, **kwds): # # Read from data manager into self._data and self._default # - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Processing data ...") self._data_manager.read() status = self._data_manager.process(self._model, self._data, self._default) @@ -168,7 +169,7 @@ def load(self, **kwds): # if _disconnect: self.disconnect() - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Done.") def store(self, **kwds): @@ -181,7 +182,7 @@ def store(self, **kwds): Other keyword arguments are passed to the :func:`connect()` method. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Storing data...") # # Process arguments @@ -217,7 +218,7 @@ def store(self, **kwds): # if _disconnect: self.disconnect() - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug("Done.") def data(self, name=None, namespace=None): diff --git a/pyomo/dataportal/process_data.py b/pyomo/dataportal/process_data.py index 6fa51490b55..78679e21910 100644 --- a/pyomo/dataportal/process_data.py +++ b/pyomo/dataportal/process_data.py @@ -13,6 +13,7 @@ import copy import logging +from pyomo.common.log import is_debug_set from pyomo.common.collections import Options, OrderedDict from pyomo.common.errors import ApplicationError from pyutilib.misc import flatten @@ -108,7 +109,7 @@ def _preprocess_data(cmd): Called by _process_data() to (1) combine tokens that comprise a tuple and (2) combine the ':' token with the previous token """ - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("_preprocess_data(start) %s",cmd) state = 0 @@ -196,7 +197,7 @@ def _process_set(cmd, _model, _data): Called by _process_data() to process a set declaration. """ #print("SET %s" % cmd) - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("DEBUG: _process_set(start) %s",cmd) # @@ -247,7 +248,7 @@ def _process_set_data(cmd, sname, _model): """ Called by _process_set() to process set data. """ - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("DEBUG: _process_set_data(start) %s",cmd) if len(cmd) == 0: @@ -294,7 +295,7 @@ def _process_param(cmd, _model, _data, _default, index=None, param=None, ncolumn Called by _process_data to process data for a Parameter declaration """ #print('PARAM %s index=%s ncolumns=%s' %(cmd, index, ncolumns)) - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("DEBUG: _process_param(start) %s",cmd) # @@ -563,7 +564,7 @@ def _process_data_list(param_name, dim, cmd): """\ Called by _process_param() to process a list of data for a Parameter. """ - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("process_data_list %d %s",dim,cmd) @@ -933,7 +934,7 @@ def _process_data(cmd, _model, _data, _default, Filename_, Lineno_=0, index=None global Filename Lineno=Lineno_ Filename=Filename_ - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) + generate_debug_messages = is_debug_set(logger) if generate_debug_messages: logger.debug("DEBUG: _process_data (start) %s",cmd) if len(cmd) == 0: #pragma:nocover diff --git a/pyomo/gdp/disjunct.py b/pyomo/gdp/disjunct.py index 8d8f884826b..bad49e8721b 100644 --- a/pyomo/gdp/disjunct.py +++ b/pyomo/gdp/disjunct.py @@ -16,6 +16,7 @@ from weakref import ref as weakref_ref from pyomo.common.errors import PyomoException +from pyomo.common.log import is_debug_set from pyomo.common.modeling import unique_component_name from pyomo.common.timing import ConstructionTimer from pyomo.core import ( @@ -357,7 +358,7 @@ def _initialize_members(self, init_set): self._data[key].xor = bool(value(val[key])) def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing disjunction %s" % (self.name)) if self._constructed: diff --git a/pyomo/gdp/plugins/bigm.py b/pyomo/gdp/plugins/bigm.py index 165fb8930f1..4e2c4d5e68a 100644 --- a/pyomo/gdp/plugins/bigm.py +++ b/pyomo/gdp/plugins/bigm.py @@ -14,6 +14,7 @@ from pyomo.common.collections import ComponentMap, ComponentSet from pyomo.common.config import ConfigBlock, ConfigValue +from pyomo.common.log import is_debug_set from pyomo.common.modeling import unique_component_name from pyomo.common.deprecation import deprecated, deprecation_warning from pyomo.contrib.fbbt.fbbt import compute_bounds_on_expr @@ -162,6 +163,7 @@ def __init__(self): LogicalConstraint: self._warn_for_active_logical_statement, ExternalFunction: False, } + self._generate_debug_messages = False def _get_bigm_suffix_list(self, block, stopping_block=None): # Note that you can only specify suffixes on BlockData objects or @@ -196,6 +198,7 @@ def _get_bigm_arg_list(self, bigm_args, block): def _apply_to(self, instance, **kwds): assert not NAME_BUFFER + self._generate_debug_messages = is_debug_set(logger) self.used_args = ComponentMap() # If everything was sure to go well, # this could be a dictionary. But if # someone messes up and gives us a Var @@ -636,7 +639,7 @@ def _transform_constraint(self, obj, disjunct, bigMargs, arg_list, upper) M = (lower[0], upper[0]) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: _name = obj.getname( fully_qualified=True, name_buffer=NAME_BUFFER) logger.debug("GDP(BigM): The value for M for constraint '%s' " @@ -655,7 +658,7 @@ def _transform_constraint(self, obj, disjunct, bigMargs, arg_list, lower, upper) M = (lower[0], upper[0]) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: _name = obj.getname( fully_qualified=True, name_buffer=NAME_BUFFER) logger.debug("GDP(BigM): The value for M for constraint '%s' " @@ -669,7 +672,7 @@ def _transform_constraint(self, obj, disjunct, bigMargs, arg_list, M = (M[0], self._estimate_M(c.body, name)[1] - c.upper) upper = (M[1], None, None) - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: _name = obj.getname( fully_qualified=True, name_buffer=NAME_BUFFER) logger.debug("GDP(BigM): The value for M for constraint '%s' " diff --git a/pyomo/gdp/plugins/cuttingplane.py b/pyomo/gdp/plugins/cuttingplane.py index a0d18f7ca82..0b1045daa4f 100644 --- a/pyomo/gdp/plugins/cuttingplane.py +++ b/pyomo/gdp/plugins/cuttingplane.py @@ -689,6 +689,7 @@ def __init__(self): super(CuttingPlane_Transformation, self).__init__() def _apply_to(self, instance, bigM=None, **kwds): + original_log_level = logger.level log_level = logger.getEffectiveLevel() try: assert not NAME_BUFFER @@ -721,7 +722,7 @@ def _apply_to(self, instance, bigM=None, **kwds): # clear the global name buffer NAME_BUFFER.clear() # restore logging level - logger.setLevel(log_level) + logger.setLevel(original_log_level) def _setup_subproblems(self, instance, bigM, tighten_relaxation_callback): # create transformation block diff --git a/pyomo/gdp/plugins/hull.py b/pyomo/gdp/plugins/hull.py index 2d5a461ed0f..9557c5cd94a 100644 --- a/pyomo/gdp/plugins/hull.py +++ b/pyomo/gdp/plugins/hull.py @@ -13,6 +13,7 @@ import pyomo.common.config as cfg from pyomo.common import deprecated from pyomo.common.collections import ComponentMap, ComponentSet +from pyomo.common.log import is_debug_set from pyomo.common.modeling import unique_component_name from pyomo.core.expr.numvalue import ZeroConstant from pyomo.core.base.component import ActiveComponent @@ -192,6 +193,7 @@ def __init__(self): Block: self._transform_block_on_disjunct, LogicalConstraint: self._warn_for_active_logical_statement, } + self._generate_debug_messages = False def _add_local_vars(self, block, local_var_dict): localVars = block.component('LocalVars') @@ -232,6 +234,7 @@ def _apply_to(self, instance, **kwds): def _apply_to_impl(self, instance, **kwds): self._config = self.CONFIG(kwds.pop('options', {})) self._config.set_value(kwds) + self._generate_debug_messages = is_debug_set(logger) targets = self._config.targets if targets is None: @@ -432,7 +435,7 @@ def _transform_disjunctionData(self, obj, index, transBlock=None): disjuncts = [d for d in varsByDisjunct if var in varsByDisjunct[d]] # clearly not local if used in more than one disjunct if len(disjuncts) > 1: - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: logger.debug("Assuming '%s' is not a local var since it is" "used in multiple disjuncts." % var.getname(fully_qualified=True, @@ -879,7 +882,7 @@ def _transform_constraint(self, obj, disjunct, var_substitute_map, continue if c.lower is not None: - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: _name = c.getname( fully_qualified=True, name_buffer=NAME_BUFFER) logger.debug("GDP(Hull): Transforming constraint " + @@ -901,7 +904,7 @@ def _transform_constraint(self, obj, disjunct, var_substitute_map, constraintMap['srcConstraints'][newConstraint['lb']] = c if c.upper is not None: - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if self._generate_debug_messages: _name = c.getname( fully_qualified=True, name_buffer=NAME_BUFFER) logger.debug("GDP(Hull): Transforming constraint " + diff --git a/pyomo/mpec/complementarity.py b/pyomo/mpec/complementarity.py index d3bebb33f16..1a4eeadf294 100644 --- a/pyomo/mpec/complementarity.py +++ b/pyomo/mpec/complementarity.py @@ -11,6 +11,7 @@ from six import iteritems from collections import namedtuple +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from pyomo.core.expr import current as EXPR from pyomo.core.expr.numvalue import ZeroConstant, native_numeric_types, as_numeric @@ -321,8 +322,7 @@ def construct(self, data=None): """ Construct the expression(s) for this complementarity condition. """ - generate_debug_messages = __debug__ and logger.isEnabledFor(logging.DEBUG) - if generate_debug_messages: + if is_debug_set(logger): logger.debug("Constructing complementarity list %s", self.name) if self._constructed: return diff --git a/pyomo/network/arc.py b/pyomo/network/arc.py index d30e06bf801..7453967f7c0 100644 --- a/pyomo/network/arc.py +++ b/pyomo/network/arc.py @@ -16,6 +16,7 @@ UnindexedComponent_set) from pyomo.core.base.misc import apply_indexed_rule from pyomo.core.base.plugin import ModelComponentFactory +from pyomo.common.log import is_debug_set from pyomo.common.timing import ConstructionTimer from six import iteritems from weakref import ref as weakref_ref @@ -290,7 +291,7 @@ def __init__(self, *args, **kwds): def construct(self, data=None): """Initialize the Arc""" - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing Arc %s" % self.name) if self._constructed: diff --git a/pyomo/network/decomposition.py b/pyomo/network/decomposition.py index f1077056c57..d9e0701b163 100644 --- a/pyomo/network/decomposition.py +++ b/pyomo/network/decomposition.py @@ -281,11 +281,22 @@ def run(self, model, function): old_log_level = logger.level logger.setLevel(logging.INFO) + self.cache.clear() + + try: + return self._run_impl(model, function) + finally: + # Cleanup + self.cache.clear() + + if self.options["log_info"]: + logger.setLevel(old_log_level) + + + def _run_impl(self, model, function): start = time.time() logger.info("Starting Sequential Decomposition") - self.cache.clear() - G = self.options["graph"] if G is None: G = self.create_graph(model) @@ -338,15 +349,10 @@ def run(self, model, function): raise ValueError( "Invalid tear_method '%s'" % (tear_method,)) - self.cache.clear() - end = time.time() logger.info("Finished Sequential Decomposition in %.2f seconds" % (end - start)) - if self.options["log_info"]: - logger.setLevel(old_log_level) - def run_order(self, G, order, function, ignore=None, use_guesses=False): """ Run computations in the order provided by calling the function diff --git a/pyomo/network/plugins/expand_arcs.py b/pyomo/network/plugins/expand_arcs.py index 4044afca11a..0eba9525011 100644 --- a/pyomo/network/plugins/expand_arcs.py +++ b/pyomo/network/plugins/expand_arcs.py @@ -13,6 +13,7 @@ from six import iteritems, itervalues +from pyomo.common.log import is_debug_set from pyomo.common.modeling import unique_component_name from pyomo.common.collections import ComponentMap, ComponentSet @@ -31,7 +32,7 @@ class ExpandArcs(Transformation): def _apply_to(self, instance, **kwds): - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Calling ArcExpander") # need to collect all ports to see every port each diff --git a/pyomo/network/port.py b/pyomo/network/port.py index 8af09cb7291..58e32fdc187 100644 --- a/pyomo/network/port.py +++ b/pyomo/network/port.py @@ -15,8 +15,9 @@ from weakref import ref as weakref_ref from pyomo.common.collections import ComponentMap -from pyomo.common.timing import ConstructionTimer +from pyomo.common.log import is_debug_set from pyomo.common.modeling import unique_component_name +from pyomo.common.timing import ConstructionTimer from pyomo.core.base.var import Var from pyomo.core.base.constraint import Constraint @@ -336,7 +337,7 @@ def _getitem_when_not_present(self, idx): return tmp def construct(self, data=None): - if __debug__ and logger.isEnabledFor(logging.DEBUG): #pragma:nocover + if is_debug_set(logger): #pragma:nocover logger.debug( "Constructing Port, name=%s, from data=%s" % (self.name, data) ) diff --git a/pyomo/opt/solver/shellcmd.py b/pyomo/opt/solver/shellcmd.py index e7af79dd139..9c126719a42 100644 --- a/pyomo/opt/solver/shellcmd.py +++ b/pyomo/opt/solver/shellcmd.py @@ -17,6 +17,7 @@ from pyomo.common.errors import ApplicationError from pyomo.common.collections import Bunch +from pyomo.common.log import is_debug_set from pyomo.common.tempfiles import TempfileManager from pyutilib.subprocess import run @@ -226,7 +227,7 @@ def _apply_solver(self): # # Execute the command # - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Running %s", self._command.cmd) # display the log/solver file names prior to execution. this is useful diff --git a/pyomo/pysp/util/misc.py b/pyomo/pysp/util/misc.py index 1a8b8e37f60..73140ff0ccd 100644 --- a/pyomo/pysp/util/misc.py +++ b/pyomo/pysp/util/misc.py @@ -307,7 +307,6 @@ def launch_command(command, import profile import pstats except ImportError: - configure_loggers(shutdown=True) raise ValueError( "Cannot use the 'profile' option: the Python " "'profile' or 'pstats' package cannot be imported!") diff --git a/pyomo/repn/beta/matrix.py b/pyomo/repn/beta/matrix.py index 2d0e3daeb82..f17dbeb7ecb 100644 --- a/pyomo/repn/beta/matrix.py +++ b/pyomo/repn/beta/matrix.py @@ -16,6 +16,7 @@ import array from weakref import ref as weakref_ref +from pyomo.common.log import is_debug_set from pyomo.core.base.set_types import Any from pyomo.core.base import (SortComponents, Var) @@ -669,7 +670,7 @@ def construct(self, data=None): """ Construct the expression(s) for this constraint. """ - if __debug__ and logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): logger.debug("Constructing constraint %s" % (self.name)) if self._constructed: diff --git a/pyomo/scripting/plugins/build_ext.py b/pyomo/scripting/plugins/build_ext.py index bab611d0301..9facb6672a0 100644 --- a/pyomo/scripting/plugins/build_ext.py +++ b/pyomo/scripting/plugins/build_ext.py @@ -20,7 +20,14 @@ def create_parser(self, parser): def call(self, args, unparsed): logger = logging.getLogger('pyomo.common') + original_level = logger.level logger.setLevel(logging.INFO) + try: + return self._call_impl(args, unparsed, logger) + finally: + logger.setLevel(original_level) + + def _call_impl(self, args, unparsed, logger): results = [] result_fmt = "[%s] %s" returncode = 0 diff --git a/pyomo/scripting/plugins/download.py b/pyomo/scripting/plugins/download.py index e271c2fa847..84ed83645de 100644 --- a/pyomo/scripting/plugins/download.py +++ b/pyomo/scripting/plugins/download.py @@ -22,7 +22,14 @@ def create_parser(self, parser): def call(self, args, unparsed): logger = logging.getLogger('pyomo.common') + original_level = logger.level logger.setLevel(logging.INFO) + try: + return self._call_impl(args, unparsed, logger) + finally: + logger.setLevel(original_level) + + def _call_impl(self, args, unparsed, logger): results = [] result_fmt = "[%s] %s" returncode = 0 diff --git a/pyomo/scripting/util.py b/pyomo/scripting/util.py index 56e22e82387..72e67be5a76 100644 --- a/pyomo/scripting/util.py +++ b/pyomo/scripting/util.py @@ -19,6 +19,8 @@ import json from six import iteritems from pyomo.common import pyomo_api +from pyomo.common.deprecation import deprecated +from pyomo.common.log import is_debug_set from pyomo.common.tempfiles import TempfileManager from pyutilib.misc import import_file, setup_redirect, reset_redirect @@ -132,7 +134,7 @@ def pyomo_excepthook(etype,value,tb): tb_list = traceback.extract_tb(tb,None) i = 0 - if not logger.isEnabledFor(logging.DEBUG) and filter_excepthook: + if not is_debug_set(logger) and filter_excepthook: while i < len(tb_list): if data.options.model.filename in tb_list[i][0]: break @@ -414,7 +416,7 @@ def create_model(data): total_time = time.time() - modify_start_time print(" %6.2f seconds required for problem transformations" % total_time) - if logger.isEnabledFor(logging.DEBUG): + if is_debug_set(logger): print("MODEL INSTANCE") instance.pprint() print("") @@ -805,51 +807,87 @@ def finalize(data, model=None, instance=None, results=None): print('\n# Leaving Interpreter, back to Pyomo\n') +@deprecated("configure_loggers is deprecated. The Pyomo command uses the " + "PyomoCommandLogContext to update the logger configuration", + version='TBD') def configure_loggers(options=None, shutdown=False): + context = PyomoCommandLogContext(options) if shutdown: - options = Options() - options.runtime = Options() - options.runtime.logging = 'quiet' - if configure_loggers.fileLogger is not None: - logging.getLogger('pyomo').handlers = [] - logging.getLogger('pyutilib').handlers = [] - configure_loggers.fileLogger.close() - configure_loggers.fileLogger = None + # historically, configure_loggers(shutdown=True) forced 'quiet' + context.options.runtime.logging = 'quiet' + context.fileLogger = configure_loggers.fileLogger + context.__exit__(None,None,None) + else: + context.__enter__() + configure_loggers.fileLogger = context.fileLogger + +configure_loggers.fileLogger = None + + +class PyomoCommandLogContext(object): + """Context manager to setup/restore logging for the Pyomo command""" + + def __init__(self, options): + if options is None: + options = Options() + if options.runtime is None: + options.runtime = Options() + self.options = options + self.fileLogger = None + self.original = None + + def __enter__(self): + _pyomo = logging.getLogger('pyomo') + _pyutilib = logging.getLogger('pyutilib') + self.original = ( _pyomo.level, _pyomo.handlers, + _pyutilib.level, _pyutilib.handlers ) + + # + # Configure the logger + # + if self.options.runtime.logging == 'quiet': + _pyomo.setLevel(logging.ERROR) + elif self.options.runtime.logging == 'warning': + _pyomo.setLevel(logging.WARNING) + elif self.options.runtime.logging == 'info': + _pyomo.setLevel(logging.INFO) + _pyutilib.setLevel(logging.INFO) + elif self.options.runtime.logging == 'verbose': + _pyomo.setLevel(logging.DEBUG) + _pyutilib.setLevel(logging.DEBUG) + elif self.options.runtime.logging == 'debug': + _pyomo.setLevel(logging.DEBUG) + _pyutilib.setLevel(logging.DEBUG) + elif _pyomo.getEffectiveLevel() == logging.NOTSET: + _pyomo.setLevel(logging.WARNING) + + if self.options.runtime.logfile: + _logfile = self.options.runtime.logfile + self.fileLogger = logging.FileHandler(_logfile, 'w') + _pyomo.handlers = [] + _pyutilib.handlers = [] + _pyomo.addHandler(self.fileLogger) + _pyutilib.addHandler(self.fileLogger) # TBD: This seems dangerous in Windows, as the process will - # have multiple open file handles pointint to the same file. - reset_redirect() + # have multiple open file handles pointing to the same file. + setup_redirect(_logfile) - # - # Configure the logger - # - if options.runtime is None: - options.runtime = Options() - if options.runtime.logging == 'quiet': - logging.getLogger('pyomo').setLevel(logging.ERROR) - elif options.runtime.logging == 'warning': - logging.getLogger('pyomo').setLevel(logging.WARNING) - elif options.runtime.logging == 'info': - logging.getLogger('pyomo').setLevel(logging.INFO) - logging.getLogger('pyutilib').setLevel(logging.INFO) - elif options.runtime.logging == 'verbose': - logging.getLogger('pyomo').setLevel(logging.DEBUG) - logging.getLogger('pyutilib').setLevel(logging.DEBUG) - elif options.runtime.logging == 'debug': - logging.getLogger('pyomo').setLevel(logging.DEBUG) - logging.getLogger('pyutilib').setLevel(logging.DEBUG) - - if options.runtime.logfile: - configure_loggers.fileLogger \ - = logging.FileHandler(options.runtime.logfile, 'w') - logging.getLogger('pyomo').handlers = [] - logging.getLogger('pyutilib').handlers = [] - logging.getLogger('pyomo').addHandler(configure_loggers.fileLogger) - logging.getLogger('pyutilib').addHandler(configure_loggers.fileLogger) - # TBD: This seems dangerous in Windows, as the process will - # have multiple open file handles pointint to the same file. - setup_redirect(options.runtime.logfile) + return self + + def __exit__(self, et, ev, tb): + _pyomo = logging.getLogger('pyomo') + _pyomo.setLevel(self.original[0]) + _pyomo.handlers = self.original[1] + _pyutilib = logging.getLogger('pyutilib') + _pyutilib.setLevel(self.original[2]) + _pyutilib.handlers = self.original[3] + + if self.fileLogger is not None: + self.fileLogger.close() + # TBD: This seems dangerous in Windows, as the process will + # have multiple open file handles pointing to the same file. + reset_redirect() -configure_loggers.fileLogger = None @pyomo_api(namespace='pyomo.script') def run_command(command=None, parser=None, args=None, name='unknown', data=None, options=None): @@ -883,15 +921,14 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, # Parse command-line options # # - retval = None - errorcode = 0 if options is None: try: if type(args) is argparse.Namespace: _options = args else: _options = parser.parse_args(args=args) - # Replace the parser options object with a pyutilib.misc.Options object + # Replace the parser options object with a + # pyutilib.misc.Options object options = Options() for key in dir(_options): if key[0] != '_': @@ -901,15 +938,29 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, except SystemExit: # the parser throws a system exit if "-h" is specified - catch # it to exit gracefully. - return Container(retval=retval, errorcode=errorcode) + return Container(retval=None, errorcode=0) # # Configure loggers # - configure_loggers(options=options) + TempfileManager.push() + try: + with PyomoCommandLogContext(options): + retval, errorcode = _run_command_impl( + command, parser, args, name, data, options) + finally: + if options.runtime.disable_gc: + gc.enable() + TempfileManager.pop(remove=not options.runtime.keep_files) + + return Container(retval=retval, errorcode=errorcode) + + +def _run_command_impl(command, parser, args, name, data, options): # # Call the main Pyomo runner with profiling # - TempfileManager.push() + retval = None + errorcode = 0 pcount = options.runtime.profile_count if pcount > 0: # Defer import of profiling packages until we know that they @@ -921,13 +972,13 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, import profile import pstats except ImportError: - configure_loggers(shutdown=True) raise ValueError( "Cannot use the 'profile' option: the Python " "'profile' or 'pstats' package cannot be imported!") tfile = TempfileManager.create_tempfile(suffix=".profile") tmp = profile.runctx( - command.__name__ + '(options=options,parser=parser)', command.__globals__, locals(), tfile + command.__name__ + '(options=options,parser=parser)', + command.__globals__, locals(), tfile ) p = pstats.Stats(tfile).strip_dirs() p.sort_stats('time', 'cumulative') @@ -947,7 +998,6 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, # # Call the main Pyomo runner without profiling # - TempfileManager.push() try: retval = command(options=options, parser=parser) except SystemExit: @@ -957,7 +1007,6 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, # exit. Otherwise, print an "Exiting..." message. # if __debug__ and (options.runtime.logging == 'debug' or options.runtime.catch_errors): - configure_loggers(shutdown=True) sys.exit(0) print('Exiting %s: %s' % (name, str(err))) errorcode = err.code @@ -968,8 +1017,6 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, # pass the exception up the chain (to pyomo_excepthook) # if __debug__ and (options.runtime.logging == 'debug' or options.runtime.catch_errors): - configure_loggers(shutdown=True) - TempfileManager.pop(remove=not options.runtime.keep_files) raise if not options.model is None and not options.model.save_file is None: @@ -997,12 +1044,8 @@ def run_command(command=None, parser=None, args=None, name='unknown', data=None, logger.error(msg+errStr) errorcode = 1 - configure_loggers(shutdown=True) + return retval, errorcode - if options.runtime.disable_gc: - gc.enable() - TempfileManager.pop(remove=not options.runtime.keep_files) - return Container(retval=retval, errorcode=errorcode) def cleanup(): for key in modelapi: