# Copyright (C) 2016 Canonical Ltd. # # Author: Ryan Harper # # This file is part of cloud-init. See LICENSE file for license information. import base64 import datetime import json import os import sys import time from cloudinit import subp, 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