#!/usr/bin/env python
# Copyright 2015 The Swarming Authors. All rights reserved.
# Use of this source code is governed under the Apache License, Version 2.0 that
# can be found in the LICENSE file.

import logging
import os
import subprocess
import sys
import tempfile
import shutil
import unittest
import re

THIS_FILE = os.path.abspath(__file__)
sys.path.insert(0, os.path.dirname(os.path.dirname(THIS_FILE)))

from utils import logging_utils


# PID YYYY-MM-DD HH:MM:SS.MMM
_LOG_HEADER = r'^%d \d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\.\d\d\d' % os.getpid()
_LOG_HEADER_PID = r'^\d+ \d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\.\d\d\d'


_PHASE = 'LOGGING_UTILS_TESTS_PHASE'


def call(phase, cwd):
  """Calls itself back."""
  env = os.environ.copy()
  env[_PHASE] = phase
  return subprocess.call([sys.executable, '-u', THIS_FILE], env=env, cwd=cwd)


class Test(unittest.TestCase):
  def setUp(self):
    super(Test, self).setUp()
    self.tmp = tempfile.mkdtemp(prefix='logging_utils')

  def tearDown(self):
    try:
      shutil.rmtree(self.tmp)
    finally:
      super(Test, self).tearDown()

  def test_capture(self):
    root = logging.RootLogger(logging.DEBUG)
    with logging_utils.CaptureLogs('foo', root) as log:
      root.debug('foo')
      result = log.read()
    expected = _LOG_HEADER + ': DEBUG foo\n$'
    if sys.platform == 'win32':
      expected = expected.replace('\n', '\r\n')
    self.assertTrue(re.match(expected, result), (expected, result))

  def test_prepare_logging(self):
    root = logging.RootLogger(logging.DEBUG)
    filepath = os.path.join(self.tmp, 'test.log')
    logging_utils.prepare_logging(filepath, root)
    root.debug('foo')
    with open(filepath, 'rb') as f:
      result = f.read()
    # It'd be nice to figure out a way to ensure it's properly in UTC but it's
    # tricky to do reliably.
    expected = _LOG_HEADER + ' D: foo\n$'
    self.assertTrue(re.match(expected, result), (expected, result))

  def test_rotating(self):
    # Create a rotating log. Create a subprocess then delete the file. Make sure
    # nothing blows up.
    # Everything is done in a child process because the called functions mutate
    # the global state.
    self.assertEqual(0, call('test_rotating_phase_1', cwd=self.tmp))
    self.assertEqual({'shared.1.log'}, set(os.listdir(self.tmp)))
    with open(os.path.join(self.tmp, 'shared.1.log'), 'rb') as f:
      lines = f.read().splitlines()
    expected = [
      r' I: Parent1',
      r' I: Child1',
      r' I: Child2',
      r' I: Parent2',
    ]
    for e, l in zip(expected, lines):
      ex = _LOG_HEADER_PID + e + '$'
      self.assertTrue(re.match(ex, l), (ex, l))
    self.assertEqual(len(expected), len(lines))


def test_rotating_phase_1():
  logging_utils.prepare_logging('shared.log')
  logging.info('Parent1')
  r = call('test_rotating_phase_2', None)
  logging.info('Parent2')
  return r


def test_rotating_phase_2():
  # Simulate rotating the log.
  logging_utils.prepare_logging('shared.log')
  logging.info('Child1')
  os.rename('shared.log', 'shared.1.log')
  logging.info('Child2')
  return 0


def main():
  phase = os.environ.get(_PHASE)
  if phase:
    return getattr(sys.modules[__name__], phase)()
  verbose = '-v' in sys.argv
  logging.basicConfig(level=logging.DEBUG if verbose else logging.ERROR)
  unittest.main()


if __name__ == '__main__':
  sys.exit(main())

