Coverage for python/lsst/daf/butler/tests/cliLogTestBase.py: 30%

1# This file is part of daf_butler.

3# Developed for the LSST Data Management System.

4# This product includes software developed by the LSST Project

5# (http://www.lsst.org).

6# See the COPYRIGHT file at the top-level directory of this distribution

7# for details of code ownership.

9# This software is dual licensed under the GNU General Public License and also

10# under a 3-clause BSD license. Recipients may choose which of these licenses

11# to use; please see the files gpl-3.0.txt and/or bsd_license.txt,

12# respectively. If you choose the GPL option then the following text applies

13# (but note that there is still no warranty even if you opt for BSD instead):

14#

15# This program is free software: you can redistribute it and/or modify

16# it under the terms of the GNU General Public License as published by

17# the Free Software Foundation, either version 3 of the License, or

18# (at your option) any later version.

19#

20# This program is distributed in the hope that it will be useful,

21# but WITHOUT ANY WARRANTY; without even the implied warranty of

22# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the

23# GNU General Public License for more details.

24#

25# You should have received a copy of the GNU General Public License

26# along with this program. If not, see <http://www.gnu.org/licenses/>.

28"""Unit tests for the daf_butler CliLog utility.

30Code is implemented in

31daf_butler but some only runs if lsst.log.Log can be imported so these parts of

32it can't be tested there because daf_butler does not directly depend on

33lsst.log, and only uses it if it has been setup by another package.

34"""

36from __future__ import annotations

38import logging

39import os

40import re

41import subprocess

42import tempfile

43import unittest.mock

44from collections import namedtuple

45from collections.abc import Callable

46from functools import partial

47from io import StringIO

48from logging import DEBUG, INFO, WARNING

49from typing import TYPE_CHECKING, Any

51import click

53from lsst.daf.butler.cli.butler import UncachedButlerCLI

54from lsst.daf.butler.cli.cliLog import CliLog

55from lsst.daf.butler.cli.opt import (

56 log_file_option,

57 log_label_option,

58 log_level_option,

59 log_tty_option,

60 long_log_option,

61)

62from lsst.daf.butler.cli.utils import LogCliRunner, clickResultMsg, command_test_env

63from lsst.daf.butler.logging import ButlerLogRecords

64from lsst.utils.logging import TRACE

66try:

67 import lsst.log as lsstLog

69 lsstLog_INFO = lsstLog.INFO

70 lsstLog_DEBUG = lsstLog.DEBUG

71 lsstLog_WARN = lsstLog.WARN

72except ModuleNotFoundError:

73 lsstLog = None

74 lsstLog_INFO = 0

75 lsstLog_DEBUG = 0

76 lsstLog_WARN = 0

79@click.command(cls=UncachedButlerCLI)

80@log_level_option()

81@long_log_option()

82@log_file_option()

83@log_tty_option()

84@log_label_option()

85def butlerCli(log_level: str, long_log: bool, log_file: str, log_tty: bool, log_label: str) -> None:

86 """Uncached ButlerCLI.

88 Parameters

89 ----------

90 log_level : `str`

91 The log level to use by default. ``log_level`` is handled by

92 ``get_command`` and ``list_commands``, and is called in

93 one of those functions before this is called.

94 long_log : `bool`

95 Enable extended log output. ``long_log`` is handled by

96 ``setup_logging``.

97 log_file : `str`

98 The log file name.

99 log_tty : `bool`

100 Whether to send logs to standard output.

101 log_label : `str`

102 Log labels.

103 """

104 pass

105

106

107@click.command()

108@click.option("--expected-pyroot-level", type=int)

109@click.option("--expected-pylsst-level", type=int)

110@click.option("--expected-pybutler-level", type=int)

111@click.option("--expected-lsstroot-level", type=int)

112@click.option("--expected-lsstbutler-level", type=int)

113@click.option("--expected-lsstx-level", type=int)

114def command_log_settings_test( # numpydoc ignore=PR01

115 expected_pyroot_level: str,

116 expected_pylsst_level: str,

117 expected_pybutler_level: str,

118 expected_lsstroot_level: str,

119 expected_lsstbutler_level: str,

120 expected_lsstx_level: str,

121) -> None:

122 """Test command-line log settings."""

123 LogLevel = namedtuple("LogLevel", ("expected", "actual", "name"))

124

