Use python logging for loguserdata.py, log to console

Python logging is configured with a stream handler and should
also replicate the previous logging to 0600 /var/log/heat-provision.log

By logging to a stream handler cloud-init will write to its log,
which will show up in the server console log. This means that heat
provisioning can now be monitored without needing to log in with:

nova console-log <servername>

This change also touches the file /var/lib/heat-cfntools/provision-finished
instead of also writing a datestamp to it, which is redundant.

Change-Id: Id0312bd2216a83753df601b17ad16d5355cdb11d

heat/cloudinit/loguserdata.py

@@ -2,6 +2,7 @@
 
 import errno
 import datetime
+import logging
 import pkg_resources
 import os
 import subprocess
@@ -11,6 +12,7 @@ from distutils.version import LooseVersion
 
 
 VAR_PATH = '/var/lib/heat-cfntools'
+LOG = logging.getLogger('heat-provision')
 
 
 def chk_ci_version():
@@ -18,56 +20,69 @@ def chk_ci_version():
     return v >= LooseVersion('0.6.0')
 
 
-def create_log(log_path):
-    fd = os.open(log_path, os.O_WRONLY | os.O_CREAT, 0600)
-    return os.fdopen(fd, 'w')
+def init_logging():
+    LOG.setLevel(logging.INFO)
+    LOG.addHandler(logging.StreamHandler())
+    fh = logging.FileHandler("/var/log/heat-provision.log")
+    os.chmod(fh.baseFilename, 0600)
+    LOG.addHandler(fh)
 
 
-def call(args, logger):
-    logger.write('%s\n' % ' '.join(args))
-    logger.flush()
+def call(args):
+
+    class LogStream:
+
+        def write(self, data):
+            LOG.info(data)
+
+        def __getattr__(self, attr):
+            return getattr(sys.stdout, attr)
+
+    LOG.info('%s\n' % ' '.join(args))
     try:
-        p = subprocess.Popen(args, stdout=logger, stderr=logger)
+        ls = LogStream()
+        p = subprocess.Popen(args, stdout=ls, stderr=ls)
         p.wait()
     except OSError as ex:
         if ex.errno == errno.ENOEXEC:
-            logger.write('Userdata empty or not executable: %s\n' % str(ex))
+            LOG.error('Userdata empty or not executable: %s\n' % str(ex))
             return os.EX_OK
         else:
-            logger.write('OS error running userdata: %s\n' % str(ex))
+            LOG.error('OS error running userdata: %s\n' % str(ex))
             return os.EX_OSERR
     except Exception as ex:
-        logger.write('Unknown error running userdata: %s\n' % str(ex))
+        LOG.error('Unknown error running userdata: %s\n' % str(ex))
         return os.EX_SOFTWARE
     return p.returncode
 
 
-def main(logger):
+def main():
 
     if not chk_ci_version():
         # pre 0.6.0 - user data executed via cloudinit, not this helper
-        logger.write('Unable to log provisioning, need a newer version of'
-                     ' cloud-init\n')
+        LOG.info('Unable to log provisioning, need a newer version of'
+                 ' cloud-init\n')
         return -1
 
     userdata_path = os.path.join(VAR_PATH, 'cfn-userdata')
     os.chmod(userdata_path, 0700)
 
-    logger.write('Provision began: %s\n' % datetime.datetime.now())
-    logger.flush()
-    returncode = call([userdata_path], logger)
-    logger.write('Provision done: %s\n' % datetime.datetime.now())
+    LOG.info('Provision began: %s\n' % datetime.datetime.now())
+    returncode = call([userdata_path])
+    LOG.info('Provision done: %s\n' % datetime.datetime.now())
     if returncode:
         return returncode
 
 
 if __name__ == '__main__':
-    with create_log('/var/log/heat-provision.log') as log:
-        code = main(log)
-        if code:
-            log.write('Provision failed')
-            sys.exit(code)
+    init_logging()
+
+    code = main()
+    if code:
+        LOG.error('Provision failed with exit code %s' % code)
+        sys.exit(code)
 
     provision_log = os.path.join(VAR_PATH, 'provision-finished')
-    with create_log(provision_log) as log:
-        log.write('%s\n' % datetime.datetime.now())
+    # touch the file so it is timestamped with when finished
+    with file(provision_log, 'a'):
+        os.utime(provision_log, None)

heat/tests/test_loguserdata.py

@@ -13,12 +13,10 @@
 #    under the License.
 
 import errno
-import fixtures
+import mox
 import os
 import pkg_resources
 import subprocess
-import stat
-import StringIO
 
 from heat.cloudinit import loguserdata
 from heat.tests.common import HeatTestCase
@@ -75,95 +73,78 @@ class LoguserdataTest(HeatTestCase):
         self.m.VerifyAll()
 
     def test_call(self):
