i-Telex Acknowledge throttling

Special problems manifested themselves in conjunction with the circular
service 11150, when calling piTelex as recipient of circulars:

1. Previously, piTelex gobbled up all data sent via i-Telex as fast as it
   could, and fed it to the teleprinter driver module, which manages the
   printing process. All read characters were instantly reported as
   "printed" in Acknowledge packets, which lead remotes to believe they
   could continue sending this quickly. Typically, the i-Telex
   connection was long closed when the printer module had emptied its
   buffer. The adverse side-effect, in particular with 11150, was that the
   final WRU exchange didn't work because the teleprinter had not printed
   even half of the data sent (with 80 chars/s or 600 Bd). The remote timed
   out on the WRU answer and reported the connection as failed.

2. Also, the first datum sent by 11150 is a WRU request. The current
   version sends it as soon as an Acknowledge with content 0 is received
   (meaning printer is running and all data has been printed, matching the
   spec), or a Heartbeat is received (contrary to the spec). Because
   piTelex sends Heartbeats early in the connection, the probability was
   high that remote sends the WRU whilst the welcome banner is still being
   printed, garbling the output.

Fix 1 by introducing ESC-~ printer buffer feedback, which serves two
purposes:

- Printer start feedback -- printer startup is signalled by sending the
  first ESC-~

- Printer buffer feedback: ESC-~ has as "payload" the current printer
  buffer length.

The legacy printer start feedback (ESC-AC/ACK/ACT) isn't needed any more
and thus removed.

Attention: This patch only contains the feedback provisions for
txDevED1000SC.

Fix 2 by disabling Heartbeats for now.

Also, record number of printed characters per session in txDevED1000SC
to aid in debugging. The overhead is minimal.

telex.py

@@ -144,6 +144,8 @@ def init():
     ctrl = txDevMCP.TelexMCP(**txConfig.CFG)
     DEVICES.append(ctrl)
 
+    # Iterate over configuration items, create configured instances and add
+    # them to DEVICES.
     for dev_name, dev_param in txConfig.CFG['devices'].items():
         if not dev_param.get('enable', False):
             continue
@@ -233,6 +235,7 @@ def init():
         else:
             l.warning("Unknown module type in configuration, section {!r}: {!r}".format(dev_name, dev_param['type']))
 
+
 # =====
 
 def exit():

txDevED1000SC.py

@@ -62,6 +62,10 @@ def __init__(self, **params):
         # - 50 offline, wait for A level
         self._rx_state = 0
 
+        # Helper variables for printer feedback
+        self._last_tx_buf_len = 0
+        self._send_feedback = False
+
         self.recv_squelch = self.params.get('recv_squelch', 100)
         self.recv_debug = self.params.get('recv_debug', False)
         self.send_WB_pulse = self.params.get('send_WB_pulse', False)
@@ -71,13 +75,15 @@ def __init__(self, **params):
         recv_f = [recv_f0, recv_f1]
         self._recv_decode_init(recv_f)
 
+        # Save how many characters have been printed per session
+        self.printed_chars = 0
+
         self._run = True
         self._tx_thread = Thread(target=self.thread_tx, name='ED1000tx')
         self._tx_thread.start()
         self._rx_thread = Thread(target=self.thread_rx, name='ED1000rx')
         self._rx_thread.start()
 
-
     def __del__(self):
         super().__del__()
 
@@ -131,9 +137,6 @@ def _check_commands(self, a:str):
 
     def _set_online(self, online:bool):
         if online:
-            # Start timer in MCP if we're going from offline to online
-            if not self._is_online.is_set():
-                self._rx_buffer.append('\x1bAC')
             l.debug("set online")
             self._is_online.set()
         else:
@@ -184,6 +187,8 @@ def thread_tx(self):
                 elif 20 <= self._rx_state <= 30:
                     if self._tx_buffer:
                         a = self._tx_buffer.pop(0)
+                        if len(a) == 1:
+                            self.printed_chars += 1
                         l.debug("[tx] Sending {!r} (buffer length {})".format(a, len(self._tx_buffer)))
                         if a == '§W':   # signal WB (ready for dial)
                             bb = (0xF9FFFFFF,)   # 40ms pulse after 500ms pause, may be interpreted as 'V'
@@ -352,8 +357,6 @@ def thread_rx(self):
                 #   properly wait for a stable Z reading.
                 if _bit_counter_1 >= 20:
                     self._rx_state = 20
-                    # Send printer start confirmation
-                    self._rx_buffer.append('\x1bACK')
                     # Reset character recognition
                     slice_counter = 0
                 # If the teleprinter doesn't switch to Z, but stays in A for at
@@ -395,7 +398,7 @@ def thread_rx(self):
             elif self._rx_state == 30: # going offline by ESC-Z ================
                 # Write out tx buffer
                 if not self._tx_buffer:
-                    l.info("[rx] tx buffer empty")
+                    l.info("[rx] tx buffer empty, printed characters: {}".format(self.printed_chars))
                     self._rx_state = 40
                 # ... but break on ST (if the operator wishes to go offline
                 # immediately).
@@ -432,6 +435,7 @@ def thread_rx(self):
                     self._rx_state = 0
                     _bit_counter_0 = 0
                     _bit_counter_1 = 0
+                    self.printed_chars = 0
                     l.debug("[rx] Received A level, offline confirmed")
 
             #l.debug("[rx] _is_online: {} bit: {}".format(self._is_online.is_set(), bit))
@@ -618,5 +622,29 @@ def _recv_decode_FIR(self, data):
             bit = None
         return bit
 
+    def idle2Hz(self):
+        # Send printer feedback (ESC-~)
+        # It contains the current printer buffer length, i.e. the number of
+        # characters that remain to be printed.
+        #
+        # Printer feedback is sent only after the printer has been started, so
+        # it doubles as a printer start feedback.
+        printer_online = (20 <= self._rx_state <= 30)
+        if printer_online or self._send_feedback:
+            tx_buf_len = len(self._tx_buffer)
+            if not self._send_feedback:
+                self._send_feedback = True
+                # We came online, send buffer length as printer start feedback
+                self._rx_buffer.append('\x1b~' + str(tx_buf_len))
+            elif self._last_tx_buf_len != tx_buf_len:
+                # Normal feedback (when buffer changed)
+                self._rx_buffer.append('\x1b~' + str(tx_buf_len))
+
+            if not printer_online:
+                # We went offline: turn off feedback
+                self._send_feedback = False
+
+            self._last_tx_buf_len = tx_buf_len
+
 #######
 

txDevITelexClient.py

@@ -56,6 +56,7 @@ def read(self) -> str:
 
 
     def write(self, a:str, source:str):
+        super().write(a, source)
         l.debug("write from {!r}: {!r}".format(source, a))
         if len(a) != 1:
             if a == '\x1bZ':   # end session
@@ -144,6 +145,7 @@ def thread_connect_as_client(self, user):
 
         s.close()
         self._rx_buffer.append('\x1bZ')
+        self._printer_running = False
 
     # =====