Skip to content

Commit

Permalink
protect calls to juju-log from messages starting with dashes (#451)
Browse files Browse the repository at this point in the history
  • Loading branch information
@chipaca
chipaca authored Nov 20, 2020
1 parent 5dd04e8 commit 2393f59
Show file tree
Hide file tree
Showing 4 changed files with 61 additions and 56 deletions.
2 changes: 1 addition & 1 deletion ops/model.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1230,7 +1230,7 @@ def application_version_set(self, version):
self._run('application-version-set', '--', version)

def juju_log(self, level, message):
self._run('juju-log', '--log-level', level, message)
self._run('juju-log', '--log-level', level, "--", message)

def network_get(self, binding_name, relation_id=None):
"""Return network info provided by network-get for a given binding.
Expand Down
29 changes: 13 additions & 16 deletions test/test_log.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -52,22 +52,19 @@ def test_default_logging(self):
self.assertEqual(logger.level, logging.DEBUG)
self.assertIsInstance(logger.handlers[-1], ops.log.JujuLogHandler)

test_cases = [(
lambda: logger.critical('critical'), [('CRITICAL', 'critical')]
), (
lambda: logger.error('error'), [('ERROR', 'error')]
), (
lambda: logger.warning('warning'), [('WARNING', 'warning')]
), (
lambda: logger.info('info'), [('INFO', 'info')]
), (
lambda: logger.debug('debug'), [('DEBUG', 'debug')]
)]

for do, res in test_cases:
do()
calls = self.backend.calls(clear=True)
self.assertEqual(calls, res)
test_cases = [
(logger.critical, 'critical', ('CRITICAL', 'critical')),
(logger.error, 'error', ('ERROR', 'error')),
(logger.warning, 'warning', ('WARNING', 'warning')),
(logger.info, 'info', ('INFO', 'info')),
(logger.debug, 'debug', ('DEBUG', 'debug')),
]

for method, message, result in test_cases:
with self.subTest(message):
method(message)
calls = self.backend.calls(clear=True)
self.assertEqual(calls, [result])

def test_handler_filtering(self):
logger = logging.getLogger()
Expand Down
82 changes: 45 additions & 37 deletions test/test_main.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,9 +63,14 @@
TEST_CHARM_DIR = Path(__file__ + '/../charms/test_main').resolve()

VERSION_LOGLINE = [
'juju-log', '--log-level', 'DEBUG',
'juju-log', '--log-level', 'DEBUG', '--',
'Operator Framework {} up and running.'.format(version),
]
SLOW_YAML_LOGLINE = [
'juju-log', '--log-level', 'DEBUG', '--',
'yaml does not have libyaml extensions, using slower pure Python yaml loader',
]

logger = logging.getLogger(__name__)


Expand Down Expand Up @@ -561,20 +566,18 @@ def test_collect_metrics(self):

expected = [
VERSION_LOGLINE,
['juju-log', '--log-level', 'DEBUG',
['juju-log', '--log-level', 'DEBUG', '--',
'Using local storage: {} already exists'.format(self.CHARM_STATE_FILE)],
['juju-log', '--log-level', 'DEBUG', 'Emitting Juju event collect_metrics.'],
['juju-log', '--log-level', 'DEBUG', '--', 'Emitting Juju event collect_metrics.'],
['add-metric', '--labels', 'bar=4.2', 'foo=42'],
]
if not yaml.__with_libyaml__:
expected.insert(1, ['juju-log', '--log-level', 'DEBUG',
'yaml does not have libyaml extensions, '
'using slower pure Python yaml loader'])
expected.insert(1, SLOW_YAML_LOGLINE)
calls = fake_script_calls(self)

if self.has_dispatch:
expected.insert(1, [
'juju-log', '--log-level', 'DEBUG',
'juju-log', '--log-level', 'DEBUG', '--',
'Legacy {} does not exist.'.format(Path('hooks/collect-metrics'))])

self.assertEqual(calls, expected)
Expand All @@ -584,19 +587,19 @@ def test_logger(self):

test_cases = [(
EventSpec(ActionEvent, 'log_critical_action', env_var='JUJU_ACTION_NAME'),
['juju-log', '--log-level', 'CRITICAL', 'super critical'],
['juju-log', '--log-level', 'CRITICAL', '--', 'super critical'],
), (
EventSpec(ActionEvent, 'log_error_action',
env_var='JUJU_ACTION_NAME'),
['juju-log', '--log-level', 'ERROR', 'grave error'],
['juju-log', '--log-level', 'ERROR', '--', 'grave error'],
), (
EventSpec(ActionEvent, 'log_warning_action',
env_var='JUJU_ACTION_NAME'),
['juju-log', '--log-level', 'WARNING', 'wise warning'],
['juju-log', '--log-level', 'WARNING', '--', 'wise warning'],
), (
EventSpec(ActionEvent, 'log_info_action',
env_var='JUJU_ACTION_NAME'),
['juju-log', '--log-level', 'INFO', 'useful info'],
['juju-log', '--log-level', 'INFO', '--', 'useful info'],
)]

# Set up action symlinks.
Expand All @@ -619,18 +622,18 @@ def test_excepthook(self):
if self.has_dispatch:
self.assertEqual(
calls.pop(0),
'juju-log --log-level DEBUG Legacy {} does not exist.'.format(
'juju-log --log-level DEBUG -- Legacy {} does not exist.'.format(
Path("hooks/install")))

if not yaml.__with_libyaml__:
self.assertRegex(calls.pop(0), 'yaml does not have libyaml extensions')
self.assertEquals(calls.pop(0), ' '.join(SLOW_YAML_LOGLINE))

self.assertRegex(calls.pop(0), 'Using local storage: not a kubernetes charm')

self.maxDiff = None
self.assertRegex(
calls[0],
'(?ms)juju-log --log-level ERROR Uncaught exception while in charm code:\n'
'(?ms)juju-log --log-level ERROR -- Uncaught exception while in charm code:\n'
'Traceback .most recent call last.:\n'
' .*'
' raise RuntimeError."failing as requested".\n'
Expand Down Expand Up @@ -794,15 +797,17 @@ def test_hook_and_dispatch(self):
hook = Path('hooks/install')
expected = [
VERSION_LOGLINE,
['juju-log', '--log-level', 'INFO', 'Running legacy {}.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', 'Legacy {} exited with status 0.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', 'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', 'Emitting Juju event install.'],
['juju-log', '--log-level', 'INFO', '--',
'Running legacy {}.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', '--',
'Legacy {} exited with status 0.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', '--',
'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', '--',
'Emitting Juju event install.'],
]
if not yaml.__with_libyaml__:
expected.insert(3, ['juju-log', '--log-level', 'DEBUG',
'yaml does not have libyaml extensions, '
'using slower pure Python yaml loader'])
expected.insert(3, SLOW_YAML_LOGLINE)
self.assertEqual(fake_script_calls(self), expected)

@unittest.skipIf(is_windows, "this is UNIXish; TODO: write equivalent windows test")
Expand All @@ -814,15 +819,15 @@ def test_non_executable_hook_and_dispatch(self):

expected = [
VERSION_LOGLINE,
['juju-log', '--log-level', 'WARNING',
['juju-log', '--log-level', 'WARNING', '--',
'Legacy hooks/install exists but is not executable.'],
['juju-log', '--log-level', 'DEBUG', 'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', 'Emitting Juju event install.'],
['juju-log', '--log-level', 'DEBUG', '--',
'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', '--',
'Emitting Juju event install.'],
]
if not yaml.__with_libyaml__:
expected.insert(2, ['juju-log', '--log-level', 'DEBUG',
'yaml does not have libyaml extensions, '
'using slower pure Python yaml loader'])
expected.insert(2, SLOW_YAML_LOGLINE)
self.assertEqual(fake_script_calls(self), expected)

def test_hook_and_dispatch_with_failing_hook(self):
Expand All @@ -843,8 +848,8 @@ def test_hook_and_dispatch_with_failing_hook(self):
hook = Path('hooks/install')
expected = [
VERSION_LOGLINE,
['juju-log', '--log-level', 'INFO', 'Running legacy {}.'.format(hook)],
['juju-log', '--log-level', 'WARNING',
['juju-log', '--log-level', 'INFO', '--', 'Running legacy {}.'.format(hook)],
['juju-log', '--log-level', 'WARNING', '--',
'Legacy {} exited with status 42.'.format(hook)],
]
self.assertEqual(calls, expected)
Expand Down Expand Up @@ -896,17 +901,20 @@ def test_hook_and_dispatch_but_hook_is_dispatch_copy(self):
hook = Path('hooks/install')
expected = [
VERSION_LOGLINE,
['juju-log', '--log-level', 'INFO', 'Running legacy {}.'.format(hook)],
['juju-log', '--log-level', 'INFO', '--',
'Running legacy {}.'.format(hook)],
VERSION_LOGLINE, # because it called itself
['juju-log', '--log-level', 'DEBUG', 'Charm called itself via {}.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', 'Legacy {} exited with status 0.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', 'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', 'Emitting Juju event install.'],
['juju-log', '--log-level', 'DEBUG', '--',
'Charm called itself via {}.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', '--',
'Legacy {} exited with status 0.'.format(hook)],
['juju-log', '--log-level', 'DEBUG', '--',
'Using local storage: not a kubernetes charm'],
['juju-log', '--log-level', 'DEBUG', '--',
'Emitting Juju event install.'],
]
if not yaml.__with_libyaml__:
expected.insert(5, ['juju-log', '--log-level', 'DEBUG',
'yaml does not have libyaml extensions, '
'using slower pure Python yaml loader'])
expected.insert(5, SLOW_YAML_LOGLINE)
self.assertEqual(fake_script_calls(self), expected)


Expand Down
4 changes: 2 additions & 2 deletions test/test_model.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1337,7 +1337,7 @@ def test_juju_log(self):
fake_script(self, 'juju-log', 'exit 0')
self.backend.juju_log('WARNING', 'foo')
self.assertEqual(fake_script_calls(self, clear=True),
[['juju-log', '--log-level', 'WARNING', 'foo']])
[['juju-log', '--log-level', 'WARNING', '--', 'foo']])

with self.assertRaises(TypeError):
self.backend.juju_log('DEBUG')
Expand All @@ -1347,7 +1347,7 @@ def test_juju_log(self):
with self.assertRaises(ops.model.ModelError):
self.backend.juju_log('BAR', 'foo')
self.assertEqual(fake_script_calls(self, clear=True),
[['juju-log', '--log-level', 'BAR', 'foo']])
[['juju-log', '--log-level', 'BAR', '--', 'foo']])

def test_valid_metrics(self):
fake_script(self, 'add-metric', 'exit 0')
Expand Down

0 comments on commit 2393f59

Please sign in to comment.