125 logLevels = [

126 LogLevel(expected_pyroot_level, logging.getLogger().level, "pyRoot"),

127 LogLevel(expected_pylsst_level, logging.getLogger("lsst").getEffectiveLevel(), "pyLsst"),

128 LogLevel(

129 expected_pybutler_level, logging.getLogger("lsst.daf.butler").getEffectiveLevel(), "pyButler"

130 ),

131 LogLevel(expected_lsstx_level, logging.getLogger("lsstx").getEffectiveLevel(), "pyLsstx"),

132 ]

133 if lsstLog is not None:

134 logLevels.extend(

135 [

136 LogLevel(expected_lsstroot_level, lsstLog.getLogger("lsst").getEffectiveLevel(), "lsstRoot"),

137 LogLevel(

138 expected_lsstbutler_level,

139 lsstLog.getLogger("lsst.daf.butler").getEffectiveLevel(),

140 "lsstButler",

141 ),

142 ]

143 )

144 for expected, actual, name in logLevels:

145 if expected != actual:

146 raise (

147 click.ClickException(message=f"expected {name} level to be {expected!r}, actual:{actual!r}")

148 )

149

150

151class CliLogTestBase:

152 """Tests log initialization, reset, and setting log levels."""

153

154 if TYPE_CHECKING:

155 assertEqual: Callable

156 assertIn: Callable

157 assertTrue: Callable

158 assertFalse: Callable

159 assertGreater: Callable

160 subTest: Callable

161 assertNotIn: Callable

162

163 def setUp(self) -> None:

164 self.runner = LogCliRunner()

165

166 class PythonLogger:

167 """Keeps track of log level of a component and number of handlers

168 attached to it at the time this object was initialized.

169

170 Parameters

171 ----------

172 component : `str` or `None`

173 The logger name.

174 """

175

176 def __init__(self, component: str | None) -> None:

177 self.logger = logging.getLogger(component)

178 self.initialLevel = self.logger.level

179

180 class LsstLogger:

181 """Keeps track of log level for a component at the time this object was

182 initialized.

183

184 Parameters

185 ----------

186 component : `str` or `None`

187 The logger name.

188 """

189

190 def __init__(self, component: str) -> None:

191 if lsstLog:

192 self.logger = lsstLog.getLogger(component)

193 self.initialLevel = self.logger.getLevel()

194 else:

195 self.logger = None

196 self.initialLevel = None

197

198 def runTest(self, cmd: Callable) -> None:

199 """Test that the log context manager works with the butler cli.

200

201 Parameters

202 ----------

203 cmd : `~collections.abc.Callable`

204 The command to run.

205

206 Notes

207 -----

208 Tests that it will initialize the logging system according to cli

209 inputs for the duration of the command execution and resets the logging

210 system to its previous state or expected state when command execution

211 finishes.

212 """

213 pyRoot = self.PythonLogger(None)

214 pyButler = self.PythonLogger("lsst.daf.butler")

215 pyLsstRoot = self.PythonLogger("lsst")

216 lsstRoot = self.LsstLogger("")

217 lsstButler = self.LsstLogger("lsst.daf.butler")

218

219 with command_test_env(

220 self.runner, "lsst.daf.butler.tests.cliLogTestBase", "command-log-settings-test"

221 ):

222 result = cmd()

223 self.assertEqual(result.exit_code, 0, clickResultMsg(result))

224

225 # The test environment may have changed the python root logger

226 # so we can not assume it will be WARNING.

227 self.assertEqual(pyRoot.logger.level, logging.getLogger().getEffectiveLevel())

228 self.assertEqual(pyLsstRoot.logger.level, logging.INFO)

229 self.assertEqual(pyButler.logger.level, pyButler.initialLevel)

230 if lsstLog is not None:

231 assert lsstRoot.logger is not None

232 assert lsstButler.logger is not None

233 self.assertEqual(lsstRoot.logger.getLevel(), lsstLog.INFO)

234 # lsstLogLevel can either be the initial level, or uninitialized or

235 # the defined default value.

236 expectedLsstLogLevel = (

237 (lsstButler.initialLevel,)

238 if lsstButler.initialLevel != -1

239 else (-1, CliLog.defaultLsstLogLevel)

240 )

241 self.assertIn(lsstButler.logger.getLevel(), expectedLsstLogLevel)

242

243 def test_butlerCliLog(self) -> None:

244 """Test that the log context manager works with the butler cli to

245 initialize the logging system according to cli inputs for the duration

246 of the command execution and resets the logging system to its previous

247 state or expected state when command execution finishes.

248 """

