- merge pip3 requests

bad_network_start.sh

@@ -0,0 +1,7 @@
+#!/bin/bash
+
+# Oneliner to find script's directory. Please note - last path component should NOT be symlink.
+SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]:-$0}"; )" &> /dev/null && pwd 2> /dev/null; )";
+
+/usr/bin/python3 ${SCRIPT_DIR}/src/utils_network_impairment.py --start
+

bad_network_stop.sh

@@ -0,0 +1,6 @@
+#!/bin/bash
+
+# Oneliner to find script's directory. Please note - last path component should NOT be symlink.
+SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]:-$0}"; )" &> /dev/null && pwd 2> /dev/null; )";
+
+/usr/bin/python3 ${SCRIPT_DIR}/src/utils_network_impairment.py --stop

config/agent.in.yaml

@@ -16,36 +16,18 @@ force_task:             no
 # Use lite speech_detector instead of silence_eraser
 speech_detector:        yes
 
-# Reboot the phone on start
-reboot_on_start:        no
-
-# adb watchdog check interval
-phone_watchdog_interval: 180
-
 # RabbitMQ related settings
 rabbitmq:
     url:                
     exchange:           
     queue:              
 
+cache_dir:              cache
 audio:
-    # Audio device used to play audio
-    play_device:        "auto"
-    
-    # Audio device used to record audio
-    record_device:      "auto"
-    
-    # Use native audio utilities from alsa-utils package instead of PyAudio based implementation
-    ALSA:               yes
-    
-    # Use samplerate
-    samplerate:         48000
-
     # Silence prefix & suffix lengths (in seconds)
     silence_prefix:     30
     silence_suffix:     30
     
-    bluetooth:          yes
     bluetooth_mac:      "MAC_ADDRESS"
 
 log:
@@ -55,11 +37,3 @@ log:
     # Verbose logging
     verbose:            yes
     
-    # Log ADB output
-    adb:                yes
-    
-    # Upload full audio recordings
-    audio:              yes
-    
-    # Where to keep audio
-    audio_dir:          /dev/shm

config/systemd/agent_gsm.in.service

@@ -19,7 +19,7 @@ KillSignal=SIGQUIT
 
 # make sure log directory exists and owned by syslog
 PermissionsStartOnly=true
-ExecStartPre=/usr/bin/rm -f ABSOLUTE_INSTALL_DIR/qualtest.pid
+ExecStartPre=/usr/bin/rm -f /dev/shm/qualtest.pid
 
 #ExecStartPre=/bin/chown syslog:adm /var/log/sleepservice
 #ExecStartPre=/bin/chmod 755 /var/log/sleepservice

debug_node.sh

@@ -0,0 +1,28 @@
+#!/bin/bash
+
+# Oneliner to find script's directory. Please note - last path component should NOT be symlink.
+SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]:-$0}"; )" &> /dev/null && pwd 2> /dev/null; )";
+
+
+DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
+
+# DBUS_SESSION_BUS_PID=`cat /run/dbus/pid`
+
+export DBUS_SESSION_BUS_ADDRESS
+# export DBUS_SESSION_BUS_PID
+
+# To avoid problems with pulseaudio
+pkill pulseaudio
+
+while true; do
+    read -p "Do you wish to enable bad network simulation for gsm.sevana.biz ? " yn
+    case $yn in
+	[Yy]* ) $SCRIPT_DIR/start_bad_network.sh; break;;
+        [Nn]* ) exit;;
+        * ) echo "Please answer yes or no.";;
+    esac
+done
+
+# Ensure BT stack is here
+python3 -u $SCRIPT_DIR/src/bt_preconnect.py $SCRIPT_DIR/config/agent.yaml
+python3 -u $SCRIPT_DIR/src/agent_gsm.py --config $SCRIPT_DIR/config/agent.yaml --test

pi_bootstrap_bt.sh

@@ -120,7 +120,6 @@ function enable-headset-ofono()
 function install_python_pkg()
 {
     info 'installing python libraries'
-    pip install pexpect
     pip3 install pexpect rabbitmq sox soundfile pyyaml
 }
 

run_agent.sh

@@ -0,0 +1,14 @@
+#!/bin/bash
+
+# Oneliner to find script's directory. Please note - last path component should NOT be symlink.
+SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]:-$0}"; )" &> /dev/null && pwd 2> /dev/null; )";
+
+
+while :
+do
+    # To avoid problems with pulseaudio
+    python3 -u $SCRIPT_DIR/src/agent_kill.py
+    pkill pulseaudio
+
+    python3 -u $SCRIPT_DIR/src/agent_gsm.py --config $SCRIPT_DIR/config/agent.yaml
+done

run_agent_screen.sh

@@ -0,0 +1,6 @@
+#!/bin/bash
+
+# Oneliner to find script's directory. Please note - last path component should NOT be symlink.
+SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]:-$0}"; )" &> /dev/null && pwd 2> /dev/null; )";
+
+/usr/bin/screen -L -Logfile $SCRIPT_DIR/agent_gsm_screen.log -d -m $SCRIPT_DIR/run_agent.sh

run_node.sh

@@ -12,10 +12,13 @@ export DBUS_SESSION_BUS_ADDRESS
 # export DBUS_SESSION_BUS_PID
 
 # To avoid problems with pulseaudio
+python3 -u $SCRIPT_DIR/src/agent_kill.py
+
 pkill pulseaudio
 
+
 # Ensure BT stack is here
-python3 -u $SCRIPT_DIR/src/bt_preconnect.py $SCRIPT_DIR/config/agent.yaml
+# python3 -u $SCRIPT_DIR/src/bt_preconnect.py $SCRIPT_DIR/config/agent.yaml
 
 #!/bin/bash
 if [ -n "$1" ]

setup/setup_agent_gsm.sh

@@ -1,15 +1,17 @@
 #!/bin/bash
 
+# Refresh apt database
+sudo apt update
+
 # Installation directory
 INSTALL_DIR=agent_gsm
 
 # Re
-GIT_SOURCE=https://git.sevana.biz/public/agent_gsm_redist
+GIT_SOURCE=https://git.sevana.biz/public/agent_gsm
 
 # Install prerequisites
-sudo apt install --assume-yes git mc python3 sox vim libffi-dev
-sudo pip3 install pyyaml sox pyrabbit soundfile dbus_python pexpect pydub requests
-sudo pip3 install rabbitpy pydub
+sudo apt install --assume-yes git mc python3 sox vim libffi-dev screen python3-pip python3-numpy
+sudo pip3 install pyyaml sox pyrabbit soundfile dbus_python pexpect pydub requests rabbitpy pydub
 
 if [ -f "$INSTALL_DIR" ]; then
     rm -rf "$INSTALL_DIR"
@@ -25,13 +27,24 @@ cd $INSTALL_DIR
 BACKEND_URL=""
 PHONE_NAME=""
 TASK_NAME=""
-read -p "Please specify backend URL (ex: https://gsm.sevana.biz ): " BACKEND_URL
+
+# Backend URL
+read -p "Please specify backend URL [https://gsm.sevana.biz] ): " BACKEND_URL
+BACKEND_URL=${BACKEND_URL:-"https://gsm.sevana.biz"}
+
+# Device name
 read -p "Please specify phone name (ex: moto_1): " PHONE_NAME
+
+# Optional task name
 read -p "Please specify expected task name (if this is answerer phone): " TASK_NAME
 
 # Get a copy of config file from redist
 cp config/agent.in.yaml config/agent.yaml
 
+# Update mc settings to ease further work
+mkdir -p ~/.config/mc
+cp config/mc/ini ~/.config/mc
+
 # Replace the values
 if [[ $BACKEND_URL != "" ]]; then
   sed -i "s|BACKEND|$BACKEND|" config/agent.yaml

src/.vscode/launch.json

