Add debug level log messages

CHANGELOG.md

@@ -8,6 +8,9 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 
 ### Added
 - Allow the scanner to update total count of hosts. [#332](https://github.com/greenbone/ospd/pull/332)
+- Add more debug logging. [#352](https://github.com/greenbone/ospd/pull/352)
+- Set end_time for interrupted scans. [#352](https://github.com/greenbone/ospd/pull/352)
+
 
 ### Fixed
 - Fix OSP version. [#326](https://github.com/greenbone/ospd/pull/326)

ospd/ospd.py

@@ -27,6 +27,7 @@
 import time
 import os
 
+from pprint import pformat
 from typing import (
     List,
     Any,
@@ -393,6 +394,9 @@ def stop_scan(self, scan_id: str) -> None:
             logger.debug('%s: The scanner task stopped unexpectedly.', scan_id)
 
         try:
+            logger.debug(
+                '%s: Terminating process group after stopping.', scan_id
+            )
             _terminate_process_group(scan_process)
         except ProcessLookupError:
             logger.info(
@@ -443,6 +447,7 @@ def daemon_exit_cleanup(self) -> None:
                 and status != ScanStatus.FINISHED
                 and status != ScanStatus.INTERRUPTED
             ):
+                logger.debug("%s: Stopping scan before daemon exit.", scan_id)
                 self.stop_scan(scan_id)
 
         # Wait for scans to be in some stopped state.
@@ -458,8 +463,12 @@ def daemon_exit_cleanup(self) -> None:
                     all_stopped = False
 
             if all_stopped:
+                logger.debug(
+                    "All scans stopped and daemon clean and ready to exit"
+                )
                 return
 
+            logger.debug("Waiting for running scans before daemon exit. ")
             time.sleep(1)
 
     def get_daemon_name(self) -> str:
@@ -574,19 +583,28 @@ def start_scan(self, scan_id: str) -> None:
                 host=self.get_scan_host(scan_id),
                 value='Host process failure (%s).' % e,
             )
-            logger.exception('While scanning: %s', scan_id)
+            logger.exception('%s: Exception %s while scanning', scan_id, e)
         else:
             logger.info("%s: Host scan finished.", scan_id)
 
-        is_stopped = self.get_scan_status(scan_id) == ScanStatus.STOPPED
+        status = self.get_scan_status(scan_id)
+        is_stopped = status == ScanStatus.STOPPED
         self.set_scan_progress(scan_id)
         progress = self.get_scan_progress(scan_id)
-
         if not is_stopped and progress == ScanProgress.FINISHED:
             self.finish_scan(scan_id)
         elif not is_stopped:
+            logger.info(
+                "%s: Host scan finished. Progress: %d, " "Status: %s",
+                scan_id,
+                progress,
+                status.name,
+            )
             self.interrupt_scan(scan_id)
 
+        # For debug purposes
+        self._get_scan_progress_raw(scan_id)
+
     def dry_run_scan(self, scan_id: str, target: Dict) -> None:
         """ Dry runs a scan. """
 
@@ -680,11 +698,14 @@ def set_scan_host_progress(
 
     def set_scan_status(self, scan_id: str, status: ScanStatus) -> None:
         """ Set the scan's status."""
+        logger.debug('%s: Set scan status %s,', scan_id, status.name)
         self.scan_collection.set_status(scan_id, status)
 
     def get_scan_status(self, scan_id: str) -> ScanStatus:
         """ Get scan_id scans's status."""
-        return self.scan_collection.get_status(scan_id)
+        status = self.scan_collection.get_status(scan_id)
+        logger.debug('%s: Current scan status: %s,', scan_id, status.name)
+        return status
 
     def scan_exists(self, scan_id: str) -> bool:
         """Checks if a scan with ID scan_id is in collection.
@@ -766,11 +787,8 @@ def get_scan_results_xml(
         logger.debug('Returning %d results', len(results))
         return results
 
-    def _get_scan_progress_xml(self, scan_id: str):
-        """Gets scan_id scan's progress in XML format.
-
-        @return: String of scan progress in xml.
-        """
+    def _get_scan_progress_raw(self, scan_id: str) -> Dict:
+        """Returns a dictionary with scan_id scan's progress information."""
         current_progress = dict()
 
         current_progress[
@@ -790,6 +808,19 @@ def _get_scan_progress_xml(self, scan_id: str):
             scan_id
         )
 
+        logging.debug(
+            "%s: Current progress: \n%s",
+            scan_id,
+            pformat(current_progress),
+        )
+        return current_progress
+
+    def _get_scan_progress_xml(self, scan_id: str):
+        """Gets scan_id scan's progress in XML format.
+
+        @return: String of scan progress in xml.
+        """
+        current_progress = self._get_scan_progress_raw(scan_id)
         return get_progress_xml(current_progress)
 
     @deprecated(
@@ -1242,8 +1273,18 @@ def handle_command(self, data: bytes, stream: Stream) -> None:
         scan_id = tree.get('scan_id')
         if self.scan_exists(scan_id) and command_name == "get_scans":
             if write_success:
+                logger.debug(
+                    '%s: Results sent succesfully to the client. Cleaning '
+                    'temporary result list.',
+                    scan_id,
+                )
                 self.scan_collection.clean_temp_result_list(scan_id)
             else:
+                logger.debug(
+                    '%s: Failed sending results to the client. Restoring '
+                    'result list into the cache.',
+                    scan_id,
+                )
                 self.scan_collection.restore_temp_result_list(scan_id)
 
     def check(self):
@@ -1426,7 +1467,8 @@ def clean_forgotten_scans(self) -> None:
 
     def check_scan_process(self, scan_id: str) -> None:
         """ Check the scan's process, and terminate the scan if not alive. """
-        if self.get_scan_status(scan_id) == ScanStatus.QUEUED:
+        status = self.get_scan_status(scan_id)
+        if status == ScanStatus.QUEUED:
             return
 
         scan_process = self.scan_processes.get(scan_id)
@@ -1437,18 +1479,28 @@ def check_scan_process(self, scan_id: str) -> None:
             and scan_process
             and not scan_process.is_alive()
         ):
-            if not self.get_scan_status(scan_id) == ScanStatus.STOPPED:
-                self.set_scan_status(scan_id, ScanStatus.STOPPED)
+            if not status == ScanStatus.STOPPED:
                 self.add_scan_error(
-                    scan_id, name="", host="", value="Scan process failure."
+                    scan_id, name="", host="", value="Scan process Failure"
                 )
 
-                logger.info("%s: Scan stopped with errors.", scan_id)
+                logger.info(
+                    "%s: Scan process is dead and its progress is %d",
+                    scan_id,
+                    progress,
+                )
                 self.interrupt_scan(scan_id)
 
         elif progress == ScanProgress.FINISHED:
             scan_process.join(0)
 
+        logger.debug(
+            "%s: Check scan process: \n\tProgress %d\n\t Status: %s",
+            scan_id,
+            progress,
+            status.name,
+        )
+
     def get_count_queued_scans(self) -> int:
         """ Get the amount of scans with queued status """
         count = 0
@@ -1459,7 +1511,9 @@ def get_count_queued_scans(self) -> int:
 
     def get_scan_progress(self, scan_id: str) -> int:
         """ Gives a scan's current progress value. """
-        return self.scan_collection.get_progress(scan_id)
+        progress = self.scan_collection.get_progress(scan_id)
+        logger.debug('%s: Current scan progress: %s,', scan_id, progress)
+        return progress
 
     def get_scan_host(self, scan_id: str) -> str:
         """ Gives a scan's target. """

ospd/scan.py

@@ -20,6 +20,7 @@
 import time
 import uuid
 
+from pprint import pformat
 from collections import OrderedDict
 from enum import Enum, IntEnum
 from typing import List, Any, Dict, Iterator, Optional, Iterable, Union
@@ -137,6 +138,13 @@ def remove_hosts_from_target_progress(
         if not hosts:
             return
 
+        LOGGER.debug(
+            '%s: Remove the following hosts from the target list, '
+            'as they are already finished or are dead: %s',
+            scan_id,
+            pformat(hosts),
+        )
+
         target = self.scans_table[scan_id].get('target_progress')
         for host in hosts:
             if host in target:
@@ -170,6 +178,11 @@ def set_host_progress(
     def set_host_finished(self, scan_id: str, hosts: List[str]) -> None:
         """ Increase the amount of finished hosts which were alive."""
 
+        LOGGER.debug(
+            '%s: Setting the following hosts as finished: %s',
+            scan_id,
+            pformat(hosts),
+        )
         total_finished = len(hosts)
         count_alive = (
             self.scans_table[scan_id].get('count_alive') + total_finished
@@ -179,6 +192,11 @@ def set_host_finished(self, scan_id: str, hosts: List[str]) -> None:
     def set_host_dead(self, scan_id: str, hosts: List[str]) -> None:
         """ Increase the amount of dead hosts. """
 
+        LOGGER.debug(
+            '%s: Setting the following hosts as dead: %s',
+            scan_id,
+            pformat(hosts),
+        )
         total_dead = len(hosts)
         count_dead = self.scans_table[scan_id].get('count_dead') + total_dead
         self.scans_table[scan_id]['count_dead'] = count_dead
@@ -332,7 +350,7 @@ def create_scan(
     def set_status(self, scan_id: str, status: ScanStatus) -> None:
         """ Sets scan_id scan's status. """
         self.scans_table[scan_id]['status'] = status
-        if status == ScanStatus.STOPPED:
+        if status == ScanStatus.STOPPED or status == ScanStatus.INTERRUPTED:
             self.scans_table[scan_id]['end_time'] = int(time.time())
 
     def get_status(self, scan_id: str) -> ScanStatus:
@@ -418,13 +436,28 @@ def calculate_target_progress(self, scan_id: str) -> int:
         count_dead = self.get_count_dead(scan_id)
         host_progresses = self.get_current_target_progress(scan_id)
 
+        LOGGER.debug(
+            "Calculating scan progress with the following data:\n"
+            "\ttotal_hosts: %d\n\t"
+            "\texc_hosts: %d\n\t"
+            "\tcount_alive: %d\n\t"
+            "\tcount_dead: %d\n\t"
+            "\thost_prgresses: %d\n\t",
+            total_hosts,
+            exc_hosts,
+            count_alive,
+            count_dead,
+            sum(host_progresses.values()),
+        )
+
         try:
             t_prog = int(
                 (sum(host_progresses.values()) + 100 * count_alive)
                 / (total_hosts - exc_hosts - count_dead)
             )
         except ZeroDivisionError:
             # Consider the case in which all hosts are dead or excluded
+            LOGGER.debug('%s: All hosts dead or excluded.')
             t_prog = ScanProgress.FINISHED.value
 
         return t_prog