249 # Run with two different log level settings.

250 log_levels = (

251 # --log-level / --log-level / expected pyroot, pylsst, pybutler,

252 # lsstroot, lsstbutler, lsstx

253 (

254 "WARNING",

255 "lsst.daf.butler=DEBUG",

256 WARNING,

257 WARNING,

258 DEBUG,

259 lsstLog_WARN,

260 lsstLog_DEBUG,

261 WARNING,

262 ),

263 ("DEBUG", "lsst.daf.butler=TRACE", WARNING, DEBUG, TRACE, lsstLog_DEBUG, lsstLog_DEBUG, WARNING),

264 (".=DEBUG", "lsst.daf.butler=WARNING", DEBUG, INFO, WARNING, lsstLog_INFO, lsstLog_WARN, DEBUG),

265 (".=DEBUG", "DEBUG", DEBUG, DEBUG, DEBUG, lsstLog_DEBUG, lsstLog_DEBUG, DEBUG),

266 (".=DEBUG", "conda=DEBUG", DEBUG, INFO, INFO, lsstLog_INFO, lsstLog_INFO, DEBUG),

267 )

268

269 self._test_levels(log_levels)

270

271 # Check that the environment variable can set additional roots.

272 log_levels = (

273 # --log-level / --log-level / expected pyroot, pylsst, pybutler,

274 # lsstroot, lsstbutler, lsstx

275 (

276 "WARNING",

277 "lsst.daf.butler=DEBUG",

278 WARNING,

279 WARNING,

280 DEBUG,

281 lsstLog_WARN,

282 lsstLog_DEBUG,

283 WARNING,

284 ),

285 ("DEBUG", "lsst.daf.butler=TRACE", WARNING, DEBUG, TRACE, lsstLog_DEBUG, lsstLog_DEBUG, DEBUG),

286 (".=DEBUG", "lsst.daf.butler=WARNING", DEBUG, INFO, WARNING, lsstLog_INFO, lsstLog_WARN, INFO),

287 (".=DEBUG", "DEBUG", DEBUG, DEBUG, DEBUG, lsstLog_DEBUG, lsstLog_DEBUG, DEBUG),

288 (".=DEBUG", "conda=DEBUG", DEBUG, INFO, INFO, lsstLog_INFO, lsstLog_INFO, INFO),

289 )

290

291 with unittest.mock.patch.dict(os.environ, {"DAF_BUTLER_ROOT_LOGGER": "lsstx"}):

292 self._test_levels(log_levels)

293

294 def _test_levels(self, log_levels: tuple[tuple[str, str, int, int, int, Any, Any, int], ...]) -> None:

295 for level1, level2, x_pyroot, x_pylsst, x_pybutler, x_lsstroot, x_lsstbutler, x_lsstx in log_levels:

296 with self.subTest("Test different log levels", level1=level1, level2=level2):

297 self.runTest(

298 partial(

299 self.runner.invoke,

300 butlerCli,

301 [

302 "--log-level",

303 level1,

304 "--log-level",

305 level2,

306 "command-log-settings-test",

307 "--expected-pyroot-level",

308 x_pyroot,

309 "--expected-pylsst-level",

310 x_pylsst,

311 "--expected-pybutler-level",

312 x_pybutler,

313 "--expected-lsstroot-level",

314 x_lsstroot,

315 "--expected-lsstbutler-level",

316 x_lsstbutler,

317 "--expected-lsstx-level",

318 x_lsstx,

319 ],

320 )

321 )

322

323 def test_helpLogReset(self) -> None:

324 """Verify that when a command does not execute, like when the help menu

325 is printed instead, that CliLog is still reset.

326 """

327 self.runTest(partial(self.runner.invoke, butlerCli, ["command-log-settings-test", "--help"]))

328

329 def testLongLog(self) -> None:

330 """Verify the timestamp is in the log messages when the --long-log

331 flag is set.

332 """

333 # When longlog=True, loglines start with the log level and a

334 # timestamp with the following format:

335 # "year-month-day T hour-minute-second.millisecond-zoneoffset"

336 # For example: "DEBUG 2020-10-28T10:20:31-07:00 ...""

337 # The log level name can change, we verify there is an all

338 # caps word there but do not verify the word. We do not verify

339 # the rest of the log string, assume that if the timestamp is

340 # in the string that the rest of the string will appear as

341 # expected.

342 timestampRegex = re.compile(

343 r".*[A-Z]+ [0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(.[0-9]{3})"

344 "?([-,+][01][0-9]:[034][05]|Z) .*"

345 )