@@ -4,14 +4,6 @@
     // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
     "version": "0.2.0",
     "configurations": [
-        {
-            "name": "Example: answerer",
-            "type": "python",
-            "request": "launch",
-            "program": "example_answer.py",
-            "console": "integratedTerminal",
-            "args": [""]
-        },
         {
             "name": "rabbitmq: utils_mcon",
             "type": "python",

src/agent_config.py

@@ -0,0 +1,137 @@
+#!/usr/bin/python3
+
+from pathlib import Path
+import argparse
+import sys
+import yaml
+
+class AgentConfig:
+    Name: str
+    Backend: str
+
+    # Name of intermediary file with audio recorded from the GSM phone
+    RecordFile = Path('/dev/shm/qualtest_recorded.wav')
+
+    # Prepared reference audio to play
+    PreparedReferenceAudio = Path('/dev/shm/reference_ready.wav')
+
+    # Reference audio to play
+    ReferenceAudio = Path('/dev/shm/reference_original.wav')
+
+    # Loaded reference audio (from backend)
+    LoadedAudio = Path('/dev/shm/loaded_audio.wav')
+
+    # Script to exec after mobile call answering
+    ExecScript : Path = None
+
+    # Backup directory (to run without internet)
+    CacheDir : Path = None
+
+    # PID file name
+    QualtestPID = Path('/dev/shm/qualtest.pid')
+
+    # Check (or not) PID file presence on the start
+    CheckPIDFile: bool = False
+
+    # Should the first task run immediately ?
+    ForceRun = False
+
+    # Use silence eraser or not (speech detector is used in this case)
+    UseSilenceEraser = True
+
+    # Path to log file
+    LogPath : Path = None
+
+    # Phone's BT MAC address
+    BT_MAC : str = None
+
+    # Verbose logging or not
+    Verbose: bool = False
+
+    # Task limit per single run
+    TaskLimit: int = 10000000
+
+    # How to modify reference audio before play
+    SilenceSuffix: int = 0
+    SilencePrefix: int = 0
+    
+    # Task name (used for answering only)
+    TaskName: str = None
+
+    def parser(self) -> argparse.ArgumentParser:
+        parser = argparse.ArgumentParser()
+        parser.add_argument("--config",         help="Path to config file, see config.in.yaml.")
+        parser.add_argument("--check-pid-file", action="store_true", help="Check if .pid file exists and exit if yes. Useful for using with .service files")
+        parser.add_argument("--test",           action="store_true", help="Run the first task immediately. Useful for testing.")
+        
+        return parser
+    
+
+    def __init__(self) -> None:
+        p = self.parser()
+        
+        # Parse arguments
+        args = p.parse_args()
+
+        if args.test:
+            self.ForceRun = True
+
+        if args.check_pid_file:
+            self.CheckPIDFile = True    
+
+        if args.config:
+            config_path = args.config
+
+            with open(config_path, 'r') as stream:
+                config = yaml.safe_load(stream)
+
+            if config['force_task']:
+                self.ForceRun = True
+
+            if 'speech_detector' in config:
+                if config['speech_detector']:
+                    self.UseSilenceEraser = False
+
+            if 'audio' in config:
+                audio = config['audio']
+                if 'bluetooth_mac' in audio:
+                    self.BT_MAC = audio['bluetooth_mac']
+                if 'silence_suffix' in audio:
+                    self.SilenceSuffix = audio['silence_suffix']
+                if 'silence_prefix' in audio:
+                    self.SilencePrefix = audio['silence_prefix']
+
+            # Logging settings
+            if 'log' in config:
+                if 'verbose' in config['log']:
+                    self.Verbose = config['log']['verbose']
+
+                if 'path' in config['log']:
+                    path = config['log']['path']
+                    if path is not None and len(path) > 0:
+                        path = Path(path)
+                        if not path.is_absolute():
+                            path = Path(__file__).parent.parent / path
+
+                        self.LogPath = path
+
+
+            # Audio directories
+            if 'cache_dir' in config:
+                self.CacheDir = Path(config['cache_dir'])
+                if not self.CacheDir.is_absolute():
+                    self.CacheDir = Path(__file__).parent.parent / config['cache_dir']
+
+            if 'task_limit' in config:
+                self.TaskLimit = int(config['task_limit'])
+
+            if 'name' in config:
+                self.Name = config['name']
+
+            if 'backend' in config:
+                self.Backend = config['backend']
+
+            if 'task' in config:
+                self.TaskName = config['task']
+
+            

src/agent_gsm.py

@@ -1,47 +1,31 @@
 #!/usr/bin/python3
 
 import os
-import platform
-import json
-import subprocess
 import time
 import argparse
 import sys
-import shlex
-import select
 import uuid
+import json
+import multiprocessing
+import signal
+import atexit
+from pathlib import Path
+
 import utils_qualtest
 import utils_sevana
-import utils_mcon
-import utils_logcat
 import utils
+import utils_cache
+from utils_types import (EXIT_ERROR, EXIT_OK)
+from agent_config import AgentConfig
+
 from bt_controller import Bluetoothctl
-import bt_call_controller
 import bt_signal
 from bt_signal import SignalBoundaries
+from bt_call_controller import INTERRUPT_SIGNAL
+import bt_call_controller
 
-import multiprocessing
-import shutil
-import signal
-import yaml
-import pathlib
-from pathlib import Path
-from datetime import datetime
 
-# Name of intermediary file with audio recorded from the GSM phone
-RECORD_FILE = "/dev/shm/qualtest_recorded.wav"
-
-# Backend instance
-BackendServer : utils_qualtest.QualtestBackend = None
-
-# Reference audio to play
-REFERENCE_AUDIO = "/dev/shm/reference.wav"
-
-# Loaded refernce audio (from backend)
-LOADED_AUDIO = Path("/dev/shm/loaded_audio.wav")
-
-# Script to exec after mobile call answering
-EXEC_SCRIPT = None
+CONFIG = AgentConfig()
 
 # Current task name.
 CURRENT_TASK = None
@@ -52,30 +36,18 @@ TASK_LIST: utils_qualtest.TaskList = utils_qualtest.TaskList()
 # Number of finished calls
 CALL_COUNTER = multiprocessing.Value('i', 0)
 
-# Maximum number of calls to to. Zero means unlimited number of calls.
-CALL_LIMIT = 0
-
 # Find script's directory
 DIR_THIS = Path(__file__).resolve().parent
+DIR_PROJECT = DIR_THIS.parent
 
-# PID file name
-QUALTEST_PID = DIR_THIS / "qualtest.pid"
+# Backup directory (to run without internet)
+CACHE = utils_cache.InfoCache(None)
 
-# Keep the recorded audio in the directory 
-LOG_AUDIO = False
+# Backend instance
+BACKEND : utils_qualtest.QualtestBackend = None
 
-# Recorded audio directory
-LOG_AUDIO_DIR = DIR_THIS.parent / 'log_audio'
-
-# Should the first task run immediately ?
-FORCE_RUN = False
-
-# Exit codes
-EXIT_OK = 0
-EXIT_ERROR = 1
-
-# Use silence eraser or not (speech detector is used in this case)
-USE_SILENCE_ERASER = True
+# ANalyzer binaries found or not ?
+VOICE_QUALITY_AVAILABLE = False
 
 def remove_oldest_log_audio():
     list_of_files = os.listdir(LOG_AUDIO_DIR)
@@ -87,10 +59,10 @@ def remove_oldest_log_audio():
 
 
 def detect_degraded_signal(file_test: Path, file_reference: Path) -> SignalBoundaries:
-    global USE_SILENCE_ERASER, LOG_AUDIO, LOG_AUDIO_DIR, BackendServer
+    global USE_SILENCE_ERASER, LOG_AUDIO_DIR, BACKEND
 
-    is_caller : bool = 'caller' in BackendServer.phone.role
-    is_answerer : bool = 'answer' in BackendServer.phone.role
+    is_caller : bool = 'caller' in BACKEND.phone.role
+    is_answerer : bool = 'answer' in BACKEND.phone.role
 
     if utils.get_wav_length(file_test) < utils.get_wav_length(file_reference):
         # Seems some problem with recording, return zero boundaries
@@ -105,32 +77,80 @@ def detect_degraded_signal(file_test: Path, file_reference: Path) -> SignalBound
 
 
 def detect_reference_signal(file_reference: Path) -> SignalBoundaries:
-    global USE_SILENCE_ERASER, LOG_AUDIO, LOG_AUDIO_DIR
     # Run silence eraser on reference file as well
-
     result = bt_signal.find_reference_signal(file_reference)
-
     return result
 
 
+def upload_results():
+    utils.log(f'Uploading remaining results...')
+    probe_list = CACHE.get_probe_list()
+    for t in probe_list:
+        # Path to .json report
+        path_report = t[0]
+
+        # Path to audio
+        path_audio = t[1]
+
+        utils.log(f'Found {path_report.name} and {path_audio.name} files.')
+        try:
+            with open(path_report, 'rt') as f:
+                report = json.loads(f.read())
+        except:
+            utils.log_error(f'Error when processing {path_report.name}')
+            continue
+
+        upload_id, success = BACKEND.upload_report(report, cache=None) 
+        if success:
+            utils.log(f'Report {upload_id} is uploaded ok.')
+            
+            # Rename files to make sync audio filename with reported ones
+            # path_report_fixed = CACHE.dir / f'{upload_id}.json'
+            # path_report = path_report.rename(path_report_fixed)
+
+            # path_audio_fixed = CACHE.dir / f'{upload_id}.wav'
+            # path_audio = path_audio.rename(path_audio_fixed)
+            if path_audio.exists():
+                utils.log(f'Uploading {path_audio.name} file...')
+                # Upload recorded audio
+                upload_result = BACKEND.upload_audio(upload_id, path_audio)
+                if upload_result:
+                    utils.log(f'  Recorded audio {upload_id}.wav is uploaded ok.')
+                os.remove(path_audio)
+            else:
+                utils.log(f'No recorded audio file found, skipping audio upload.')
+            os.remove(path_report)
+            
+        else:
+            utils.log(f'Failed to upload report {path_report.name}')
+            break
+        
 def run_analyze(file_test: str, file_reference: str, number: str) -> bool:
     global CALL_COUNTER
 
     result = False
-
-    if file_test:
+    if not VOICE_QUALITY_AVAILABLE:
+        utils.log('Voice quality analyzers are not available, skipping analysis.')
+        return
+        
+    if file_test.exists():
         # Wait 5 seconds to give a chance to flush recorded file
         time.sleep(5.0)
 
         # Check how long audio file is
-        audio_length = utils.get_wav_length(file_test)
+        test_audio_length = round(utils.get_wav_length(file_test), 3)
+        ref_audio_length = round(utils.get_wav_length(file_reference), 3)
+
+        is_caller : bool = 'caller' in BACKEND.phone.role
+        is_answerer : bool = 'answer' in BACKEND.phone.role
         
-        is_caller : bool = 'caller' in BackendServer.phone.role
-        is_answerer : bool = 'answer' in BackendServer.phone.role
+        utils.log(f'Recorded audio call duration: {test_audio_length}s, reference audio length: {ref_audio_length}s')
         
-        utils.log(f'Recorded audio call duration: {round(audio_length, 3)}s')
         # Check if audio length is strange - skip such calls. Usually this is missed call.
-        if (is_caller and audio_length >= utils_mcon.TIME_LIMIT_CALL) or (is_answerer and audio_length >= utils_mcon.TIME_LIMIT_CALL * 1.2):
+        is_caller_audio_big = is_caller and test_audio_length > ref_audio_length * 1.5
+        is_answerer_audio_big = is_answerer and test_audio_length > ref_audio_length * 1.5
+
+        if is_caller_audio_big or is_answerer_audio_big:
             utils.log_error(f'Recorded call is too big - looks like mobile operator prompt, skipping analysis')
             return False
         
@@ -138,12 +158,7 @@ def run_analyze(file_test: str, file_reference: str, number: str) -> bool:
             bounds_signal : SignalBoundaries = detect_degraded_signal(Path(file_test), Path(file_reference))
             # bounds_signal.offset_start = 0
             # bounds_signal.offset_finish = 0
-
             print(f'Found signal bounds: {bounds_signal}')
-            # Check if there is a time to remove oldest files
-            if LOG_AUDIO:
-                remove_oldest_log_audio()
-                remove_oldest_log_audio()
 
             # PVQA report
             pvqa_mos, pvqa_report, pvqa_rfactor = utils_sevana.find_pvqa_mos(file_test, bounds_signal.offset_start, bounds_signal.offset_finish)
@@ -177,36 +192,37 @@ def run_analyze(file_test: str, file_reference: str, number: str) -> bool:
                 r['report_pvqa'] = pvqa_report
                 r['report_aqua'] = aqua_report
                 r['r_factor'] = pvqa_rfactor
-                r["percents_aqua"] = aqua_percents
+                r['percents_aqua'] = aqua_percents
                 r['error'] = ''
                 r['target'] = number
                 r['audio_id'] = 0
             
-            r['phone_id'] = BackendServer.phone.identifier
+            r['phone_id'] = BACKEND.phone.identifier
             r['phone_name'] = ''
             r['task_id'] = 0
             r['task_name'] = CURRENT_TASK
             
             # Upload report
-            upload_id = BackendServer.upload_report(r, []) 
-            if upload_id != None:
+            upload_id, success = BACKEND.upload_report(r, cache=CACHE) 
+            if success:
                 utils.log('Report is uploaded ok.')
 
                 # Upload recorded audio
-                upload_result = BackendServer.upload_audio(r['id'], file_test)
+                upload_result = BACKEND.upload_audio(r['id'], file_test)
 
                 if upload_result:
-                    utils.log('Recorded audio is uploaded ok.')
+                    utils.log('  Recorded audio is uploaded ok.')
                     result = True
                 else:
-                    utils.log_error('Recorded audio is not uploaded.')
+                    utils.log_error('  Recorded audio is not uploaded.')
+                    CACHE.add_recorded_audio(file_test, probe_id=upload_id)
             else:
-                utils.log_error('Failed to upload report.')
+                CACHE.add_recorded_audio(file_test, probe_id=upload_id)
 
         except Exception as e:
             utils.log_error(e)    
     else:
-        utils.log_error('Seems the file is not recorded. Usually it happens because adb logcat is not stable sometimes. Return signal to restart')
+        utils.log_error('Seems the file is not recorded. Skipping analysis and upload.')
         
     # Increase finished calls counter
     CALL_COUNTER.value = CALL_COUNTER.value + 1
@@ -220,53 +236,75 @@ def run_error(error_message: str):
 
     
 def make_call(target: str):
-    global REFERENCE_AUDIO
-
     # Remove old recorded file
-    record_file = '/dev/shm/bt_record.wav'
-    # if Path(record_file).exists():
-    #     os.remove(record_file)
+    if CONFIG.RecordFile.exists():
+         os.remove(CONFIG.RecordFile)
 
     # Add prefix and suffix silence for reference to give a chance to record all the file
-    reference_filename = '/dev/shm/prepared_reference.wav'
-    utils.prepare_reference_file(fname=REFERENCE_AUDIO, silence_prefix_length=10.0, silence_suffix_length=5.0, output_fname=reference_filename)
+    utils.log(f'Preparing reference file...')
+    if CONFIG.PreparedReferenceAudio.exists():
+        os.remove(CONFIG.PreparedReferenceAudio)
+    utils.prepare_reference_file(fname=str(CONFIG.ReferenceAudio), 
+                                 silence_prefix_length=CONFIG.SilencePrefix, 
+                                 silence_suffix_length=CONFIG.SilenceSuffix, 
+                                 output_fname=str(CONFIG.PreparedReferenceAudio))
     
     # Find duration of prepared reference file
-    reference_length = int(utils.get_wav_length(reference_filename))
+    ref_time_length = round(utils.get_wav_length(CONFIG.PreparedReferenceAudio), 3)
+    utils.log(f' Done. Length of prepared reference audio file: {ref_time_length}s')
 
     # Compose a command
-    cmd = f'/usr/bin/python3 {DIR_THIS}/bt_call_controller.py --play-file {reference_filename} --record-file {record_file} --timelimit {reference_length} --target {target}'
-    retcode = os.system(cmd)
-    if retcode != 0:
-        utils.log_error(f'BT caller script exited with non-zero code {retcode}, skipping analysis.')
-    else:
-        run_analyze(record_file, REFERENCE_AUDIO, target)
-
+    # utils.close_log_file()
+    try:
+        bt_call_controller.run(play_file=CONFIG.PreparedReferenceAudio, 
+                               record_file=CONFIG.RecordFile, 
+                               timelimit_seconds=ref_time_length, 
+                               target=target)
+        
+        run_analyze(CONFIG.RecordFile, CONFIG.ReferenceAudio, target)
+    except Exception as e:
+        utils.log_error(f'BT I/O failed finally. Error: {str(e)}')
+                        
 
 def perform_answerer():
-    global CALL_LIMIT
+    if CONFIG.PreparedReferenceAudio.exists():
+        os.remove(CONFIG.PreparedReferenceAudio)
 
+    # Prepare answering file - this must be prepended with few seconds of silence which can be eatean by call setup procedure
+    utils.prepare_reference_file(fname=str(CONFIG.ReferenceAudio), 
+                                 silence_prefix_length=CONFIG.SilencePrefix, 
+                                 silence_suffix_length=CONFIG.SilenceSuffix, 
+                                 output_fname=str(CONFIG.PreparedReferenceAudio))
+    
     # Get reference audio duration in seconds
-    reference_length = utils.get_wav_length(REFERENCE_AUDIO)
+    ref_time_length = round(utils.get_wav_length(CONFIG.PreparedReferenceAudio), 3)
     
     # Setup analyzer script
     # Run answering script
-    while True:
+    attempt_idx = 0
+    while attempt_idx < CONFIG.TaskLimit or CONFIG.TaskLimit is None or CONFIG.TaskLimit == 0:
         # Remove old recording
-        record_file = f'/dev/shm/bt_record.wav'
+        if CONFIG.RecordFile.exists():
+            os.remove(CONFIG.RecordFile)
 
-        cmd = f'/usr/bin/python3 {DIR_THIS}/bt_call_controller.py --play-file {REFERENCE_AUDIO} --record-file {record_file} --timelimit {int(reference_length)}'
-        retcode = os.system(cmd)
-        if retcode != 0:
-            utils.log(f'Got non-zero exit code {retcode} from BT call controller, exiting.')
+        try:
+            bt_call_controller.run(play_file=CONFIG.PreparedReferenceAudio, 
+                                   record_file=CONFIG.RecordFile, 
+                                   timelimit_seconds=int(ref_time_length), 
+                                   target=None)
+        except Exception as e:
+            utils.log(f'BT I/O failed, exiting. Error: {str(e)}')
             break
 
         # Call analyzer script
-        run_analyze(record_file, REFERENCE_AUDIO, '')
+        run_analyze(CONFIG.RecordFile, CONFIG.ReferenceAudio, '')
+        
+        # Increase counter of attempts
+        attempt_idx += 1
 
 
 def run_caller_task(t):
-    global CURRENT_TASK, LOADED_AUDIO, REFERENCE_AUDIO
+    global CURRENT_TASK
 
     utils.log("Running task:" + str(t))
 
@@ -278,15 +316,23 @@ def run_caller_task(t):
     task_name = t['name'].strip()
 
     # Load reference audio
-    if LOADED_AUDIO.exists():
-        os.remove(LOADED_AUDIO)
+    if CONFIG.LoadedAudio.exists():
+        os.remove(CONFIG.LoadedAudio)
+
+    audio_id = t["audio_id"]
+    if CACHE.get_reference_audio(audio_id, CONFIG.LoadedAudio):
+        utils.log(f'Reference audio {audio_id} found in cache.')
+    else:
+        utils.log(f'Reference audio {audio_id} not found in cache.')
+        if not BACKEND.load_audio(audio_id, CONFIG.LoadedAudio):
+            utils.log_error(f'Failed to load reference audio with ID {audio_id}.')
+            raise RuntimeError(f'Reference audio (ID: {audio_id}) is not available.')
+
+        # Cache loaded audio
+        CACHE.add_reference_audio(audio_id, CONFIG.LoadedAudio)
 
-    if not BackendServer.load_audio(t["audio_id"], LOADED_AUDIO):
-        utils.log_error('No audio is available, exiting.')
-        sys.exit(EXIT_ERROR)
-    
     # Use loaded audio as reference
-    REFERENCE_AUDIO = str(LOADED_AUDIO)
+    CONFIG.ReferenceAudio = str(CONFIG.LoadedAudio)
 
     CURRENT_TASK = task_name
 
@@ -311,34 +357,45 @@ def run_caller_task(t):
 
 # Runs caller probe - load task list and perform calls
 def run_probe():
-    global TASK_LIST, REFERENCE_AUDIO, LOADED_AUDIO, CURRENT_TASK, FORCE_RUN
+    global TASK_LIST, CURRENT_TASK
 
     while True:
         # Get task list update
-        tasks = BackendServer.load_tasks()
-        # Did we fetch anything ?
-        if tasks:
-            # Merge with existing ones. Some tasks can be removed, some can be add.
-            changed = TASK_LIST.merge_with(tasks)
-        else:
-            utils.log_verbose(f"No task list assigned, exiting.")
-            sys.exit(EXIT_ERROR)
+        new_tasks = BACKEND.load_tasks()
+        if new_tasks is None:
+            # Check in cache
+            utils.log('Checking for task list in cache...')
+            new_tasks = CACHE.get_tasks(BACKEND.phone.name)
 
+        # Did we fetch anything ?
+        if new_tasks:
+            utils.log(f'  Task list found.')
+            # Merge with existing ones. Some tasks can be removed, some can be add.
+            changed = TASK_LIST.merge_with(incoming_tasklist = new_tasks)
+            CACHE.put_tasks(name=BACKEND.phone.name, tasks=TASK_LIST)
+        else:
+            utils.log('  Task isn\'t found in cache.')
+            raise RuntimeError(f'No task list found, exiting.')
+
+        if len(TASK_LIST.tasks) == 0:
+            utils.log(f'Task list is empty, exiting from running loop')
+            return
+        
         # Sort tasks by triggering time
         TASK_LIST.schedule()
         if TASK_LIST.tasks is not None:
             utils.log_verbose(f"Resulting task list: {TASK_LIST.tasks}")
 
 
-        if FORCE_RUN and len(TASK_LIST.tasks) > 0:
+        if CONFIG.ForceRun and len(TASK_LIST.tasks) > 0:
             run_caller_task(TASK_LIST.tasks[0])
             break
         
         # Process tasks and measure spent time
-        start_time = time.monotonic()
+        start_time = utils.get_monotonic_time()
 
         for t in TASK_LIST.tasks:
-            if t["scheduled_time"] <= time.monotonic():
+            if t["scheduled_time"] <= utils.get_monotonic_time():
                 if t["command"] == "call":
                     try:
                         # Remove sheduled time
@@ -348,15 +405,15 @@ def run_probe():
                         run_caller_task(t)
                         
                         utils.log_verbose(f'Call #{CALL_COUNTER.value} finished')
-                        if CALL_COUNTER.value >= CALL_LIMIT and CALL_LIMIT > 0:
+                        if CALL_COUNTER.value >= CONFIG.TaskLimit and CONFIG.TaskLimit > 0:
                             # Time to exit from the script
-                            utils.log(f'Call limit {CALL_LIMIT} hit, exiting.')
+                            utils.log(f'Call limit {CONFIG.TaskLimit} hit, exiting.')
                             return
 
                     except Exception as err:
                         utils.log_error(message="Unexpected error.", err=err)
 
-            spent_time = time.monotonic() - start_time
+            spent_time = utils.get_monotonic_time() - start_time
 
             # Wait 1 minute
             if spent_time < 60:
@@ -367,192 +424,150 @@ def run_probe():
             time.sleep(60)
 
 
+def remove_pid_on_exit():
+    if CONFIG.QualtestPID:
+        if CONFIG.QualtestPID.exists():
+            os.remove(CONFIG.QualtestPID)
+
+
 def receive_signal(signal_number, frame):
+    global INTERRUPT_SIGNAL
+
     # Delete PID file
-    if os.path.exists(QUALTEST_PID):
-        os.remove(QUALTEST_PID)
+    remove_pid_on_exit()
     
     # Debugging info
     print(f'Got signal {signal_number} from {frame}')
     
-    # Stop GSM call
-    utils_mcon.gsm_stop_call()
-    
+    # This it to break BT play controller
+    INTERRUPT_SIGNAL = True
+
     # Exit
     raise SystemExit('Exiting')
     return
 
 
+
 # Check if Python version is ok
 assert sys.version_info >= (3, 6)
 
 # Use later configuration files
 # https://stackoverflow.com/questions/3609852/which-is-the-best-way-to-allow-configuration-options-be-overridden-at-the-comman
 
+if __name__ == '__main__':
+    CONFIG = AgentConfig()
+    if len(sys.argv) < 2:
+        CONFIG.parser().print_help()
+        sys.exit(EXIT_OK)
 
-parser = argparse.ArgumentParser()
-parser.add_argument("--config",         help="Path to config file, see config.in.yaml.")
-parser.add_argument("--check-pid-file", action="store_true", help="Check if .pid file exists and exit if yes. Useful for using with .service files")
-parser.add_argument("--test",           action="store_true", help="Run the first task immediately. Useful for testing.")
+    if CONFIG.QualtestPID.exists() and CONFIG.CheckPIDFile:
+        print(f'File {CONFIG.QualtestPID} exists, seems another instance of script is running. Please delete {CONFIG.QualtestPID} to allow the start.')
+        sys.exit(EXIT_OK)
 
-# Parse arguments
-args = parser.parse_args()
+    # Remove PID file on exit (if needed)
+    atexit.register(remove_pid_on_exit)
 
-# Show help and exit if required
-if len(sys.argv) < 2:
-    parser.print_help()
-    sys.exit(EXIT_OK)
+    # register the signals to be caught
+    signal.signal(signal.SIGINT, receive_signal)
+    signal.signal(signal.SIGQUIT, receive_signal)
 
-if args.test:
-    FORCE_RUN = True
-    
-if Path(QUALTEST_PID).exists() and args.check_pid_file:
-    print(f'File {QUALTEST_PID} exists, seems another instance of script is running. Please delete {QUALTEST_PID} to allow the start.')
-    sys.exit(EXIT_OK)
-
-# Check if config file exists
-config = None
-config_path = 'config.yaml'
-
-if args.config:
-    config_path = args.config
-
-with open(config_path, 'r') as stream:
-    config = yaml.safe_load(stream)
-
-
-# register the signals to be caught
-signal.signal(signal.SIGINT, receive_signal)
-signal.signal(signal.SIGQUIT, receive_signal)
-# signal.signal(signal.SIGTERM, receive_signal)
-# SIGTERM is sent from utils_mcon as well (multiprocessing?)
-
-# Override default audio samplerate if needed
-if 'samplerate' in config['audio']:
-    if config['audio']['samplerate']:
-        utils_mcon.SAMPLERATE = int(config['audio']['samplerate'])
-
-if config['force_task']:
-    FORCE_RUN = True
-
-if 'speech_detector' in config:
-    if config['speech_detector']:
-        USE_SILENCE_ERASER = False
-
-if 'bluetooth_mac' in config['audio']:
-    bt_mac = config['audio']['bluetooth_mac']
-    if len(bt_mac) > 0:
+    # Preconnect the phone
+    if CONFIG.BT_MAC:
         # Connect to phone before
+        utils.log(f'Connecting to BT MAC {CONFIG.BT_MAC} ...')
         bt_ctl = Bluetoothctl()
-        bt_ctl.connect(bt_mac)
+        bt_ctl.connect(CONFIG.BT_MAC)
+        utils.log(f'  Done.')
+    else:
+        utils.log_error(f'No BT MAC specified, cannot connect. Exiting.')
+        raise SystemExit(EXIT_ERROR)
+    
+    # Init BT modem
+    bt_call_controller.init()
 
-# Logging settings
-utils.verbose_logging = config['log']['verbose']
+    # Logging settings
+    utils.verbose_logging = CONFIG.Verbose
 
-if config['log']['path']:
-    utils.open_log_file(config['log']['path'], 'wt')
-
-# Use native ALSA utilities on RPi
-if utils.is_raspberrypi():
-    utils.log('RPi detected, using alsa-utils player & recorded')
-    utils_mcon.USE_ALSA_AUDIO = True
-
-if 'ALSA' in config['audio']:
-    if config['audio']['ALSA']:
-        utils_mcon.USE_ALSA_AUDIO = True
+    if CONFIG.LogPath:
+        utils.open_log_file(CONFIG.LogPath, 'at')
 
 
-if config['log']['adb']:
-    utils_mcon.VERBOSE_ADB = True
-    utils.log('Enabled adb logcat output')
-
-# Audio directories
-if 'audio_dir' in config['log']:
-    if config['log']['audio_dir']:
-        LOG_AUDIO_DIR = config['log']['audio_dir']
-
-        # Ensure subdirectory log_audio exists
-        if not os.path.exists(LOG_AUDIO_DIR):
-            utils.log(f'Creating {LOG_AUDIO_DIR}')
-            os.mkdir(LOG_AUDIO_DIR)
-
-if 'audio' in config['log']:
-    if config['log']['audio']:
-        LOG_AUDIO = True
+    if CONFIG.CacheDir:
+        CACHE = utils_cache.InfoCache(dir=CONFIG.CacheDir)
 
 
+    # Update path to pvqa/aqua-wb
+    VOICE_QUALITY_AVAILABLE = utils_sevana.find_binaries(DIR_PROJECT / 'bin')
 
-# Update path to pvqa/aqua-wb
-dir_script = os.path.dirname(os.path.realpath(__file__))
-utils_sevana.find_binaries(os.path.join(dir_script, "../bin"))
-utils.log('Analyzer binaries are found')
+    # Load latest licenses & configs - this requires utils_sevana.find_binaries() to be called before
+    # utils_sevana.load_config_and_licenses(config['backend'])
 
-# Load latest licenses & configs - this requires utils_sevana.find_binaries() to be called before
-utils_sevana.load_config_and_licenses(config['backend'])
 
-# Audio devices
-if 'record_device' in config['audio'] and 'play_device' in config['audio']:
-    utils_mcon.AUDIO_DEV_RECORD = config['audio']['record_device']
-    utils_mcon.AUDIO_DEV_PLAY = config['audio']['play_device']
+    # Limit number of calls
+    if CONFIG.TaskLimit:
+        utils.log(f'Limiting number of calls to {CONFIG.TaskLimit}')
 
-# Limit number of calls
-if config['task_limit']:
-    CALL_LIMIT = config['task_limit']
-    utils.log(f'Limiting number of calls to {CALL_LIMIT}')
+    # Reset task list
+    utils_qualtest.TASK_LIST = []
 
-# Reset task list
-utils_qualtest.TASK_LIST = []
-
-# Init backend server
-BackendServer = utils_qualtest.QualtestBackend()
-BackendServer.instance = config['name']
-BackendServer.address = config['backend']
+    # Init backend server
+    BACKEND = utils_qualtest.QualtestBackend()
+    BACKEND.instance = CONFIG.Name
+    BACKEND.address = CONFIG.Backend
 
     
-# Write pid file to current working directory
-with open(QUALTEST_PID, "w") as f:
-    f.write(str(os.getpid()))
-    f.close()
+    # Write pid file to current working directory
+    if CONFIG.QualtestPID:
+        with open(CONFIG.QualtestPID, 'w') as f:
+            f.write(str(os.getpid()))
+            f.close()
 
+    try:
+        # Load information about phone
+        utils.log(f'Loading information about the node {BACKEND.instance} from {BACKEND.address}')
+        BACKEND.preload(CACHE)
+        if BACKEND.phone is None:
+            utils.log_error(f'Failed to obtain information about {BACKEND.instance}. Exiting.')
+            exit(EXIT_ERROR)
+    
+        # Cache phone information
+        CACHE.put_phone(BACKEND.phone)
 
-try:
-    # Load information about phone
-    utils.log(f'Loading information about the node {BackendServer.instance} from {BackendServer.address}')
-    BackendServer.preload()
+        # Upload results which were remaining in cache
+        upload_results()
 
-    if 'answerer' in BackendServer.phone.role:
-        # Check if task name is specified
-        if not config['task']:
-            utils.log_error('Please specify task value in config file.')
-            if os.path.exists(QUALTEST_PID):
-                os.remove(QUALTEST_PID)
-            sys.exit(utils_mcon.EXIT_ERROR)
+        if 'answerer' in BACKEND.phone.role:
+            # Check if task name is specified
+            if CONFIG.TaskName is None:
+                utils.log_error('Please specify task value in config file.')
+                sys.exit(EXIT_ERROR)
 
-        # Save current task name
-        CURRENT_TASK = config['task']
+            # Save current task name
+            CURRENT_TASK = CONFIG.TaskName
 
-        # Load reference audio
-        utils.log('Loading reference audio...')
-        if not BackendServer.load_audio(BackendServer.phone.audio_id, REFERENCE_AUDIO):
-            utils.log_error('Audio is not available, exiting.')
-            sys.exit(EXIT_ERROR)
+            # Load reference audio
+            if BACKEND.load_audio(BACKEND.phone.audio_id, CONFIG.ReferenceAudio):
+                CACHE.add_reference_audio(BACKEND.phone.audio_id, CONFIG.ReferenceAudio)
+            else:
+                utils.log('Audio is not available online...')
+                if not CACHE.get_reference_audio(BACKEND.phone.audio_id, CONFIG.ReferenceAudio):
+                    utils.log_error('  Reference audio is not cached, sorry. Exiting.')
+                    sys.exit(EXIT_ERROR)
+                else:
+                    utils.log(f'  Found in cache.')
+                    
+            # Preparing reference audio
+            utils.log('Running answering loop...')
+            perform_answerer()
 
-        # Preparing reference audio
-        utils.log('Running answering loop...')
-        perform_answerer()
+        elif 'caller' in BACKEND.phone.role:
+            utils.log('Running caller...')
+            run_probe()
 
-    elif 'caller' in BackendServer.phone.role:
-        utils.log('Running caller...')
-        run_probe()
+    except Exception as e:
+        utils.log_error('Error', e)
 
-except Exception as e:
-    utils.log_error('Error', e)
+    # Close log file
+    utils.close_log_file()
 
-# Close log file
-utils.close_log_file()
-
-# Exit with success code
-if os.path.exists(QUALTEST_PID):
-    os.remove(QUALTEST_PID)
-
-sys.exit(EXIT_OK)
+    sys.exit(EXIT_OK)

src/agent_kill.py

@@ -0,0 +1,14 @@
+#!/usr/bin/python3
+
+import agent_config
+import os
+
+if __name__ == '__main__':
+    config = agent_config.AgentConfig()
+    if config.QualtestPID:
+        if config.QualtestPID.exists():
+            with open(config.QualtestPID, 'rt') as f:
+                pid = f.read().strip()
+                os.system(f'pkill {pid}')
+                
+

src/bt_call_controller.py

@@ -22,6 +22,7 @@ CALL_ADDED = multiprocessing.Value('b', False)
 CALL_REMOVED = multiprocessing.Value('b', False)
 CALL_LOCK = threading.Lock()
 
+INTERRUPT_SIGNAL = multiprocessing.Value('b', False)
 
 # Call state change event
 class CallState(bt_phone.Observer):
@@ -41,13 +42,18 @@ class CallState(bt_phone.Observer):
 
 
 # Listen to call changes
-CALL_STATE_EVENT = CallState()
-PHONE = bt_phone.Phone()
-PHONE.addObserver(CALL_STATE_EVENT)
+CALL_STATE_EVENT = None
+PHONE = None
 
 # virtualmic module
 PA_MODULE_IDX = -1
 
+def init():
+    global CALL_STATE_EVENT, PHONE
+    CALL_STATE_EVENT = CallState()
+    PHONE = bt_phone.Phone()
+    PHONE.addObserver(CALL_STATE_EVENT)
+
 
 # Set volume 0..100%
 def set_headset_spk_volume(vol: float):
@@ -63,10 +69,11 @@ def set_headset_mic_volume(vol: float):
 
 
 # Function to get the phone stream index to capture the downlink.
-def get_headset_spk_idx():
+def get_headset_spk_idx(timeout: int = 10):
     utils.log('Waiting for phone stream index (please ensure all PA Bluetooth modules are loaded before)... ')
     phoneIdx = ''
-    while phoneIdx == '':
+    startTime = time.time()
+    while phoneIdx == '' and (time.time() - startTime < timeout):
         time.sleep(1)
         # grep 1-4 digit
         phoneIdx = os.popen('pacmd list-sink-inputs | grep -B5 alsa_output | grep index | grep -oP "[0-9]{1,4}"').read()
@@ -93,13 +100,17 @@ def dial_number(number: str, play_file: str):
 
 # Answer the call
 def answer_call(play_file: str):
-    global CALL_PATH, CALL_LOCK, CALL_ADDED
+    global CALL_PATH, CALL_LOCK, CALL_ADDED, INTERRUPT_SIGNAL
     utils.log('Waiting for incoming call...')
 
     # Wait for incoming call
-    while not CALL_ADDED.value:
-        time.sleep(0.1)
+    while not CALL_ADDED.value and not INTERRUPT_SIGNAL.value:
+        time.sleep(0.01)
 
+    if INTERRUPT_SIGNAL.value:
+        utils.log(f'Interrupt signal detected, exiting.')
+        return
+    
     utils.log(f'Found incoming call {CALL_PATH}')
     # CALL_LOCK.release()
 
@@ -116,6 +127,9 @@ def answer_call(play_file: str):
 # Record downlink.
 def capture_phone_alsaoutput(output_path: str):
     default_output = get_headset_spk_idx().rstrip('\n')
+    if default_output == '':
+        return None
+    
     cmd = f'parec --monitor-stream={default_output} --file-format=wav {output_path}'
     utils.log(cmd)
     # Example: parec --monitor-stream=34 --file-format=wav sample1.wav
@@ -231,26 +245,23 @@ def get_pid(name):
     return int(subprocess(["pidof","-s",name]))
 
 
-def main(args: dict):
+def run(play_file: str, record_file: str, timelimit_seconds: int, target: str):
     global CALL_PATH, CALL_LOCK, CALL_ADDED, CALL_REMOVED
 
     # Ensure Ctrl-C handler is default
     # signal.signal(signal.SIGINT, signal.SIG_DFL)
    
     # Check if input file exists
-    if not os.path.exists(args['play_file']):
+    if not os.path.exists(play_file):
         utils.log(f'Problem: file to play ({args["play_file"]}) doesn\'t exists.')
         exit(os.EX_DATAERR)
 
 
-    # Duration in seconds
-    watchdog_timeout = int(args['timelimit'])
-
-    if watchdog_timeout == 0:
+    if timelimit_seconds == 0:
         # Use duration of played file
-        audio_file = soundfile.SoundFile(args['play_file'])
-        watchdog_timeout = int(audio_file.frames / audio_file.samplerate + 0.5)
-        utils.log(f'Play timeout is set to {watchdog_timeout} seconds')
+        audio_file = soundfile.SoundFile(play_file)
+        timelimit_seconds = int(audio_file.frames / audio_file.samplerate + 0.5)
+        utils.log(f'Play timeout is set to {timelimit_seconds} seconds')
     
     # Empty call path means 'no call started'
     # CALL_LOCK.acquire()
@@ -269,15 +280,11 @@ def main(args: dict):
     PHONE.setup_dbus_loop()
 
     # Start call
-    if 'target' in args:
-        target_number = args['target']
-        if target_number is not None and len(target_number) > 0:
-            # Make a call
-            dial_number(target_number, args['play_file'])
-        else:
-            answer_call(args['play_file'])
+    if target is not None and len(target) > 0:
+        # Make a call
+        dial_number(target, play_file)
     else:
-        answer_call(args['play_file'])
+        answer_call(play_file)
 
     # Don't make volume 100% - that's too much
     audio_volume = 50
@@ -286,14 +293,19 @@ def main(args: dict):
     set_headset_mic_volume(audio_volume)
 
     # Start recording
-    utils.log(f'Start recording with ALSA to {args["record_file"]}')
-    process_recording = capture_phone_alsaoutput(args['record_file'])
+    utils.log(f'Start recording with ALSA to {record_file}')
+    process_recording = capture_phone_alsaoutput(record_file)
+    if process_recording is None:
+        utils.log_error(f'Failed to start recording downlink, exiting.')
+        cleanup()
+        return
+    
     utils.log(f'Main loop PID: {os.getpid()}, TID: {threading.get_ident()}')
     
     # Wait until call is finished
     time_start = time.time()
     
-    while not CALL_REMOVED.value and time_start + watchdog_timeout > time.time():
+    while not CALL_REMOVED.value and time_start + timelimit_seconds > time.time():
         time.sleep(0.5)
     
     utils.log(f'Call {CALL_PATH} finished.')
@@ -319,7 +331,7 @@ if __name__ == "__main__":
     
     retcode = 0
     try:
-        main(args)
+        run(args['play_file'], args['record_file'], args['timelimit'], args['target'] if 'target' in args else None)
     except KeyboardInterrupt as e:
         print('Ctrl-C pressed, exiting')
         cleanup()

src/bt_controller.py

@@ -12,9 +12,9 @@ class Bluetoothctl:
     """A wrapper for bluetoothctl utility."""
 
     def __init__(self):
-        out = subprocess.check_output("rfkill unblock bluetooth", shell = True)
+        out = subprocess.check_output("/usr/sbin/rfkill unblock bluetooth", shell = True)
         # print("Bluetoothctl")
-        self.child = pexpect.spawn("bluetoothctl", echo = False)
+        self.child = pexpect.spawn("/usr/bin/sudo /usr/bin/bluetoothctl", echo = False)
 
     def get_output(self, command, pause = 0):
         """Run a command in bluetoothctl prompt, return output as a list of lines."""

src/bt_phone.py

@@ -59,7 +59,7 @@ class Phone(Observable):
                                 model_serial = properties['Serial']
                                 modem_online = properties['Online']
 
-                                print(f'Found modem: {path} name: {modem_name} serial: {model_serial} online: {modem_online}')
+                                # utils.log(f'Found modem: {path} name: {modem_name} serial: {model_serial} online: {modem_online}')
                                 if modem_online == 1:
                                         return path
 
@@ -67,14 +67,17 @@ class Phone(Observable):
 
 
         # Wait for online modem and return this
-        def wait_for_online_modem(self):
-                while True:
+        def wait_for_online_modem(self, timeout_seconds: int = 1000000):
+                timestamp = time.time()
+                while True and timestamp + timeout_seconds > time.time():
                         modem = self.get_online_modem()
                         if modem != None:
                                 return modem
 
                         # Sleep another 10 seconds  and check again
-                        time.sleep(10.0)
+                        time.sleep(1.0)
+
+                return None
 
 
         def get_incoming_call(self):
@@ -93,11 +96,11 @@ class Phone(Observable):
 
         def __init__(self):
                 super(Phone,self).__init__()
-
+                utils.log('Ataching to DBus...')
                 # Attach to DBus
                 dbus.mainloop.glib.DBusGMainLoop(set_as_default=True)
                 
-                utils.log('Phone set up')
+                utils.log('Going to setup phone...')
                 self.bus = dbus.SystemBus()
                 
                 # Get ofono manager
@@ -107,11 +110,15 @@ class Phone(Observable):
                 self.modems = self.manager.GetModems()
 
                 # Wait for online modem
-                utils.log('Waiting for BT modem (phone must be paired and connected before)...')
-                self.modem = self.wait_for_online_modem()
-                
+                utils.log('Waiting for BT modem (phone must be paired and connected before) with timeout 10 seconds...')
+                self.modem = self.wait_for_online_modem(timeout_seconds=10) # 10 seconds timeout
+
+                if self.modem is None:
+                        utils.log_error(f'  No BT modem found. Please reconnect the phone.')
+                        raise RuntimeError('No BT modem found.')
+                     
                 # Log about found modem
-                utils.log(f'BT modem found. Modem: {self.modem}')
+                utils.log(f'  BT modem found. Modem: {self.modem}')
 
                 # Get access to ofono API
                 self.org_ofono_obj = self.bus.get_object('org.ofono', self.modem)
@@ -144,13 +151,11 @@ class Phone(Observable):
 
 
         def set_call_add(self, object, properties):
-                # print('Call add')
                 self.notifyObservers(object, EVENT_CALL_ADD)
                 self.call_in_progress = True
 
 
         def set_call_ended(self, object):
-                # print('Call removed')
                 self.notifyObservers(object, EVENT_CALL_REMOVE)
                 self.call_in_progress = False
 

src/bt_preconnect.py

@@ -1,37 +0,0 @@
-#!/usr/bin/python3
-
-import os
-import sys
-import yaml
-import subprocess
-import utils_bt_audio
-from bt_controller import Bluetoothctl
-
-if __name__ == '__main__':
-    if len(sys.argv) < 2:
-        print(f'Usage: bt_preconnect.py <path to config file>')
-        exit(0)
-
-    with open(sys.argv[1], 'r') as config_stream:
-        config = yaml.safe_load(config_stream)
-
-        if 'bluetooth_mac' in config['audio'] and 'bluetooth' in config['audio']:
-            use_bt = config['audio']['bluetooth']
-            bt_mac = config['audio']['bluetooth_mac']
-            if use_bt and len(bt_mac) > 0:
-                
-                if not utils_bt_audio.start_PA():
-                    print('Exiting')
-                    exit(1)
-                
-                # Connect to phone
-                print(f'Connecting to {bt_mac} ...')
-                bt_ctl = Bluetoothctl()
-                status = bt_ctl.connect(bt_mac)
-                if status:
-                    print(f'Connected ok.')
-                else:
-                    print(f'Not connected, sorry.')
-        else:
-            print('BT config not found.')
-        exit(0)

src/utils.py

@@ -1,4 +1,5 @@
 #!/usr/bin/python
+
 import typing
 import datetime
 import traceback
@@ -10,6 +11,7 @@ import smtplib
 import socket
 import sox
 import io
+import time
 
 from email.mime.multipart import MIMEMultipart
 from email.mime.application import MIMEApplication
@@ -26,7 +28,13 @@ verbose_logging: bool = False
 the_log = None
 
 # 1 minute network timeout
-NETWORK_TIMEOUT = 60
+NETWORK_TIMEOUT = 15
+
+start_system_time = time.time()
+start_monotonic_time = time.monotonic()
+
+def get_monotonic_time():
+    return time.monotonic() - start_monotonic_time + start_system_time
 
 
 def open_log_file(path: str, mode: str):
@@ -44,13 +52,13 @@ def close_log_file():
 
 
 def get_current_time_str():
-    return str(datetime.datetime.now())
-
+    s = str(datetime.datetime.now())
+    s = s[:-3]
+    return s
 
 def get_log_line(message: str) -> str:
-    current_time = get_current_time_str()
     pid = os.getpid()
-    line = f'{current_time} : {pid} : {message}'
+    line = f'{get_current_time_str()} : {pid} : {message}'
 
     return line
 

src/utils_bt_audio.py

@@ -40,10 +40,10 @@ def start_PA() -> bool:
     utils.log('Attempt to load module-bluetooth-discover...')
     retcode = os.system('pacmd load-module module-bluetooth-discover')
     if retcode != 0:
-        utils.log(f'Failed to load module-bluetooth-discover, exit code: {retcode}')
+        utils.log_error(f'  Failed to load module-bluetooth-discover, exit code: {retcode}')
         return False
     else:
-        print('...success.')
+        utils.log('  Load success.')
     
     return True
 

src/utils_cache.py

@@ -0,0 +1,133 @@
+#!/usr/bin/python3
+from pathlib import Path
+from utils_types import Phone, TaskList
+import os
+import shutil
+import json
+import uuid
+import utils
+
+class InfoCache:
+    dir: Path    
+    
+    def __init__(self, dir: Path) -> None:
+        self.dir = dir
+        if dir is not None and not dir.exists():
+            try:
+                os.mkdir(dir)
+            except Exception as e:
+                utils.log_error(str(e))
+                self.dir = None                
+
+
+
+    def is_active(self) -> bool:
+        return self.dir is not None
+
+
+    def add_reference_audio(self, audio_id: int, src_path: Path):
+        if not self.is_active():
+            return
+        
+        p = self.dir / f'ref_{audio_id}.wav'
+        if not p.exists():
+            shutil.copy(src_path, p)
+
+
+    def get_reference_audio(self, audio_id: int, dst_path: Path) -> bool:
+        if not self.is_active():
+            return False
+        
+        p = self.dir / f'ref_{audio_id}.wav'
+        if p.exists():
+            shutil.copy(p, dst_path)
+            return True
+        
+        return False
+
+
+    def add_recorded_audio(self, src_path: Path, probe_id: str) -> Path:
+        if not self.is_active():
+            return None
+        
+        p = self.dir / f'{probe_id}.wav'
+        
+        shutil.copy(src_path, p)
+        return p
+        
+
+    def get_recorded_audio(self, probe_id: str) -> Path:
+        if not self.is_active():
+            return None
+        
+        p = self.dir / f'audio_{probe_id}.wav'
+        if p.exists():        
+            return p
+        else:
+            return None
+
+
+    def is_valid_uuid(self, value):
+        try:
+            uuid.UUID(str(value))
+            return True
+        except ValueError:
+            return False
+    
+    # Returns list of tuples (path_to_probe.json, path_to_audio.wav)
+    def get_probe_list(self):
+        r = []
+        lst = os.listdir(self.dir)
+        for n in lst:
+            p = self.dir / n
+            if self.is_valid_uuid(p.stem) and n.endswith('.json'):
+                # Probe found
+                p_audio = p.with_suffix('.wav')
+                if p_audio.exists():
+                    r.append((p, p.with_suffix('.wav')))
+        
+        return r
+
+    # Caches phone information
+    def put_phone(self, phone: Phone):
+        if self.is_active():
+            with open(self.dir / f'phone_{phone.name}.json', 'wt') as f:
+                f.write(phone.dump())
+
+    def get_phone(self, name: str) -> Phone:
+        p = self.dir / f'phone_{name}.json'
+        if not p.exists():
+            utils.log(f'Phone definition at path {p} not found.')
+            return None
+        
+        with open(p, 'rt') as f:
+            return Phone.make(json.loads(f.read()))
+            
+    def put_tasks(self, name: str, tasks: TaskList):
+        p = self.dir / f'tasks_{name}.json'
+        with open(p, 'wt') as f:
+            f.write(json.dumps(tasks.tasks)) 
+        
+    
+    def get_tasks(self, name: str) -> TaskList:
+        p = self.dir / f'tasks_{name}.json'
+        try:
+            with open(p, 'rt') as f:
+                r = TaskList()
+                r.tasks = json.loads(f.read())
+                return r
+        except:
+            return None
+
+
+    def add_report(self, report: dict) -> str:
+        if not self.is_active():
+            return None
+        
+        # Generate UUID manually and save under this name to cache dir
+        probe_id = uuid.uuid1().urn[9:]
+        with open(self.dir / f'{probe_id}.json', 'wt') as f:
+            f.write(json.dumps(report, indent=4))
+        return probe_id
+    
+    

src/utils_logcat.py

@@ -39,14 +39,14 @@ class LogcatEventSource(multiprocessing.Process):
         process_poll.register(process_logcat.stdout, select.POLLIN)
 
         # Monitoring start time
-        current_timestamp = time.monotonic()
+        current_timestamp = utils.get_monotonic_time()
 
         # Read logcat output line by line
         while self.terminate_flag.value == 0:
             # Check if time limit is hit
-            if time.monotonic() - current_timestamp > self.timelimit:
+            if utils.get_monotonic_time() - current_timestamp > self.timelimit:
                 break
-            current_timestamp = time.monotonic()
+            current_timestamp = utils.get_monotonic_time()
 
             # Look for available data on stdout
             try:

src/utils_mcon.py

@@ -1,648 +0,0 @@
-#!/usr/bin/python3
-# coding: utf-8
-import argparse
-from multiprocessing.synchronize import Event
-import os
-import sys
-import traceback
-import time
-import subprocess
-import multiprocessing
-import signal
-import enum
-import utils
-import utils_logcat
-import utils_rabbitmq
-import utils_event
-
-from enum import Enum
-from multiprocessing import Value
-
-import utils_alsa
-# if not utils.is_raspberrypi():
-#    import utils_audio
-# import uiautomator2 as u2
-
-# This script is a bridge between android phone & audio recording & mobile helper app (Qualtest GSM)
-
-ADB = utils_logcat.ADB
-
-# This script version number
-MCON_VERSION = "1.2.7"
-
-# Audio devices to play & record
-AUDIO_DEV_PLAY = None
-AUDIO_DEV_RECORD = None
-
-# Files to play & record
-FILE_PLAY = None
-FILE_RECORD = None
-
-# Exit codes
-EXIT_SUCCESS = 0
-EXIT_ERROR = 1
-
-# Time limitation for monitoring function
-TIME_LIMIT_MONITORING = 86400*10000
-
-# Subprocesses
-PROCESS_MONITOR : multiprocessing.Process = None
-# PROCESS_RECORD : multiprocessing.Process = None
-# PROCESS_PLAY : multiprocessing.Process = None
-
-# Log ADB messages in verbose mode ?
-VERBOSE_ADB = False
-
-# Call time limit (in seconds)
-TIME_LIMIT_CALL = 120
-
-# Silence suffix length (in seconds)
-SILENCE_SUFFIX_LENGTH = 30
-
-# Silence prefix length (in seconds)
-SILENCE_PREFIX_LENGTH = 15
-
-# Override samplerate if needed
-SAMPLERATE: int = 48000
-
-# Processing script
-PROCESSING_SCRIPT = None
-
-# Nr of processed calls
-PROCESSED_CALLS: Value = Value('i', 0)
-
-# Number of calls todo
-LIMIT_CALLS: Value = Value('i', 0)
-
-# Use aplay / arecord from alsa-utils to play&capture an audio
-USE_ALSA_AUDIO: bool = False
-
-# Stop notification. Put it to non-zero when script has to be stopped.
-STOP_FLAG = multiprocessing.Value('i', 0)
-
-RABBITMQ_CONNECTION = None
-RABBITMQ_EXCHANGE = None
-RABBITMQ_QUEUE = None
-RABBITMQ_SESSIONID = None
-
-# Can be 'caller' or 'answerer'
-class Role(Enum):
-    Caller = 1
-    Answerer = 2
-
-ROLE = None
-
-
-def signal_handler(signum, frame):
-    print(f'Signal handler with code {signum}')
-    if PROCESS_MONITOR:
-        if PROCESS_MONITOR.is_alive:
-            print('Finishing the monitoring process...')
-            try:
-                if PROCESS_MONITOR._popen is not None:
-                    PROCESS_MONITOR.terminate()
-            except Exception:
-                traceback.print_exc()
-
-    print('Signal handler exit.')
-    exit(0)    
-
-
-def start_gsm_app():
-    cmdline = f'{ADB} shell am start -n biz.sevana.qualtestgsm/.MainActivity'
-    retcode = os.system(cmdline)
-    if retcode != 0:
-        raise IOError()
-
-
-# Initiates file playing and wait for finish (optionally)
-def play_file(path: str, wait: bool, device: str, samplerate: int = None):
-    path_to_player = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'audio_play.py')
-    
-    cmdline = f'python3 {path_to_player} --device "{device}" --input "{path}"'
-    if samplerate:
-        cmdline = cmdline + f' --samplerate {samplerate}'
-
-    utils.log_verbose(cmdline)
-    if wait:
-        os.system(cmdline)
-    else:
-        p = subprocess.Popen(cmdline, stdout=subprocess.PIPE, shell=True)
-        return p
-
-
-# Initiates file playing and wait for finish (optionally)
-def record_file(path: str, wait: bool, device: str, time_limit: int = 10, samplerate: int = None):
-    path_to_recorder = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'audio_record.py')
-
-    # Please be aware - macOS prohibits recording from microphone by default. When debugging under VSCode please ensure it has permission to record audio.
-    cmdline = f'python3 {path_to_recorder} --device "{device}" --output "{path}" --limit {time_limit}'
-    if samplerate:
-        cmdline = cmdline + f' --samplerate {samplerate}'
-        
-    utils.log_verbose(cmdline)
-    if wait:
-        os.system(cmdline)
-    else:
-        p = subprocess.Popen(cmdline, stdout=subprocess.PIPE, shell=True)
-        return p
-
-
-# Accept incoming GSM call
-def gsm_accept_incoming():
-    os.system(f"{ADB} shell input keyevent 5")
-
-
-# Reject incoming GSM call
-def gsm_reject_incoming():
-    os.system(f"{ADB} shell input keyevent 6")
-
-
-# Initiate new GSM call
-def gsm_make_call(target: str):
-    os.system(f"{ADB} shell am start -a android.intent.action.CALL -d tel:{target}")
-
-
-# End current GSM call
-def gsm_stop_call():
-    os.system(f"{ADB} shell input keyevent 6")
-    utils.log_verbose('GSM call stop keyevent is sent.')
-
-
-def gsm_send_digit(digit: str):
-    os.system(f"{ADB} shell input KEYCODE_{digit}")
-
-
-#def gsm_attach_automator():
-#    # Run stock dialer as way to preload automator stack
-#    utils.log("Connecting to device...")
-#    d = u2.connect()
-
-#    # Preload GSM helper app
-#    utils.log("Preloading GSM helper app")
-#    d.app_start("biz.sevana.qualtestgsm")
-
-#    # Wait timeout for UI element is 60.0s
-#    d.implicitly_wait(60.0)
-
-#    # Preload stock dialer
-#    # utils.log("Preloading stock dialer")
-#    # d.app_start("com.skype.raider")
-#    return d
-
-
-def gsm_switch_to_dtmf_panel(d):
-    # As stub for now - use Skype Contact click
-    # d(resourceId="com.skype.raider:id/vm_name", text=contact_name).click()
-    return None
-
-
-def run_shell_script(file_recorded: str, file_played: str, number: str):
-    global PROCESSED_CALLS
-    # Log about passed parameters
-    utils.log_verbose(f'Running shell script with variables: recorded - {file_recorded}, played - {file_played}, number - {number}')
-    utils.log_verbose(f'Template: {PROCESSING_SCRIPT}')
-
-    # Prepare command line
-    cmdline = PROCESSING_SCRIPT.replace('$RECORDED', file_recorded).replace('$PLAYED', file_played).replace('$NUMBER', number)
-    utils.log_verbose(cmdline)
-    
-    # Run script
-    retcode = os.system(cmdline)
-    if retcode != 0:
-        utils.log_error(f'Processing script call \'{cmdline}\' returned exit code {retcode}')
-
-    PROCESSED_CALLS.value = PROCESSED_CALLS.value + 1
-    return True
-
-
-def run_error_handler(error_message):
-    global PROCESSED_CALLS
-
-    utils.log_error(f'Processing script call ended with problem: {error_message}')
-    # Increase counter of processed calls to allow script to exit
-    PROCESSED_CALLS.value = PROCESSED_CALLS.value + 1
-
-
-class CallState(enum.Enum):
-    IDLE = 0
-    INCOMING = 1
-    ESTABLISHED = 2
-
-
-# Monitor logcat output and tell about events
-# on_start is lambda with 3 parameters (file_test, file_reference, phone_number) 
-# on_finish is lambda with 3 parameters (file_test, file_reference, phone_number)
-PREPARED_REFERENCE_AUDIO = '/dev/shm/reference_prepared.wav'
-
-def gsm_monitor(file_to_play: str, file_to_record: str, on_start, on_finish, on_error):
-    global PREPARED_REFERENCE_AUDIO, STOP_FLAG, USE_ALSA_AUDIO, AUDIO_DEV_RECORD, AUDIO_DEV_PLAY
-    
-    utils.log_verbose(f'File to play: {file_to_play}, file to record: {file_to_record}')
-    utils.log_verbose(f'on_start: {on_start}, on_finish: {on_finish}, on_error: {on_error}')
-    
-    # Reset stop flag
-    STOP_FLAG.value = 0
-
-    # Prepare reference audio for RPi
-    utils.prepare_reference_file(fname=file_to_play, 
-        silence_prefix_length=SILENCE_PREFIX_LENGTH, 
-        silence_suffix_length=SILENCE_SUFFIX_LENGTH, 
-        output_fname=PREPARED_REFERENCE_AUDIO)
-    
-    # Create event queue
-    event_queue = multiprocessing.Queue()
-    
-    # Logcat event source
-    logcat = utils_logcat.LogcatEventSource()
-    logcat.queue = event_queue
-    logcat.open()
-
-    # RabbitMQ event source
-    rabbitmq = utils_rabbitmq.RabbitMQServer()
-    rabbitmq.event_queue = event_queue
-    rabbitmq.queue_name =       RABBITMQ_QUEUE
-    rabbitmq.exchange_name =    RABBITMQ_EXCHANGE
-    rabbitmq.url =              RABBITMQ_CONNECTION
-    rabbitmq.open()
-
-    # Audio related processes and poll objects
-    audio_player = None
-    audio_recorder = None
-
-    # Ensure audio devices are recognized
-    if USE_ALSA_AUDIO:
-        if AUDIO_DEV_RECORD == 'auto':
-            AUDIO_DEV_RECORD = utils_alsa.AlsaRecorder.find_default()
-            utils.log(f'Recording device resolved to {AUDIO_DEV_RECORD}')
-        if AUDIO_DEV_PLAY == 'auto':
-            AUDIO_DEV_PLAY = utils_alsa.AlsaPlayer.find_default()
-            utils.log(f'Playing device resolved to {AUDIO_DEV_PLAY}')
-
-    # Monitoring start time
-    timestamp_start = time.monotonic()
-    
-    # Call start time
-    timestamp_call = None
-    if ROLE == Role.Caller:
-        timestamp_call = time.monotonic()
-
-    # Should call to be stopped ?
-    force_call_stop = False
-
-    call_state : CallState = CallState.IDLE
-
-    # Read logcat output line by line
-    while True:
-        # Check if time limit is hit
-        if time.monotonic() - timestamp_start > TIME_LIMIT_MONITORING:
-            break
-        
-        # Check if limit of calls hit
-        if LIMIT_CALLS.value != 0 and PROCESSED_CALLS.value >= LIMIT_CALLS.value:
-            break
-
-        # Check if call hit maximum length - smth goes weird, exit from the script
-        if timestamp_call:
-            if time.monotonic() - timestamp_call > TIME_LIMIT_CALL:
-                utils.log_verbose(f'Call time limit ({TIME_LIMIT_CALL}s). Stop the call.')
-                timestamp_call = None
-                
-                # Try to end mobile call twice. Sometimes first attempt fails (observed on Galaxy M11).
-                gsm_stop_call()
-                gsm_stop_call()
-                
-                if ROLE == Role.Caller:
-                    # Treat call as stopped
-                    # Exit from loop
-                    utils.log_verbose(f'Exit from the processing loop as call time limit hit; smth goes wrong, exit from the script.')
-                    
-                    # Signal to caller to stop processing outer script
-                    STOP_FLAG.value = 1
-
-                    # Exit
-                    exit(1)
-                    # break
-
-        # Next event ?
-        event: utils_event.CallEvent = None
-        try:
-            event = event_queue.get(timeout = 1.0)
-        except:
-            # No event available
-            continue
-
-        if event is None:
-            continue
-        
-        if len(event.session_id) > 0 and event.session_id != RABBITMQ_SESSIONID:
-            utils.log_verbose(f'Skip event from old session')
-            continue
-
-        # Process events
-        if event.name == utils_event.EVENT_IDLE:
-            idle_detected = True
-            
-        elif event.name == utils_event.EVENT_CALL_INCOMING:
-            if call_state != CallState.IDLE:
-                utils.log(f'Duplicate event {event}, ignoring.')
-                continue
-
-            call_state = CallState.INCOMING
-            # Accept incoming call
-            utils.log_verbose(f'Detected Incoming call notification (number {event.number}) from mobile helper app.')
-            
-            # Double accept - sometimes phones ignore the first attempts
-            gsm_accept_incoming()
-            gsm_accept_incoming()
-            utils.log_verbose(f'Incoming call accepted.')
-                
-        elif event.name == utils_event.EVENT_CALL_FINISHED:
-            if call_state != CallState.ESTABLISHED:
-                utils.log(f'Duplicate event {event}, ignoring.')
-
-            call_state = CallState.IDLE
-            utils.log_verbose(f'Detected call stop notification from the mobile helper app')
-            # Reset counter of call length
-            timestamp_call = None
-
-            # Stop playing & capturing
-            utils.log_verbose(f'Call from {event.number} finished.')
-            if audio_recorder:
-                audio_recorder.stop_recording()
-                audio_recorder.close()
-                audio_recorder = None
-
-            if audio_player:
-                audio_player.stop_playing()
-                audio_player.close()
-                audio_player = None
-                
-            # Restart audio - lot of debugging output from ALSA libraries can be here. It is a known problem of ALSA libraries.
-            if USE_ALSA_AUDIO:
-                utils_alsa.restart_audio()
-            else:
-                utils_audio.restart_audio()
-
-            # Here recording finished, call script to process
-            if on_finish:
-                if os.path.exists(file_to_record):
-                    utils.log(f'Recorded file: {file_to_record}')
-
-                    # Call handler
-                    if on_finish(file_to_record, file_to_play, event.permissions) in [False, None] :
-                        utils.log_error(f'Analyzer routine returned negative result, exiting.')
-                        
-                        # Signal to caller to stop processing outer script
-                        STOP_FLAG.value = 1
-
-                        sys.exit(EXIT_ERROR)
-                    
-                    # Remove processed file before writing the next one
-                    # if os.path.exists(file_to_record):
-                    #    os.remove(file_to_record)
-                else:
-                    utils.log_error(f'Smth wrong - no recorded file {file_to_record}')    
-                    if not on_finish(None, file_to_play, None):
-                        # Signal to caller to stop processing outer script
-                        STOP_FLAG.value = 1
-
-                        sys.exit(EXIT_ERROR)
-                        
-
-        elif event.name == utils_event.EVENT_CALL_ESTABLISHED:
-            if call_state == CallState.ESTABLISHED:
-                utils.log(f'Duplicate event {event}, ignoring.')
-                continue
-            call_state = CallState.ESTABLISHED
-
-            utils.log_verbose(f'Detected call start notification from the mobile helper app, trying to start audio.')
-
-            # Save call start time
-            timestamp_call = time.monotonic()
-
-            # Is audio failed 
-            audio_failed = False
-
-            # Start playing
-            utils.log_verbose(f'Call with {event.number} is established.')
-            if file_to_play:
-                if not USE_ALSA_AUDIO:
-                    device_index, device_rate = utils_audio.get_output_device_index(AUDIO_DEV_PLAY)
-                if SAMPLERATE:
-                    device_rate = SAMPLERATE
-
-                utils.resample_to(file_to_play, int(device_rate))
-
-                utils.log_verbose(f'Playing file: {file_to_play}')
-                try:
-                    if USE_ALSA_AUDIO:
-                        audio_player = utils_alsa.AlsaPlayer(device_name=AUDIO_DEV_PLAY, channels=2, rate=48000, fname=PREPARED_REFERENCE_AUDIO)
-                    else:
-                        audio_player = utils_audio.Player(device_index=device_index).open(fname=file_to_play, 
-                            silence_prefix=SILENCE_PREFIX_LENGTH, silence_suffix=SILENCE_SUFFIX_LENGTH)
-                    audio_player.start_playing()
-                    
-                except Exception as e:
-                    utils.log_error(e)
-                    audio_failed = True
-
-            # Start capturing
-            if file_to_record and not audio_failed:
-                utils.log_verbose(f'Recording file: {file_to_record}')
-                
-                # Remove old file if needed
-                if os.path.exists(file_to_record):
-                    os.remove(file_to_record)
-                if not USE_ALSA_AUDIO:
-                    device_index, device_rate = utils_audio.get_input_device_index(AUDIO_DEV_RECORD)
-                if SAMPLERATE:
-                    device_rate = SAMPLERATE
-
-                try:
-                    if USE_ALSA_AUDIO:
-                        audio_recorder = utils_alsa.AlsaRecorder(device_name=AUDIO_DEV_RECORD, rate=int(device_rate), fname=file_to_record)
-                    else:
-                        audio_recorder = utils_audio.Recorder(device_index=device_index, rate=int(device_rate)).open(fname=file_to_record)
-                    audio_recorder.start_recording()
-                except Exception as e:
-                    utils.log_error(e)
-                    audio_failed = True
-            
-            if audio_failed:
-                gsm_stop_call()
-                gsm_stop_call()
-
-                if on_error: 
-                    on_error('Audio failed.')
-
-            elif on_start:
-                on_start(file_to_record, file_to_play, event.number)
-
-
-
-def make_call(target: str):
-    global ROLE, PROCESS_MONITOR, STOP_FLAG, PROCESSED_CALLS
-
-    ROLE = Role.Caller
-
-    # Start subprocess to monitor events from Qualtest GSM
-    finish_handler = lambda file_record, file_play, number: run_shell_script(file_record, file_play, number)
-    error_handler = lambda error_message: run_error_handler(error_message)
-
-    PROCESS_MONITOR = multiprocessing.Process(target=gsm_monitor, args=(FILE_PLAY, FILE_RECORD, None, finish_handler, error_handler))
-    PROCESS_MONITOR.start()
-    
-    # Initiate GSM phone call via adb
-    gsm_make_call(target)
-
-    # Log    
-    utils.log_verbose('Call is initiated, processing...')
-
-    # Wait for call finish with some timeout. Kill monitoring process on finish.
-    while True and STOP_FLAG.value != 1 and PROCESSED_CALLS.value == 0:
-        time.sleep(0.5)
-
-    # Kill the monitoring process - this will send SIGTERM signal. It is a cause why agent_gsm doesn't handle SIGTERM
-    PROCESS_MONITOR.terminate()
-    
-    return None
-
-
-def answer_calls():
-    global ROLE, PROCESS_MONITOR, STOP_FLAG, PROCESSED_CALLS
-
-    ROLE = Role.Answerer
-
-    # Start subprocess to monitor events from Qualtest GSM.  
-    finish_handler = lambda file_record, file_play, number: run_shell_script(file_record, file_play, number)
-    error_handler = lambda error_message: run_error_handler(error_message)
-
-    PROCESS_MONITOR = multiprocessing.Process(target=gsm_monitor, args=(FILE_PLAY, FILE_RECORD, None, finish_handler, error_handler))
-    PROCESS_MONITOR.start()
-
-    # Indefinite loop. Exit is in signal handler
-    while True and STOP_FLAG.value != 1 and PROCESSED_CALLS.value == 0:
-        time.sleep(0.5)
-
-    # Kill the monitoring process - this will send SIGTERM signal. It is a cause why agent_gsm doesn't handle SIGTERM
-    PROCESS_MONITOR.terminate()
-    return None
-
-
-if __name__ == '__main__':
-    # Default exit code
-    retcode = EXIT_SUCCESS
-
-    # Handle signals
-    signal.signal(signal.SIGINT, signal_handler)
-    signal.signal(signal.SIGTERM, signal_handler)
-
-    # Command line parameters
-    parser = argparse.ArgumentParser()
-    parser.add_argument("--play-device",        help="Output audio device name. Used to play reference audio to mobile call. Example (for ALSA): hw:2,0")
-    parser.add_argument("--record-device",      help="Input device name. Used to record audio received from the mobile call.")
-    # parser.add_argument("--show-devices",       help="list available output audio devices.", action="store_true")
-    parser.add_argument("--make-call",          help="Target number as is. Usuall smth like +XYZ. Initiate a call to target number invoking the call on mobile phone and playing/recording audio to/from the call. Otherwise script will run expecting for incoming call.")
-    parser.add_argument("--play-file",          help="Path to played (reference) audio. On RPi platform this should be 48KHz stereo audio.")
-    parser.add_argument("--record-file",        help="Path to recorded audio (received from mobile call). On RPi platform it will be 48KHz mono audio.")
-    parser.add_argument("--exec",               help="Path to postprocessing script. Postprocessing script will be run after the call finish with path to recorded audio as parameter. This should be a string like /home/user/postprocessing.sh $RECORDED. Substring $RECORDED will be replaced with actual path to recorded audio.")
-    # parser.add_argument("--adb-path",           help="Path to adb utility. This must be set to work with mobile phone!")
-    parser.add_argument("--call-timelimit",     help="Number of seconds. Call will be ended after specified timeout. Default value is 0 - no timeout.")
-    parser.add_argument("--test-play",          help="Play test audio file. Useful when testing configuration. However this will not work on RPi.", action="store_true")
-    parser.add_argument("--test-record",        help="Record test audio file for 10 seconds. Useful when testing configuration. However this will not work on RPi.", action="store_true")
-    parser.add_argument("--silence-prefix",     help="Number of seconds. Adds silence before played audio. Default value is 10 (seconds)")
-    parser.add_argument("--silence-suffix",     help="Number of seconds. Adds silence after played audio. Default value is 10 (seconds)")
-    parser.add_argument("--verbose",            help="Run in verbose mode. It doesn't generate too much data, recommended to set.", action="store_true")
-    parser.add_argument("--verbose-adb",        help="Log ADB messages when running in verbose mode. This can generate a lot of data, please be aware.", action="store_true")
-    parser.add_argument("--log-file",           help="Path to log file. By default log is sent to console.")
-    parser.add_argument("--version",            help="Show version number & exit", action="store_true")
-    parser.add_argument("--alsa-audio",         help="Use ALSA audio instead of PyAudio (portaudio)", action="store_true")
-    parser.add_argument("--rabbitmq-connection")
-    parser.add_argument("--rabbitmq-exchange")
-    parser.add_argument("--rabbitmq-queue")
-    parser.add_argument("--rabbitmq-sessionid")
-    # parser.add_argument("--dtmf",               help="Send DTMF string after call establishing and finish a call. Helper tool for some cases.")
-    # parser.add_argument("--samplerate",         help="<audio samplerate>. Overrides default audio samplerate.")
-    args = parser.parse_args()
-
-    if args.version:
-        print(f"Version: {MCON_VERSION}")
-        sys.exit(0)
-
-    RABBITMQ_CONNECTION = args.rabbitmq_connection
-    RABBITMQ_EXCHANGE = args.rabbitmq_exchange
-    RABBITMQ_QUEUE = args.rabbitmq_queue
-    RABBITMQ_SESSIONID = args.rabbitmq_sessionid
-
-    # ALSA audio ? Required on RPi
-    USE_ALSA_AUDIO = args.alsa_audio
-
-    # Open log file if needed
-    VERBOSE_ADB = args.verbose_adb
-    utils.verbose_logging = args.verbose
-    if args.log_file:
-        utils.open_log_file(args.log_file, "at")
-        utils.log(f"mcon version: {MCON_VERSION}")
-
-    if args.call_timelimit:
-        TIME_LIMIT_CALL = int(args.call_timelimit)
-    elif args.play_file:
-        TIME_LIMIT_CALL = utils.get_wav_length(args.play_file)
-    
-    utils.log(f'Limiting call time to {TIME_LIMIT_CALL}')
-
-    # Save audio devices
-    if args.play_device:
-        AUDIO_DEV_PLAY = args.play_device
-
-    if args.record_device:
-        AUDIO_DEV_RECORD = args.record_device
-
-    # Save files to play & record
-    if args.play_file:
-        FILE_PLAY = args.play_file
-
-    if args.record_file:
-        FILE_RECORD = args.record_file
-
-    # Processing script
-    if args.exec:
-        PROCESSING_SCRIPT = args.exec
-
-    # Should we make test here ?
-    if args.test_play:
-        if FILE_PLAY:
-            utils.log(f"Start test playing {FILE_PLAY} to {AUDIO_DEV_PLAY}")
-            play_file(FILE_PLAY, device=AUDIO_DEV_PLAY, wait=True)
-        else:
-            utils.log_error("File to play is not specified, exiting.")
-            retcode = EXIT_ERROR
-
-        sys.exit(retcode)
-
-    if args.test_record:
-        if FILE_RECORD:
-            utils.log(f"Start test recording from {AUDIO_DEV_RECORD} to {FILE_RECORD}")
-            record_file(FILE_RECORD, device=AUDIO_DEV_RECORD, wait=True)
-        else:
-            utils.log_error("File to record is not specified, exiting")
-            retcode = EXIT_ERROR
-
-        sys.exit(retcode)
-
-    # Check if we have to make a call
-    try:
-        if args.make_call:
-            make_call(args.make_call)
-        else:
-            answer_calls()
-
-    except Exception as e:
-        utils.log_error(e)
-
-    # Close log file
-    utils.close_log_file()
-
-    # Exit code 0 (success)
-    sys.exit(retcode)

