File: test_loggingutil.py

package info (click to toggle)
cylc-flow 8.6.1-1
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid
  • size: 14,368 kB
  • sloc: python: 87,751; sh: 17,109; sql: 233; xml: 171; javascript: 78; lisp: 55; makefile: 11
file content (279 lines) | stat: -rw-r--r-- 9,423 bytes parent folder | download
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
# THIS FILE IS PART OF THE CYLC WORKFLOW ENGINE.
# Copyright (C) NIWA & British Crown (Met Office) & Contributors.
#
# This program is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program.  If not, see <http://www.gnu.org/licenses/>.

import logging
import re
import sys
from io import TextIOWrapper
from pathlib import Path
from time import sleep
from typing import Callable, cast
from unittest import mock

import pytest
from pytest import param

from cylc.flow import LOG
from cylc.flow.cfgspec.glbl_cfg import glbl_cfg
from cylc.flow.cfgspec.globalcfg import GlobalConfig
from cylc.flow.loggingutil import (
    CylcLogFormatter,
    RotatingLogFileHandler,
    get_reload_start_number,
    get_sorted_logs_by_time,
    patch_log_level,
    set_timestamps,
)


@pytest.fixture
def rotating_log_file_handler(tmp_path: Path):
    """Fixture to create a RotatingLogFileHandler for testing."""
    log_file = tmp_path / "log"
    log_file.touch()

    handler = cast('RotatingLogFileHandler', None)
    orig_stream = cast('TextIOWrapper', None)

    def inner(
        *args, level: int = logging.INFO, **kwargs
    ) -> RotatingLogFileHandler:
        nonlocal handler, orig_stream
        handler = RotatingLogFileHandler(log_file, *args, **kwargs)
        orig_stream = handler.stream
        # next line is important as pytest can have a "Bad file descriptor"
        # due to a FileHandler with default "a" (pytest tries to r/w).
        handler.mode = "a+"

        # enable the logger
        LOG.setLevel(level)
        LOG.addHandler(handler)

        return handler

    yield inner

    # clean up
    LOG.setLevel(logging.INFO)
    LOG.removeHandler(handler)


@mock.patch("cylc.flow.loggingutil.glbl_cfg")
def test_value_error_raises_system_exit(
    mocked_glbl_cfg, rotating_log_file_handler
):
    """Test that a ValueError when writing to a log stream won't result
    in multiple exceptions (what could lead to infinite loop in some
    occasions. Instead, it **must** raise a SystemExit"""
    # mock objects used when creating the file handler
    mocked = mock.MagicMock()
    mocked_glbl_cfg.return_value = mocked
    mocked.get.return_value = 100
    file_handler = rotating_log_file_handler(level=logging.INFO)

    # Disable raising uncaught exceptions in logging, due to file
    # handler using stdin.fileno. See the following links for more.
    # https://github.com/pytest-dev/pytest/issues/2276 &
    # https://github.com/pytest-dev/pytest/issues/1585
    logging.raiseExceptions = False

    # first message will initialize the stream and the handler
    LOG.info("What could go")

    # here we change the stream of the handler
    file_handler.stream = mock.MagicMock()
    file_handler.stream.seek = mock.MagicMock()
    # in case where
    file_handler.stream.seek.side_effect = ValueError

    with pytest.raises(SystemExit):
        # next call will call the emit method and use the mocked stream
        LOG.info("wrong?!")

    # clean up
    logging.raiseExceptions = True


@pytest.mark.parametrize(
    'dev_info, expect',
    [
        param(
            True,
            (
                '%(asctime)s %(levelname)-2s - [%(module)s:%(lineno)d] - '
                '%(message)s'
            ),
            id='dev_info=True'
        ),
        param(
            False,
            '%(asctime)s %(levelname)-2s - %(message)s',
            id='dev_info=False'
        )
    ]
)
def test_CylcLogFormatter__init__dev_info(dev_info, expect):
    """dev_info switch changes the logging format string."""
    formatter = CylcLogFormatter(dev_info=dev_info)
    assert formatter._fmt == expect


def test_update_log_archive(tmp_run_dir: Callable):
    """Test log archive performs as expected"""
    run_dir = tmp_run_dir('some_workflow')
    log_dir = Path(run_dir / 'log' / 'scheduler')
    log_dir.mkdir(exist_ok=True, parents=True)
    log_file = log_dir.joinpath('log')
    log_file.touch()
    log_object = RotatingLogFileHandler(
        log_file, no_detach=False, restart_num=0
    )

    for i in range(1, 5):
        (log_dir / f'{i:02d}-start-{i:02d}.log').touch()
    log_object.update_log_archive(2)
    assert list((log_dir.iterdir())).sort() == [
        Path(log_dir / 'log'),
        Path(log_dir / '03-start-03.log'),
        Path(log_dir / '04-start-04.log')].sort()