346

347 # When longlog=False, log lines start with the module name and

348 # log level, for example:

349 # lsst.daf.butler.config DEBUG: ...

350 modulesRegex = re.compile(r".* ([a-z]+\.)+[a-z]+ [A-Z]+: .*")

351

352 with self.runner.isolated_filesystem():

353 for longlog in (True, False):

354 # The pytest log handler interferes with the log configuration

355 # settings set up by initLog -- therefore test by using

356 # a subprocess.

357 args: tuple[str, ...]

358 if longlog:

359 args = ("butler", "--log-level", "DEBUG", "--long-log", "create", "here")

360 else:

361 args = ("butler", "--log-level", "DEBUG", "create", "here")

362 result = subprocess.run(args, capture_output=True)

363 # There are cases where the newlines are stripped from the log

364 # output (like in Jenkins), since we can't depend on newlines

365 # in log output they are removed here from test output.

366 output = StringIO(result.stderr.decode().replace("\n", " "))

367 startedWithTimestamp = any(timestampRegex.match(line) for line in output.readlines())

368 output.seek(0)

369 startedWithModule = any(modulesRegex.match(line) for line in output.readlines())

370 if longlog:

371 self.assertTrue(

372 startedWithTimestamp, msg=f"did not find timestamp in: \n{output.getvalue()}"

373 )

374 self.assertFalse(

375 startedWithModule, msg=f"found lines starting with module in: \n{output.getvalue()}"

376 )

377 else:

378 self.assertFalse(startedWithTimestamp, msg=f"found timestamp in: \n{output.getvalue()}")

379 self.assertTrue(

380 startedWithModule,

381 msg=f"did not find lines starting with module in: \n{output.getvalue()}",

382 )

383

384 def testFileLogging(self) -> None:

385 """Test --log-file option."""

386 with self.runner.isolated_filesystem():

387 for i, suffix in enumerate([".json", ".log"]):

388 # Get a temporary file name and immediately close it

389 fd = tempfile.NamedTemporaryFile(suffix=suffix)

390 filename = fd.name

391 fd.close()

392

393 args = (

394 "--log-level",

395 "DEBUG",

396 "--log-file",

397 filename,

398 "--log-label",

399 "k1=v1,k2=v2",

400 "--log-label",

401 "k3=v3",

402 "create",

403 f"here{i}",

404 )

405

406 result = self.runner.invoke(butlerCli, args)

407 self.assertEqual(result.exit_code, 0, clickResultMsg(result))

408

409 # We have no real control over other packages causing lsst

410 # DEBUG log messages to turn up (for example from misconfigured

411 # CLI plugins). Check for any DEBUG messages.

412 # We know there are at least this number of log

413 # messages issued.

414 min_records = 10

415

416 if suffix == ".json":

417 records = ButlerLogRecords.from_file(filename)

418 self.assertGreater(len(records), min_records)

419 self.assertEqual(records[0].MDC, dict(K1="v1", K2="v2", K3="v3"))

420 # Find a DEBUG message.

421 self.assertTrue(any(rec.levelname == "DEBUG" for rec in records), records)

422 else:

423 with open(filename) as filed:

424 records_text = filed.readlines()

425 self.assertGreater(len(records_text), min_records) # Counting lines not records.

426 content = "".join(records_text)

427 self.assertFalse(content.startswith("{"), f"Checking for JSON content in {content}")

428

429 self.assertTrue(any("DEBUG:" in rec for rec in records_text), content)

430

431 def testLogTty(self) -> None:

432 """Verify that log output to terminal can be suppressed."""

433 with self.runner.isolated_filesystem():

434 for log_tty in (True, False):

435 # The pytest log handler interferes with the log configuration

436 # settings set up by initLog -- therefore test by using

437 # a subprocess.

438 if log_tty:

439 args = ("butler", "--log-level", "DEBUG", "--log-tty", "create", "here")

440 else:

441 args = ("butler", "--log-level", "DEBUG", "--no-log-tty", "create", "here2")

442 result = subprocess.run(args, capture_output=True)

443

444 output = result.stderr.decode()

445 if log_tty:

446 self.assertIn("DEBUG", output)

447 else:

448 self.assertNotIn("DEBUG", output)

449

450

451if __name__ == "__main__":

452 unittest.main()

Coverage for python / lsst / daf / butler / tests / cliLogTestBase.py: 30%

147 statements