src/utils_network_impairment.py

@@ -0,0 +1,237 @@
+#!/usr/bin/python3
+# -*- coding: utf-8 -*-
+
+# FLEDGE_BEGIN
+# See: http://fledge-iot.readthedocs.io/
+# FLEDGE_END
+
+""" Module for applying network impairments."""
+
+
+__author__ = "Deepanshu Yadav"
+__copyright__ = "Copyright (c) 2022 Dianomic Systems Inc."
+__license__ = "Apache 2.0"
+__version__ = "${VERSION}"
+
+# References
+# 1. http://myconfigure.blogspot.com/2012/03/traffic-shaping.html
+# 2. https://lartc.org/howto/lartc.qdisc.classful.html
+# 3. https://lartc.org/howto/lartc.qdisc.filters.html
+# 4. https://serverfault.com/a/841865
+# 5. https://serverfault.com/a/906499
+# 6. https://wiki.linuxfoundation.org/networking/netem
+# 7. https://srtlab.github.io/srt-cookbook/how-to-articles/using-netem-to-emulate-networks/
+# 8. https://wiki.linuxfoundation.org/networking/netem
+
+import subprocess
+import multiprocessing
+import datetime
+import time
+import socket
+import argparse
+
+def check_for_interface(interface):
+    """Checks for given interface if present in output of ifconfig"""
+    for tup in socket.if_nameindex():
+        if tup[1] == interface:
+            return True
+
+    return False
+
+
+class Distortion(multiprocessing.Process):
+    def __init__(self, run_cmd_list, clear_cmd, duration):
+        super(Distortion, self).__init__()
+        self.run_cmd_list = run_cmd_list
+        self.duration = duration
+        self.clear_cmd = clear_cmd
+
+    @staticmethod
+    def run_command(command):
+        """Executes a shell command using subprocess module."""
+        try:
+            process = subprocess.Popen(command, cwd=None, shell=True, stdout=subprocess.PIPE, stdin=subprocess.PIPE)
+        except Exception as inst:
+            print("Problem running command : \n   ", str(command))
+            return False
+
+        [stdoutdata, stderrdata] = process.communicate(None)
+        if process.returncode:
+            print(stderrdata)
+            print("Problem running command : \n   ", str(command), " ", process.returncode)
+            return False
+
+        return True
+
+    def run(self) -> None:
+
+        # Make sure we are in clean state. Ignore error if there.
+        _ = Distortion.run_command(self.clear_cmd)
+
+        for run_cmd in self.run_cmd_list:
+            print("Executing {}".format(run_cmd), flush=True)
+            ret_val = Distortion.run_command(run_cmd)
+            if not ret_val:
+                print("Could not perform execution of command {}".format(run_cmd), flush=True)
+                return
+
+        end_time = datetime.datetime.now() + datetime.timedelta(seconds=self.duration)
+        while datetime.datetime.now() < end_time:
+            time.sleep(0.5)
+
+        print("Executing {}".format(self.clear_cmd), flush=True)
+        ret_val = Distortion.run_command(self.clear_cmd)
+        if not ret_val:
+            print("Could not perform execution of command {}".format(self.clear_cmd), flush=True)
+            return
+
+        print("Network Impairment complete.", flush=True)
+
+
+def reset_network(interface):
+    """
+    Reset the network in the middle of impairment.
+    :param interface: The interface of the network.
+    :type interface: string
+    :return: True/False If successful.
+    :rtype: boolean
+    """
+    if not check_for_interface(interface):
+        raise Exception("Could not find given {} among present interfaces.".format(interface))
+
+    clear_cmd = "sudo tc qdisc del dev {} root".format(interface)
+    ret_val = Distortion.run_command(command=clear_cmd)
+
+    if ret_val:
+        print("Network has been reset.")
+    else:
+        print("Could not reset the network.")
+
+
+def distort_network(interface, duration, rate_limit, latency, ip=None, port=None,
+                    traffic=''):
+    """
+
+    :param interface: Interface on which network impairment will be applied. See ifconfig in
+                       your linux machine to decide.
+    :type interface: string
+    :param duration: The duration (in seconds) for which impairment will be applied. Note it will
+                     get auto cleared after application.
+    :type duration: integer
+    :param traffic:  If inbound then the given ip and port will be used to filter packets coming
+                     from destination. For these packets only the impairment will be applied.
+                     If outbound then we are talking about packets leaving this machine for destination.
+                     This is exactly the opposite of first case.
+    :type traffic:  inbound/ outbound string
+    :param ip: The ip of machine where packets are coming / leaving to filter. Keep None
+               if no filter required.
+    :type ip: string
+    :param port: The port of machine where packets are coming / leaving to filter.  Keep None
+               if no filter required.
+    :type port: integer
+    :param rate_limit: The restriction in rate in kbps. Use value 20 for 20 kbps.
+    :type rate_limit: integer
+    :param latency: The delay to cause for every packet leaving/ coming from machine in
+                    milliseconds. Use something like 300 for causing a delay for 300 milliseconds.
+    :type latency: integer
+    :return: None
+    :rtype: None
+    """
+
+    if not check_for_interface(interface):
+        raise Exception("Could not find given {} among present interfaces.".format(interface))
+
+    if not latency and not rate_limit:
+        raise Exception("Could not find latency or  rate_limit.")
+
+    if latency:
+        latency_converted = str(latency) + 'ms'
+    else:
+        latency_converted = None
+
+    if rate_limit:
+        rate_limit_converted = str(rate_limit) + 'Kbit'
+    else:
+        rate_limit_converted = None
+
+    if not (ip and port):
+        if rate_limit_converted and latency_converted:
+            run_cmd = "sudo tc qdisc add dev {} root netem" \
+                      " delay {} rate {}".format(interface, latency_converted,
+                                                 rate_limit_converted)
+        elif rate_limit_converted and not latency_converted:
+            run_cmd = "sudo tc qdisc add dev {} root netem" \
+                      " rate {}".format(interface, rate_limit_converted)
+        elif not rate_limit_converted and latency_converted:
+            run_cmd = "sudo tc qdisc add dev {} root netem" \
+                      "delay {}".format(interface, latency_converted)
+
+        clear_cmd = "sudo tc qdisc del dev {} root".format(interface)
+        p = Distortion([run_cmd], clear_cmd, duration)
+        p.daemon = True
+        p.start()
+
+    else:
+        r1 = "sudo tc qdisc add dev {} root handle 1: prio" \
+             " priomap 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2".format(interface)
+        if latency_converted and rate_limit_converted:
+            r2 = "sudo tc qdisc add dev {} parent 1:1 " \
+                 "handle 10: netem delay {} rate {}".format(interface,
+                                                            latency_converted,
+                                                            rate_limit_converted)
+        elif not latency_converted and rate_limit_converted:
+            r2 = "sudo tc qdisc add dev {} parent 1:1 " \
+                 "handle 10: netem  rate {}".format(interface,
+                                                    rate_limit_converted)
+        elif latency_converted and not rate_limit_converted:
+            r2 = "sudo tc qdisc add dev {} parent 1:1 " \
+                 "handle 10: netem delay {} ".format(interface,
+                                                     latency_converted)
+
+        if traffic.lower() == 'outbound':
+            ip_param = 'dst'
+            port_param = 'dport'
+
+        elif traffic.lower() == "inbound":
+            ip_param = 'src'
+            port_param = 'sport'
+        else:
+            raise Exception("For ip and port are given then traffic has to be either inbound or outbound."
+                            " But got other than these two. ")
+
+        r3 = "sudo tc filter add dev {} protocol ip parent 1:0 prio 1 u32 " \
+             "match ip {} {}/32 match ip {} {}  0xffff flowid 1:1".format(interface, ip_param,
+                                                                          ip, port_param, port)
+        clear_cmd = "sudo tc qdisc del dev {} root".format(interface)
+        run_cmd_list = [r1, r2, r3]
+        p = Distortion(run_cmd_list, clear_cmd, duration)
+        p.daemon = True
+        p.start()
+
+
+""" -------------------------Usage -------------------------------------"""
+
+# from network_impairment import distort_network, reset_network
+# distort_network(interface="wlp2s0", duration=40, rate_limit=20, latency=300,
+#                 ip="192.168.1.80", port=8081, traffic="inbound")
+#
+# distort_network(interface="wlp2s0", duration=40, rate_limit=20, latency=300,
+#                 ip="192.168.1.80", port=8081, traffic="outbound")
+#
+# distort_network(interface="wlp2s0", duration=40, rate_limit=20, latency=300)
+
+# reset_network(interface="wlp2s0")
+
+if __name__ == '__main__':
+    parser = argparse.ArgumentParser()
+    parser.add_argument('--stop', action='store_true')
+    parser.add_argument('--start', action='store_true')
+    parser.add_argument('--ip')
+
+    config = parser.parse_args()
+    interface_name = 'wlp2s0'
+    if config.start and config.ip:
+        distort_network(interface='', duration=300, rate_limit=20, latency=300, ip=config.ip, port=443, traffic='outbound')
+        distort_network(interface='', duration=300, rate_limit=20, latency=300, ip=config.ip, port=443, traffic='inbound')
+    elif config.stop:
+        reset_network(interface='')

