# Copyright (C) 2016 Canonical Ltd.
#
# Author: Ryan Harper <ryan.harper@canonical.com>
#
# This file is part of cloud-init. See LICENSE file for license information.
import base64
import datetime
import json
import os
import time
import sys
from cloudinit import subp
from cloudinit import util
from cloudinit.distros import uses_systemd
# Example events:
# {
# "description": "executing late commands",
# "event_type": "start",
# "level": "INFO",
# "name": "cmd-install/stage-late"
# "origin": "cloudinit",
# "timestamp": 1461164249.1590767,
# }
# {
# "description": "executing late commands",
# "event_type": "finish",
# "level": "INFO",
# "name": "cmd-install/stage-late",
# "origin": "cloudinit",
# "result": "SUCCESS",
# "timestamp": 1461164249.1590767
# }
format_key = {
'%d': 'delta',
'%D': 'description',
'%E': 'elapsed',
'%e': 'event_type',
'%I': 'indent',
'%l': 'level',
'%n': 'name',
'%o': 'origin',
'%r': 'result',
'%t': 'timestamp',
'%T': 'total_time',
}
formatting_help = " ".join(["{0}: {1}".format(k.replace('%', '%%'), v)
for k, v in format_key.items()])
SUCCESS_CODE = 'successful'
FAIL_CODE = 'failure'
CONTAINER_CODE = 'container'
TIMESTAMP_UNKNOWN = (FAIL_CODE, -1, -1, -1)
def format_record(msg, event):
for i, j in format_key.items():
if i in msg:
# ensure consistent formatting of time values
if j in ['delta', 'elapsed', 'timestamp']:
msg = msg.replace(i, "{%s:08.5f}" % j)
else:
msg = msg.replace(i, "{%s}" % j)
return msg.format(**event)
def dump_event_files(event):
content = dict((k, v) for k, v in event.items() if k not in ['content'])
files = content['files']
saved = []
for f in files:
fname = f['path']
fn_local = os.path.basename(fname)
fcontent = base64.b64decode(f['content']).decode('ascii')
util.write_file(fn_local, fcontent)
saved.append(fn_local)
return saved
def event_name(event):
if event:
return event.get('name')
return None
def event_type(event):
if event:
return event.get('event_type')
return None
def event_parent(event):
if event:
return event_name(event).split("/")[0]
return None
def event_timestamp(event):
return float(event.get('timestamp'))
def event_datetime(event):
return datetime.datetime.utcfromtimestamp(event_timestamp(event))
def delta_seconds(t1, t2):
return (t2 - t1).total_seconds()
def event_duration(start, finish):
return delta_seconds(event_datetime(start), event_datetime(finish))
def event_record(start_time, start, finish):
record = finish.copy()
record.update({
'delta': event_duration(start, finish),
'elapsed': delta_seconds(start_time, event_datetime(start)),
'indent': '|' + ' ' * (event_name(start).count('/') - 1) + '`->',
})
return record
def total_time_record(total_time):
return 'Total Time: %3.5f seconds\n' % total_time
class SystemctlReader(object):
'''
Class for dealing with all systemctl subp calls in a consistent manner.
'''
def __init__(self, property, parameter=None):
self.epoch = None
self.args = ['/bin/systemctl', 'show']
if parameter:
self.args.append(parameter)
self.args.extend(['-p', property])
# Don't want the init of our object to break. Instead of throwing
# an exception, set an error code that gets checked when data is
# requested from the object
self.failure = self.subp()
def subp(self):
'''
Make a subp call based on set args and handle errors by setting
failure code
:return: whether the subp call failed or not
'''
try:
value, err = subp.subp(self.args, capture=True)
if err:
return err
self.epoch = value
return None
except Exception as systemctl_fail:
return systemctl_fail
def parse_epoch_as_float(self):
'''
If subp call succeeded, return the timestamp from subp as a float.
:return: timestamp as a float
'''
# subp has 2 ways to fail: it either fails and throws an exception,
# or returns an error code. Raise an exception here in order to make
# sure both scenarios throw exceptions
if self.failure:
raise RuntimeError('Subprocess call to systemctl has failed, '
'returning error code ({})'
.format(self.failure))
# Output from systemctl show has the format Property=Value.
# For example, UserspaceMonotonic=1929304
timestamp = self.epoch.split('=')[1]
# Timestamps reported by systemctl are in microseconds, converting
return float(timestamp) / 1000000
def dist_check_timestamp():
'''
Determine which init system a particular linux distro is using.
Each init system (systemd, upstart, etc) has a different way of
providing timestamps.
:return: timestamps of kernelboot, kernelendboot, and cloud-initstart
or TIMESTAMP_UNKNOWN if the timestamps cannot be retrieved.
'''
if uses_systemd():
return gather_timestamps_using_systemd()
# Use dmesg to get timestamps if the distro does not have systemd
if util.is_FreeBSD() or 'gentoo' in \
util.system_info()['system'].lower():
return gather_timestamps_using_dmesg()
# this distro doesn't fit anything that is supported by cloud-init. just
# return error codes
return TIMESTAMP_UNKNOWN
def gather_timestamps_using_dmesg():
'''
Gather timestamps that corresponds to kernel begin initialization,
kernel finish initialization using dmesg as opposed to systemctl
:return: the two timestamps plus a dummy timestamp to keep consistency
with gather_timestamps_using_systemd
'''
try:
data, _ = subp.subp(['dmesg'], capture=True)
split_entries = data[0].splitlines()
for i in split_entries:
if i.decode('UTF-8').find('user') != -1:
splitup = i.decode('UTF-8').split()
stripped = splitup[1].strip(']')
# kernel timestamp from dmesg is equal to 0,
# with the userspace timestamp relative to it.
user_space_timestamp = float(stripped)
kernel_start = float(time.time()) - float(util.uptime())
kernel_end = kernel_start + user_space_timestamp
# systemd wont start cloud-init in this case,
# so we cannot get that timestamp
return SUCCESS_CODE, kernel_start, kernel_end, \
kernel_end
except Exception:
pass
return TIMESTAMP_UNKNOWN
def gather_timestamps_using_systemd():
'''
Gather timestamps that corresponds to kernel begin initialization,
kernel finish initialization. and cloud-init systemd unit activation
:return: the three timestamps
'''
kernel_start = float(time.time()) - float(util.uptime())
try:
delta_k_end = SystemctlReader('UserspaceTimestampMonotonic')\
.parse_epoch_as_float()
delta_ci_s = SystemctlReader('InactiveExitTimestampMonotonic',
'cloud-init-local').parse_epoch_as_float()
base_time = kernel_start
status = SUCCESS_CODE
# lxc based containers do not set their monotonic zero point to be when
# the container starts, instead keep using host boot as zero point
# time.CLOCK_MONOTONIC_RAW is only available in python 3.3
if util.is_container():
# clock.monotonic also uses host boot as zero point
if sys.version_info >= (3, 3):
base_time = float(time.time()) - float(time.monotonic())
# TODO: lxcfs automatically truncates /proc/uptime to seconds
# in containers when https://github.com/lxc/lxcfs/issues/292
# is fixed, util.uptime() should be used instead of stat on
try:
file_stat = os.stat('/proc/1/cmdline')
kernel_start = file_stat.st_atime
except OSError as err:
raise RuntimeError('Could not determine container boot '
'time from /proc/1/cmdline. ({})'
.format(err)) from err
status = CONTAINER_CODE
else:
status = FAIL_CODE
kernel_end = base_time + delta_k_end
cloudinit_sysd = base_time + delta_ci_s
except Exception as e:
# Except ALL exceptions as Systemctl reader can throw many different
# errors, but any failure in systemctl means that timestamps cannot be
# obtained
print(e)
return TIMESTAMP_UNKNOWN
return status, kernel_start, kernel_end, cloudinit_sysd
def generate_records(events, blame_sort=False,
print_format="(%n) %d seconds in %I%D",
dump_files=False, log_datafiles=False):
'''
Take in raw events and create parent-child dependencies between events
in order to order events in chronological order.
:param events: JSONs from dump that represents events taken from logs
:param blame_sort: whether to sort by timestamp or by time taken.
:param print_format: formatting to represent event, time stamp,
and time taken by the event in one line
:param dump_files: whether to dump files into JSONs
:param log_datafiles: whether or not to log events generated
:return: boot records ordered chronologically
'''
sorted_events = sorted(events, key=lambda x: x['timestamp'])
records = []
start_time = None
total_time = 0.0
stage_start_time = {}
stages_seen = []
boot_records = []
unprocessed = []
for e in range(0, len(sorted_events)):
event = events[e]
try:
next_evt = events[e + 1]
except IndexError:
next_evt = None
if event_type(event) == 'start':
if event.get('name') in stages_seen:
records.append(total_time_record(total_time))
boot_records.append(records)
records = []
start_time = None
total_time = 0.0
if start_time is None:
stages_seen = []
start_time = event_datetime(event)
stage_start_time[event_parent(event)] = start_time
# see if we have a pair
if event_name(event) == event_name(next_evt):
if event_type(next_evt) == 'finish':
records.append(format_record(print_format,
event_record(start_time,
event,
next_evt)))
else:
# This is a parent event
records.append("Starting stage: %s" % event.get('name'))
unprocessed.append(event)
stages_seen.append(event.get('name'))
continue
else:
prev_evt = unprocessed.pop()
if event_name(event) == event_name(prev_evt):
record = event_record(start_time, prev_evt, event)
records.append(format_record("Finished stage: "
"(%n) %d seconds",
record) + "\n")
total_time += record.get('delta')
else:
# not a match, put it back
unprocessed.append(prev_evt)
records.append(total_time_record(total_time))
boot_records.append(records)
return boot_records
def show_events(events, print_format):
'''
A passthrough method that makes it easier to call generate_records()
:param events: JSONs from dump that represents events taken from logs
:param print_format: formatting to represent event, time stamp,
and time taken by the event in one line
:return: boot records ordered chronologically
'''
return generate_records(events, print_format=print_format)
def load_events_infile(infile):
'''
Takes in a log file, read it, and convert to json.
:param infile: The Log file to be read
:return: json version of logfile, raw file
'''
data = infile.read()
try:
return json.loads(data), data
except ValueError:
return None, data