# Copyright 2018 The Chromium OS Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

import re
import subprocess
import threading
import time

# A path of the log file
_PATH_LOG_FILE = '/var/log/messages'
# Time margin as a number of seconds. It is used during parsing of the log file.
# Sometimes, logs are not in strict datetime order. This value defines maximum
# possible datetime error in logs sequence.
_TIME_MARGIN = 2
# Max time in seconds to wait for CUPS logs to appear in the log file.
_TIME_MAX_WAIT = 100
# A list of filters that are installed by loading components.
# Currently, they are Star and Epson drivers.
_COMPONENT_FILTERS = ['rastertostar', 'rastertostarlm', 'epson-escpr-wrapper']


class LogReader():
    """
    An instance of this class is responsible for gathering data about CUPS jobs
    and extracting their results and pipelines by parsing the main log file. It
    can check for internal errors during a job execution and build a bash script
    simulating an executed pipeline. CUPS server must have logging level set to
    'debug' to make a pipeline extraction possible.

    """

    def _read_last_lines(self, lines_count):
        """
        The function reads given number of lines from the end of the log file.
        The last line is omitted if it is not ended with EOL character. If a
        whole file was read, count of returned lines may be smaller than
        requested number. Always at least one line is returned; if the file has
        no EOL characters an exception is raised.

        @param lines_count: a number of lines to read

        @returns a list of lines

        """
        assert lines_count > 0
        argv = ['tail', '-n', '%d' % (lines_count+1), _PATH_LOG_FILE]
        p1 = subprocess.Popen(argv, stdout=subprocess.PIPE)
        out,err = p1.communicate()
        lines = out.split('\n')
        lines.pop()
        if len(lines) > lines_count:
            if len(lines) == 0:
                raise Exception('The file %s is empty' % _PATH_LOG_FILE)
            lines = lines[1:]
        return lines


    def _get_datetime_from_line(self, line):
        """
        Parse datetime from the given line read from the log file.

        @param line_count: single line from the log files

        @returns a datetime as a number of seconds from the epoch (float)

        """
        return time.mktime(time.strptime(line[:20], "%Y-%m-%dT%H:%M:%S."))


    def __init__(self):
        """
        Constructor.

        """
        # the last line read from the log file
        self._last_line_read = self._read_last_lines(1)[0]
        # logs obtained from the log file after preprocessing
        # key = a tuple (CUPS pid, job id)
        # value = list with logs
        self._logs = dict()
        # data extracted from logs
        # key = a tuple (CUPS pid, job id)
        # value = a tuple (result(bool),envp(dict),argv(list),filters(list))
        self._results = dict()
        # mapping from printer's name to a list of CUPS jobs
        # key = printer name
        # value = a list of tuples (CUPS pid, job id)
        self._printer_name_to_key = dict()
        # a lock for synchronization
        self._critical_section = threading.Lock()


    def _parse_logs(self):
        """
        This method read and parses new lines from the log file (all complete
        lines after the line saved in self._last_line_read). The lines are
        filtered and saved in self._logs. Dictionaries self._results and
        self._printer_name_to_key are updated accordingly.

        """
        # ==============================================
        # try to read lines from the end of the log file until the line from
        # self._last_line_read is found
        dt_last_line_read = self._get_datetime_from_line(self._last_line_read)
        lines_count = 1024
        pos_last_line_read = None
        while True:
            lines = self._read_last_lines(lines_count)
            # search for self._last_line_read in lines read from the file
            for index,line in enumerate(lines):
                dt_line = self._get_datetime_from_line(line)
                if dt_line > dt_last_line_read + _TIME_MARGIN:
                    # a datetime of the line is far behind, exit the loop
                    break
                if line == self._last_line_read:
                    # the line was found, save its index and exit the loop
                    pos_last_line_read = index
                    break
            # if the self._last_line_read was found, exit the 'while' loop
            if pos_last_line_read is not None:
                break
            # check if we can try to read more lines from the file to repeat
            # the search, if not then throw an exception
            if ( len(lines) < lines_count or
                    self._get_datetime_from_line(lines[0]) +
                    _TIME_MARGIN < dt_last_line_read ):
                raise Exception('Cannot find the last read line in the log'
                        ' file (maybe it has been erased?)')
            # increase the number of lines to read
            lines_count = lines_count * 2
        # check if there are any new lines, exit if not
        if pos_last_line_read + 1 == len(lines):
            return
        # update the field with the last line read from the log file
        self._last_line_read = lines[-1]
        # ==============================================
        # parse logs, select these ones from CUPS jobs and save them to
        # self._logs
        updated_jobs = set()
        for line in lines[pos_last_line_read+1:]:
            tokens = line.split(' ', 5)
            if ( len(tokens) < 6 or tokens[2][:6] != 'cupsd[' or
                    tokens[3] != '[Job' ):
                continue
            pid = int(tokens[2][6:-2])
            job_id = int(tokens[4][:-1])
            message = tokens[5]
            key = (pid,job_id)
            if key not in self._logs:
                self._logs[key] = []
            self._logs[key].append(message)
            updated_jobs.add(key)
        # ==============================================
        # try to interpret logs
        for key in updated_jobs:
            number_of_processes_to_check = None
            printer_name = None
            result = True
            envp = dict()
            argv = []
            filters = []
            for msg in self._logs[key]:
                if number_of_processes_to_check is None:
                    regexp = re.match(r'(\d) filters for job:', msg)
                    if regexp is not None:
                        number_of_processes_to_check = int(regexp.group(1)) + 1
                        assert number_of_processes_to_check > 0
                elif printer_name is None:
                    regexp = re.match(r'(\S+) \(\S+ to (\S+), cost \d+\)', msg)
                    if regexp is not None:
                        fltr = regexp.group(1)
                        if fltr == '-':
                            number_of_processes_to_check -= 1
                        else:
                            filters.append(fltr)
                        trg = regexp.group(2)
                        if trg.startswith('printer/') and '/' not in trg[8:]:
                            printer_name = trg[8:]
                else:
                    regexp = re.match(r'envp\[\d+\]="(\S+)=(\S+)"', msg)
                    if regexp is not None:
                        envp[regexp.group(1)] = regexp.group(2)
                        continue
                    regexp = re.match(r'argv\[(\d+)\]="(.+)"', msg)
                    if regexp is not None:
                        if len(argv) != int(regexp.group(1)):
                            raise Exception('Error when parsing argv for %s'
                                    % printer_name)
                        argv.append(regexp.group(2))
                        continue
                    if number_of_processes_to_check > 0:
                        regexp = re.match(r'PID \d+ \(\S+\) ', msg)
                        if regexp is not None:
                            number_of_processes_to_check -= 1
                            if ( not msg.endswith(' exited with no errors.') and
                                    'was terminated normally with signal'
                                    not in msg ):
                                result = False
            if number_of_processes_to_check == 0:
                # if it is a new job, update self._printer_name_to_key
                if key not in self._results:
                    if printer_name not in self._printer_name_to_key:
                        self._printer_name_to_key[printer_name] = [key]
                    else:
                        self._printer_name_to_key[printer_name].append(key)
                # update results
                self._results[key] = (result,envp,argv,filters)


    def _build_pipeline(
            self, printer_name, envp, argv, filters,
            path_ppd, path_doc, path_workdir):
        """
        This function tries to build a bash script containing a pipeline used
        internally by CUPS. All printer's parameters are passed by the field
        self._printers_data. Resultant script is saved in self._pipelines.

        @param printer_name: a printer's name
        @param envp: a dictionary with environment variables for the pipeline
        @param argv: a list with command line parameters for filters
        @param filters: a list of filters
        @param path_ppd: a path to PPD file (string)
        @param path_doc: a path to input document (string)
        @param path_workdir: a path to a directory, that should be used as home
                directory and temporary location by filters

        @returns a pipeline as a bash script (string)

        """
        # update paths set in environment variables
        envp['PPD'] = path_ppd
        envp['HOME'] = path_workdir
        envp['TMPDIR'] = path_workdir
        # drop the last argument, it is an input file
        argv.pop()
        # replace filter names by full path for Star and Epson drivers
        if filters[-1] in _COMPONENT_FILTERS:
            find_cmd = ['find', '/run/imageloader/', '-type', 'f', '-name']
            find_cmd.append(filters[-1])
            filters[-1] = subprocess.check_output(find_cmd).rstrip()
        # build and return the script
        script = '#!/bin/bash\nset -e\nset -o pipefail\n'
        for name, value in envp.iteritems():
            script += ('export %s=%s\n' % (name, value))
        for ind, filt in enumerate(filters):
            if ind > 0:
                script += ('gzip -dc %d.doc.gz | ' % ind)
            script += ('(exec -a "%s" %s' % (argv[0], filt))
            for arg in argv[1:]:
                script += (' "%s"' % arg)
            if ind == 0:
                script += (' "%s"' % path_doc)
            script += (') 2>%d.err | gzip -9 >%d.doc.gz\n' % (ind+1, ind+1))
        return script


    def extract_result(
            self, printer_name,
            path_ppd=None, path_doc=None, path_workdir=None):
        """
        This function extract from the log file CUPS logs related to printer
        with given name. Extracted logs are also interpreted, the function
        checks for any failures. If all optional parameters are set, a pipeline
        used by CUPS is extracted from the logs. If some of required results
        cannot be extracted, an exception is raised. This function is
        thread-safe, it can be called simultaneously by many Python threads.
        However, all simultaneous calls must have different values of the
        printer_name parameter (calls with the same printer_name must be done
        sequentially).

        @param printer_name: a printer's name
        @param path_ppd: a path to PPD file (string), required for pipelinie
                extraction only
        @param path_doc: a path to input document (string), required for
                pipelinie extraction only
        @param path_workdir: a path to a directory, that should be used as home
                directory and temporary location by filters, required for
                pipelinie extraction only

        @returns a tuple of three variables:
                1. True if no errors were detected, False otherwise
                2. logs extracted from the log file (string)
                3. pipeline as a bash script (string), None if not requested

        @raises Exception in case of any errors

        """
        # time when we started efforts to get logs
        time_start = time.time()
        # all three parameters must be set to extract a pipeline
        pipeline_required = (path_ppd is not None and path_doc is not None
                and path_workdir is not None)
        try:
            # try to get and parse logs
            while True:
                with self._critical_section:
                    # leave the loop if we have everything
                    if printer_name in self._printer_name_to_key:
                        if not pipeline_required:
                            break
                        key = self._printer_name_to_key[printer_name][0]
                        envp = self._results[key][1]
                        argv = self._results[key][2]
                        if len(envp) > 0 and len(argv) > 0:
                            break
                    # save current time and try to parse the log file
                    time_last_read = time.time()
                    self._parse_logs()
                    # leave the loop if we have everything
                    if printer_name in self._printer_name_to_key:
                        if not pipeline_required:
                            break
                        key = self._printer_name_to_key[printer_name][0]
                        envp = self._results[key][1]
                        argv = self._results[key][2]
                        if len(envp) > 0 and len(argv) > 0:
                            break
                # raise an exception if we have been waiting too long
                if time_last_read - time_start > _TIME_MAX_WAIT:
                    raise Exception('Cannot parse logs for %s or they did not'
                            ' appear in %s within %d seconds from printing the'
                            ' document' % (printer_name, _PATH_LOG_FILE,
                            _TIME_MAX_WAIT))
                # wait 1 second and try again to parse acquired logs
                time.sleep(1)
            # retrieve required data
            with self._critical_section:
                if pipeline_required:
                    # key, envp, argv are already set in the loop above
                    filters = self._results[key][3]
                else:
                    key = self._printer_name_to_key[printer_name][0]
                no_errors = self._results[key][0]
                logs = '\n'.join(self._logs[key])
            # build a pipeline script if required
            if pipeline_required:
                pipeline = self._build_pipeline(printer_name, envp, argv,
                        filters, path_ppd, path_doc, path_workdir)
            else:
                pipeline = None
            # return results
            return no_errors, logs, pipeline
        finally:
            # cleanup
            if printer_name in self._printer_name_to_key:
                with self._critical_section:
                    key = self._printer_name_to_key[printer_name].pop(0)
                    if len(self._printer_name_to_key[printer_name]) == 0:
                        self._printer_name_to_key.pop(printer_name)
                    self._logs.pop(key)
                    self._results.pop(key)