#!/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, 'os.path.abspath', 'os.path.abspath', (['__file__'], {}), False, 'import os\n'), (22, 'os.getpid', 'os.getpid', ([], {}), False, 'import os\n'), (31, 'os.environ.copy', 'os.environ.copy', ([], {}), False, 'import os\n'), (33, 'subprocess.call', 'subprocess.call', (["[sys.executable, '-u', THIS_FILE]"], {'env': 'env', 'cwd': 'cwd'}), False, 'import subprocess\n'), (91, 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', (['"""shared.log"""'], {}), False, 'from utils import logging_utils\n'), (92, 'logging.info', 'logging.info', (['"""Parent1"""'], {}), False, 'import logging\n'), (94, 'logging.info', 'logging.info', (['"""Parent2"""'], {}), False, 'import logging\n'), (100, 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', (['"""shared.log"""'], {}), False, 'from utils import logging_utils\n'), (101, 'logging.info', 'logging.info', (['"""Child1"""'], {}), False, 'import logging\n'), (102, 'os.rename', 'os.rename', (['"""shared.log"""', '"""shared.1.log"""'], {}), False, 'import os\n'), (103, 'logging.info', 'logging.info', (['"""Child2"""'], {}), False, 'import logging\n'), (108, 'os.environ.get', 'os.environ.get', (['_PHASE'], {}), False, 'import os\n'), (112, 'logging.basicConfig', 'logging.basicConfig', ([], {'level': '(logging.DEBUG if verbose else logging.ERROR)'}), False, 'import logging\n'), (113, 'unittest.main', 'unittest.main', ([], {}), False, 'import unittest\n'), (16, 'os.path.dirname', 'os.path.dirname', (['THIS_FILE'], {}), False, 'import os\n'), (39, 'tempfile.mkdtemp', 'tempfile.mkdtemp', ([], {'prefix': '"""logging_utils"""'}), False, 'import tempfile\n'), (48, 'logging.RootLogger', 'logging.RootLogger', (['logging.DEBUG'], {}), False, 'import logging\n'), (58, 'logging.RootLogger', 'logging.RootLogger', (['logging.DEBUG'], {}), False, 'import logging\n'), (59, 'os.path.join', 'os.path.join', (['self.tmp', '"""test.log"""'], {}), False, 'import os\n'), (60, 'utils.logging_utils.prepare_logging', 'logging_utils.prepare_logging', (['filepath', 'root'], {}), False, 'from utils import logging_utils\n'), (43, 'shutil.rmtree', 'shutil.rmtree', (['self.tmp'], {}), False, 'import shutil\n'), (49, 'utils.logging_utils.CaptureLogs', 'logging_utils.CaptureLogs', (['"""foo"""', 'root'], {}), False, 'from utils import logging_utils\n'), (55, 're.match', 're.match', (['expected', 'result'], {}), False, 'import re\n'), (67, 're.match', 're.match', (['expected', 'result'], {}), False, 'import re\n'), (75, 'os.listdir', 'os.listdir', (['self.tmp'], {}), False, 'import os\n'), (76, 'os.path.join', 'os.path.join', (['self.tmp', '"""shared.1.log"""'], {}), False, 'import os\n'), (86, 're.match', 're.match', (['ex', 'l'], {}), False, 'import re\n')]