diff --git a/arat-rl.py b/arat-rl.py index c08adec..258f742 100644 --- a/arat-rl.py +++ b/arat-rl.py @@ -9,12 +9,16 @@ import base64 import random import string +import logging import prance import difflib import requests import datetime import functools from collections import defaultdict +from logger_config import setup_logging + +logger = logging.getLogger('arat-rl') @@ -232,7 +236,7 @@ def send_request(content_type): elif method == 'head': return requests.head(url, headers=headers, params=query_params) except requests.exceptions.RequestException as e: - print(f"Request error: {e}") + logger.warning('Request error: %s', e) return None for param_value_dict in selected_parameters: @@ -402,7 +406,7 @@ def report_http_500_errors(): with open(filename, 'w') as file: file.write(report_content) - print(f"Report saved to {filename}") + logger.info('Report saved to %s', filename) def update_q_table(q_table, alpha, gamma, selected_operation, selected_parameters, response, path, query_params, body_params): @@ -423,6 +427,7 @@ def update_q_table(q_table, alpha, gamma, selected_operation, selected_parameter reward = -5 if response.status_code == 500: + logger.info('HTTP 500 error detected for operation: %s', operation_id) if operation_id not in http_500_operations: http_500_operations.append(operation_id) total_n[0] = total_n[0] + 1 @@ -685,6 +690,10 @@ def main(): operations, parameters_frequency = analyze_information(openapi_spec) alpha, gamma, q_table = initialize_q_learning(operations, parameters_frequency) + logger.info('Starting ARAT-RL with spec: %s, base URL: %s, time limit: %s', + openapi_spec_file, base_url, sys.argv[3]) + logger.info('Found %d operations', len(operations)) + start_time = time.time() time_limit = int(sys.argv[3]) iteration = 0 @@ -694,6 +703,8 @@ def main(): elapsed_time = time.time() - start_time if elapsed_time >= time_limit: break + if iteration % 100 == 0: + logger.info('Iteration %d, elapsed time: %.1fs', iteration, elapsed_time) parameter_values = generate_parameter_values(operations) selected_operation, selected_parameters = select_operations_and_parameters(operations, parameter_values, q_table) @@ -732,6 +743,7 @@ def main(): iteration += 1 if __name__ == "__main__": + setup_logging('arat-rl', log_file='arat-rl.log') base_url = sys.argv[2] EPSILON = [0.1] ss = [None] @@ -749,4 +761,5 @@ def main(): q_value = {} MUTATION_RATE = 0.1 main() + logger.info('Testing completed, generating report') report_http_500_errors() diff --git a/logger_config.py b/logger_config.py new file mode 100644 index 0000000..0dc86d8 --- /dev/null +++ b/logger_config.py @@ -0,0 +1,70 @@ +"""Centralized logging configuration for ARAT-RL. + +Usage: + from logger_config import setup_logging, get_logger + + # In entry point scripts (if __name__ == "__main__"): + setup_logging('arat-rl', log_file='arat-rl.log') + + # Create a module-level logger: + logger = get_logger('arat-rl') + + # Use the logger: + logger.info('Starting testing with spec: %s', spec_file) + logger.warning('Request error: %s', e) + logger.debug('Response value: %s = %s', key, value) + +The log level can be controlled via the LOG_LEVEL environment variable. +Supported levels: DEBUG, INFO, WARNING, ERROR. Default: INFO. +""" + +import os +import logging + + +def setup_logging(name, log_level='INFO', log_file=None): + """Configure and return a logger with console and optional file output. + + Args: + name: Logger name. + log_level: Default log level (overridden by LOG_LEVEL env var). + log_file: Optional path to a log file. + + Returns: + Configured logging.Logger instance. + """ + level_str = os.environ.get('LOG_LEVEL', log_level).upper() + level = getattr(logging, level_str, logging.INFO) + + logger = logging.getLogger(name) + logger.setLevel(level) + + formatter = logging.Formatter( + fmt='%(asctime)s [%(levelname)s] %(name)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + ) + + console_handler = logging.StreamHandler() + console_handler.setLevel(level) + console_handler.setFormatter(formatter) + logger.addHandler(console_handler) + + if log_file is not None: + file_handler = logging.FileHandler(log_file) + file_handler.setLevel(level) + file_handler.setFormatter(formatter) + logger.addHandler(file_handler) + + return logger + + +def get_logger(name): + """Convenience function to get a logger by name. + + Args: + name: Logger name. + + Returns: + logging.Logger instance. + """ + return logging.getLogger(name) diff --git a/main.py b/main.py index d8ea85c..48f1c1d 100644 --- a/main.py +++ b/main.py @@ -9,12 +9,16 @@ import base64 import random import string +import logging import prance import difflib import requests import datetime import functools from collections import defaultdict +from logger_config import setup_logging + +logger = logging.getLogger('arat-rl-main') @@ -232,7 +236,7 @@ def send_request(content_type): elif method == 'head': return requests.head(url, headers=headers, params=query_params) except requests.exceptions.RequestException as e: - print(f"Request error: {e}") + logger.warning('Request error: %s', e) return None for param_value_dict in selected_parameters: @@ -642,6 +646,9 @@ def main(): operations, parameters_frequency = analyze_information(openapi_spec) alpha, gamma, q_table = initialize_q_learning(operations, parameters_frequency) + logger.info('Starting arat-rl-main with spec: %s, base URL: %s', openapi_spec_file, base_url) + logger.info('Found %d operations', len(operations)) + start_time = time.time() time_limit = 3600 iteration = 0 @@ -651,6 +658,8 @@ def main(): elapsed_time = time.time() - start_time if elapsed_time >= time_limit: break + if iteration % 100 == 0: + logger.info('Iteration %d, elapsed time: %.1fs', iteration, elapsed_time) parameter_values = generate_parameter_values(operations) selected_operation, selected_parameters = select_operations_and_parameters(operations, parameter_values, q_table) @@ -689,6 +698,7 @@ def main(): iteration += 1 if __name__ == "__main__": + setup_logging('arat-rl-main', log_file='arat-rl-main.log') base_url = sys.argv[2] EPSILON = [0.1] ss = [None] diff --git a/morest/experiment_utils/php_coverage_merger.py b/morest/experiment_utils/php_coverage_merger.py index 6410abe..04019bd 100644 --- a/morest/experiment_utils/php_coverage_merger.py +++ b/morest/experiment_utils/php_coverage_merger.py @@ -1,8 +1,11 @@ import argparse +import logging import os import json import time +logger = logging.getLogger('morest.experiment.coverage') + def get_coverage_logs(path): files = os.listdir(path) @@ -20,7 +23,7 @@ def read_data(path=""): def run_single(folder, result={}): logs = (get_coverage_logs(folder)) for log in logs: - print("read", log) + logger.info('Read: %s', log) data = read_data(log) for file_name in data: if not (file_name in result): @@ -36,7 +39,7 @@ def run_single(folder, result={}): continue line_count += len(result[file_name]) result["line_count"] = line_count - print("total line count", line_count) + logger.info('Total line count: %d', line_count) def main(args): @@ -44,8 +47,8 @@ def main(args): output_file = args.o result = {} while True: - print("read from", coverage_folder) - print("write to", output_file) + logger.info('Read from: %s', coverage_folder) + logger.info('Write to: %s', output_file) run_single(coverage_folder, result) with open(output_file, 'w') as data: json.dump(result, data) diff --git a/morest/fuzzer.py b/morest/fuzzer.py index 3e628ee..9bacdd8 100644 --- a/morest/fuzzer.py +++ b/morest/fuzzer.py @@ -1,11 +1,15 @@ import os import sys +import logging from prance import ResolvingParser from build_graph import parse from fuzzer.fuzzer import APIFuzzer from utils.auth_util import get_token, SUT +from logger_config import setup_logging + +logger = logging.getLogger('morest') def default_reclimit_handler(limit, parsed_url, recursions=()): @@ -18,6 +22,7 @@ def default_reclimit_handler(limit, parsed_url, recursions=()): def main(): + setup_logging('morest') # testing arguments format: swagger address, server address, system under test's name, *args to obtain token test_args = [sys.argv[1], sys.argv[2], SUT.BITBUCKET] parser = ResolvingParser(test_args[0], diff --git a/morest/fuzzer/fuzzer.py b/morest/fuzzer/fuzzer.py index 7a0c889..cb95b88 100644 --- a/morest/fuzzer/fuzzer.py +++ b/morest/fuzzer/fuzzer.py @@ -1,4 +1,5 @@ import json +import logging import time import uuid from datetime import datetime @@ -15,6 +16,8 @@ from .runtime_dictionary import RuntimeDictionary from model.sequence import SequenceOrigin +logger = logging.getLogger('morest.fuzzer') + class APIFuzzer: @@ -110,9 +113,9 @@ def run(self): # analyze dependency to add self.analyze_dependency_to_add() - print('current seq') + logger.debug('Current sequences:') for seq in self.sequences: - print(seq.to_str()) + logger.debug('%s', seq.to_str()) # Phase 2 # if previous_success_size != len(self.success_sequence) and np.random.random() > 0.95: # previous_success_size = len(self.success_sequence) @@ -125,7 +128,7 @@ def run(self): # executor.draw_response_dict() def mutation_fuzz_run(self): - print("Continue to mutation fuzzing \n-------------------- \n") + logger.info('Continue to mutation fuzzing') time.sleep(3) # re_initialize the fuzzer self.runtime_dict = RuntimeDictionary() @@ -159,10 +162,10 @@ def mutation_fuzz_run(self): self.send_msg_count += 1 self.process_mutation_response(baseline_res, res, sequence, mutation_index) self.write_mutation_result() - print(self.violations) + logger.info('Violations: %s', self.violations) def synthesis_resource_sequence(self, executor): - print('synthesis resource') + logger.debug('Synthesis resource') add_sequence_size = 100 matched_pair = {} success_sequence = list(self.success_sequence) @@ -346,9 +349,8 @@ def analyze_dependency_to_add(self): if not is_valid: break generated_sequences.add(new_seq) - print('add ref in sequence', sequence.requests[0].method_name, "to", method, - f'via {request_parameters}', "new sequence", - len(new_seq)) + logger.debug('add ref in sequence %s to %s via %s, new sequence %d', sequence.requests[0].method_name, method, + request_parameters, len(new_seq)) break # print('request_parameter_to_methods') @@ -398,7 +400,7 @@ def process_response(self, resp, sequence): "time": time.time() - self.begin, 'count': len(self.success_endpoint) + 1 }) - print(method_path, 'method path') + logger.debug('Method path: %s', method_path) self.success_endpoint.add(method_path) self.success_apis.add(response["apiName"]) if status_code > 499 and status_code < 600: @@ -560,38 +562,51 @@ def overall_status(self): sequence_source = {} for seq in self.success_sequence: sequence_source[seq.origin] = sequence_source.get(seq.origin, 0) + 1 - print( - f'{datetime.now().strftime("%Y/%m/%d %H:%M:%S")}, Fuzzing Time: {elapsed}s, Send Msg Count: {self.send_msg_count}, ' - f'Receive Msg Count: {self.receive_msg_count}, Success Response Sequence Count: {self.success_sequence_count}, ' - f'Success Sequence Rate: {float(self.success_sequence_count) / self.receive_msg_count}, ' - f'Success API: {float(len(self.success_apis)) / len(self.total_apis)}' - f' ({len(self.success_apis)}/{len(self.total_apis)}),' - f'Error API: {float(len(self.error_apis)) / len(self.total_apis)}' - f' ({len(self.error_apis)}/{len(self.total_apis)}),' - f'Success Endpoint: {float(len(self.success_endpoint)) / len(self.apis)}' - f' ({len(self.success_endpoint)}/{len(self.apis)}),' - f'Error Endpoint: {float(len(self.error_endpoint)) / len(self.apis)}' - f' ({len(self.error_endpoint)}/{len(self.apis)}),' - f' Tested Error and Success Unique API: {float(len(set.union(self.success_apis, self.error_apis))) / len(self.total_apis)}' - f' ({len(set.union(self.success_apis, self.error_apis))}/{len(self.total_apis)}),' - f' Request Count: {self.request_count}, ' - f'Response Count: {self.response_count}, Response / Request: {float(self.response_count) / self.request_count}, ' - f'Request(QPS): {float(self.request_count) / elapsed}, Response(QPS):' - f' {float(self.response_count) / elapsed}, Violation Count: {len(self.violations)}' - f' Remain Sequence Count: {len(self.sequences)}' - f' Success Sequence: {len(self.success_sequence)}') - print('success') - print(self.success_apis) - print('errors') - print(self.error_apis) - print('==API Curve') - print({ + logger.info( + '%s, Fuzzing Time: %ss, Send Msg Count: %s, ' + 'Receive Msg Count: %s, Success Response Sequence Count: %s, ' + 'Success Sequence Rate: %s, ' + 'Success API: %s (%s/%s),' + 'Error API: %s (%s/%s),' + 'Success Endpoint: %s (%s/%s),' + 'Error Endpoint: %s (%s/%s),' + ' Tested Error and Success Unique API: %s (%s/%s),' + ' Request Count: %s, ' + 'Response Count: %s, Response / Request: %s, ' + 'Request(QPS): %s, Response(QPS): %s, Violation Count: %s' + ' Remain Sequence Count: %s' + ' Success Sequence: %s', + datetime.now().strftime("%Y/%m/%d %H:%M:%S"), elapsed, self.send_msg_count, + self.receive_msg_count, self.success_sequence_count, + float(self.success_sequence_count) / self.receive_msg_count, + float(len(self.success_apis)) / len(self.total_apis), + len(self.success_apis), len(self.total_apis), + float(len(self.error_apis)) / len(self.total_apis), + len(self.error_apis), len(self.total_apis), + float(len(self.success_endpoint)) / len(self.apis), + len(self.success_endpoint), len(self.apis), + float(len(self.error_endpoint)) / len(self.apis), + len(self.error_endpoint), len(self.apis), + float(len(set.union(self.success_apis, self.error_apis))) / len(self.total_apis), + len(set.union(self.success_apis, self.error_apis)), len(self.total_apis), + self.request_count, + self.response_count, float(self.response_count) / self.request_count, + float(self.request_count) / elapsed, + float(self.response_count) / elapsed, len(self.violations), + len(self.sequences), + len(self.success_sequence)) + logger.debug('success') + logger.debug('%s', self.success_apis) + logger.debug('errors') + logger.debug('%s', self.error_apis) + logger.debug('==API Curve') + logger.debug('%s', { "success_api": self.api_curve, "error_api": self.error_api_curve, "success_endpoint": self.success_endpoint_api_curve, "error_endpoint": self.error_endpoint_api_curve, }) - print(self.runtime_dict.signature_to_value.keys()) - print(status_stat) + logger.debug('%s', self.runtime_dict.signature_to_value.keys()) + logger.debug('%s', status_stat) # print(sequence_source) - print("sequence source", sequence_source) + logger.debug('sequence source %s', sequence_source) diff --git a/morest/fuzzer/fuzzer_huawei.py b/morest/fuzzer/fuzzer_huawei.py index a291461..3b9bdd9 100644 --- a/morest/fuzzer/fuzzer_huawei.py +++ b/morest/fuzzer/fuzzer_huawei.py @@ -1,4 +1,5 @@ import json +import logging import time import uuid from datetime import datetime @@ -11,6 +12,8 @@ from .huawei_converter import HuaWeiConverter from .runtime_dictionary import RuntimeDictionary +logger = logging.getLogger('morest.fuzzer.huawei') + class APIFuzzer: @@ -101,9 +104,9 @@ def run(self): # analyze dependency to add self.analyze_dependency_to_add() break - print('current seq') + logger.debug('Current sequences:') for seq in self.sequences: - print(seq.to_str()) + logger.debug('%s', seq.to_str()) # print('\n runtime dictionary') # for signature in self.runtime_dict.signature_to_value.keys(): # print(signature) @@ -187,9 +190,8 @@ def analyze_dependency_to_add(self): for req, res in request_parameters: new_seq.add_ref(len(new_seq) - 1, req, res) res.add(new_seq) - print('add ref in sequence', sequence.requests[0].method_name, "to", method, - f'via {request_parameters}', "new sequence", - len(new_seq)) + logger.debug('add ref in sequence %s to %s via %s, new sequence %d', sequence.requests[0].method_name, method, + request_parameters, len(new_seq)) # print('request_parameter_to_methods') # print(request_parameter_to_methods) @@ -204,7 +206,7 @@ def process_response(self): resp = ResponseReader.message_queue.pop() response_sequence_id = resp["sequenceID"] if not self.pending_request.__contains__(response_sequence_id): - print('mix request', response_sequence_id) + logger.warning('mix request %s', response_sequence_id) continue violations = validate(resp, self.apis) has_error = False @@ -242,7 +244,7 @@ def process_response(self): }) self.success_apis.add(response["apiName"]) if status_code == 0: - print(resp) + logger.warning('Zero status response: %s', resp) time.sleep(10) if status_code > 499 and status_code < 600: self.error_apis.add(response['apiName']) @@ -317,26 +319,37 @@ def overall_status(self): for status_code in self.status_code_status.keys(): status_stat += f'{status_code}:{self.status_code_status[status_code]},' \ f'{float(self.status_code_status[status_code]) / self.response_count} ' - print( - f'{datetime.now().strftime("%Y/%m/%d %H:%M:%S")}, Fuzzing Time: {elapsed}s, Send Msg Count: {self.send_msg_count}, ' - f'Receive Msg Count: {self.receive_msg_count}, Success Response Sequence Count: {self.success_sequence_count}, ' - f'Success Sequence Rate: {float(self.success_sequence_count) / self.receive_msg_count}, ' - f'Success API: {float(len(self.success_apis)) / len(self.total_apis)}' - f' ({len(self.success_apis)}/{len(self.total_apis)}),' - f'Error API: {float(len(self.error_apis)) / len(self.total_apis)}' - f' ({len(self.error_apis)}/{len(self.total_apis)}),' - f' Tested Error and Success Unique API: {float(len(set.union(self.success_apis, self.error_apis))) / len(self.total_apis)}' - f' ({len(set.union(self.success_apis, self.error_apis))}/{len(self.total_apis)}),' - f' Request Count: {self.request_count}, ' - f'Response Count: {self.response_count}, Response / Request: {float(self.response_count) / self.request_count}, ' - f'Request(QPS): {float(self.request_count) / elapsed}, Response(QPS):' - f' {float(self.response_count) / elapsed}, Violation Count: {len(self.violations)}' - f' Remain Sequence Count: {len(self.sequences)}' - f' Success Sequence: {len(self.success_sequence)}') - print('success') - print(self.success_apis) - print('errors') - print(self.error_apis) - print(self.api_curve) - print(self.runtime_dict.signature_to_value.keys()) - print(status_stat) + logger.info( + '%s, Fuzzing Time: %ss, Send Msg Count: %s, ' + 'Receive Msg Count: %s, Success Response Sequence Count: %s, ' + 'Success Sequence Rate: %s, ' + 'Success API: %s (%s/%s),' + 'Error API: %s (%s/%s),' + ' Tested Error and Success Unique API: %s (%s/%s),' + ' Request Count: %s, ' + 'Response Count: %s, Response / Request: %s, ' + 'Request(QPS): %s, Response(QPS): %s, Violation Count: %s' + ' Remain Sequence Count: %s' + ' Success Sequence: %s', + datetime.now().strftime("%Y/%m/%d %H:%M:%S"), elapsed, self.send_msg_count, + self.receive_msg_count, self.success_sequence_count, + float(self.success_sequence_count) / self.receive_msg_count, + float(len(self.success_apis)) / len(self.total_apis), + len(self.success_apis), len(self.total_apis), + float(len(self.error_apis)) / len(self.total_apis), + len(self.error_apis), len(self.total_apis), + float(len(set.union(self.success_apis, self.error_apis))) / len(self.total_apis), + len(set.union(self.success_apis, self.error_apis)), len(self.total_apis), + self.request_count, + self.response_count, float(self.response_count) / self.request_count, + float(self.request_count) / elapsed, + float(self.response_count) / elapsed, len(self.violations), + len(self.sequences), + len(self.success_sequence)) + logger.debug('success') + logger.debug('%s', self.success_apis) + logger.debug('errors') + logger.debug('%s', self.error_apis) + logger.debug('%s', self.api_curve) + logger.debug('%s', self.runtime_dict.signature_to_value.keys()) + logger.debug('%s', status_stat) diff --git a/morest/fuzzer/mutation_executor.py b/morest/fuzzer/mutation_executor.py index 2ee1c14..b8ffd14 100644 --- a/morest/fuzzer/mutation_executor.py +++ b/morest/fuzzer/mutation_executor.py @@ -16,6 +16,7 @@ import re logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.INFO) +logger = logging.getLogger('morest.fuzzer.mutation_executor') class NpEncoder(json.JSONEncoder): @@ -134,7 +135,7 @@ def do_request(self, session, url, method, params, data, headers, files, form_da for ind, key in enumerate(headers): self.check_header_validity((key, headers[key])) except Exception as ex: - print(ex) + logger.warning('Header validation error: %s', ex) headers = {} # add pre defined headers for k in pre_defined_headers.keys(): @@ -144,7 +145,7 @@ def do_request(self, session, url, method, params, data, headers, files, form_da try: raw_response = executed_method(url, params=params, data=form_data, json=data, headers=headers, files=files, allow_redirects=False, timeout=3) except requests.exceptions.ReadTimeout as err: - print(err) + logger.warning('Request timeout: %s', err) response["statusCode"] = 524 response["content"] = "Timeout Error" response["resolved_value"] = "None" diff --git a/morest/fuzzer/normal_executor.py b/morest/fuzzer/normal_executor.py index 0107d33..2a1089b 100644 --- a/morest/fuzzer/normal_executor.py +++ b/morest/fuzzer/normal_executor.py @@ -15,6 +15,7 @@ import re logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.INFO) +logger = logging.getLogger('morest.fuzzer.normal_executor') class NpEncoder(json.JSONEncoder): @@ -118,7 +119,7 @@ def do_request(self, session, url, method, params, data, headers, files, form_da for ind, key in enumerate(headers): self.check_header_validity((key, headers[key])) except Exception as ex: - print(ex) + logger.warning('Header validation error: %s', ex) headers = {} # add pre defined headers for k in pre_defined_headers.keys(): @@ -129,7 +130,7 @@ def do_request(self, session, url, method, params, data, headers, files, form_da raw_response = executed_method(url, params=params, data=form_data, json=data, headers=headers, files=files, allow_redirects=False, timeout=3) except requests.exceptions.ReadTimeout as err: - print(err) + logger.warning('Request timeout: %s', err) response["statusCode"] = 524 response["content"] = "Timeout Error" response["resolved_value"] = "None" diff --git a/morest/fuzzer/runtime_dictionary.py b/morest/fuzzer/runtime_dictionary.py index 5f4442b..d0b664c 100644 --- a/morest/fuzzer/runtime_dictionary.py +++ b/morest/fuzzer/runtime_dictionary.py @@ -1,6 +1,7 @@ import collections import difflib import json +import logging import re import numpy as np @@ -9,6 +10,8 @@ from .util import resolve_json_value from fuzzer.relation_reasoner import RelationReasoner +logger = logging.getLogger('morest.fuzzer.runtime_dictionary') + class ParameterType: STRING = "STRING" @@ -223,7 +226,7 @@ def parse(self, method, response={}): self.signature_to_value[signature] = signature_to_value self.update_signature_to_path_threshold(signature) has_new_attribute = True - print(signature, value) + logger.debug('Runtime dict: %s = %s', signature, value) # record value type # value_type_set = self.path_to_type.get(signature, set()) # value_type_set.add(value_type) @@ -247,7 +250,6 @@ def parse(self, method, response={}): signature_to_value.append(value) return has_new_attribute except Exception as e: - print("exception", content) - print(e) + logger.warning('Exception parsing content: %s - %s', content, e) # raise e return has_new_attribute diff --git a/morest/fuzzer_bitbucket.py b/morest/fuzzer_bitbucket.py index 604bf56..5e5368e 100644 --- a/morest/fuzzer_bitbucket.py +++ b/morest/fuzzer_bitbucket.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.bitbucket') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/fuzzer_feature.py b/morest/fuzzer_feature.py index 90d0d8c..f316b4f 100644 --- a/morest/fuzzer_feature.py +++ b/morest/fuzzer_feature.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.feature') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/fuzzer_language.py b/morest/fuzzer_language.py index ed21d62..da035b2 100644 --- a/morest/fuzzer_language.py +++ b/morest/fuzzer_language.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.language') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/fuzzer_magento.py b/morest/fuzzer_magento.py index 09d33d7..788a666 100644 --- a/morest/fuzzer_magento.py +++ b/morest/fuzzer_magento.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.magento') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/fuzzer_petstore.py b/morest/fuzzer_petstore.py index ac3a946..a971fa7 100644 --- a/morest/fuzzer_petstore.py +++ b/morest/fuzzer_petstore.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.petstore') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/fuzzer_spree.py b/morest/fuzzer_spree.py index 0c24a70..c6aada6 100644 --- a/morest/fuzzer_spree.py +++ b/morest/fuzzer_spree.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -7,6 +8,8 @@ import requests import json +logger = logging.getLogger('morest.fuzzer.spree') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -23,7 +26,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token'%str(ip_address), json = spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return token diff --git a/morest/ga/ga_generator.py b/morest/ga/ga_generator.py index 67a04de..0c81a4a 100644 --- a/morest/ga/ga_generator.py +++ b/morest/ga/ga_generator.py @@ -1,4 +1,5 @@ import time +import logging from fuzzer.runtime_dictionary import RuntimeDictionary from model.operation_dependency_graph import OperationDependencyGraph import uuid @@ -12,6 +13,8 @@ import itertools import numpy as np +logger = logging.getLogger('morest.ga.generator') + class GAGenerator: def __init__(self, apis=[], specification={}, odg: OperationDependencyGraph = OperationDependencyGraph(), @@ -104,8 +107,8 @@ def run(self): for chromosome in self._chromosomes: self.result.append(copy.deepcopy(chromosome)) if self.verbose: - print( - f'time: {time.time()}, round:{counter}, best result:{sorted(self._chromosomes, key=lambda x: x.fitness)[0].fitness}') + logger.debug( + 'time: %s, round:%s, best result:%s', time.time(), counter, sorted(self._chromosomes, key=lambda x: x.fitness)[0].fitness) counter += 1 return self.result diff --git a/morest/generator/generator.py b/morest/generator/generator.py index 7cb50d5..f911a21 100644 --- a/morest/generator/generator.py +++ b/morest/generator/generator.py @@ -1,9 +1,12 @@ import copy +import logging from model.method import Method import json import random import string +logger = logging.getLogger('morest.generator') + def randomString(stringLength=8): letters = string.ascii_lowercase @@ -69,7 +72,7 @@ def extract_steps(methods=[]): with open("testcase.json", 'w') as data: json.dump(res, data) - print(type) + logger.debug('Generated types: %s', type) def traverser(apis=[]): diff --git a/morest/logger_config.py b/morest/logger_config.py new file mode 100644 index 0000000..0dc86d8 --- /dev/null +++ b/morest/logger_config.py @@ -0,0 +1,70 @@ +"""Centralized logging configuration for ARAT-RL. + +Usage: + from logger_config import setup_logging, get_logger + + # In entry point scripts (if __name__ == "__main__"): + setup_logging('arat-rl', log_file='arat-rl.log') + + # Create a module-level logger: + logger = get_logger('arat-rl') + + # Use the logger: + logger.info('Starting testing with spec: %s', spec_file) + logger.warning('Request error: %s', e) + logger.debug('Response value: %s = %s', key, value) + +The log level can be controlled via the LOG_LEVEL environment variable. +Supported levels: DEBUG, INFO, WARNING, ERROR. Default: INFO. +""" + +import os +import logging + + +def setup_logging(name, log_level='INFO', log_file=None): + """Configure and return a logger with console and optional file output. + + Args: + name: Logger name. + log_level: Default log level (overridden by LOG_LEVEL env var). + log_file: Optional path to a log file. + + Returns: + Configured logging.Logger instance. + """ + level_str = os.environ.get('LOG_LEVEL', log_level).upper() + level = getattr(logging, level_str, logging.INFO) + + logger = logging.getLogger(name) + logger.setLevel(level) + + formatter = logging.Formatter( + fmt='%(asctime)s [%(levelname)s] %(name)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + ) + + console_handler = logging.StreamHandler() + console_handler.setLevel(level) + console_handler.setFormatter(formatter) + logger.addHandler(console_handler) + + if log_file is not None: + file_handler = logging.FileHandler(log_file) + file_handler.setLevel(level) + file_handler.setFormatter(formatter) + logger.addHandler(file_handler) + + return logger + + +def get_logger(name): + """Convenience function to get a logger by name. + + Args: + name: Logger name. + + Returns: + logging.Logger instance. + """ + return logging.getLogger(name) diff --git a/morest/model/api_path.py b/morest/model/api_path.py index e093db3..46b4eaa 100644 --- a/morest/model/api_path.py +++ b/morest/model/api_path.py @@ -1,6 +1,9 @@ from model.method import Method from model.constant import METHOD_CONST from model.rule.matcher import RuleMatcher +import logging + +logger = logging.getLogger('morest.model.api_path') class API: @@ -26,7 +29,7 @@ def parse_body(self, body): body[method]['parameters'].extend(body['parameters']) if len(body[method].keys()) == 0: continue - print(method, self.path) + logger.debug('Method: %s, Path: %s', method, self.path) method = self.wrap_method(method, self.path, body[method]) methods.append(method) self.method_map[method] = method @@ -54,4 +57,4 @@ def crud_sematic(self): method.feed_from_method.add(post_method) def __str__(self): - print(self.path) + logger.debug('Path: %s', self.path) diff --git a/morest/model/method.py b/morest/model/method.py index 6f4157c..ed68548 100644 --- a/morest/model/method.py +++ b/morest/model/method.py @@ -1,8 +1,11 @@ import uuid import re +import logging from model.constant import METHOD_CONST from model.parameter import Parameter +logger = logging.getLogger('morest.model.method') + crud_sort_map = { "head": 1, "post": 2, @@ -48,7 +51,7 @@ def parse(self, body={}): responses = body["responses"] for respon in responses: format_response = self.parse_response(respon, responses[respon]) - print("Response", self.response_parameter_name) + logger.debug('Response: %s', self.response_parameter_name) def parse_param(self, parameters=[]): res = {} @@ -60,7 +63,7 @@ def parse_param(self, parameters=[]): body_tuple_list = self.request_parameter_body_tuple.get(k, []) body_tuple_list.extend(res[name].parameter_body_tuple[k]) self.request_parameter_body_tuple[k] = body_tuple_list - print("Request", self.request_parameter_name) + logger.debug('Request: %s', self.request_parameter_name) return res def parse_response(self, status_code, response={}): @@ -93,7 +96,7 @@ def get_parameter_property_name(self, param_property_name=""): def _get_nominal_parameters(self, parameters, with_parameter_name=True): res = set() if len(parameters) == 0: - print(self.method_signature, 'has no parameter [in get nominal parameters]') + logger.debug('%s has no parameter [in get nominal parameters]', self.method_signature) for parameter in parameters: for nominal_values in parameter.attribute_path_dict.values(): for value in nominal_values: diff --git a/morest/model/operation_dependency_graph.py b/morest/model/operation_dependency_graph.py index b28b035..4855128 100644 --- a/morest/model/operation_dependency_graph.py +++ b/morest/model/operation_dependency_graph.py @@ -1,4 +1,5 @@ import json +import logging import re import numpy as np from graphviz import Digraph @@ -6,6 +7,8 @@ from .sequence import Sequence from .sequence import SequenceOrigin +logger = logging.getLogger('morest.model.odg') + class Path: def __init__(self): @@ -118,7 +121,7 @@ def get_traffic_map_with_yaml(self, path): dependency = self.load_traffic_dependency(path) yaml_method_map = self.get_yaml_method_path_map() results = self.get_traffic_yaml_mapped_methods_map(dependency, yaml_method_map) - print(len(results), results) + logger.debug('Results: %d - %s', len(results), results) def get_yaml_method_path_map(self): path_pattern = re.compile('\{(.*?)\}') @@ -184,7 +187,7 @@ def print_path(self, methods): for method in methods: method_signatures.append(f'{method.method_type} {method.method_path}') res = ' -> '.join(method_signatures) - print(res) + logger.debug('Result: %s', res) return res def extend_sequence(self, path): @@ -254,7 +257,7 @@ def generate_sequence(self, simple=False, fast=False): continue if method in covered_apis and method.crud > crud_sort_map['post']: continue - print('traversing path', method) + logger.debug('Traversing path: %s', method) paths, covered = self.generate_graph_sequence(method) covered_apis = covered_apis.union(covered) raw_sequences.extend(paths) @@ -263,10 +266,10 @@ def generate_sequence(self, simple=False, fast=False): sequence = self.extend_sequence(seq) sequence.origin = SequenceOrigin.ODG wrapped_sequences.append(sequence) - print('hashing') + logger.debug('Hashing') result = set(wrapped_sequences) - print("Generate sequences # : ", len(raw_sequences), ' extending sequences # : ', len(wrapped_sequences), - ' result ', len(result)) + logger.info('Generate sequences: %d, extending sequences: %d, total: %d', len(raw_sequences), len(wrapped_sequences), + len(result)) return result def get_single_node_sequence(self): diff --git a/morest/model/parameter.py b/morest/model/parameter.py index 79f8079..9247ad5 100644 --- a/morest/model/parameter.py +++ b/morest/model/parameter.py @@ -1,7 +1,10 @@ import re import uuid +import logging from nltk.stem.snowball import SnowballStemmer +logger = logging.getLogger('morest.model.parameter') + class TargetStatus: EMPTY = 'EMPTY' @@ -73,7 +76,7 @@ def parse(self, body={}): self.schema = body self.parse_schema(self.schema["properties"]) else: - print("Body without name") + logger.debug('Body without name') def parse_schema(self, schema={}): if isinstance(schema, dict): diff --git a/morest/model/rule/concrete_rule.py b/morest/model/rule/concrete_rule.py index fa29734..5868f47 100644 --- a/morest/model/rule/concrete_rule.py +++ b/morest/model/rule/concrete_rule.py @@ -1,5 +1,8 @@ from model.rule.blacklist import BLACK_LIST from model.util.type_reasoner import reason_type +import logging + +logger = logging.getLogger('morest.model.rule.concrete') class ConcreteRule: diff --git a/morest/model/rule/resource_path_rule.py b/morest/model/rule/resource_path_rule.py index 69bd885..7dc32b5 100644 --- a/morest/model/rule/resource_path_rule.py +++ b/morest/model/rule/resource_path_rule.py @@ -1,4 +1,7 @@ from model.util.path_resource_util import WordUtil +import logging + +logger = logging.getLogger('morest.model.rule.resource_path') class ResourcePathRule: @@ -18,6 +21,6 @@ def match(from_method, to_method): return False if from_method_resource_path in [to_method_resource_path[i:len(from_method_resource_path) + i] for i in range(len(to_method_resource_path))]: - print('resource path infer', from_method, '->', to_method) + logger.debug('resource path infer %s -> %s', from_method, to_method) return True return False diff --git a/morest/test/single_method_data_generation.py b/morest/test/single_method_data_generation.py index c13f901..26e17c1 100644 --- a/morest/test/single_method_data_generation.py +++ b/morest/test/single_method_data_generation.py @@ -1,4 +1,5 @@ import os +import logging from prance import ResolvingParser @@ -6,6 +7,8 @@ from fuzzer.fuzzer import APIFuzzer from fuzzer.normal_test_data_generator import RandomDataGenerator +logger = logging.getLogger('morest.test') + def default_reclimit_handler(limit, parsed_url, recursions=()): """Raise prance.util.url.ResolutionError.""" @@ -25,12 +28,12 @@ def main(): parameter = method.request_parameters[parameter_name] random_data_generator = RandomDataGenerator(parameter) result = random_data_generator.generate() - print(result) + logger.debug('Result: %s', result) if method.request_body is not None: generator = RandomDataGenerator(method.request_body) generated_value = generator.generate() data = generated_value - print(data) + logger.debug('Data: %s', data) if __name__ == '__main__': diff --git a/morest/utils/PayloadDataGenerator.py b/morest/utils/PayloadDataGenerator.py index fd06964..a4f34c6 100644 --- a/morest/utils/PayloadDataGenerator.py +++ b/morest/utils/PayloadDataGenerator.py @@ -1,4 +1,5 @@ import datetime +import logging import random import string from utils.basic_payloads import general_payload_list @@ -8,6 +9,8 @@ from fuzzer.runtime_dictionary import RuntimeDictionary +logger = logging.getLogger('morest.utils.payload_generator') + class PayloadDataGenerator: def __init__(self, parameter, runtime_dictionary: RuntimeDictionary = RuntimeDictionary(), ref_dict: {} = {}, @@ -57,22 +60,18 @@ def _modify_example(self, example_value, param_type): pass # do further processing elif param_type == 'array': - print("Current param type is array; array content: ") - print(example_value) + logger.debug('Current param type is array; array content: %s', example_value) raise Exception("Update code to handle the case.") elif param_type == 'schema': - print("Current param type is schema; schema content: ") - print(example_value) + logger.debug('Current param type is schema; schema content: %s', example_value) raise Exception("Update code to handle the case.") elif param_type == "properties": - print("Current param type is schema; properties content: ") - print(example_value) + logger.debug('Current param type is schema; properties content: %s', example_value) raise Exception("Update code to handle the case.") elif param_type == 'object': - print("Current param type is schema; object content: ") - print(example_value) + logger.debug('Current param type is schema; object content: %s', example_value) raise Exception("Update code to handle the case.") elif param_type == 'boolean': @@ -323,7 +322,7 @@ def object_factory(self, path, object_body={}): ref, matched = self._build_ref(self.ref_dict[path]) if matched: return ref - print(object_body) + logger.debug('Object body: %s', object_body) if self.can_use_example(object_body): return object_body["example"] if self.should_use_dictionary_value(path): diff --git a/morest/utils/auth_util.py b/morest/utils/auth_util.py index f611138..e9f137d 100644 --- a/morest/utils/auth_util.py +++ b/morest/utils/auth_util.py @@ -1,6 +1,9 @@ import json +import logging import requests +logger = logging.getLogger('morest.utils.auth') + class SUT: SPREE = "SPREE" @@ -14,7 +17,7 @@ def spree_login(ip_address): "password": "spree123" } spree_login = requests.post('%s/spree_oauth/token' % str(ip_address), json=spree_payload) - print(spree_login.text) + logger.debug('Login response: %s', spree_login.text) token = "Bearer " + json.loads(spree_login.text)['access_token'] # token = "Bearer 894fa3111b5a8c4ff8778f2e20f067a367b665918a6eac28" return {'Bearer': token} diff --git a/morest/utils/dict_mutator.py b/morest/utils/dict_mutator.py index 962591c..e6888b7 100644 --- a/morest/utils/dict_mutator.py +++ b/morest/utils/dict_mutator.py @@ -1,6 +1,9 @@ import copy +import logging import requests +logger = logging.getLogger('morest.utils.dict_mutator') + def dict_generator(indict, pre=None): pre = pre[:] if pre else [] if isinstance(indict, dict): @@ -75,7 +78,7 @@ def send_all_methods(http_methods,url,payload,key,value): for method in http_methods: response = requests.request(method,url,json=payload) #print(key,":",value," ",method," ",response.status_code," ",len(response.content)) - print("{:20.15}:{:20.15}{:10.8}{:15}{:10}".format(key, value, method, str(response.status_code), str(len(response.content)))) + logger.debug('%s: %s %s %s %s', key, value, method, str(response.status_code), str(len(response.content))) if __name__ == "__main__": @@ -121,15 +124,15 @@ def send_all_methods(http_methods,url,payload,key,value): combinedTamperedJsonList = tamperedValueJsonList + tamperedKeyJsonList combinedKeyList = tKeyList + keyList combinedValueList = valueList + tValueList - print("Request Prepared. Sending requests..") - print("--------------------------------------------------------------------------------------") + logger.info('Request Prepared. Sending requests..') + logger.info('--------------------------------------------------------------------------------------') #response = requests.request("CONNECT","http://127.0.0.1:3000/user",json=tamperedValueJsonList[0]) #print(response) - print("{:20}{:20}{:10}{:15}{:10}".format("Key","Value", "Method", "Response Code", "Response Length")) + logger.info('Key Value Method Response Code Response Length') #print("Modified Parameter Method Response Code Response Length") - print("--------------------------------------------------------------------------------------") + logger.info('--------------------------------------------------------------------------------------') for i in range(0,len(combinedTamperedJsonList)): #May need to create custom request to modify headers to spoof as a real web request diff --git a/morest/validator/validator.py b/morest/validator/validator.py index 8120707..d7fb64c 100644 --- a/morest/validator/validator.py +++ b/morest/validator/validator.py @@ -1,7 +1,10 @@ import json +import logging from flex.core import validate as flex_validate +logger = logging.getLogger('morest.validator') + class ViolationType: SCHEMA_VIOLATION = "SCHEMA_VIOLATION" @@ -75,7 +78,7 @@ def find_method_by_response(apis, response): for method in api.methods: if method.method_name == api_name: return method - print(api_name, "not found ") + logger.warning('%s not found', api_name) assert False diff --git a/morest/validator/validator_huawei.py b/morest/validator/validator_huawei.py index 639f457..ed34b52 100644 --- a/morest/validator/validator_huawei.py +++ b/morest/validator/validator_huawei.py @@ -1,7 +1,10 @@ import json +import logging from flex.core import validate as flex_validate +logger = logging.getLogger('morest.validator.huawei') + class ViolationType: SCHEMA_VIOLATION = "SCHEMA_VIOLATION" @@ -77,7 +80,7 @@ def find_method_by_response(apis, response): for method in api.methods: if method.method_name == api_name: return method - print(api_name, "not found ") + logger.warning('%s not found', api_name) assert False diff --git a/morest/validator/validator_payload.py b/morest/validator/validator_payload.py index e61c27b..cc53dea 100644 --- a/morest/validator/validator_payload.py +++ b/morest/validator/validator_payload.py @@ -1,7 +1,10 @@ import json +import logging from flex.core import validate as flex_validate +logger = logging.getLogger('morest.validator.payload') + class ViolationType: SCHEMA_VIOLATION = "SCHEMA_VIOLATION" @@ -80,7 +83,7 @@ def find_method_by_response(apis, response): for method in api.methods: if method.method_name == api_name: return method - print(api_name, "not found ") + logger.warning('%s not found', api_name) assert False def validate_mutations(method, baseline_response, response, mutation_index, current_index): diff --git a/no_feedback.py b/no_feedback.py index 078120e..eaf0c7c 100644 --- a/no_feedback.py +++ b/no_feedback.py @@ -9,12 +9,16 @@ import base64 import random import string +import logging import prance import difflib import requests import datetime import functools from collections import defaultdict +from logger_config import setup_logging + +logger = logging.getLogger('no-feedback') @@ -232,7 +236,7 @@ def send_request(content_type): elif method == 'head': return requests.head(url, headers=headers, params=query_params) except requests.exceptions.RequestException as e: - print(f"Request error: {e}") + logger.warning('Request error: %s', e) return None for param_value_dict in selected_parameters: @@ -636,6 +640,9 @@ def main(): operations, parameters_frequency = analyze_information(openapi_spec) alpha, gamma, q_table = initialize_q_learning(operations, parameters_frequency) + logger.info('Starting no-feedback with spec: %s, base URL: %s', openapi_spec_file, base_url) + logger.info('Found %d operations', len(operations)) + start_time = time.time() time_limit = 3600 iteration = 0 @@ -683,6 +690,7 @@ def main(): iteration += 1 if __name__ == "__main__": + setup_logging('no-feedback', log_file='no-feedback.log') base_url = sys.argv[2] EPSILON = [0.1] ss = [None] diff --git a/no_prioritization.py b/no_prioritization.py index 5abadbf..85fb9e0 100644 --- a/no_prioritization.py +++ b/no_prioritization.py @@ -9,12 +9,16 @@ import base64 import random import string +import logging import prance import difflib import requests import datetime import functools from collections import defaultdict +from logger_config import setup_logging + +logger = logging.getLogger('no-prioritization') @@ -232,7 +236,7 @@ def send_request(content_type): elif method == 'head': return requests.head(url, headers=headers, params=query_params) except requests.exceptions.RequestException as e: - print(f"Request error: {e}") + logger.warning('Request error: %s', e) return None for param_value_dict in selected_parameters: @@ -642,6 +646,9 @@ def main(): operations, parameters_frequency = analyze_information(openapi_spec) alpha, gamma, q_table = initialize_q_learning(operations, parameters_frequency) + logger.info('Starting no-prioritization with spec: %s, base URL: %s', openapi_spec_file, base_url) + logger.info('Found %d operations', len(operations)) + start_time = time.time() time_limit = 3600 iteration = 0 @@ -689,6 +696,7 @@ def main(): iteration += 1 if __name__ == "__main__": + setup_logging('no-prioritization', log_file='no-prioritization.log') base_url = sys.argv[2] EPSILON = [1] ss = [None] diff --git a/no_sampling.py b/no_sampling.py index 074f24c..4eacdec 100644 --- a/no_sampling.py +++ b/no_sampling.py @@ -9,12 +9,16 @@ import base64 import random import string +import logging import prance import difflib import requests import datetime import functools from collections import defaultdict +from logger_config import setup_logging + +logger = logging.getLogger('no-sampling') @@ -143,7 +147,7 @@ def extract_response_values(response, op): extract_response_values(val, op) elif isinstance(response, dict): for key, value in response.items(): - print(key, value) + logger.debug('Response value: %s = %s', key, value) if key not in response_values: response_values[key] = [] if value not in response_values[key]: @@ -222,7 +226,7 @@ def send_request(content_type): elif method == 'head': return requests.head(url, headers=headers, params=query_params) except requests.exceptions.RequestException as e: - print(f"Request error: {e}") + logger.warning('Request error: %s', e) return None for param_value_dict in selected_parameters: @@ -632,6 +636,9 @@ def main(): operations, parameters_frequency = analyze_information(openapi_spec) alpha, gamma, q_table = initialize_q_learning(operations, parameters_frequency) + logger.info('Starting no-sampling with spec: %s, base URL: %s', openapi_spec_file, base_url) + logger.info('Found %d operations', len(operations)) + start_time = time.time() time_limit = 3600 iteration = 0 @@ -680,6 +687,7 @@ def main(): iteration += 1 if __name__ == "__main__": + setup_logging('no-sampling', log_file='no-sampling.log') base_url = sys.argv[2] EPSILON = [0.1] ss = [None] diff --git a/parse_log.py b/parse_log.py index fe91c5a..9a56bea 100644 --- a/parse_log.py +++ b/parse_log.py @@ -1,10 +1,15 @@ import os import re import json +import logging import subprocess from collections import Counter from json import JSONDecodeError +from logger_config import setup_logging + +logger = logging.getLogger('parse-log') + def count_coverage(path, port): class_files = [] @@ -59,10 +64,10 @@ def parse_log_file(file_path): log_data.append(current_log) current_log = {} result[0] = result[0] + str(status2xx + status4xx + status5xx) + ',' + str(status2xx)+ ',' + str(status4xx) + ',' + str(status5xx) + ',' - print("Total: " + str(status2xx + status4xx + status5xx)) - print("Status 2xx: " + str(status2xx)) - print("Status 4xx: " + str(status4xx)) - print("Status 5xx: " + str(status5xx)) + logger.info('Total: %d', status2xx + status4xx + status5xx) + logger.info('Status 2xx: %d', status2xx) + logger.info('Status 4xx: %d', status4xx) + logger.info('Status 5xx: %d', status5xx) return log_data @@ -99,6 +104,7 @@ def count_unique_5xx_errors(log_data): return unique_stack_traces if __name__ == '__main__': + setup_logging('parse-log') logs = ["features.txt", "languagetool.txt", "ncs.txt", "restcountries.txt", "scs.txt", "genome.txt", "person.txt", "user.txt", "market.txt", "project.txt"] csvs = ["_11000_1.csv","_11010_1.csv","_11020_1.csv","_11030_1.csv","_11040_1.csv","_11050_1.csv","_11060_1.csv","_11070_1.csv","_11080_1.csv","_11090_1.csv"] result = [""] @@ -116,7 +122,7 @@ def count_unique_5xx_errors(log_data): count_coverage("service/jdk11/market", "_11080_1") count_coverage("service/jdk11/project-tracking-system", "_11090_1") for log_file in logs: - print(log_file) + logger.info('Processing: %s', log_file) errors[log_file] = [] log_data = parse_log_file(log_file) unique_stack_traces = count_unique_5xx_errors(log_data) @@ -124,7 +130,7 @@ def count_unique_5xx_errors(log_data): for stack_trace, count in unique_stack_traces.items(): errors[log_file].append(full_stack_traces[stack_trace]) unique_5xx_count += 1 - print(f'\nTotal unique number of 5xx errors: {unique_5xx_count}') + logger.info('Total unique number of 5xx errors: %d', unique_5xx_count) result[0] = result[0] + str(unique_5xx_count) + '\n' @@ -146,7 +152,7 @@ def count_unique_5xx_errors(log_data): total_line = total_line + int(items[8]) + int(items[7]) covered_method = covered_method + int(items[12]) total_method = total_method + int(items[12]) + int(items[11]) - print(covered_branch/total_branch*100, covered_line/total_line*100, covered_method/total_method*100) + logger.info('Coverage - Branch: %.2f%%, Line: %.2f%%, Method: %.2f%%', covered_branch/total_branch*100, covered_line/total_line*100, covered_method/total_method*100) result[0] = result[0] + str(covered_method/total_method*100) + ',' + str(covered_branch/total_branch*100) + ',' + str(covered_line/total_line*100) + '\n' with open("res.csv", "w") as f: diff --git a/run.py b/run.py index 0b7e76f..cfcdab5 100644 --- a/run.py +++ b/run.py @@ -1,9 +1,15 @@ import sys import time import subprocess +import logging + +from logger_config import setup_logging + +logger = logging.getLogger('run') if __name__ == "__main__": + setup_logging('run') tool = sys.argv[1] time_limit = "1" @@ -12,7 +18,7 @@ for i in range(10): cov_port = base_cov_port + i*10 - print("Running " + tool + " for " + services[i] + ": " + str(cov_port)) + logger.info('Running %s for %s: %s', tool, services[i], cov_port) session = tool + '_' + services[i] cov_session = services[i] + "_cov" subprocess.run("tmux new -d -s " + cov_session + " sh get_cov.sh " + str(cov_port), shell=True) @@ -21,7 +27,7 @@ time.sleep(300) time.sleep(int(time_limit) * 60 * 60) - print("Stop running services...") + logger.info('Stop running services...') subprocess.run("sudo docker stop `sudo docker ps -a -q`", shell=True) time.sleep(30) subprocess.run("sudo docker rm `sudo docker ps -a -q`", shell=True) diff --git a/run_service.py b/run_service.py index 157cfe0..acac91e 100644 --- a/run_service.py +++ b/run_service.py @@ -2,6 +2,9 @@ import time import sys import os +import logging + +logger = logging.getLogger('run-service') def run_service(service_path, class_name): with open(service_path + "/cp.txt", 'r') as f: diff --git a/run_tool.py b/run_tool.py index 854129f..64a5eec 100644 --- a/run_tool.py +++ b/run_tool.py @@ -2,6 +2,11 @@ import sys import time import subprocess +import logging + +from logger_config import setup_logging + +logger = logging.getLogger('run-tool') def whitebox(port): @@ -46,6 +51,7 @@ def blackbox(swagger, port): subprocess.run(run + options, shell=True) if __name__ == "__main__": + setup_logging('run-tool') tool = sys.argv[1] service = sys.argv[2] port = sys.argv[3] @@ -58,7 +64,7 @@ def blackbox(swagger, port): else: subprocess.run("python3 run_service.py " + service + " " + str(port) + " blackbox", shell=True) - print("Service started in the background. To check or kill the session, please see README file.") + logger.info('Service started in the background. To check or kill the session, please see README file.') time.sleep(30) if service == "features-service": @@ -133,8 +139,8 @@ def blackbox(swagger, port): else: blackbox(os.path.join(curdir, "spec/project.yaml"), 30118) - print( - "Experiments are done. We are safely closing the service now. If you want to run more, please check if there is unclosed session. You can check it with 'tmux ls' command. To close the session, you can run 'tmux kill-sess -t {session name}'") + logger.info( + 'Experiments are done. We are safely closing the service now. If you want to run more, please check if there is unclosed session. You can check it with \'tmux ls\' command. To close the session, you can run \'tmux kill-sess -t {session name}\'') time.sleep(180) subprocess.run("tmux kill-sess -t " + service, shell=True) diff --git a/verify_setup.py b/verify_setup.py index e63b955..c9c4247 100755 --- a/verify_setup.py +++ b/verify_setup.py @@ -8,39 +8,46 @@ import subprocess import os import sys +import logging from pathlib import Path +from logger_config import setup_logging + +logger = logging.getLogger('verify-setup') + def run_command(cmd, description): """Run a command and return success status.""" try: result = subprocess.run(cmd, shell=True, capture_output=True, text=True) if result.returncode == 0: - print(f"✓ {description}") + logger.info('%s', description) return True else: - print(f"✗ {description}: {result.stderr.strip()}") + logger.error('%s: %s', description, result.stderr.strip()) return False except Exception as e: - print(f"✗ {description}: {str(e)}") + logger.error('%s: %s', description, str(e)) return False def check_file_exists(filepath, description): """Check if a file exists.""" if Path(filepath).exists(): - print(f"✓ {description}") + logger.info('%s', description) return True else: - print(f"✗ {description}: File not found") + logger.error('%s: File not found', description) return False def main(): - print("ARAT-RL Setup Verification") - print("=" * 40) + setup_logging('verify-setup') + logger.info('ARAT-RL Setup Verification') + logger.info('=' * 40) all_checks_passed = True # Check basic tools - print("\n1. Basic Tools:") + logger.info('') + logger.info('1. Basic Tools:') all_checks_passed &= run_command("java -version", "Java is installed") all_checks_passed &= run_command("mvn -version", "Maven is installed") all_checks_passed &= run_command("docker --version", "Docker is installed") @@ -48,79 +55,88 @@ def main(): all_checks_passed &= run_command("tmux -V", "tmux is installed") # Check Java versions - print("\n2. Java Versions:") + logger.info('') + logger.info('2. Java Versions:') java_output = subprocess.run("java -version", shell=True, capture_output=True, text=True) if "1.8" in java_output.stderr: - print("✓ Java 8 detected") + logger.info('Java 8 detected') elif "11" in java_output.stderr: - print("✓ Java 11 detected") + logger.info('Java 11 detected') else: - print("✗ Unexpected Java version") + logger.error('Unexpected Java version') all_checks_passed = False # Check environment files - print("\n3. Environment Files:") + logger.info('') + logger.info('3. Environment Files:') all_checks_passed &= check_file_exists("java8.env", "java8.env exists") all_checks_passed &= check_file_exists("java11.env", "java11.env exists") # Check build artifacts - print("\n4. Build Artifacts:") + logger.info('') + logger.info('4. Build Artifacts:') cp_files = list(Path("service").rglob("cp.txt")) if len(cp_files) == 6: - print(f"✓ All {len(cp_files)} cp.txt files found") + logger.info('All %d cp.txt files found', len(cp_files)) else: - print(f"✗ Expected 6 cp.txt files, found {len(cp_files)}") + logger.error('Expected 6 cp.txt files, found %d', len(cp_files)) all_checks_passed = False # Check JAR files - print("\n5. JAR Files:") + logger.info('') + logger.info('5. JAR Files:') all_checks_passed &= check_file_exists("evomaster.jar", "EvoMaster JAR") all_checks_passed &= check_file_exists("org.jacoco.agent-0.8.7-runtime.jar", "JaCoCo Agent JAR") all_checks_passed &= check_file_exists("org.jacoco.cli-0.8.7-nodeps.jar", "JaCoCo CLI JAR") # Check Python dependencies - print("\n6. Python Dependencies:") + logger.info('') + logger.info('6. Python Dependencies:') try: import yaml import requests - print("✓ Required Python packages installed") + logger.info('Required Python packages installed') except ImportError as e: - print(f"✗ Missing Python package: {e}") + logger.error('Missing Python package: %s', e) all_checks_passed = False # Check Docker images - print("\n7. Docker Images:") + logger.info('') + logger.info('7. Docker Images:') docker_images = subprocess.run("docker images", shell=True, capture_output=True, text=True) if "genomenexus/gn-mongo" in docker_images.stdout: - print("✓ Genome Nexus MongoDB image") + logger.info('Genome Nexus MongoDB image') else: - print("✗ Genome Nexus MongoDB image not found") + logger.error('Genome Nexus MongoDB image not found') all_checks_passed = False if "mongo" in docker_images.stdout: - print("✓ MongoDB image") + logger.info('MongoDB image') else: - print("✗ MongoDB image not found") + logger.error('MongoDB image not found') all_checks_passed = False if "mysql" in docker_images.stdout: - print("✓ MySQL image") + logger.info('MySQL image') else: - print("✗ MySQL image not found") + logger.error('MySQL image not found') all_checks_passed = False # Summary - print("\n" + "=" * 40) + logger.info('') + logger.info('=' * 40) if all_checks_passed: - print("✓ All checks passed! ARAT-RL setup appears to be correct.") - print("\nYou can now run:") - print(" python3 arat-rl.py spec/features.yaml http://localhost:30100/ 60") + logger.info('All checks passed! ARAT-RL setup appears to be correct.') + logger.info('') + logger.info('You can now run:') + logger.info(' python3 arat-rl.py spec/features.yaml http://localhost:30100/ 60') else: - print("✗ Some checks failed. Please review the issues above.") - print("\nCommon solutions:") - print(" - Run setup script: sh setup_macos.sh (macOS) or sh setup.sh (Ubuntu)") - print(" - Check troubleshooting guide: TROUBLESHOOTING.md") - print(" - Verify all dependencies are installed") + logger.error('Some checks failed. Please review the issues above.') + logger.info('') + logger.info('Common solutions:') + logger.info(' - Run setup script: sh setup_macos.sh (macOS) or sh setup.sh (Ubuntu)') + logger.info(' - Check troubleshooting guide: TROUBLESHOOTING.md') + logger.info(' - Verify all dependencies are installed') sys.exit(1) if __name__ == "__main__":