-        log = StringIO.StringIO()
         subprocess.Popen(
             ['echo', 'hi'],
-            stderr=log,
-            stdout=log).AndReturn(FakePOpen(0))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndReturn(FakePOpen(0))
 
         self.m.ReplayAll()
-        self.assertEqual(0, loguserdata.call(['echo', 'hi'], log))
+        self.assertEqual(0, loguserdata.call(['echo', 'hi']))
         self.m.VerifyAll()
 
-    def test_create_log(self):
-        tempdir = self.useFixture(fixtures.TempDir())
-        log_name = os.path.join(tempdir.path, 'test_log')
-        with loguserdata.create_log(log_name) as log:
-            log.write('testing')
-
-        log = open(log_name, 'r')
-        self.assertEqual('testing', log.read())
-        mode = os.stat(log_name).st_mode
-        self.assertEqual(0600, stat.S_IMODE(mode))
-
     def test_main(self):
 
-        log = StringIO.StringIO()
         pkg_resources.get_distribution('cloud-init').AndReturn(
             FakeCiVersion('0.7.0'))
 
         os.chmod('/var/lib/heat-cfntools/cfn-userdata', 0700).AndReturn(None)
         subprocess.Popen(
             ['/var/lib/heat-cfntools/cfn-userdata'],
-            stderr=log,
-            stdout=log).AndReturn(FakePOpen(0))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndReturn(FakePOpen(0))
 
         self.m.ReplayAll()
-        loguserdata.main(log)
+        loguserdata.main()
         self.m.VerifyAll()
 
     def test_main_script_empty(self):
 
-        log = StringIO.StringIO()
-
         pkg_resources.get_distribution('cloud-init').AndReturn(
             FakeCiVersion('0.7.0'))
 
         os.chmod('/var/lib/heat-cfntools/cfn-userdata', 0700).AndReturn(None)
         subprocess.Popen(
             ['/var/lib/heat-cfntools/cfn-userdata'],
-            stderr=log,
-            stdout=log).AndRaise(OSError(errno.ENOEXEC, "empty script"))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndRaise(
+                OSError(errno.ENOEXEC, "empty script"))
 
         self.m.ReplayAll()
-        self.assertEqual(None, loguserdata.main(log))
+        self.assertEqual(None, loguserdata.main())
 
         self.m.VerifyAll()
 
     def test_main_os_error(self):
 
-        log = StringIO.StringIO()
-
         pkg_resources.get_distribution('cloud-init').AndReturn(
             FakeCiVersion('0.7.0'))
 
         os.chmod('/var/lib/heat-cfntools/cfn-userdata', 0700).AndReturn(None)
         subprocess.Popen(
             ['/var/lib/heat-cfntools/cfn-userdata'],
-            stderr=log,
-            stdout=log).AndRaise(OSError(errno.ENOENT, "no such file"))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndRaise(
+                OSError(errno.ENOENT, "no such file"))
 
         self.m.ReplayAll()
-        self.assertEqual(os.EX_OSERR, loguserdata.main(log))
+        self.assertEqual(os.EX_OSERR, loguserdata.main())
 
         self.m.VerifyAll()
 
     def test_main_error_other(self):
-        log = StringIO.StringIO()
         pkg_resources.get_distribution('cloud-init').AndReturn(
             FakeCiVersion('0.7.0'))
         os.chmod('/var/lib/heat-cfntools/cfn-userdata', 0700).AndReturn(None)
         subprocess.Popen(
             ['/var/lib/heat-cfntools/cfn-userdata'],
-            stderr=log,
-            stdout=log).AndRaise(IOError("read failed"))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndRaise(IOError("read failed"))
 
         self.m.ReplayAll()
-        self.assertEqual(os.EX_SOFTWARE, loguserdata.main(log))
+        self.assertEqual(os.EX_SOFTWARE, loguserdata.main())
         self.m.VerifyAll()
 
     def test_main_fails(self):
-        log = StringIO.StringIO()
 
         #fail on ci version
         pkg_resources.get_distribution('cloud-init').AndReturn(
@@ -175,10 +156,10 @@ class LoguserdataTest(HeatTestCase):
         os.chmod('/var/lib/heat-cfntools/cfn-userdata', 0700).AndReturn(None)
         subprocess.Popen(
             ['/var/lib/heat-cfntools/cfn-userdata'],
-            stderr=log,
-            stdout=log).AndReturn(FakePOpen(-2))
+            stderr=mox.IgnoreArg(),
+            stdout=mox.IgnoreArg()).AndReturn(FakePOpen(-2))
 
         self.m.ReplayAll()
-        self.assertEqual(-1, loguserdata.main(log))
-        self.assertEqual(-2, loguserdata.main(log))
+        self.assertEqual(-1, loguserdata.main())
+        self.assertEqual(-2, loguserdata.main())
         self.m.VerifyAll()