src/utils_qualtest.py

@@ -17,9 +17,8 @@ import requests
 from socket import timeout
 from crontab import CronTab
 from pathlib import Path
-
-start_system_time = time.time()
-start_monotonic_time = time.monotonic()
+from utils_cache import InfoCache
+from utils_types import Phone, TaskList
 
 # Error report produced by this function has to be updated with 'task_name' & 'phone_name' keys
 def build_error_report(endtime: int, reason: str):
@@ -36,94 +35,6 @@ def build_error_report(endtime: int, reason: str):
     return r
 
 
-class TaskList:
-    tasks: list = []
-
-    def __init__(self):
-        self.tasks = []
-
-
-    # Merges incoming task list to existing one
-    # It preserves existing schedules
-    # New items are NOT scheduled automatically
-    def merge_with(self, tasklist) -> bool:
-        changed = False
-        if tasklist.tasks is None:
-            return True
-
-        # Iterate all tasks, see if task with the same name exists already
-        # Copy all keys, but keep existing ones
-        for new_task in tasklist.tasks:
-            # Find if this task exists already
-            existing_task = self.find_task_by_name(new_task["name"])
-
-            # If task is found - copy all items to it.
-            # It is required as task can hold schedule items already
-            # Bad idea to copy tasks itself.
-            if existing_task is not None:
-                # Check if scheduled time point has to be removed (if cron string changed)
-                if new_task["schedule"] != existing_task["schedule"] and "scheduled_time" in existing_task:
-                    del existing_task["scheduled_time"]
-                
-
-                # Finally copy new values
-                for key, value in new_task.items():
-                    if existing_task[key] != value:
-                        existing_task[key] = value
-                        changed = True
-            else:
-                # Copy new task to list
-                self.tasks.extend([new_task])
-                changed = True
-
-        # Check if old tasks are here... And delete them
-        for existing_task in self.tasks:
-            new_task = self.find_task_by_name(existing_task["name"])
-            if new_task is None:
-                self.tasks.remove(existing_task)
-                changed = True
-
-        return changed
-
-    
-    def schedule(self):
-        # Remove items without schedule before
-        self.tasks = [t for t in self.tasks if len(t['schedule']) > 0]
-
-        # https://crontab.guru is good for crontab strings generation
-        # Use monotonic time source!
-        current_time = time.monotonic()
-        for task in self.tasks:
-            if 'scheduled_time' not in task and 'schedule' in task:
-                # No schedule flag, so time to schedule
-                try:
-                    cron_string = task['schedule'].strip()
-                    if cron_string == '* * * * *':
-                        task['scheduled_time'] = time.monotonic() - 0.001 # To ensure further comparison will not be affected by precision errors
-                    else:
-                        cron = CronTab(task['schedule'])
-                        task['scheduled_time'] = current_time + cron.next(default_utc=True)
-
-                    # Just to help in further log reading & debugging - show the scheduled time in readable form
-                    task['scheduled_time_str'] = time.ctime(task['scheduled_time'] - start_monotonic_time + start_system_time)
-                except:
-                    utils.log_error("Error", sys.exc_info()[0])
-
-        # Remove non scheduled items 
-        self.tasks = [t for t in self.tasks if 'scheduled_time' in t]
-
-        # Sort everything
-        self.tasks = sorted(self.tasks, key=lambda t: t["scheduled_time"])
-        
-
-    # Returns None if failed
-    def find_task_by_name(self, name):
-        for t in self.tasks:
-            if t["name"] == name:
-                return t
-
-        return None
-
 
 def ParseAttributes(t: str) -> dict:
     result: dict = dict()
