threaded_sender.py

#Copyright (c) 2015 3D Control Systems LTD

#3DPrinterOS client is free software: you can redistribute it and/or modify
#it under the terms of the GNU Affero General Public License as published by
#the Free Software Foundation, either version 3 of the License, or
#(at your option) any later version.

#3DPrinterOS client is distributed in the hope that it will be useful,
#but WITHOUT ANY WARRANTY; without even the implied warranty of
#MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
#GNU Affero General Public License for more details.

#You should have received a copy of the GNU Affero General Public License
#along with 3DPrinterOS client.  If not, see <http://www.gnu.org/licenses/>.

# Author: Vladimir Avdeev <another.vic@yandex.ru>

import re
import time
import string
import logging
import threading
import collections

from base_sender import BaseSender
from serial_connection import SerialConnection
import config
import log

class Sender(BaseSender):

    positive_acks = ['start', 'Grbl ', 'ok']
    resend_request_prefixes = ['resend', 'rs']
    temperature_acks_signs = ["T:", "T0:", "T1:", "T2:"]
    pause_lift_height = 5
    pause_extrude_length = 7

    CONNECTION_TIMEOUT = 6
    TEMP_REQUEST_PERIOD = 3
    PAUSE_ON_ERROR_READING_PORT = 0.5
    CONNECTION_RETRIES_PER_BAUDRATE = 2
    CONNECTION_LINE_READ_ATTEMPTS = 2
    CONNECTION_READ_ATTEMPTS = 10
    CONNECTION_GREATINGS_READ_TIMEOUT = 20
    GET_FIRMWARE_VERSION_GCODE = "M115"
    GET_POSITION_GCODE = 'M114'
    GET_TEMP_GCODE = 'M105'
    BOARD_RESET_GCODE = "M999"
    PRINT_JOIN_TIMEOUT = 6

    OK_TIMEOUT = 60

    ok_re = re.compile(".ok")

    def __init__(self, profile, usb_info, connection_class=SerialConnection, buffer_class=collections.deque):
        BaseSender.__init__(self, profile, usb_info)
        self.define_regexps()
        self.logger = logging.getLogger(self.__class__.__name__)
        self.buffer_class = buffer_class
        self.connection_class = connection_class
        self.operational_flag = False
        self.correct_baudrate = None
        self.thread_start_lock = threading.Lock()
        self.ready_for_command = threading.Event()
        self.init()

    def init(self):
        if self.connect():
            self.extra_oks = 0
            self.ready_for_command.set()
            self.in_relative_pos_mode = False
            self.in_heating = False
            self.last_gcode_was_blocking_heating = False
            self.print_thread = None
            self.read_thread = threading.Thread(target=self.reading, name="Read thread")
            self.read_thread.start()
            self.send_homing_gcodes()
            self.start_temp_requesting()
        else:
            raise RuntimeError("Can't connection to printer at baudrates: " + str(self.profile['baudrate']))

    def connect(self):
        if not self.usb_info.get('COM'):
            raise RuntimeError("No serial port detected for serial printer")
        self.logger.info('Baudrates list for %s : %s' % (self.profile['name'], self.profile['baudrate']))
        for baudrate in self.profile['baudrate']:
            if self.correct_baudrate: #FIXME too ugly
                baudrate = self.correct_baudrate
                self.connection.close()
            self.logger.info("Connecting at baudrate %d" % baudrate)
            self.connection = self.connection_class(self.usb_info['COM'], baudrate)
            if self.connection.port:
                retries = 0
                while not self.stop_flag and retries <= self.CONNECTION_RETRIES_PER_BAUDRATE:
                    connection_result =  self.wait_for_online()
                    if connection_result:
                        self.correct_baudrate = baudrate
                        self.logger.info("Successful connection to %s: %s" % (self.profile['alias'], str(self.usb_info)))
                        return True
                    elif connection_result == None:
                        retries += 1
                    else:
                        retries = self.CONNECTION_RETRIES_PER_BAUDRATE + 1
                    self.connection.reset()
                    time.sleep(2)
            self.logger.warning("Error connecting to printer at %d" % baudrate)
            self.connection.close()

    def wait_for_online(self):
        start_time = time.time()
        while time.time() < start_time + self.CONNECTION_TIMEOUT and not self.stop_flag:
            if self.connection.send(self.GET_TEMP_GCODE):
                return self.read_greetings()

    def read_greetings(self):
        line_read_attempts = 0
        start_time = time.time()
        while not self.stop_flag and line_read_attempts < self.CONNECTION_LINE_READ_ATTEMPTS:
            line = ""
            read_attempts = 0
            while not self.stop_flag and read_attempts < self.CONNECTION_READ_ATTEMPTS and\
                            time.time() < start_time + self.CONNECTION_GREATINGS_READ_TIMEOUT:
                symbol = self.connection.recv(1)
                read_attempts += 1
                if not symbol or symbol == "\n":
                    break
                elif not ord(symbol):
                    time.sleep(0.1)
                elif not symbol in string.printable:
                    return False
                else:
                    read_attempts = 0
                    line += symbol
            if self.BOARD_RESET_GCODE in line:
                self.logger.info("Printer's board requested reset. Resetting...")
                return False
            for ack in self.positive_acks:
                if line.startswith(ack):
                    self.logger.info("Printer is online")
                    return True
            for ack in self.temperature_acks_signs:
                if line.startswith(ack):
                    self.logger.info("Printer is in blocking heating mode. Need to reset...")
                    return False
            line_read_attempts += 1

    def analyze_sent_line(self, line):
        self.last_line_sent = line
        if 'M109' in line:
            tool_match = re.match('.+T(\d+)', line)
            if tool_match:
                tool = int(tool_match.group(1)) + 1
            else:
                tool = 1
            temp_match = re.match('.+S([\d\.]+)', line)
            if temp_match:
                if not tool >= len(self.target_temps):
                    self.target_temps[tool] = float(temp_match.group(1))
        elif 'M190' in line:
            temp_match = re.match('.+S([\d\.]+)', line)
            if temp_match:
                self.target_temps[0] = float(temp_match.group(1))
        elif 'G90' in line:
            self.in_relative_pos_mode = False
        elif 'G91' in line:
            self.in_relative_pos_mode = True
        self.last_gcode_was_blocking_heating = self.in_heating
        self.in_heating = 'M109' in line or 'M190' in line

    def send_now(self, line_or_lines_list):
        with self.thread_start_lock:
            if not self.print_thread or not self.print_thread.is_alive():
                self.print_thread = PrintThread(self, name="SendNowThread")
                self.add_lines_to_send_now_buffer(line_or_lines_list)
                self.print_thread.start()
            else:
                self.add_lines_to_send_now_buffer(line_or_lines_list)

    def add_lines_to_send_now_buffer(self, line_or_lines_list):
        if type(line_or_lines_list) == str:
            self.print_thread.send_now_buffer.append(line_or_lines_list)
        else:
            self.print_thread.send_now_buffer.extend(line_or_lines_list)

    def send_homing_gcodes(self):
        with self.thread_start_lock:
            self.logger.info("Starting homing thread")
            gcodes = []
            gcodes.extend(self.profile["end_gcodes"])
            gcodes.append(self.GET_FIRMWARE_VERSION_GCODE)
            self.print_thread = PrintThread(self, name="HomingThread")
            self.print_thread.send_now_buffer.extend(gcodes)
            self.print_thread.start()

    def define_regexps(self):
        self.temp_re = re.compile('.*T:([\d\.]+) /([\d\.]+) B:(-?[\d\.]+) /(-?[\d\.]+)')
        self.position_re = re.compile('.*X:(-?[\d\.]+).?Y:(-?[\d\.]+).?Z:(-?[\d\.]+).?E:(-?[\d\.]+).*')
        # self.wait_tool_temp_re = re.compile('T:([\d\.]+) E:(\d+)')
        self.wait_tool_temp_re = re.compile('T:([\d\.]+)')
        self.wait_platform_temp_re = re.compile('.+B:(-?[\d\.]+)')
        self.firmware_re = re.compile(".*(FIRMWARE_NAME:.*$)")
        self.resend_number_re = re.compile("(\d+)")

    @log.log_exception
    def reading(self):
        last_ok_time = time.time()
        while not self.stop_flag:
            line = self.connection.recv()
            if self.parse_printer_answers(line):
                last_ok_time = time.time()
                if self.last_gcode_was_blocking_heating and not self.in_heating: # dropping in_heating flag
                    self.last_gcode_was_blocking_heating = False                 # after ok on next gcode
            elif not self.in_heating:
                self.in_heating = self.last_gcode_was_blocking_heating # assuming last ok was for blocking heating
                if last_ok_time > time.time() + self.OK_TIMEOUT:
                    message = "Warning! Timeout while waiting for ok. Must be printer error."
                    config.create_error_report(251, message, self.usb_info, self.logger, is_blocking=False)
                    last_ok_time = time.time()

    def parse_printer_answers(self, line):
        if line is None:  # None means error reading from printer, but "" is ok
            self.operational_flag = False
            time.sleep(self.PAUSE_ON_ERROR_READING_PORT)
        elif not line or "wait" in line:
            if self.extra_oks:
                self.extra_oks -= 1
                self.ready_for_command.set()
            return # return is needed here for faster the parsing
        elif self.is_ok(line):
            self.operational_flag = True
            self.check_temperature_and_position(line)
            if self.ready_for_command.is_set():
                self.extra_oks += 1
                self.logger.info("Warning: double ok was received. Extra oks counter is now: %d" % self.extra_oks)
            self.ready_for_command.set()
            return self.last_line_sent != self.GET_TEMP_GCODE # M105 should not be affect anti-stuck code mechanism
        elif line[0] == "T" or (len(line) > 1 and line[1] == "T"):
            self.parse_waiting_temperature_updates(line)
            self.operational_flag = True
        elif self.check_for_resend_requests(line):
            self.logger.debug(line)
            self.logger.info("Last_line: " + self.last_line_sent)
            self.operational_flag = True
            self.ready_for_command.set()
        elif line.startswith('Error'):
            self.logger.debug(line)
            self.logger.info("Last_line: " + self.last_line_sent)
            if not ("checksum" in line or
                    "Checksum" in line or
                    "expected line" in line or
                    "Line Number is not Last Line Number+1" in line or
                    "Format error" in line):
                is_blocking = self.BOARD_RESET_GCODE in line or "disabling all for safety!" in line
                self.operational_flag = False
                config.create_error_report(201, line, self.usb_info, self.logger, is_blocking=is_blocking)
        elif line.startswith('DEBUG'):
            self.logger.info(line)
        else:
            self.log_strange_acks(line)

    def log_strange_acks(self, line):
        self.logger.warning("Received: " + line.strip())

    def start_temp_requesting(self):
        self.stop_temp_requesting_flag = False
        self.temperature_request_thread = threading.Thread(target=self.temperature_requesting, name="TemperatureThread")
        self.temperature_request_thread.start()

    @log.log_exception
    def temperature_requesting(self):
        STEPS_NUMBER = 100
        sleep_step = self.TEMP_REQUEST_PERIOD / float(STEPS_NUMBER)
        while not self.stop_flag and not self.stop_temp_requesting_flag:
            if not self.in_heating:
                self.send_now(self.GET_TEMP_GCODE)
            sleep_step_count = STEPS_NUMBER
            while not self.stop_flag and sleep_step_count:
                time.sleep(sleep_step)
                sleep_step_count -= 1

    def parse_temperature(self, line):
        self.logger.debug(line)
        match = self.temp_re.match(line)
        if match:
            tool_temp = float(match.group(1))
            tool_target_temp = float(match.group(2))
            platform_temp = float(match.group(3))
            platform_target_temp = float(match.group(4))
            self.temps = [platform_temp, tool_temp]
            self.target_temps = [platform_target_temp, tool_target_temp]
            return True

    def parse_waiting_temperature_updates(self, line):
        match = self.wait_platform_temp_re.match(line)
        if match:
            self.temps[0] = float(match.group(1))
        match = self.wait_tool_temp_re.match(line)
        if match:
            self.temps[1] = float(match.group(1))

    def check_for_resend_requests(self, line):
        for prefix in self.resend_request_prefixes:
            if line.lower().startswith(prefix):
                match = self.resend_number_re.search(line)
                if match:
                    failed_line_number = int(match.group(1))
                    self.logger.info("Request to resend line N%d" % failed_line_number)
                    self.print_thread.lines_sent = failed_line_number
                    return True
                else:
                    self.logger.warning("Can't parse line number from resent request")

    def is_ok(self, line):
        for ack in self.positive_acks:
            if line.startswith(ack):
                return True
        return self.ok_re.match(line)

    def check_temperature_and_position(self, line):
        match = self.position_re.match(line)
        if match:
            self.position = [float(match.group(1)), float(match.group(2)), float(match.group(3)), float(match.group(4))]
        match = self.firmware_re.match(line)
        if match:
            firmware_info = match.group(1)
            self.logger.info("Firmware info: " + firmware_info)
            self.profile['firmware_info'] = firmware_info
        for sing in self.temperature_acks_signs:
            if sing in line:
                return self.parse_temperature(line)

    def load_gcodes(self, gcodes):
        self.logger.info("Loading gcodes in ThreadedSender")
        with self.thread_start_lock:
            if (self.print_thread and self.print_thread.is_alive()):
                self.logger.info("Joining printing thread...")
                self.print_thread.join(timeout=self.PRINT_JOIN_TIMEOUT)
                if self.print_thread.is_alive():
                    message = "Can't start print cause already printing"
                    config.create_error_report(260, message, self.usb_info, self.logger, is_blocking=False)
                    return False
            self.print_thread = PrintThread(self)
            self.print_thread.load_gcodes(gcodes)
            self.print_thread.start()
            self.logger.info("Print thread started")

    def is_printing(self):
        return self.print_thread and self.print_thread.is_alive() and self.print_thread.buffer

    def is_paused(self):
        return self.print_thread and self.print_thread.is_alive() and self.print_thread.paused

    def is_operational(self):
        return self.operational_flag

    def pause(self):
        if self.print_thread:
            if not self.print_thread.paused:
                if self.in_heating:
                    message = "Can't pause during heating."
                    config.create_error_report(254, message, self.usb_info, self.logger, is_blocking=False)
                    return False
                self.print_thread.paused = True
                self.was_in_relative_before_pause = self.in_relative_pos_mode
                if not self.in_relative_pos_mode:
                    self.send_now("G91")
                self.send_now("G1 Z+%d E-%d" % (self.pause_lift_height, self.pause_extrude_length))
                return True
        return False

    def unpause(self):
        if self.print_thread:
            if self.print_thread.paused:
                self.send_now("G1 Z-%d E+%d" % (self.pause_lift_height, self.pause_extrude_length))
                if not self.was_in_relative_before_pause:
                    self.send_now("G90")
                self.print_thread.paused = False
                return True
        return False

    def cancel(self):
        if not self.cancel_download():
            if self.profile.get('no_DTR') and self.in_heating:
                message = "This printer model can't cancel during heating."
                config.create_error_report(257, message, self.usb_info, self.logger, is_blocking=False)
                return False
            else:
                self.stop_flag = True
                if self.print_thread:
                    self.print_thread.cancel()
                self.print_thread.join()
                self.read_thread.join()
                self.temperature_request_thread.join()
                self.reset()
                self.stop_flag = False
                try:
                    self.init()
                    self.logger.info("Successful cancel")
                except RuntimeError:
                    message = "Can't reconnect to printer after cancel."
                    config.create_error_report(255, message, self.usb_info, self.logger, is_blocking=True)

    def reset(self):
        if not self.connection:
            self.logger.warning("No connection to printer to reset")
            return False
        elif self.profile.get('no_DTR'):
            self.logger.warning("DTR reset is forbidden for this printer type. Canceling using gcodes")
            self.connection.send(self.BOARD_RESET_GCODE)
            time.sleep(2)
        else:
            self.connection.reset()
            self.logger.info("Successful reset")

    def get_percent(self):
        if self.is_downloading():
            return self.downloader.get_percent()
        elif self.print_thread:
            return self.print_thread.get_percent()
        else:
            return 0

    def get_current_line_number(self):
        if self.print_thread:
            return self.print_thread.lines_sent
        else:
            return 0

    def unbuffered_gcodes(self, gcodes):
        self.logger.info("Gcodes to send now: " + str(gcodes))
        gcodes = self.preprocess_gcodes(gcodes)
        gcodes.append(self.GET_POSITION_GCODE)
        self.send_now(gcodes)
        self.logger.info("Gcodes were sent to printer")

    def close(self):
        self.stop_flag = True
        self.logger.debug("Joining reading thread...")
        self.read_thread.join()
        self.logger.debug("...done")
        with self.thread_start_lock:
            if self.print_thread:
                self.logger.debug("Joining printing thread...")
                self.print_thread.join()
                self.logger.debug("...done")
        if hasattr(self, "temperature_request_thread"):
            self.logger.debug("Joining temperature thread...")
            self.temperature_request_thread.join()
            self.logger.debug("...done")
        #self.connection.reset()
        self.connection.close()
        self.is_running = False
        self.logger.info("Threaded sender is closed")