def test_get_sorted_logs_by_time(tmp_run_dir: Callable):
    run_dir = tmp_run_dir('some_workflow')
    config_log_dir = Path(run_dir / 'log' / 'config')
    config_log_dir.mkdir(exist_ok=True, parents=True)
    for file in ['01-start-01.cylc',
                 '02-start-01.cylc',
                 '03-restart-02.cylc',
                 '04-reload-02.cylc']:
        (config_log_dir / file).touch()
        # Sleep required to ensure modification times are sufficiently
        # different for sort
        sleep(0.1)
    loggies = get_sorted_logs_by_time(config_log_dir, "*.cylc")
    assert loggies == [f'{config_log_dir}/01-start-01.cylc',
                       f'{config_log_dir}/02-start-01.cylc',
                       f'{config_log_dir}/03-restart-02.cylc',
                       f'{config_log_dir}/04-reload-02.cylc']


def test_get_reload_number(tmp_run_dir: Callable):
    run_dir = tmp_run_dir('some_reloaded_workflow')
    config_log_dir = Path(run_dir / 'log' / 'config')
    config_log_dir.mkdir(exist_ok=True, parents=True)
    for file in [
        '01-start-01.cylc',
        '02-reload-01.cylc',
        '03-restart-02.cylc',
        '04-restart-02.cylc'
    ]:
        (config_log_dir / file).touch()
        # Sleeps required to ensure modification times are sufficiently
        # different for sort
        sleep(0.1)
    config_logs = get_sorted_logs_by_time(config_log_dir, "*.cylc")

    assert get_reload_start_number(config_logs) == '02'


def test_get_reload_number_no_logs(tmp_run_dir: Callable):
    run_dir = tmp_run_dir('another_reloaded_workflow')
    config_log_dir = Path(run_dir / 'log' / 'config')
    config_log_dir.mkdir(exist_ok=True, parents=True)
    config_logs = get_sorted_logs_by_time(config_log_dir, "*.cylc")
    assert get_reload_start_number(config_logs) == '01'


def test_set_timestamps(capsys):
    """The enable and disable timstamp methods do what they say"""
    # Setup log handler
    log_handler = logging.StreamHandler(sys.stderr)
    log_handler.setFormatter(CylcLogFormatter())
    LOG.addHandler(log_handler)

    # Log some messages with timestamps on or off:
    LOG.warning('foo')
    set_timestamps(LOG, False)
    LOG.warning('bar')
    set_timestamps(LOG, True)
    LOG.warning('baz')

    # Check 1st and 3rd error have something timestamp-like:
    errors = capsys.readouterr().err.split('\n')
    assert re.match('^[0-9]{4}', errors[0])
    assert re.match('^WARNING - bar', errors[1])
    assert re.match('^[0-9]{4}', errors[2])

    LOG.removeHandler(log_handler)


def test_log_emit_and_glbl_cfg(
    monkeypatch: pytest.MonkeyPatch, rotating_log_file_handler
):
    """Test that log calls do not access the global config object.

    Doing so can have the side effect of expanding the global config object
    so should be avoided - see https://github.com/cylc/cylc-flow/issues/6244
    """
    rotating_log_file_handler(level=logging.DEBUG)
    mock_cfg = mock.Mock(spec=GlobalConfig)
    monkeypatch.setattr(
        'cylc.flow.cfgspec.globalcfg.GlobalConfig',
        mock.Mock(
            spec=GlobalConfig,
            get_inst=lambda *a, **k: mock_cfg
        )
    )

    # Check mocking is correct:
    glbl_cfg().get(['kinesis'])
    assert mock_cfg.get.call_args_list == [mock.call(['kinesis'])]
    mock_cfg.reset_mock()

    # Check log emit does not access global config object:
    LOG.debug("Entering zero gravity")
    assert mock_cfg.get.call_args_list == []


def test_patch_log_level(caplog: pytest.LogCaptureFixture):
    """Test patch_log_level temporarily changes the log level."""
    caplog.set_level(logging.DEBUG)
    logger = logging.getLogger("forest")
    logger.setLevel(logging.ERROR)
    logger.info("nope")
    assert not caplog.records
    with patch_log_level(logger, logging.INFO):
        LOG.info("yep")
        assert len(caplog.records) == 1
    logger.info("nope")
    assert len(caplog.records) == 1


def test_patch_log_level__reset(caplog: pytest.LogCaptureFixture):
    """Test patch_log_level resets the log level correctly after
    use, not affected by the parent logger level - see
    https://github.com/cylc/cylc-flow/pull/6327
    """
    caplog.set_level(logging.ERROR)
    logger = logging.getLogger("woods")
    assert logger.level == logging.NOTSET
    with patch_log_level(logger, logging.INFO):
        logger.info("emitted but not captured, as caplog is at ERROR level")
        assert not caplog.records
    caplog.set_level(logging.INFO)
    logger.info("yep")
    assert len(caplog.records) == 1
    assert logger.level == logging.NOTSET