@@ -134,20 +45,21 @@ def ParseAttributes(t: str) -> dict:
             result[tokens[0].strip()] = tokens[1].strip()
     return result
 
-    
-class Phone:
-    identifier: int = 0
-    name: str = ""
-    role: str = ""
-    attributes: dict = ""
-    audio_id: int = 0
 
-    def __init__(self):
-        self.identifier = 0
-        self.name = ""
-        self.role = ""
-        self.attributes = dict()
-        self.audio_id = 0
+# Time of operation start
+TRACE_START_TIME = None
+
+# 10 seconds for I/O operation
+TRACE_TOTAL_TIMEOUT = 30 
+
+
+# This function serves as a "hook" that executes for each Python statement
+# down the road. There may be some performance penalty, but as downloading
+# a webpage is mostly I/O bound, it's not going to be significant.
+
+def trace_function(frame, event, arg):
+    if time.time() - TRACE_START_TIME > TRACE_TOTAL_TIMEOUT:
+        raise Exception('Timed out!') # Use whatever exception you consider appropriate.
 
     
 class QualtestBackend:
@@ -165,44 +77,52 @@ class QualtestBackend:
         return self.__phone
 
 
-    def preload(self):
-        self.__phone = self.load_phone()
+    def preload(self, cache: InfoCache):
+        self.__phone = self.load_phone(cache)
 
 
-    def upload_report(self, report, files) -> str:
+    def upload_report(self, report: dict, cache: InfoCache) -> (str, bool):
         # UUID string as result