class PrintThread(threading.Thread):

    RESUME_WAITING_STEP = 0.1
    GO_TO_LINE_N_GCODE = "M110"

    def __init__(self, sender, name=None):
        self.sender = sender
        self.lines_sent = 0 # need to here for multithreading purposes(lines_sent count be read before load gcodes)
        self.paused = False
        self.buffer = None
        self.send_now_buffer = collections.deque()
        if not name:
            name = self.__class__.__name__
        self.logger = logging.getLogger(name)
        super(PrintThread, self).__init__(name=name)

    def calc_checksum(self, command):
        return reduce(lambda x, y: x ^ y, map(ord, command))

    def load_gcodes(self, gcodes):
        self.logger.info("Starting gcodes loading...")
        gcodes = self.sender.preprocess_gcodes(gcodes)
        self.total_gcodes = len(gcodes)
        self.lines_sent = 0
        gcodes.insert(0, self.GO_TO_LINE_N_GCODE)
        self.buffer = self.sender.buffer_class(gcodes)
        self.logger.info("...done loading gcodes")

    def add_line_number_and_checksum(self, line):
        command = "N%d %s" % (self.lines_sent, line)
        command = command + "*" + str(self.calc_checksum(command))
        return command

    def send(self, line, add_checksum=True):
        if add_checksum:
            line = self.add_line_number_and_checksum(line)
        # we need to do this before sending to avoid bugs when resent request change line number before +1
        self.sender.ready_for_command.clear()
        if self.sender.connection.send(line):
            if add_checksum:
                self.lines_sent += 1
            self.sender.analyze_sent_line(line)
        else:
            self.sender.ready_for_command.set()
            config.create_error_report(250, "Unable to write to serial port",
                                       self.sender.usb_info, self.logger, is_blocking=False)

    @log.log_exception
    def run(self):
        while not self.sender.stop_flag and self.sender.connection.port:
            while not self.sender.ready_for_command.wait(1):
                if self.sender.stop_flag:
                    return
            if self.send_now_buffer:
                line = self.send_now_buffer.popleft()
                self.send(line, add_checksum=False)
            elif self.paused:
                time.sleep(self.RESUME_WAITING_STEP)
            else:
                try:
                    line = self.buffer[self.lines_sent]
                except (IndexError, TypeError):
                    self.logger.info(threading.currentThread().getName() + " is finished.")
                    if self.buffer:
                        self.logger.info("Print finished on %d/%d." % (self.lines_sent, self.total_gcodes))
                        self.buffer = None
                    return
                else:
                    self.send(line)

    def pause(self):
        self.paused = True

    def unpause(self):
        self.paused = False

    def cancel(self):
        self.buffer = None

    def get_percent(self):
        if not self.lines_sent:
            return 0
        else:
            return int(self.lines_sent / float(self.total_gcodes) * 100)