From e340fe8066a430c62234e66d821cbdb9c7a2acc9 Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 13:11:39 +0200 Subject: [PATCH 1/6] Add info log when ospd starts --- ospd/main.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/ospd/main.py b/ospd/main.py index 29966599..df901e08 100644 --- a/ospd/main.py +++ b/ospd/main.py @@ -191,6 +191,11 @@ def main( if not daemon.check(): return 1 + LOGGER.info( + "Starting %s version %s." + % (daemon.daemon_info['name'], daemon.daemon_info['version']) + ) + daemon.init(server) daemon.run() From 7b7002d668754dbb1f474b9318d8715bd7b6fd43 Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 15:54:05 +0200 Subject: [PATCH 2/6] Degrade default log level from warning to info --- ospd/parser.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ospd/parser.py b/ospd/parser.py index 88150c1c..fbbecd7b 100644 --- a/ospd/parser.py +++ b/ospd/parser.py @@ -121,7 +121,7 @@ def __init__(self, description: str) -> None: parser.add_argument( '-L', '--log-level', - default='WARNING', + default='INFO', type=self.log_level, help='Wished level of logging. Default: %(default)s', ) From 6edb2b5fa6c02db442faffb3b8a1c5240dba4f0e Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 15:54:43 +0200 Subject: [PATCH 3/6] Improve logging when a task is queued Add log when the max queued scans limit has been reached. Also a message if the scan was queued successfully and inform the position of the scan in the queue. --- ospd/command/command.py | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/ospd/command/command.py b/ospd/command/command.py index 9e01b854..2d0a1dbf 100644 --- a/ospd/command/command.py +++ b/ospd/command/command.py @@ -478,13 +478,19 @@ def handle_xml(self, xml: Element) -> bytes: Response string for command. """ + current_queued_scans = self._daemon.get_count_queued_scans() if ( self._daemon.max_queued_scans - and self._daemon.get_count_queued_scans() - >= self._daemon.max_queued_scans + and current_queued_scans >= self._daemon.max_queued_scans ): + logger.info( + 'Maximum number of queued scans set to %d reached.' + % self._daemon.max_queued_scans, + ) raise OspdCommandError( - 'Maximum number of queued scans reached.', 'start_scan' + 'Maximum number of queued scans set to %d reached.' + % self._daemon.max_queued_scans, + 'start_scan', ) target_str = xml.get('target') @@ -555,6 +561,11 @@ def handle_xml(self, xml: Element) -> bytes: id_.text = scan_id_aux return simple_response_str('start_scan', 100, 'Continue', id_) + logger.info( + 'Scan %s added to the queue in position %d.' + % (scan_id, current_queued_scans + 1) + ) + if dry_run: scan_func = self._daemon.dry_run_scan scan_process = create_process( From d12a12c04740477ae0432a192104d855f3ff422e Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 16:02:19 +0200 Subject: [PATCH 4/6] Improve logging when trying to start a queued scan --- ospd/ospd.py | 50 +++++++++++++++++++++++++++++++++----------------- 1 file changed, 33 insertions(+), 17 deletions(-) diff --git a/ospd/ospd.py b/ospd/ospd.py index 610a08b7..b5011646 100644 --- a/ospd/ospd.py +++ b/ospd/ospd.py @@ -1213,20 +1213,19 @@ def run(self) -> None: def start_queued_scans(self) -> None: """ Starts a queued scan if it is allowed """ - for scan_id in self.scan_collection.ids_iterator(): - if not self.is_new_scan_allowed(): - logger.debug( - 'Not possible to run a new scan. Max scan limit reached.' - ) - return + current_queued_scans = self.get_count_queued_scans() + if not current_queued_scans: + return - if not self.is_enough_free_memory(): - logger.debug( - 'Not possible to run a new scan. Not enough free memory.' - ) - return + logger.info('Currently %d queued scans.' % current_queued_scans) - if self.get_scan_status(scan_id) == ScanStatus.QUEUED: + for scan_id in self.scan_collection.ids_iterator(): + scan_allowed = ( + self.is_new_scan_allowed() and self.is_enough_free_memory() + ) + scan_is_queued = self.get_scan_status(scan_id) == ScanStatus.QUEUED + + if scan_is_queued and scan_allowed: try: self.scan_collection.unpickle_scan_info(scan_id) except OspdCommandError as e: @@ -1240,16 +1239,27 @@ def start_queued_scans(self) -> None: scan_process.start() self.set_scan_status(scan_id, ScanStatus.INIT) + current_queued_scans = current_queued_scans - 1 + logger.info('Starting scan %s.' % scan_id) + elif scan_is_queued and not scan_allowed: + return + def is_new_scan_allowed(self) -> bool: """ Check if max_scans has been reached. Return: True if a new scan can be launch. """ - if (self.max_scans == 0) or (len(self.scan_processes) < self.max_scans): - return True + if (self.max_scans != 0) and ( + len(self.scan_processes) >= self.max_scans + ): + logger.info( + 'Not possible to run a new scan. Max scan limit set to %d reached.' + % self.max_scans + ) + return False - return False + return True def is_enough_free_memory(self) -> bool: """ Check if there is enough free memory in the system to run @@ -1262,11 +1272,17 @@ def is_enough_free_memory(self) -> bool: if not self.min_free_mem_scan_queue: return True - free_mem = psutil.virtual_memory().free + free_mem = psutil.virtual_memory().free / (1024 * 1024) - if (free_mem / (1024 * 1024)) > self.min_free_mem_scan_queue: + if free_mem > self.min_free_mem_scan_queue: return True + logger.info( + 'Not possible to run a new scan. Not enough free memory. ' + 'Only %d MB available but at least %d are required' + % (free_mem, self.min_free_mem_scan_queue) + ) + return False def scheduler(self): From 9c806cd02f6c87b50499b325336ba71809a13424 Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 16:03:44 +0200 Subject: [PATCH 5/6] Update test --- tests/test_argument_parser.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_argument_parser.py b/tests/test_argument_parser.py index 0dd038b8..faef018e 100644 --- a/tests/test_argument_parser.py +++ b/tests/test_argument_parser.py @@ -94,7 +94,7 @@ def test_defaults(self): self.assertEqual(args.key_file, DEFAULT_KEY_FILE) self.assertEqual(args.niceness, DEFAULT_NICENESS) - self.assertEqual(args.log_level, logging.WARNING) + self.assertEqual(args.log_level, logging.INFO) self.assertEqual(args.address, DEFAULT_ADDRESS) self.assertEqual(args.port, DEFAULT_PORT) self.assertEqual(args.scaninfo_store_time, DEFAULT_SCANINFO_STORE_TIME) From 2b534b00f7aae8cb5a7c5d705dd268ef31f77527 Mon Sep 17 00:00:00 2001 From: Juan Jose Nicola Date: Mon, 8 Jun 2020 16:40:07 +0200 Subject: [PATCH 6/6] Log message when a scan is stopped and removed from the queue Also, fix logging-no-lazy for pylint --- ospd/command/command.py | 9 +++++---- ospd/main.py | 5 +++-- ospd/ospd.py | 16 ++++++++++------ 3 files changed, 18 insertions(+), 12 deletions(-) diff --git a/ospd/command/command.py b/ospd/command/command.py index 2d0a1dbf..e00b6533 100644 --- a/ospd/command/command.py +++ b/ospd/command/command.py @@ -484,8 +484,8 @@ def handle_xml(self, xml: Element) -> bytes: and current_queued_scans >= self._daemon.max_queued_scans ): logger.info( - 'Maximum number of queued scans set to %d reached.' - % self._daemon.max_queued_scans, + 'Maximum number of queued scans set to %d reached.', + self._daemon.max_queued_scans, ) raise OspdCommandError( 'Maximum number of queued scans set to %d reached.' @@ -562,8 +562,9 @@ def handle_xml(self, xml: Element) -> bytes: return simple_response_str('start_scan', 100, 'Continue', id_) logger.info( - 'Scan %s added to the queue in position %d.' - % (scan_id, current_queued_scans + 1) + 'Scan %s added to the queue in position %d.', + scan_id, + current_queued_scans + 1, ) if dry_run: diff --git a/ospd/main.py b/ospd/main.py index df901e08..9cbe00ac 100644 --- a/ospd/main.py +++ b/ospd/main.py @@ -192,8 +192,9 @@ def main( return 1 LOGGER.info( - "Starting %s version %s." - % (daemon.daemon_info['name'], daemon.daemon_info['version']) + "Starting %s version %s.", + daemon.daemon_info['name'], + daemon.daemon_info['version'], ) daemon.init(server) diff --git a/ospd/ospd.py b/ospd/ospd.py index b5011646..1c61c491 100644 --- a/ospd/ospd.py +++ b/ospd/ospd.py @@ -375,8 +375,10 @@ def stop_scan(self, scan_id: str) -> None: scan_id in self.scan_collection.ids_iterator() and self.get_scan_status(scan_id) == ScanStatus.QUEUED ): + logger.info('Scan %s has been removed from the queue.', scan_id) self.scan_collection.remove_file_pickled_scan_info(scan_id) self.set_scan_status(scan_id, ScanStatus.STOPPED) + return scan_process = self.scan_processes.get(scan_id) @@ -1217,7 +1219,7 @@ def start_queued_scans(self) -> None: if not current_queued_scans: return - logger.info('Currently %d queued scans.' % current_queued_scans) + logger.info('Currently %d queued scans.', current_queued_scans) for scan_id in self.scan_collection.ids_iterator(): scan_allowed = ( @@ -1240,7 +1242,7 @@ def start_queued_scans(self) -> None: self.set_scan_status(scan_id, ScanStatus.INIT) current_queued_scans = current_queued_scans - 1 - logger.info('Starting scan %s.' % scan_id) + logger.info('Starting scan %s.', scan_id) elif scan_is_queued and not scan_allowed: return @@ -1254,8 +1256,9 @@ def is_new_scan_allowed(self) -> bool: len(self.scan_processes) >= self.max_scans ): logger.info( - 'Not possible to run a new scan. Max scan limit set to %d reached.' - % self.max_scans + 'Not possible to run a new scan. Max scan limit set ' + 'to %d reached.', + self.max_scans, ) return False @@ -1279,8 +1282,9 @@ def is_enough_free_memory(self) -> bool: logger.info( 'Not possible to run a new scan. Not enough free memory. ' - 'Only %d MB available but at least %d are required' - % (free_mem, self.min_free_mem_scan_queue) + 'Only %d MB available but at least %d are required', + free_mem, + self.min_free_mem_scan_queue, ) return False