-        result = None
+        result = (None, False)
         
         # Log about upload attempt
-        utils.log_verbose(f"Uploading to {self.address} files {files} and report: {json.dumps(report, indent=4)}")
-
-        # POST will be sent to args.qualtest_server with args.qualtest_instance ID
-        json_content = json.dumps(report, indent=4).encode('utf8')
-        
-        # Find URL for uploading
+        utils.log_verbose(f'Uploading to {self.address} report with audio duration: {report["duration"]}s, AQuA MOS: {round(report["mos_aqua"], 3)}')
         url = utils.join_host_and_path(self.address, "/probes/")
+        
         try:
-            # Step 1 - upload result record
-            req = urllib.request.Request(url,
-                                        data=json_content,
-                                        headers={'content-type': 'application/json'})
-            response = urllib.request.urlopen(req, timeout=utils.NETWORK_TIMEOUT)
-            result = response.read().decode('utf8')
-            utils.log_verbose(f"Response (probe ID): {result}")
-            utils.log_verbose(f"Upload to {self.address} finished.")
+            r = requests.post(url=url, json=report, timeout=utils.NETWORK_TIMEOUT)
+            utils.log_verbose(f"Upload report finished. Response (probe ID): {r.content}")
+            if r.status_code != 200:
+                if r.status_code == 500 and 'Duplicate entry' in r.content.decode():
+                    # Suppose it success
+                    result = (report['id'], True)
+                else:
+                    raise RuntimeError(f'Server returned code {r.status_code}')
             