[((15, 12, 15, 37), 'os.path.abspath', 'os.path.abspath', ({(15, 28, 15, 36): '__file__'}, {}), '(__file__)', False, 'import os\n'), ((22, 65, 22, 76), 'os.getpid', 'os.getpid', ({}, {}), '()', False, 'import os\n'), ((31, 8, 31, 25), 'os.environ.copy', 'os.environ.copy', ({}, {}), '()', False, 'import os\n'), ((33, 9, 33, 77), 'subprocess.call', 'subprocess.call', (), '', False, 'import subprocess\n'), ((91, 2, 91, 45), 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', ({(91, 32, 91, 44): '"""shared.log"""'}, {}), "('shared.log')", False, 'from utils import logging_utils\n'), ((92, 2, 92, 25), 'logging.info', 'logging.info', ({(92, 15, 92, 24): '"""Parent1"""'}, {}), "('Parent1')", False, 'import logging\n'), ((94, 2, 94, 25), 'logging.info', 'logging.info', ({(94, 15, 94, 24): '"""Parent2"""'}, {}), "('Parent2')", False, 'import logging\n'), ((100, 2, 100, 45), 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', ({(100, 32, 100, 44): '"""shared.log"""'}, {}), "('shared.log')", False, 'from utils import logging_utils\n'), ((101, 2, 101, 24), 'logging.info', 'logging.info', ({(101, 15, 101, 23): '"""Child1"""'}, {}), "('Child1')", False, 'import logging\n'), ((102, 2, 102, 41), 'os.rename', 'os.rename', ({(102, 12, 102, 24): '"""shared.log"""', (102, 26, 102, 40): '"""shared.1.log"""'}, {}), "('shared.log', 'shared.1.log')", False, 'import os\n'), ((103, 2, 103, 24), 'logging.info', 'logging.info', ({(103, 15, 103, 23): '"""Child2"""'}, {}), "('Child2')", False, 'import logging\n'), ((108, 10, 108, 32), 'os.environ.get', 'os.environ.get', ({(108, 25, 108, 31): '_PHASE'}, {}), '(_PHASE)', False, 'import os\n'), ((112, 2, 112, 72), 'logging.basicConfig', 'logging.basicConfig', (), '', False, 'import logging\n'), ((113, 2, 113, 17), 'unittest.main', 'unittest.main', ({}, {}), '()', False, 'import unittest\n'), ((16, 35, 16, 61), 'os.path.dirname', 'os.path.dirname', ({(16, 51, 16, 60): 'THIS_FILE'}, {}), '(THIS_FILE)', False, 'import os\n'), ((39, 15, 39, 55), 'tempfile.mkdtemp', 'tempfile.mkdtemp', (), '', False, 'import tempfile\n'), ((48, 11, 48, 44), 'logging.RootLogger', 'logging.RootLogger', ({(48, 30, 48, 43): 'logging.DEBUG'}, {}), '(logging.DEBUG)', False, 'import logging\n'), ((58, 11, 58, 44), 'logging.RootLogger', 'logging.RootLogger', ({(58, 30, 58, 43): 'logging.DEBUG'}, {}), '(logging.DEBUG)', False, 'import logging\n'), ((59, 15, 59, 49), 'os.path.join', 'os.path.join', ({(59, 28, 59, 36): 'self.tmp', (59, 38, 59, 48): '"""test.log"""'}, {}), "(self.tmp, 'test.log')", False, 'import os\n'), ((60, 4, 60, 49), 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', ({(60, 34, 60, 42): 'filepath', (60, 44, 60, 48): 'root'}, {}), '(filepath, root)', False, 'from utils import logging_utils\n'), ((43, 6, 43, 29), 'shutil.rmtree', 'shutil.rmtree', ({(43, 20, 43, 28): 'self.tmp'}, {}), '(self.tmp)', False, 'import shutil\n'), ((49, 9, 49, 47), 'utils.logging_utils.CaptureLogs', 'logging_utils.CaptureLogs', ({(49, 35, 49, 40): '"""foo"""', (49, 42, 49, 46): 'root'}, {}), "('foo', root)", False, 'from utils import logging_utils\n'), ((55, 20, 55, 46), 're.match', 're.match', ({(55, 29, 55, 37): 'expected', (55, 39, 55, 45): 'result'}, {}), '(expected, result)', False, 'import re\n'), ((67, 20, 67, 46), 're.match', 're.match', ({(67, 29, 67, 37): 'expected', (67, 39, 67, 45): 'result'}, {}), '(expected, result)', False, 'import re\n'), ((75, 43, 75, 63), 'os.listdir', 'os.listdir', ({(75, 54, 75, 62): 'self.tmp'}, {}), '(self.tmp)', False, 'import os\n'), ((76, 14, 76, 52), 'os.path.join', 'os.path.join', ({(76, 27, 76, 35): 'self.tmp', (76, 37, 76, 51): '"""shared.1.log"""'}, {}), "(self.tmp, 'shared.1.log')", False, 'import os\n'), ((86, 22, 86, 37), 're.match', 're.match', ({(86, 31, 86, 33): 'ex', (86, 35, 86, 36): 'l'}, {}), '(ex, l)', False, 'import re\n')]