+            result = (r.content.decode().strip('" '), True)
         except Exception as e:
-            utils.log_error(f"Upload to {self.address} finished with error.", err=e)
+            utils.log_error(f'Upload report to {self.address} finished with error: {str(e)}')
+            # Backup probe result
+            if cache is not None:
+                probe_id = cache.add_report(report)
+                utils.log(f'  {probe_id}.json report is put to cache.')
+                result = (probe_id, False)
+            else:
+                return (None, None)
         
         return result
         
 
-    def upload_audio(self, probe_id, path_recorded):
+    def upload_audio(self, probe_id, path_recorded: Path):
         result = False
 
         # Log about upload attempt
         utils.log_verbose(f"Uploading to {self.address} audio {path_recorded}")
-        
+        if not path_recorded.exists():
+            utils.log_error('  File doesn\'t exists, skip.')
+            return False
+
+
         # Find URL for uploading
         url = utils.join_host_and_path(self.address, "/upload_audio/")
         try:
@@ -211,13 +131,20 @@ class QualtestBackend:
                      'audio_kind': (None, '1'),
                      'audio_name': (None, os.path.basename(path_recorded))}
                      
-            # values = {'probe_id': probe_id}
-            response = requests.post(url, files=files, timeout=utils.NETWORK_TIMEOUT)
+            try:
+                # Limit POST time by TRACE_TOTAL_TIMEOUT seconds
+                TRACE_START_TIME = time.time()
+                sys.settrace(trace_function)
+                response = requests.post(url, files=files, timeout=utils.NETWORK_TIMEOUT)
+            except:
+                raise
+            finally:
+                sys.settrace(None)
+
             if response.status_code != 200:
                 utils.log_error(f"Upload audio to {self.address} finished with error {response.status_code}", None)
             else:
-                utils.log_verbose(f"Response (audio ID): {response.text}")
-                utils.log_verbose(f"Upload audio to {self.address} finished.")
+                utils.log_verbose(f"Upload audio finished. Response (audio ID): {response.text}")
                 result = True
         except Exception as e:
             utils.log_error(f"Upload audio to {self.address} finished with error.", err=e)
@@ -235,8 +162,7 @@ class QualtestBackend:
             # Get response from server
             response = urllib.request.urlopen(url, timeout=utils.NETWORK_TIMEOUT)
             if response.getcode() != 200:
-                utils.log_error("Failed to get task list. Error code: %s" % response.getcode())
-                return None
+                raise RuntimeError(f'Failed to get task list. Error code: {response.getcode()}')
 
             result = TaskList()
             response_content = response.read().decode()
@@ -244,11 +170,12 @@ class QualtestBackend:
             return result
 
         except Exception as err:
-            utils.log_error("Exception when fetching task list: {0}".format(err))
+            utils.log_error(f'Error when fetching task list from backend: {str(err)}')
             return None
 
     
-    def load_phone(self) -> dict:
+    def load_phone(self, cache: InfoCache) -> dict:
+        result = None
         try:
             # Build query for both V1 & V2 API
             instance = urllib.parse.urlencode({"phone_id": self.instance, "phone_name": self.instance})
@@ -257,16 +184,24 @@ class QualtestBackend:
             url = utils.join_host_and_path(self.address, "/phones/?") + instance
 
             # Get response from server
-            response = urllib.request.urlopen(url, timeout=utils.NETWORK_TIMEOUT)
-            if response.getcode() != 200:
-                utils.log_error("Failed to get task list. Error code: %s" % response.getcode())
-                return None
-
-            result: Phone = Phone()
+            try:
+                response = urllib.request.urlopen(url, timeout=utils.NETWORK_TIMEOUT)
+                if response.getcode() != 200:
+                    raise RuntimeError(f'Failed to load phone definition from server. Error code: {response.getcode()}')
+            except Exception as e:
+                utils.log_error(f'Problem when loading the phone definition from backend. Error: {str(e)}')
+                r = cache.get_phone(self.instance)
+                if r is None:
+                    raise RuntimeError(f'No cached phone definition.')
+                utils.log(f'  Found phone definition in cache.')
+                return r
+            
+            # Get possible list of phones
             phones = json.loads(response.read().decode())
             if len(phones) == 0:
-                return result
+                return None
 
+            # But use first one
             phone = phones[0]
 
             attr_dict = dict()
@@ -290,6 +225,7 @@ class QualtestBackend:
             if 'sip_useproxy' not in attr_dict:
                 attr_dict['sip_useproxy'] = True
 
+            result = Phone()
             result.attributes = attr_dict
             result.identifier = phone['id']
             result.name = phone['instance']
@@ -299,12 +235,15 @@ class QualtestBackend:
             return result
 
         except Exception as err:
-            utils.log_error("Exception when fetching task list: {0}".format(err))
-            return dict()
+            utils.log_error(f"Exception loading phone information: {str(err)}")
+            return None
 
 
     def load_audio(self, audio_id: int, output_path: Path):
-        utils.log(f'Loading audio with ID: {audio_id}')
+        global TRACE_START_TIME
+
+        utils.log(f'Loading audio with ID: {audio_id} ...')
+        TRACE_START_TIME = time.time()
         try:
             # Build query for both V1 & V2 API
             params = urllib.parse.urlencode({"audio_id": audio_id})
@@ -312,19 +251,26 @@ class QualtestBackend:
             # Find URL
             url = utils.join_host_and_path(self.address, "/play_audio/?") + params
 
-            # Get response from server
-            response = urllib.request.urlopen(url, timeout=utils.NETWORK_TIMEOUT)
-            if response.getcode() != 200:
-                utils.log_error("Failed to get audio. Error code: %s" % response.getcode())
+            sys.settrace(trace_function)
+            try:
+                # Get response from server
+                response = requests.get(url, timeout=(utils.NETWORK_TIMEOUT, 5))
+            except:
+                raise
+            finally:
+                sys.settrace(None)
+
+            if response.status_code != 200:
+                utils.log_error(f'  Failed to get audio. Error code: {response.status_code}, msg: {response.content}')
                 return False
 
-            audio_content = response.read()
             with open (output_path, 'wb') as f:
-                f.write(audio_content)
+                f.write(response.content)
             
+            utils.log('  Done.')
             return True
         except Exception as err:
-            utils.log_error("Exception when fetching  list: {0}".format(err))
+            utils.log_error(f'  Exception when fetching audio: {str(err)}')
             
             return False
 

src/utils_sevana.py

@@ -13,6 +13,7 @@ import urllib
 
 from pathlib import Path
 from colorama import Fore, Style
+from utils_cache import InfoCache
 
 PVQA_CMD = "{pvqa} --license {pvqa_lic} --config {pvqa_cfg} --mode analysis --channel 0 " \
            "--report {output} --input {input} --cut-begin {cut_begin} --cut-end {cut_end}"
@@ -72,12 +73,15 @@ def load_file(url: str, output_path: str):
 
 
 def load_config_and_licenses(server: str):
-    load_file(utils.join_host_and_path(server, '/deploy/pvqa.cfg'), PVQA_CFG_PATH)
-    load_file(utils.join_host_and_path(server, '/deploy/pvqa.lic'), PVQA_LIC_PATH)
-    load_file(utils.join_host_and_path(server, '/deploy/aqua-wb.lic'), AQUA_LIC_PATH)
-    
+    # ToDo: validate licenses before. If they are ok - skip their update 
+    try:
+        load_file(utils.join_host_and_path(server, '/deploy/pvqa.cfg'), PVQA_CFG_PATH)
+        load_file(utils.join_host_and_path(server, '/deploy/pvqa.lic'), PVQA_LIC_PATH)
+        load_file(utils.join_host_and_path(server, '/deploy/aqua-wb.lic'), AQUA_LIC_PATH)
+    except Exception as e:
+        utils.log_error(f'Failed to fetch new licenses and config. Skipping it.')
 
-def find_binaries(directory: str, license_server: str = None):
+def find_binaries(bin_directory: Path, license_server: str = None) -> bool:
     # Update path to pvqa/aqua-wb
     global PVQA_CFG_PATH, PVQA_LIC_PATH, AQUA_LIC_PATH, PVQA_PATH, AQUA_PATH, PVQA_CMD, AQUA_CMD, SILER_PATH, SPEECH_DETECTOR_PATH
 
@@ -86,8 +90,6 @@ def find_binaries(directory: str, license_server: str = None):
     if utils.is_raspberrypi():
         platform_prefix = 'rpi'
         
-    bin_directory = Path(directory)
-
     PVQA_PATH =             bin_directory / platform_prefix / PVQA_PATH
     PVQA_LIC_PATH =         bin_directory / PVQA_LIC_PATH
     PVQA_CFG_PATH =         bin_directory / PVQA_CFG_PATH
@@ -96,27 +98,27 @@ def find_binaries(directory: str, license_server: str = None):
     SILER_PATH =            bin_directory / platform_prefix / SILER_PATH
     SPEECH_DETECTOR_PATH =  bin_directory / platform_prefix / SPEECH_DETECTOR_PATH
 
-    print(f'Looking for binaries/licenses/configs at {directory}...', end=' ')
+    utils.log(f'Looking for binaries/licenses/configs at {bin_directory}...')
 
     # Check if binaries exist
     if not PVQA_PATH.exists():
-        print(f'Failed to find pvqa binary at {PVQA_PATH}. Exiting.')
+        utils.log_error(f'Failed to find pvqa binary at {PVQA_PATH}. Exiting.')
         sys.exit(1)
 
     if not PVQA_CFG_PATH.exists():
         PVQA_CFG_PATH = Path(utils.get_script_path()) / 'pvqa.cfg'
     
     if not PVQA_CFG_PATH.exists():
-        print(f'Failed to find pvqa config. Exiting.')
-        sys.exit(1)
+        utils.log_error(f'Failed to find pvqa config.')
+        return False
 
     if not AQUA_PATH.exists():
-        print(f'Failed to find aqua-wb binary. Exiting.')
-        sys.exit(1)
+        utils.log_error(f'Failed to find aqua-wb binary.')
+        return False
 
     if not SILER_PATH.exists():
-        print(f'Failed to find silence_eraser binary. Exiting.')
-        sys.exit(1)
+        utils.log_error(f'Failed to find silence_eraser binary..')
+        return False
 
     if license_server is not None:
         AQUA_LIC_PATH = '"license://' + license_server + '"'
@@ -126,16 +128,17 @@ def find_binaries(directory: str, license_server: str = None):
         if not PVQA_LIC_PATH.exists():
             PVQA_LIC_PATH = Path(utils.get_script_path()) / 'pvqa.lic'
         if not PVQA_LIC_PATH.exists():
-            print(f'Failed to find pvqa license. Exiting.')
-            sys.exit(1)
+            utils.log_error(f'Failed to find pvqa license.')
+            return False
 
     if not AQUA_LIC_PATH.exists():
         AQUA_LIC_PATH = Path(utils.get_script_path()) / 'aqua-wb.lic'
         if not AQUA_LIC_PATH.exists():
-            print(f'Failed to find AQuA license. Exiting.')
-            sys.exit(1)
+            utils.log_error(f'Failed to find AQuA license.')
+            return False
 
-    print(f'Found all analyzers.')
+    utils.log(f'  Found all analyzers.')
+    return True
 
 
 def speech_detector(test_path: str):

src/utils_types.py

@@ -0,0 +1,147 @@
+#!/usr/bin/python3
+
+import time
+import sys
+import utils
+import json
+from crontab import CronTab
+
+
+
+# Exit codes
+EXIT_OK = 0
+EXIT_ERROR = 1
+
+class Phone:
+    identifier: int = 0
+    name: str = ""
+    role: str = ""
+    attributes: dict = ""
+    audio_id: int = 0
+
+    def __init__(self):
+        self.identifier = 0
+        self.name = ""
+        self.role = ""
+        self.attributes = dict()
+        self.audio_id = 0
+
+    def to_dict(self) -> dict:
+        return {
+            'id': self.identifier,
+            'name': self.name,
+            'role': self.role,
+            'attr': self.attributes,
+            'audio_id': self.audio_id
+        }
+
+    def make(d: dict):
+        r = Phone()
+
+        r.identifier = d['id']
+        r.name = d['name']
+        r.role = d['role']
+        if 'attr' in d:
+            r.attr = d['attr']
+        else:
+            r.attr = None
+
+        if 'audio_id' in d:
+            r.audio_id = d['audio_id']
+        else:
+            r.audio_id = None
+
+        return r
+
+
+    def dump(self) -> str:
+        return json.dumps(self.to_dict(), indent=4)
+
+
+class TaskList:
+    tasks: list = []
+
+    def __init__(self):
+        self.tasks = []
+
+
+    # Merges incoming task list to existing one
+    # It preserves existing schedules
+    # New items are NOT scheduled automatically
+    def merge_with(self, incoming_tasklist) -> bool:
+        changed = False
+        if incoming_tasklist.tasks is None:
+            return True
+
+        # Iterate all tasks, see if task with the same name exists already
+        # Copy all keys, but keep existing ones
+        for new_task in incoming_tasklist.tasks:
+            # Find if this task exists already
+            existing_task = self.find_task_by_name(new_task["name"])
+
+            # If task is found - copy all items to it.
+            # It is required as task can hold schedule items already
+            # Bad idea to copy tasks itself.
+            if existing_task is not None:
+                # Check if scheduled time point has to be removed (if cron string changed)
+                if new_task["schedule"] != existing_task["schedule"] and "scheduled_time" in existing_task:
+                    del existing_task["scheduled_time"]
+                
+
+                # Finally copy new values
+                for key, value in new_task.items():
+                    if existing_task[key] != value:
+                        existing_task[key] = value
+                        changed = True
+            else:
+                # Copy new task to list
+                self.tasks.extend([new_task])
+                changed = True
+
+        # Check if old tasks are here... And delete them
+        for existing_task in self.tasks:
+            new_task = self.find_task_by_name(existing_task["name"])
+            if new_task is None:
+                self.tasks.remove(existing_task)
+                changed = True
+
+        return changed
+
+    
+    def schedule(self):
+        # Remove items without schedule before
+        self.tasks = [t for t in self.tasks if len(t['schedule']) > 0]
+
+        # https://crontab.guru is good for crontab strings generation
+        # Use monotonic time source!
+        current_time = utils.get_monotonic_time()
+        for task in self.tasks:
+            if 'scheduled_time' not in task and 'schedule' in task:
+                # No schedule flag, so time to schedule
+                try:
+                    cron_string = task['schedule'].strip()
+                    if cron_string == '* * * * *':
+                        task['scheduled_time'] = utils.get_monotonic_time() - 0.001 # To ensure further comparison will not be affected by precision errors
+                    else:
+                        cron = CronTab(task['schedule'])
+                        task['scheduled_time'] = current_time + cron.next(default_utc=True)
+
+                    # Just to help in further log reading & debugging - show the scheduled time in readable form
+                    task['scheduled_time_str'] = time.ctime(task['scheduled_time'])
+                except:
+                    utils.log_error("Error", sys.exc_info()[0])
+
+        # Remove non scheduled items 
+        self.tasks = [t for t in self.tasks if 'scheduled_time' in t]
+
+        # Sort everything
+        self.tasks = sorted(self.tasks, key=lambda t: t["scheduled_time"])
+        
+
+    # Returns None if failed
+    def find_task_by_name(self, name):
+        for t in self.tasks:
+            if t["name"] == name:
+                return t
+
+        return None