From 7881eb5cbfd010ed3663854970395a898693d334 Mon Sep 17 00:00:00 2001 From: Karl Chen Date: Wed, 2 Jul 2003 02:02:18 +0000 Subject: [PATCH] rewrote logging facilities svn path=/trunk/boinc/; revision=1634 --- checkin_notes | 44 ++++++++ client/app.C | 83 ++++++++------- client/client_state.C | 201 ++++++++++++++++--------------------- client/cs_apps.C | 13 +-- client/cs_files.C | 19 ++-- client/cs_scheduler.C | 41 +++----- client/file_xfer.C | 25 +++-- client/http.C | 51 +++++----- client/main.C | 17 ++-- client/message.h | 47 +++++++-- client/net_xfer.C | 36 +++---- client/pers_file_xfer.C | 28 +++--- client/scheduler_op.C | 73 ++++++-------- lib/util.h | 55 +++++++++- sched/assimilate_handler.C | 14 +-- sched/assimilator.C | 19 ++-- sched/db_dump.C | 14 +-- sched/feeder.C | 38 +++---- sched/file_deleter.C | 16 +-- sched/main.C | 26 ++--- sched/make_work.C | 30 +++--- sched/sched_util.C | 65 +----------- sched/sched_util.h | 27 +++-- sched/server_types.C | 12 +-- sched/start_servers.C | 12 ++- sched/update_stats.C | 18 ++-- sched/validate.C | 40 ++++---- 27 files changed, 539 insertions(+), 525 deletions(-) diff --git a/checkin_notes b/checkin_notes index 81ac67e371..5e31ed5c45 100755 --- a/checkin_notes +++ b/checkin_notes @@ -5177,3 +5177,47 @@ David July 1 2003 db_action.php db_form.php index.php + +Karl 2003/07/01 + - redesigned logging facilities for both scheduler servers and client + + client/ + Makefile.am + app.C + client_messages.C (added) + client_state.C + cs_apps.C + cs_files.C + cs_scheduler.C + file_xfer.C + http.C + main.C + message.h + net_xfer.C + pers_file_xfer.C + scheduler_op.C + + lib/ + messages.C (added) + util.h + + sched/ + Makefile.am + assimilate_handler.C + assimilator.C + db_dump.C + feeder.C + file_deleter.C + file_upload_handler.C + handle_request.C + main.C + make_work.C + sched_messages.C (added) + sched_util.C + sched_util.h + server_types.C + start_servers.C + timeout_check.C + update_stats.C + validate.C + validate_test.C diff --git a/client/app.C b/client/app.C index 40a3413683..92a7dc6bf5 100644 --- a/client/app.C +++ b/client/app.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. -// Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// Portions created by the SETI@home project are Copyright (C) 2002, 2003 +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -66,7 +66,6 @@ #include "client_types.h" #include "filesys.h" #include "file_names.h" -#include "log_flags.h" #include "parse.h" #include "shmem.h" #include "util.h" @@ -75,12 +74,16 @@ // Goes through an array of strings, and prints each string // -static int print_argv(char** argv) { +static int debug_print_argv(char** argv) { int i; + log_messages.printf(ClientMessages::DEBUG_TASK, "Arguments:"); + ++log_messages; for (i=0; argv[i]; i++) { - fprintf(stderr, "argv[%d]: %s\n", i, argv[i]); + log_messages.printf(ClientMessages::DEBUG_TASK, + "argv[%d]: %s\n", i, argv[i]); } + --log_messages; return 0; } @@ -110,7 +113,7 @@ int ACTIVE_TASK::init(RESULT* rp) { max_cpu_time = gstate.estimate_cpu_time(*rp->wup)*2; max_disk_usage = rp->wup->rsc_disk; max_mem_usage = rp->wup->rsc_memory; - + return 0; } @@ -131,6 +134,9 @@ int ACTIVE_TASK::start(bool first_time) { APP_INIT_DATA aid; GRAPHICS_INFO gi; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_TASK); + scope_messages.printf("ACTIVE_TASK::start(first_time=%d)\n", first_time); + if (first_time) { checkpoint_cpu_time = 0; } @@ -182,7 +188,7 @@ int ACTIVE_TASK::start(bool first_time) { retval = write_init_data_file(f, aid); if (retval) return retval; - + fclose(f); sprintf(graphics_data_path, "%s%s%s", slot_dir, PATH_SEPARATOR, GRAPHICS_DATA_FILE); @@ -216,9 +222,7 @@ int ACTIVE_TASK::start(bool first_time) { sprintf(link_path, "%s%s%s", slot_dir, PATH_SEPARATOR, strlen(fref.open_name)?fref.open_name:fip->name); sprintf(buf, "..%s..%s%s", PATH_SEPARATOR, PATH_SEPARATOR, file_path); retval = boinc_link(buf, link_path); - if (log_flags.task_debug) { - printf("link %s to %s\n", file_path, link_path); - } + scope_messages.printf("ACTIVE_TASK::start(): Linking %s to %s\n", file_path, link_path); if (retval) { msg_printf(wup->project, MSG_ERROR, "Can't link %s to %s", file_path, link_path); fclose(f); @@ -236,9 +240,7 @@ int ACTIVE_TASK::start(bool first_time) { if (first_time) { sprintf(link_path, "%s%s%s", slot_dir, PATH_SEPARATOR, file_ref.open_name); sprintf(buf, "..%s..%s%s", PATH_SEPARATOR, PATH_SEPARATOR, file_path ); - if (log_flags.task_debug) { - printf("link %s to %s\n", file_path, link_path); - } + scope_messages.printf("ACTIVE_TASK::start(): link %s to %s\n", file_path, link_path); if (file_ref.copy_file) { retval = boinc_copy(file_path, link_path); if (retval) { @@ -271,9 +273,7 @@ int ACTIVE_TASK::start(bool first_time) { if (first_time) { sprintf(link_path, "%s%s%s", slot_dir, PATH_SEPARATOR, file_ref.open_name); sprintf(buf, "..%s..%s%s", PATH_SEPARATOR, PATH_SEPARATOR, file_path ); - if (log_flags.task_debug) { - printf("link %s to %s\n", file_path, link_path); - } + scope_messages.printf("ACTIVE_TASK::start(): link %s to %s\n", file_path, link_path); retval = boinc_link(buf, link_path); if (retval) { msg_printf(wup->project, MSG_ERROR, "Can't link %s to %s", file_path, link_path); @@ -351,7 +351,7 @@ int ACTIVE_TASK::start(bool first_time) { thread_handle = process_info.hThread; #else char* argv[100]; - + // Set up core/app shared memory seg // shm_key = aid.shm_key; @@ -360,7 +360,7 @@ int ACTIVE_TASK::start(bool first_time) { ) { app_client_shm.reset_msgs(); } - + pid = fork(); if (pid == 0) { // from here on we're running in a new process. @@ -381,15 +381,15 @@ int ACTIVE_TASK::start(bool first_time) { argv[0] = exec_name; parse_command_line(wup->command_line, argv+1); - if (log_flags.task_debug) print_argv(argv); + debug_print_argv(argv); sprintf(buf, "..%s..%s%s", PATH_SEPARATOR, PATH_SEPARATOR, exec_path ); retval = execv(buf, argv); fprintf(stderr, "execv failed: %d\n", retval); perror("execv"); exit(1); } - - if (log_flags.task_debug) printf("forked process: pid %d\n", pid); + + scope_messages.printf("ACTIVE_TASK::start(): forked process: pid %d\n", pid); #endif state = PROCESS_RUNNING; result->active_task_state = PROCESS_RUNNING; @@ -488,6 +488,9 @@ bool ACTIVE_TASK_SET::poll() { bool ACTIVE_TASK_SET::check_app_exited() { ACTIVE_TASK* atp; + + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_TASK); + #ifdef _WIN32 unsigned long exit_code; bool found = false; @@ -541,10 +544,10 @@ bool ACTIVE_TASK_SET::check_app_exited() { pid = wait4(0, &stat, WNOHANG, &rs); if (pid > 0) { - if (log_flags.task_debug) printf("process %d is done\n", pid); + scope_messages.printf("ACTIVE_TASK_SET::check_app_exited(): process %d is done\n", pid); atp = lookup_pid(pid); if (!atp) { - fprintf(stderr, "ACTIVE_TASK_SET::poll(): pid %d not found\n", pid); + fprintf(stderr, "ACTIVE_TASK_SET::check_app_exited(): pid %d not found\n", pid); return true; } double x = rs.ru_utime.tv_sec + rs.ru_utime.tv_usec/1.e6; @@ -572,9 +575,7 @@ bool ACTIVE_TASK_SET::check_app_exited() { "process exited with a nonzero exit code\n" ); } - if (log_flags.task_debug) { - printf("process exited: status %d\n", atp->exit_status); - } + scope_messages.printf("ACTIVE_TASK_SET::check_app_exited(): process exited: status %d\n", atp->exit_status); } else if (WIFSIGNALED(stat)) { atp->state = PROCESS_WAS_SIGNALED; atp->signal = WTERMSIG(stat); @@ -583,9 +584,7 @@ bool ACTIVE_TASK_SET::check_app_exited() { gstate.report_result_error( *(atp->result), 0, "process was signaled\n" ); - if (log_flags.task_debug) { - printf("process was signaled: %d\n", atp->signal); - } + scope_messages.printf("ACTIVE_TASK_SET::check_app_exited(): process was signaled: %d\n", atp->signal); } else { atp->state = PROCESS_EXIT_UNKNOWN; atp->result->state = PROCESS_EXIT_UNKNOWN; @@ -683,7 +682,7 @@ bool ACTIVE_TASK_SET::check_rsc_limits_exceeded() { // The application has done something wrong. // May as well send it a kill signal. -// +// int ACTIVE_TASK::abort() { state = PROCESS_ABORT_PENDING; result->active_task_state = PROCESS_ABORT_PENDING; @@ -741,7 +740,7 @@ int ACTIVE_TASK_SET::exit_tasks() { } get_cpu_times(); - + return 0; } @@ -814,7 +813,7 @@ void ACTIVE_TASK_SET::unsuspend_all() { "ACTIVE_TASK_SET::unsuspend_all(): could not unsuspend active_task" ); } - } + } } // initiate exit of all currently running tasks @@ -891,6 +890,8 @@ int ACTIVE_TASK_SET::restart_tasks() { ACTIVE_TASK* atp; int retval; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_TASK); + iter = active_tasks.begin(); while (iter != active_tasks.end()) { atp = *iter; @@ -898,9 +899,7 @@ int ACTIVE_TASK_SET::restart_tasks() { get_slot_dir(atp->slot, atp->slot_dir); atp->result->is_active = true; retval = atp->start(false); - if (log_flags.task) { - msg_printf(atp->wup->project, MSG_INFO, "Restarting computation for result %s", atp->result->name); - } + scope_messages.printf("ACTIVE_TASK_SET::restart_tasks(): Restarting computation for result %s", atp->result->name); if (retval) { msg_printf(atp->wup->project, MSG_ERROR, "ACTIVE_TASKS::restart_tasks(); restart failed: %d\n", retval); atp->result->active_task_state = PROCESS_COULDNT_START; @@ -921,7 +920,7 @@ int ACTIVE_TASK::get_cpu_time_via_os() { FILETIME creation_time, exit_time, kernel_time, user_time; ULARGE_INTEGER tKernel, tUser; LONGLONG totTime; - + // Get the elapsed CPU time if (GetProcessTimes(pid_handle, &creation_time, &exit_time, &kernel_time, &user_time)) { tKernel.LowPart = kernel_time.dwLowDateTime; diff --git a/client/client_state.C b/client/client_state.C index 6435dc183c..a91e4eea3d 100644 --- a/client/client_state.C +++ b/client/client_state.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. // Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -50,9 +50,9 @@ #include "file_names.h" #include "hostinfo.h" #include "http.h" -#include "log_flags.h" #include "speed_stats.h" #include "client_state.h" +#include "log_flags.h" #define BENCHMARK_PERIOD (SECONDS_PER_DAY*30) // rerun CPU benchmarks this often (hardware may have been upgraded) @@ -211,9 +211,7 @@ int CLIENT_STATE::init() { clear_host_info(host_info); parse_state_file(); - if (log_flags.state_debug) { - print_summary(); - } + print_summary(); if (show_projects) { printf("projects:\n"); @@ -358,41 +356,28 @@ int CLIENT_STATE::cpu_benchmarks() { double iop_test_secs = 3.3; double mem_test_secs = 3.3; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_MEASUREMENT); + scope_messages.printf("CLIENT_STATE::cpu_benchmarks(): Running CPU benchmarks.\n"); + clear_host_info(host_info); - if (log_flags.measurement_debug) { - printf("Running CPU benchmarks.\n"); - } + ++log_messages; if (skip_cpu_benchmarks) { - if (log_flags.measurement_debug) { - msg_printf(0, MSG_INFO, "Skipping CPU benchmarks\n"); - } + scope_messages.printf("CLIENT_STATE::cpu_benchmarks(): Skipping CPU benchmarks.\n"); host_info.p_fpops = 1e9; host_info.p_iops = 1e9; host_info.p_membw = 4e9; host_info.m_cache = 1e6; } else { - if (log_flags.measurement_debug) { - printf( - "Running floating point test for about %.1f seconds.\n", - fpop_test_secs - ); - } + scope_messages.printf("CLIENT_STATE::cpu_benchmarks(): Running floating point test for about %.1f seconds.\n", + fpop_test_secs); host_info.p_fpop_err = run_double_prec_test(fpop_test_secs, host_info.p_fpops); - if (log_flags.measurement_debug) { - printf( - "Running integer test for about %.1f seconds.\n", - iop_test_secs - ); - } + scope_messages.printf("CLIENT_STATE::cpu_benchmarks(): Running integer test for about %.1f seconds.\n", + iop_test_secs); host_info.p_iop_err = run_int_test(iop_test_secs, host_info.p_iops); - if (log_flags.measurement_debug) { - printf( - "Running memory bandwidth test for about %.1f seconds.\n", - mem_test_secs - ); - } + scope_messages.printf("CLIENT_STATE::cpu_benchmarks(): Running memory bandwidth test for about %.1f seconds.\n", + mem_test_secs); host_info.p_membw_err = run_mem_bandwidth_test(mem_test_secs, host_info.p_membw); // need to check cache!! @@ -405,6 +390,7 @@ int CLIENT_STATE::cpu_benchmarks() { host_info.write_cpu_benchmarks(finfo); fclose(finfo); + --log_messages; return 0; } @@ -574,12 +560,6 @@ int CLIENT_STATE::check_suspend_activities() { return 0; } -static void print_log(char* p) { - if (log_flags.poll_debug) { - printf(p); - } -} - // sleep up to x seconds, // but if network I/O becomes possible, // wake up and do as much as limits allow. @@ -600,67 +580,59 @@ int CLIENT_STATE::net_sleep(double x) { // (in which case should call this again immediately) // bool CLIENT_STATE::do_something() { - bool action = false, x; + int actions = 0; check_suspend_activities(); if (check_cpu_benchmarks() == CPU_BENCHMARKS_RUNNING) return false; - print_log("Polling; active layers:\n"); + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_POLL); + scope_messages.printf("CLIENT_STATE::do_evil(): Begin poll:\n"); + ++scope_messages; net_stats.poll(*net_xfers); ss_logic.poll(); - x = scheduler_rpc_poll(); - if (x) {action=true; print_log("scheduler_rpc\n"); } +#define POLL_ACTION(name, func) \ + do { if (func()) { \ + ++actions; \ + scope_messages.printf("CLIENT_STATE::do_evil(): active task: " #name "\n"); \ + } } while(0) + + POLL_ACTION(scheduler_rpc, scheduler_rpc_poll); if (activities_suspended) { - print_log("None (suspended)\n"); + scope_messages.printf("CLIENT_STATE::do_evil(): No active tasks! (suspended)\n"); } else { // Call these functions in bottom to top order with // respect to the FSM hierarchy - x = net_xfers->poll(); - if (x) { action=true; print_log("net_xfers\n"); } + POLL_ACTION(net_xfers , net_xfers->poll ); + POLL_ACTION(http_ops , http_ops->poll ); + POLL_ACTION(file_xfers , file_xfers->poll ); + POLL_ACTION(active_tasks , active_tasks.poll ); + POLL_ACTION(scheduler_rpc , scheduler_rpc_poll ); + POLL_ACTION(start_apps , start_apps ); + POLL_ACTION(pers_xfers , pers_xfers->poll ); + POLL_ACTION(handle_finished_apps , handle_finished_apps ); + POLL_ACTION(handle_pers_file_xfers , handle_pers_file_xfers ); + POLL_ACTION(garbage_collect , garbage_collect ); + POLL_ACTION(update_results , update_results ); - x = http_ops->poll(); - if (x) {action=true; print_log("http_ops\n"); } - - x = file_xfers->poll(); - if (x) {action=true; print_log("file_xfers\n"); } - - x = active_tasks.poll(); - if (x) {action=true; print_log("active_tasks::poll\n"); } - - x = scheduler_rpc_poll(); - if (x) {action=true; print_log("scheduler_rpc\n"); } - - x = start_apps(); - if (x) {action=true; print_log("start_apps\n"); } - - x = pers_xfers->poll(); - if (x) {action=true; print_log("pers_xfers\n"); } - - x = handle_finished_apps(); - if (x) {action=true; print_log("handle_finished_apps\n"); } - - x = handle_pers_file_xfers(); - if (x) {action=true; print_log("handle_pers_file_xfers\n"); } - - x = garbage_collect(); - if (x) {action=true; print_log("garbage_collect\n"); } - - x = update_results(); - if (x) {action=true; print_log("update_results\n"); } +#undef POLL_ACTION if (write_state_file_if_needed()) { msg_printf(NULL, MSG_ERROR, "Couldn't write state file"); } } - print_log("End poll\n"); - if (!action) { + --log_messages; + scope_messages.printf("CLIENT_STATE::do_evil(): End poll: %d tasks active\n", + actions); + if (actions > 0) { + return true; + } else { time_stats.update(true, !activities_suspended); + return false; } - return action; } // Parse the client_state.xml file @@ -672,10 +644,9 @@ int CLIENT_STATE::parse_state_file() { int retval=0; int failnum; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_STATE); if (!f) { - if (log_flags.state_debug) { - printf("No state file; will create one\n"); - } + scope_messages.printf("CLIENT_STATE::parse_state_file(): No state file; will create one\n"); // avoid warning messages about version // @@ -807,9 +778,8 @@ int CLIENT_STATE::write_state_file() { FILE* f = fopen(STATE_FILE_TEMP, "w"); int retval; - if (log_flags.state_debug) { - printf("Writing state file\n"); - } + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_STATE); + scope_messages.printf("CLIENT_STATE::write_state_file(): Writing state file\n"); if (!f) { msg_printf(0, MSG_ERROR, "Can't open temp state file: %s\n", STATE_FILE_TEMP); return ERR_FOPEN; @@ -883,9 +853,7 @@ int CLIENT_STATE::write_state_file() { fprintf(f, "\n"); fclose(f); retval = boinc_rename(STATE_FILE_TEMP, STATE_FILE_NAME); - if (log_flags.state_debug) { - printf("Done writing state file\n"); - } + scope_messages.printf("CLIENT_STATE::write_state_file(): Done writing state file\n"); if (retval) return ERR_RENAME; return 0; } @@ -1114,40 +1082,43 @@ void CLIENT_STATE::print_summary() { int t; if (!log_flags.state_debug) return; - printf("Client state summary:\n"); - printf(" %d projects\n", (int)projects.size()); + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_STATE); + scope_messages.printf("CLIENT_STATE::print_summary(): Client state summary:\n"); + ++log_messages; + scope_messages.printf("%d projects:\n", (int)projects.size()); for (i=0; imaster_url); t = projects[i]->min_rpc_time; if (t) { - printf(" min RPC %d seconds from now", (int)(t-time(0))); + scope_messages.printf(" %s min RPC %d seconds from now\n", projects[i]->master_url, (int)(t-time(0))); + } else { + scope_messages.printf(" %s\n", projects[i]->master_url); } - printf("\n"); } - printf(" %d file_infos\n", (int)file_infos.size()); + scope_messages.printf("%d file_infos:\n", (int)file_infos.size()); for (i=0; iname, file_infos[i]->status, file_infos[i]->pers_file_xfer?"active":"inactive"); + scope_messages.printf(" %s status:%d %s\n", file_infos[i]->name, file_infos[i]->status, file_infos[i]->pers_file_xfer?"active":"inactive"); } - printf(" %d app_versions\n", (int)app_versions.size()); + scope_messages.printf("%d app_versions\n", (int)app_versions.size()); for (i=0; iapp_name, app_versions[i]->version_num); + scope_messages.printf(" %s %d\n", app_versions[i]->app_name, app_versions[i]->version_num); } - printf(" %d workunits\n", (int)workunits.size()); + scope_messages.printf("%d workunits\n", (int)workunits.size()); for (i=0; iname); + scope_messages.printf(" %s\n", workunits[i]->name); } - printf(" %d results\n", (int)results.size()); + scope_messages.printf("%d results\n", (int)results.size()); for (i=0; iname, results[i]->state); + scope_messages.printf(" %s state:%d\n", results[i]->name, results[i]->state); } - printf(" %d persistent file xfers\n", (int)pers_xfers->pers_file_xfers.size()); + scope_messages.printf("%d persistent file xfers\n", (int)pers_xfers->pers_file_xfers.size()); for (i=0; ipers_file_xfers.size(); i++) { - printf(" %s http op state: %d\n", pers_xfers->pers_file_xfers[i]->fip->name, (pers_xfers->pers_file_xfers[i]->fxp?pers_xfers->pers_file_xfers[i]->fxp->http_op_state:-1)); + scope_messages.printf(" %s http op state: %d\n", pers_xfers->pers_file_xfers[i]->fip->name, (pers_xfers->pers_file_xfers[i]->fxp?pers_xfers->pers_file_xfers[i]->fxp->http_op_state:-1)); } - printf(" %d active tasks\n", (int)active_tasks.active_tasks.size()); + scope_messages.printf("%d active tasks\n", (int)active_tasks.active_tasks.size()); for (i=0; iresult->name); + scope_messages.printf(" %s\n", active_tasks.active_tasks[i]->result->name); } + --log_messages; } // delete unneeded records and files @@ -1165,6 +1136,8 @@ bool CLIENT_STATE::garbage_collect() { vector::iterator avp_iter; bool action = false, found; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_STATE); + // zero references counts on WUs, FILE_INFOs and APP_VERSIONs for (i=0; iserver_ack) { - if (log_flags.state_debug) printf("deleting result %s\n", rp->name); + scope_messages.printf("CLIENT_STATE::garbage_collect(): deleting result %s\n", rp->name); delete rp; result_iter = results.erase(result_iter); action = true; @@ -1236,9 +1209,7 @@ bool CLIENT_STATE::garbage_collect() { while (wu_iter != workunits.end()) { wup = *wu_iter; if (wup->ref_cnt == 0) { - if (log_flags.state_debug) { - printf("deleting workunit %s\n", wup->name); - } + scope_messages.printf("CLIENT_STATE::garbage_collect(): deleting workunit %s\n", wup->name); delete wup; wu_iter = workunits.erase(wu_iter); action = true; @@ -1297,7 +1268,7 @@ bool CLIENT_STATE::garbage_collect() { fip = *fi_iter; if (fip->ref_cnt==0 && !fip->sticky) { fip->delete_file(); - if (log_flags.state_debug) printf("deleting file %s\n", fip->name); + scope_messages.printf("CLIENT_STATE::garbage_collect(): deleting file %s\n", fip->name); delete fip; fi_iter = file_infos.erase(fi_iter); action = true; @@ -1306,7 +1277,7 @@ bool CLIENT_STATE::garbage_collect() { } } - if (action && log_flags.state_debug) { + if (action) { print_summary(); } @@ -1502,9 +1473,7 @@ bool CLIENT_STATE::time_to_exit() { } void CLIENT_STATE::set_client_state_dirty(char* source) { - if (log_flags.state_debug) { - printf("set dirty: %s\n", source); - } + log_messages.printf(ClientMessages::DEBUG_STATE, "set dirty: %s\n", source); client_state_dirty = true; } @@ -1588,7 +1557,7 @@ int CLIENT_STATE::report_result_error( } } } - + res.stderr_out = res.stderr_out.substr(0,MAX_BLOB_LEN-1); return 0; } diff --git a/client/cs_apps.C b/client/cs_apps.C index 4f32fa25a3..8f22639f35 100644 --- a/client/cs_apps.C +++ b/client/cs_apps.C @@ -30,11 +30,10 @@ #include "md5_file.h" #include "error_numbers.h" -#include "log_flags.h" #include "file_names.h" #include "filesys.h" #include "shmem.h" - +#include "log_flags.h" #include "client_state.h" // Make a directory for each available slot @@ -152,6 +151,8 @@ bool CLIENT_STATE::handle_finished_apps() { ACTIVE_TASK* atp; bool action = false; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_TASK); + for (i=0; istate) { @@ -160,12 +161,8 @@ bool CLIENT_STATE::handle_finished_apps() { break; default: msg_printf(atp->wup->project, MSG_INFO, "Computation for result %s finished", atp->wup->name); - if (log_flags.task_debug) { - printf( - "task finished; pid %d, status %d\n", - atp->pid, atp->exit_status - ); - } + scope_messages.printf("CLIENT_STATE::handle_finished_apps(): task finished; pid %d, status %d\n", + atp->pid, atp->exit_status); app_finished(*atp); active_tasks.remove(atp); delete atp; diff --git a/client/cs_files.C b/client/cs_files.C index 7f2fdb81a7..1f973e5bd7 100644 --- a/client/cs_files.C +++ b/client/cs_files.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. -// Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// Portions created by the SETI@home project are Copyright (C) 2002, 2003 +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -35,7 +35,6 @@ #include "file_xfer.h" #include "file_names.h" #include "client_types.h" -#include "log_flags.h" #include "client_state.h" #include "filesys.h" #include "error_numbers.h" @@ -165,6 +164,6 @@ bool CLIENT_STATE::handle_pers_file_xfers() { iter++; } } - + return action; } diff --git a/client/cs_scheduler.C b/client/cs_scheduler.C index 22c464fb69..6c8a00d7e5 100644 --- a/client/cs_scheduler.C +++ b/client/cs_scheduler.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. -// Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// Portions created by the SETI@home project are Copyright (C) 2002, 2003 +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -34,7 +34,6 @@ #include "parse.h" #include "util.h" -#include "log_flags.h" #include "account.h" #include "message.h" #include "scheduler_op.h" @@ -84,7 +83,7 @@ void CLIENT_STATE::update_avg_cpu(PROJECT* p) { } // find a project that needs its master file parsed -// +// PROJECT* CLIENT_STATE::next_project_master_pending() { unsigned int i; PROJECT* p; @@ -101,7 +100,7 @@ PROJECT* CLIENT_STATE::next_project_master_pending() { } // find a project that needs to contact its scheduling server -// +// PROJECT* CLIENT_STATE::next_project_sched_rpc_pending() { unsigned int i; time_t now = time(0); @@ -343,13 +342,9 @@ int CLIENT_STATE::handle_scheduler_reply( nresults = 0; contacted_sched_server = true; - if (log_flags.sched_op_debug) { - f = fopen(SCHED_OP_RESULT_FILE, "r"); - printf("------------- SCHEDULER REPLY ----------\n"); - copy_stream(f, stdout); - fclose(f); - printf("------------- END ----------\n"); - } + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + + scope_messages.printf_file(SCHED_OP_RESULT_FILE, "CLIENT_STATE::handle_scheduler_reply(): reply: "); f = fopen(SCHED_OP_RESULT_FILE, "r"); if (!f) return ERR_FOPEN; @@ -514,9 +509,7 @@ int CLIENT_STATE::handle_scheduler_reply( // for (i=0; iserver_ack = true; } else { @@ -528,9 +521,7 @@ int CLIENT_STATE::handle_scheduler_reply( } project->sched_rpc_pending = false; set_client_state_dirty("handle_scheduler_reply"); - if (log_flags.state_debug) { - printf("State after handle_scheduler_reply():\n"); - print_summary(); - } + scope_messages.printf("CLIENT_STATE::handle_scheduler_reply(): State after handle_scheduler_reply():\n"); + print_summary(); return 0; } diff --git a/client/file_xfer.C b/client/file_xfer.C index 9df784d176..beb03359b0 100644 --- a/client/file_xfer.C +++ b/client/file_xfer.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. -// Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// Portions created by the SETI@home project are Copyright (C) 2002, 2003 +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -23,7 +23,6 @@ #include "file_names.h" #include "client_state.h" #include "filesys.h" -#include "log_flags.h" #include "message.h" #include "file_xfer.h" #include "parse.h" @@ -128,7 +127,7 @@ int FILE_XFER::parse_server_response(double &nbytes) { } else { status = ERR_UPLOAD_TRANSIENT; } - + if (parse_str(req1, "", buf, sizeof(buf))) { msg_printf(fip->project, MSG_ERROR, "Error on file upload: %s", buf); } @@ -180,14 +179,14 @@ bool FILE_XFER_SET::poll() { FILE_XFER* fxp; bool action = false; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_FILE_XFER); + for (i=0; ihttp_op_done()) { action = true; fxp->file_xfer_done = true; - if (log_flags.file_xfer_debug) { - printf("http op done; retval %d\n", fxp->http_op_retval); - } + scope_messages.printf("FILE_XFER_SET::poll(): http op done; retval %d\n", fxp->http_op_retval); fxp->file_xfer_retval = fxp->http_op_retval; if (fxp->file_xfer_retval == 0) { if (fxp->is_upload) { diff --git a/client/http.C b/client/http.C index f8a7bf6e9e..d3b9bee51a 100644 --- a/client/http.C +++ b/client/http.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. // Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -36,9 +36,9 @@ #include "error_numbers.h" #include "filesys.h" -#include "log_flags.h" #include "http.h" #include "util.h" +#include "message.h" #define HTTP_BLOCKSIZE 16384 @@ -128,6 +128,9 @@ static void http_post_request_header( int read_http_reply_header(int socket, HTTP_REPLY_HEADER& header) { int i, n; char buf[1024], *p; + + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_HTTP); + if (socket<0) { fprintf(stderr, "error: read_http_reply_header: negative socket\n"); return ERR_NEG; @@ -138,7 +141,8 @@ int read_http_reply_header(int socket, HTTP_REPLY_HEADER& header) { for (i=0; i<1024; i++) { n = recv(socket, buf+i, 1, 0); if (strstr(buf, "\r\n\r\n") || strstr(buf, "\n\n")) { - if (log_flags.http_debug) printf("reply header on socket %d:\n%s", socket, buf); + // scope_messages.printf("read_http_reply_header(): reply header on socket %d:\n", socket); + scope_messages.printf_multiline(buf, "read_http_reply_header(): header: "); p = strchr(buf, ' '); if (p) { header.status = atoi(p+1); @@ -244,6 +248,8 @@ int HTTP_OP::init_post(char* url, char* in, char* out) { double size; char proxy_buf[256]; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_HTTP); + parse_url(url, hostname, port, filename); NET_XFER::init(use_http_proxy?proxy_server_name:hostname, use_http_proxy?proxy_server_port:port, HTTP_BLOCKSIZE); safe_strcpy(infile, in); @@ -260,10 +266,8 @@ int HTTP_OP::init_post(char* url, char* in, char* out) { } http_post_request_header( request_header, hostname, port, proxy_buf, content_length - ); - if (log_flags.http_debug) { - printf("init_post: %x io_done %d\n", (unsigned int)this, io_done); - } + ); + scope_messages.printf("HTTP_OP::init_post(): %x io_done %d\n", (unsigned int)this, io_done); return 0; } @@ -330,6 +334,8 @@ bool HTTP_OP_SET::poll() { int n, retval; bool action = false; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_HTTP); + for (i=0; ihttp_op_state) { @@ -351,13 +357,10 @@ bool HTTP_OP_SET::poll() { n = send( htp->socket, htp->request_header, strlen(htp->request_header), 0 - ); - if (log_flags.http_debug) { - printf( - "wrote HTTP header to socket %d: %d bytes\n%s", - htp->socket, n, htp->request_header ); - } + scope_messages.printf("HTTP_OP_SET::poll(): wrote HTTP header to socket %d: %d bytes\n", + htp->socket, n); + scope_messages.printf_multiline(htp->request_header, "HTTP_OP_SET::poll(): request header: "); htp->io_ready = false; switch(htp->http_op_type) { case HTTP_OP_POST: @@ -411,9 +414,7 @@ bool HTTP_OP_SET::poll() { case HTTP_STATE_REQUEST_BODY: if (htp->io_done) { action = true; - if (log_flags.http_debug) { - printf("finished sending request body\n"); - } + scope_messages.printf("HTTP_OP_SET::poll(): finished sending request body\n"); htp->http_op_state = HTTP_STATE_REPLY_HEADER; if (htp->file) { fclose(htp->file); @@ -428,7 +429,7 @@ bool HTTP_OP_SET::poll() { case HTTP_STATE_REPLY_HEADER: if (htp->io_ready) { action = true; - if (log_flags.http_debug) printf("got reply header; %x io_done %d\n", (unsigned int)htp, htp->io_done); + scope_messages.printf("HTTP_OP_SET::poll(): got reply header; %x io_done %d\n", (unsigned int)htp, htp->io_done); read_http_reply_header(htp->socket, htp->hrh); // TODO: handle all kinds of redirects here @@ -498,7 +499,7 @@ bool HTTP_OP_SET::poll() { case HTTP_STATE_REPLY_BODY: if (htp->error) { action = true; - if (log_flags.http_debug) printf("net_xfer returned error %d\n", htp->error); + scope_messages.printf("HTTP_OP_SET::poll(): net_xfer returned error %d\n", htp->error); htp->http_op_state = HTTP_STATE_DONE; htp->http_op_retval = htp->error; } @@ -514,7 +515,7 @@ bool HTTP_OP_SET::poll() { htp->file = 0; break; } - if (log_flags.http_debug) printf("got reply body\n"); + scope_messages.printf("HTTP_OP_SET::poll(): got reply body\n"); htp->http_op_state = HTTP_STATE_DONE; htp->http_op_retval = 0; } diff --git a/client/main.C b/client/main.C index 90480b4f08..abb76cfbaa 100644 --- a/client/main.C +++ b/client/main.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. // Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -37,6 +37,7 @@ #include "log_flags.h" #include "prefs.h" #include "util.h" +#include "message.h" // dummies void create_curtain(){} @@ -158,7 +159,7 @@ int main(int argc, char** argv) { dt = dtime(); gstate.net_sleep(1.); dt = dtime() - dt; - if (log_flags.time_debug) printf("SLEPT %f SECONDS\n", dt); + log_messages.printf(ClientMessages::DEBUG_TIME, "SLEPT %f SECONDS\n", dt); fflush(stdout); } diff --git a/client/message.h b/client/message.h index f9e624ea4b..a59b5c6d71 100644 --- a/client/message.h +++ b/client/message.h @@ -2,21 +2,26 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. -// Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// Portions created by the SETI@home project are Copyright (C) 2002, 2003 +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // +#ifndef MESSAGE_H +#define MESSAGE_H + +#include "util.h" + // Show a message, preceded by timestamp and project name // priorities: @@ -27,4 +32,28 @@ // cmdline: write to stderr // GUI: write to msg window in bold or red -extern void show_message(PROJECT *p, char* message, int priority); +extern void show_message(class PROJECT *p, char* message, int priority); + + +class ClientMessages : public Messages { + int debug_level; + const char* v_format_kind(int kind) const; + bool v_message_wanted(int kind) const; +public: + enum Kind { + DEBUG_STATE, // changes to CLIENT_STATE structure + DEBUG_TASK, + DEBUG_FILE_XFER, + DEBUG_SCHED_OP, + DEBUG_HTTP, + DEBUG_TIME, // print message on sleep + DEBUG_NET_XFER, + DEBUG_MEASUREMENT, // host measurement notices + DEBUG_POLL, // show what polls are responding + }; + ClientMessages(): Messages(stdout) {} +}; + +extern ClientMessages log_messages; + +#endif diff --git a/client/net_xfer.C b/client/net_xfer.C index c7a43cd013..9ea8f39ba2 100644 --- a/client/net_xfer.C +++ b/client/net_xfer.C @@ -61,7 +61,6 @@ #include #include "error_numbers.h" -#include "log_flags.h" #include "net_xfer.h" #include "util.h" #include "client_types.h" @@ -333,6 +332,8 @@ int NET_XFER_SET::do_select(double& bytes_transferred, timeval& timeout) { socklen_t intsize = sizeof(int); #endif + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_NET_XFER); + // if a second has gone by, do rate-limit accounting // time_t t = time(0); @@ -364,19 +365,19 @@ int NET_XFER_SET::do_select(double& bytes_transferred, timeval& timeout) { if (bytes_left_down > 0) { FD_SET(nxp->socket, &read_fds); } else { - if (log_flags.net_xfer_debug) printf("Throttling download\n"); + scope_messages.printf("NET_XFER_SET::do_select(): Throttling download\n"); } } else if (nxp->want_upload) { if (bytes_left_up > 0) { FD_SET(nxp->socket, &write_fds); } else { - if (log_flags.net_xfer_debug) printf("Throttling upload\n"); + scope_messages.printf("NET_XFER_SET::do_select(): Throttling upload\n"); } } FD_SET(nxp->socket, &error_fds); } n = select(FD_SETSIZE, &read_fds, &write_fds, &error_fds, &timeout); - if (log_flags.net_xfer_debug) printf("select returned %d\n", n); + scope_messages.printf("NET_XFER_SET::do_select(): select returned %d\n", n); if (n == 0) return 0; if (n < 0) return ERR_SELECT; @@ -397,15 +398,11 @@ int NET_XFER_SET::do_select(double& bytes_transferred, timeval& timeout) { getsockopt(fd, SOL_SOCKET, SO_ERROR, (void*)&n, &intsize); #endif if (n) { - if (log_flags.net_xfer_debug) { - printf("socket %d connect failed\n", fd); - } + scope_messages.printf("NET_XFER_SET::do_select(): socket %d connect failed\n", fd); nxp->error = ERR_CONNECT; nxp->io_done = true; } else { - if (log_flags.net_xfer_debug) { - printf("socket %d is connected\n", fd); - } + scope_messages.printf("NET_XFER_SET::do_select(): socket %d is connected\n", fd); nxp->is_connected = true; bytes_transferred += 1; } @@ -432,7 +429,7 @@ int NET_XFER_SET::do_select(double& bytes_transferred, timeval& timeout) { nxp->io_ready = true; } } else if (FD_ISSET(fd, &error_fds)) { - if (log_flags.net_xfer_debug) printf("got error on socket %d\n", fd); + scope_messages.printf("NET_XFER_SET::do_select(): got error on socket %d\n", fd); nxp = lookup_fd(fd); if (nxp) { nxp->got_error(); @@ -465,15 +462,15 @@ int NET_XFER::do_xfer(int& nbytes_transferred) { nbytes_transferred = 0; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_NET_XFER); + if (want_download) { #ifdef _WIN32 n = recv(socket, buf, blocksize, 0); #else n = read(socket, buf, blocksize); #endif - if (log_flags.net_xfer_debug) { - printf("read %d bytes from socket %d\n", n, socket); - } + scope_messages.printf("NET_XFER::do_xfer(): read %d bytes from socket %d\n", n, socket); if (n == 0) { io_done = true; want_download = false; @@ -517,10 +514,8 @@ int NET_XFER::do_xfer(int& nbytes_transferred) { would_block = (errno == EAGAIN); #endif if (would_block && n < 0) n = 0; - if (log_flags.net_xfer_debug) { - printf("wrote %d bytes to socket %d%s\n", n, socket, - (would_block?", would have blocked":"")); - } + scope_messages.printf("NET_XFER::do_xfer(): wrote %d bytes to socket %d%s\n", n, socket, + (would_block?", would have blocked":"")); if (n < 0 && !would_block) { error = ERR_WRITE; io_done = true; @@ -563,9 +558,8 @@ void NET_XFER::update_speed(int nbytes) { void NET_XFER::got_error() { error = ERR_IO; io_done = true; - if (log_flags.net_xfer_debug) { - printf("IO error on socket %d\n", socket); - } + log_messages.printf(ClientMessages::DEBUG_NET_XFER, + "IO error on socket %d\n", socket); } // return true if an upload is currently in progress diff --git a/client/pers_file_xfer.C b/client/pers_file_xfer.C index 502d868d8e..b4c5143211 100644 --- a/client/pers_file_xfer.C +++ b/client/pers_file_xfer.C @@ -26,10 +26,10 @@ #include "client_types.h" #include "error_numbers.h" #include "file_names.h" -#include "log_flags.h" #include "md5_file.h" #include "parse.h" #include "util.h" +#include "log_flags.h" // PERS_FILE_XFER represents a persistent file transfer. // A set of URLs is given. @@ -64,6 +64,8 @@ int PERS_FILE_XFER::start_xfer() { FILE_XFER *file_xfer; int retval; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_FILE_XFER); + // Decide whether to start a new file transfer // if (!gstate.start_new_file_xfer()) { @@ -109,9 +111,7 @@ int PERS_FILE_XFER::start_xfer() { msg_printf(fip->project, MSG_INFO, "Started %s of %s", (is_upload ? "upload" : "download"), fip->name); } - if (log_flags.file_xfer_debug) { - msg_printf(fip->project, MSG_INFO, "URL: %s",fip->get_url()); - } + scope_messages.printf("PERS_FILE_XFER::start_xfer(): URL: %s",fip->get_url()); return 0; } @@ -123,6 +123,8 @@ bool PERS_FILE_XFER::poll(time_t now) { int retval; char pathname[256]; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_FILE_XFER); + if (xfer_done) { return false; } @@ -154,10 +156,8 @@ bool PERS_FILE_XFER::poll(time_t now) { msg_printf(fip->project, MSG_INFO, "Finished %s of %s", is_upload?"upload":"download", fip->name); } - if (log_flags.file_xfer_debug) { - msg_printf(fip->project, MSG_INFO, "file transfer status %d", - fxp->file_xfer_retval); - } + scope_messages.printf("PERS_FILE_XFER::poll(): file transfer status %d", + fxp->file_xfer_retval); if (fxp->file_xfer_retval == 0) { // The transfer finished with no errors. // @@ -179,9 +179,7 @@ bool PERS_FILE_XFER::poll(time_t now) { msg_printf(fip->project, MSG_ERROR, "Checksum or signature error for %s", fip->name); fip->status = retval; } else { - if (log_flags.file_xfer_debug) { - msg_printf(fip->project, MSG_INFO, "MD5 checksum validated for %s", pathname); - } + scope_messages.printf("PERS_FILE_XFER::poll(): MD5 checksum validated for %s", pathname); // Set the appropriate permissions depending on whether // it's an executable or normal file // @@ -246,6 +244,8 @@ void PERS_FILE_XFER::retry_or_backoff() { time_t now; int backoff = 0; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_FILE_XFER); + now = time(0); // newtime = localtime(&now); @@ -270,10 +270,8 @@ void PERS_FILE_XFER::retry_or_backoff() { // fip->name, this, nretry, // backoff, now, next_request_time); } - if (log_flags.file_xfer_debug) { - msg_printf(fip->project, MSG_INFO, "Backing off %d seconds on transfer of file %s", - backoff, fip->name); - } + scope_messages.printf("PERS_FILE_XFER::retry_or_backoff(): Backing off %d seconds on transfer of file %s", + backoff, fip->name); } // Parse XML information about a single persistent file transfer diff --git a/client/scheduler_op.C b/client/scheduler_op.C index 8f4bdf4659..17ae366231 100644 --- a/client/scheduler_op.C +++ b/client/scheduler_op.C @@ -2,18 +2,18 @@ // Version 1.0 (the "License"); you may not use this file except in // compliance with the License. You may obtain a copy of the License at // http://boinc.berkeley.edu/license_1.0.txt -// +// // Software distributed under the License is distributed on an "AS IS" // basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the // License for the specific language governing rights and limitations -// under the License. -// -// The Original Code is the Berkeley Open Infrastructure for Network Computing. -// +// under the License. +// +// The Original Code is the Berkeley Open Infrastructure for Network Computing. +// // The Initial Developer of the Original Code is the SETI@home project. // Portions created by the SETI@home project are Copyright (C) 2002 -// University of California at Berkeley. All Rights Reserved. -// +// University of California at Berkeley. All Rights Reserved. +// // Contributor(s): // @@ -100,9 +100,9 @@ int SCHEDULER_OP::init_op_project(double ns) { int retval; char err_msg[256]; - if (log_flags.sched_op_debug) { - printf("init_op_project: starting op for %s\n", project->master_url); - } + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + + scope_messages.printf("SCHEDULER_OP::init_op_project(): starting op for %s\n", project->master_url); // if project has no schedulers, skip everything else // and just get its master file. @@ -138,12 +138,12 @@ int SCHEDULER_OP::set_min_rpc_time(PROJECT* p) { int n = p->nrpc_failures; if (n > gstate.retry_cap) n = gstate.retry_cap; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + // we've hit the limit on master_url fetches // if (p->master_fetch_failures >= gstate.master_fetch_retry_cap) { - if (log_flags.sched_op_debug) { - printf("we've hit the limit on master_url fetches\n"); - } + scope_messages.printf("SCHEDULER_OP::set_min_rpc_time(): we've hit the limit on master_url fetches\n"); exp_backoff = calculate_exponential_backoff("scheduler_op/master_url", p->master_fetch_failures, gstate.sched_retry_delay_min, gstate.master_fetch_interval @@ -188,9 +188,10 @@ void SCHEDULER_OP::backoff(PROJECT* p, char *error_msg ) { // If successful, creates an HTTP_OP that must be polled // int SCHEDULER_OP::start_rpc() { - FILE *f; int retval; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + safe_strcpy(scheduler_url, project->scheduler_urls[url_index].text); if (log_flags.sched_ops) { msg_printf( @@ -198,13 +199,9 @@ int SCHEDULER_OP::start_rpc() { "Sending request to scheduler: %s\n", scheduler_url ); } - if (log_flags.sched_op_debug) { - f = fopen(SCHED_OP_REQUEST_FILE, "r"); - printf("--------- SCHEDULER REQUEST ---------\n"); - copy_stream(f, stdout); - printf("--------- END ---------\n"); - fclose(f); - } + + scope_messages.printf_file(SCHED_OP_REQUEST_FILE, "SCHEDULER_OP::start_rpc(): request xml: "); + if (gstate.use_http_proxy) { http_op.use_http_proxy = true; safe_strcpy(http_op.proxy_server_name, gstate.proxy_server_name); @@ -227,10 +224,10 @@ int SCHEDULER_OP::start_rpc() { int SCHEDULER_OP::init_master_fetch(PROJECT* p) { int retval; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + project = p; - if (log_flags.sched_ops) { - printf("Fetching master file for %s\n", project->master_url); - } + scope_messages.printf("SCHEDULER_OP::init_master_fetch(): Fetching master file for %s\n", project->master_url); if (gstate.use_http_proxy) { http_op.use_http_proxy = true; safe_strcpy(http_op.proxy_server_name, gstate.proxy_server_name); @@ -251,6 +248,8 @@ int SCHEDULER_OP::parse_master_file(vector &urls) { STRING256 str; FILE* f; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + f = fopen(MASTER_FILE_NAME, "r"); if (!f) { msg_printf(project, MSG_ERROR, "Can't open master file\n"); @@ -263,9 +262,7 @@ int SCHEDULER_OP::parse_master_file(vector &urls) { } } fclose(f); - if (log_flags.sched_op_debug) { - printf("Parsed master file; got %d scheduler URLs\n", (int)urls.size()); - } + scope_messages.printf("SCHEDULER_OP::parse_master_file(): got %d scheduler URLs\n", (int)urls.size()); // couldn't find any urls in the master file? // @@ -313,6 +310,8 @@ bool SCHEDULER_OP::poll() { bool action = false, err = false; char err_msg[256],*err_url=NULL; + ScopeMessages scope_messages(log_messages, ClientMessages::DEBUG_SCHED_OP); + switch(state) { case SCHEDULER_OP_STATE_GET_MASTER: // here we're fetching the master file for a project @@ -323,12 +322,8 @@ bool SCHEDULER_OP::poll() { gstate.set_client_state_dirty("master URL fetch done"); http_ops->remove(&http_op); if (http_op.http_op_retval == 0) { - if (log_flags.sched_op_debug) { - printf( - "Got master file from %s; parsing\n", - project->master_url - ); - } + scope_messages.printf("SCHEDULER_OP::poll(): Got master file from %s; parsing\n", + project->master_url); retval = parse_master_file(urls); if (retval) { // master file parse failed. @@ -381,9 +376,7 @@ bool SCHEDULER_OP::poll() { // if (!check_master_fetch_start()) { state = SCHEDULER_OP_STATE_IDLE; - if (log_flags.sched_op_debug) { - printf("Scheduler_op: return to idle state\n"); - } + scope_messages.printf("SCHEDULER_OP::poll(): return to idle state\n"); } } @@ -483,16 +476,12 @@ bool SCHEDULER_OP::poll() { if (project) { retval = init_master_fetch(project); if (retval) { - if (log_flags.sched_op_debug) { - printf("Scheduler op: init_master_fetch failed.\n" ); - } + scope_messages.printf("SCHEDULER_OP::poll(): init_master_fetch failed.\n" ); backoff(project, "Scheduler op: init_master_fetch failed.\n" ); } } else { state = SCHEDULER_OP_STATE_IDLE; - if (log_flags.sched_op_debug) { - printf("Scheduler_op: return to idle state\n"); - } + scope_messages.printf("SCHEDULER_OP::poll(): return to idle state\n"); } } break; diff --git a/lib/util.h b/lib/util.h index bc93ef980f..2da2682f6b 100755 --- a/lib/util.h +++ b/lib/util.h @@ -17,12 +17,14 @@ // Contributor(s): // +#ifndef UTIL_H +#define UTIL_H + #include #include #include - -#ifndef _UTIL_H_ -#define _UTIL_H_ +#include +#include extern int double_to_ydhms (double x, int smallest_timescale, char *buf); extern void get_byte_string(double nbytes, double total_bytes, char* str, int len); @@ -49,6 +51,53 @@ extern char* timestamp(); #define min(a,b) (((a) < (b)) ? (a) : (b)) #endif + +// use ClientMessages or SchedMessages +class Messages { + int debug_level; + int indent_level; + char spaces[80]; + FILE* output; +public: + + Messages(FILE* output); + void enter_level(int = 1); + void leave_level() { enter_level(-1); } + Messages& operator++() { enter_level(); return *this; } + Messages& operator--() { leave_level(); return *this; } + + void printf(int kind, const char* format, ...); + void printf_multiline(int kind, const char* str, const char* prefix_format, ...); + void printf_file(int kind, const char* filename, const char* prefix_format, ...); + + void vprintf(int kind, const char* format, va_list va); + void vprintf_multiline(int kind, const char* str, const char* prefix_format, va_list va); + void vprintf_file(int kind, const char* filename, const char* prefix_format, va_list va); + +protected: + + virtual const char* v_format_kind(int kind) const = 0; + virtual bool v_message_wanted(int kind) const = 0; +}; + +// automatically ++/--Messages on scope entry / exit +class ScopeMessages +{ + Messages& messages; + int kind; +public: + ScopeMessages(Messages& messages_, int kind_) : messages(messages_), kind(kind_) + { ++messages; } + ~ScopeMessages() { --messages; } + ScopeMessages& operator++() { ++messages; return *this; } + ScopeMessages& operator--() { --messages; return *this; } + + void printf(const char* format, ...); + void printf_multiline(const char* str, const char* prefix_format, ...); + void printf_file(const char* filename, const char* prefix_format, ...); +}; + + #define SECONDS_PER_DAY 86400 static inline double drand() { diff --git a/sched/assimilate_handler.C b/sched/assimilate_handler.C index f4c58dcc5a..6d8c2a759d 100644 --- a/sched/assimilate_handler.C +++ b/sched/assimilate_handler.C @@ -8,20 +8,20 @@ void assimilate_handler( WORKUNIT& wu, vector& results, RESULT& canonical_result ) { - write_log(MSG_NORMAL, "assimilating WU %s\n", wu.name); + log_messages.printf(SchedMessages::NORMAL, "[%s] Assimilating\n", wu.name); if (wu.canonical_resultid) { - write_log(MSG_NORMAL, "canonical result:\n"); - write_log_multiline(MSG_NORMAL, canonical_result.xml_doc_out); + log_messages.printf(SchedMessages::NORMAL, "canonical result:\n"); + log_messages.printf_multiline(SchedMessages::NORMAL, canonical_result.xml_doc_out, "[%s] ", wu.name); } else { - write_log(MSG_NORMAL, "no canonical result\n"); + log_messages.printf(SchedMessages::NORMAL, "no canonical result\n"); } if (wu.error_mask&WU_ERROR_COULDNT_SEND_RESULT) { - write_log(MSG_NORMAL, "Error: couldn't send a result\n"); + log_messages.printf(SchedMessages::NORMAL, "Error: couldn't send a result\n"); } if (wu.error_mask&WU_ERROR_TOO_MANY_ERROR_RESULTS) { - write_log(MSG_NORMAL, "Error: too many error results\n"); + log_messages.printf(SchedMessages::NORMAL, "Error: too many error results\n"); } if (wu.error_mask&WU_ERROR_TOO_MANY_RESULTS) { - write_log(MSG_NORMAL, "Error: too many total results\n"); + log_messages.printf(SchedMessages::NORMAL, "Error: too many total results\n"); } } diff --git a/sched/assimilator.C b/sched/assimilator.C index 46f849f45a..3e59029169 100644 --- a/sched/assimilator.C +++ b/sched/assimilator.C @@ -52,10 +52,7 @@ bool do_pass(APP& app) { while (!wu.enumerate(buf)) { did_something = true; - write_log(MSG_DEBUG, - "Assimilating WU %s, assim state %d\n", - wu.name, wu.assimilate_state - ); + log_messages.printf(SchedMessages::DEBUG, "[%s] assimilating; state=%d\n", wu.name, wu.assimilate_state); sprintf(buf, "where workunitid=%d", wu.id); while (!result.enumerate(buf)) { @@ -126,17 +123,17 @@ int main(int argc, char** argv) { } else if (!strcmp(argv[i], "-one_pass")) { one_pass = true; } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else if (!strcmp(argv[i], "-app")) { strcpy(app.name, argv[++i]); } else { - write_log(MSG_CRITICAL, "Unrecognized arg: %s\n", argv[i]); + log_messages.printf(SchedMessages::CRITICAL, "Unrecognized arg: %s\n", argv[i]); } } retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't parse config file\n"); exit(1); } @@ -148,22 +145,22 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Not starting; another copy of assimilator is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Not starting; another copy of assimilator is already running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "Can't open DB\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't open DB\n"); exit(1); } sprintf(buf, "where name='%s'", app.name); retval = app.lookup(buf); if (retval) { - write_log(MSG_CRITICAL, "Can't find app\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't find app\n"); exit(1); } install_sigint_handler(); diff --git a/sched/db_dump.C b/sched/db_dump.C index ce886efeb3..4bf2dcf9cc 100644 --- a/sched/db_dump.C +++ b/sched/db_dump.C @@ -553,7 +553,7 @@ int main(int argc, char** argv) { if (!strcmp(argv[i], "-dir")) { strcpy(dir, argv[++i]); } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else if (!strcmp(argv[i], "-gzip")) { zip_files = true; strcpy( zip_cmd, "gzip -fq" ); @@ -568,31 +568,31 @@ int main(int argc, char** argv) { } if (nrecs_per_file_summary <= 0 || nrecs_per_file_detail <= 0) { - write_log(MSG_NORMAL, "Too few records per file.\n"); + log_messages.printf(SchedMessages::NORMAL, "Too few records per file.\n"); exit(1); } if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of db_dump is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of db_dump is already running\n"); exit(1); } - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); retval = config.parse_file(); if (retval) { - write_log(MSG_NORMAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::NORMAL, "Can't parse config file\n"); exit(1); } retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_NORMAL, "Can't open DB\n"); + log_messages.printf(SchedMessages::NORMAL, "Can't open DB\n"); exit(1); } if (strlen(dir)) { retval = chdir(dir); if (retval) { - write_log(MSG_NORMAL, "can't chdir to %s\n", dir); + log_messages.printf(SchedMessages::NORMAL, "can't chdir to %s\n", dir); exit(1); } } diff --git a/sched/feeder.C b/sched/feeder.C index 2a8fc5379a..cfbd680a08 100644 --- a/sched/feeder.C +++ b/sched/feeder.C @@ -129,7 +129,7 @@ try_again: // there's no point in doing it again. // if (restarted_enum) { - write_log(MSG_DEBUG, "already restarted enum on this pass\n"); + log_messages.printf(SchedMessages::DEBUG, "already restarted enum on this pass\n"); break; } @@ -137,9 +137,9 @@ try_again: // restarted_enum = true; retval = result.enumerate(clause); - write_log(MSG_DEBUG, "restarting enumeration\n"); + log_messages.printf(SchedMessages::DEBUG, "restarting enumeration\n"); if (retval) { - write_log(MSG_NORMAL, "enumeration restart returned nothing\n"); + log_messages.printf(SchedMessages::NORMAL, "enumeration restart returned nothing\n"); no_wus = true; break; } @@ -151,11 +151,11 @@ try_again: // retval = result.lookup_id(result.id); if (retval) { - write_log(MSG_NORMAL, "can't reread result %s\n", result.name); + log_messages.printf(SchedMessages::NORMAL, "can't reread result %s\n", result.name); goto try_again; } if (result.server_state != RESULT_SERVER_STATE_UNSENT) { - write_log(MSG_NORMAL, "RESULT STATE CHANGED: %s\n", result.name); + log_messages.printf(SchedMessages::NORMAL, "RESULT STATE CHANGED: %s\n", result.name); goto try_again; } collision = false; @@ -169,10 +169,10 @@ try_again: } } if (!collision) { - write_log(MSG_DEBUG, "adding result %d in slot %d\n", result.id, i); + log_messages.printf(SchedMessages::DEBUG, "adding result %d in slot %d\n", result.id, i); retval = wu.lookup_id(result.workunitid); if (retval) { - write_log(MSG_CRITICAL, "can't read workunit %d: %d\n", result.workunitid, retval); + log_messages.printf(SchedMessages::CRITICAL, "can't read workunit %d: %d\n", result.workunitid, retval); continue; } ssp->wu_results[i].result = result; @@ -184,17 +184,17 @@ try_again: } ssp->ready = true; if (nadditions == 0) { - write_log(MSG_DEBUG, "no results added\n"); + log_messages.printf(SchedMessages::DEBUG, "no results added\n"); sleep(1); } else { - write_log(MSG_DEBUG, "added %d results to array\n", nadditions); + log_messages.printf(SchedMessages::DEBUG, "added %d results to array\n", nadditions); } if (no_wus) { - write_log(MSG_DEBUG, "feeder: no results available\n"); + log_messages.printf(SchedMessages::DEBUG, "feeder: no results available\n"); sleep(5); } if (ncollisions) { - write_log(MSG_DEBUG, "feeder: some results already in array - sleeping\n"); + log_messages.printf(SchedMessages::DEBUG, "feeder: some results already in array - sleeping\n"); sleep(5); } fflush(stdout); @@ -212,7 +212,7 @@ int main(int argc, char** argv) { retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't parse config file\n"); exit(1); } @@ -220,7 +220,7 @@ int main(int argc, char** argv) { if (!strcmp(argv[i], "-asynch")) { asynch = true; } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } } @@ -232,20 +232,20 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of feeder is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of feeder is already running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); retval = destroy_shmem(config.shmem_key); if (retval) { - write_log(MSG_CRITICAL, "can't destroy shmem\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't destroy shmem\n"); exit(1); } retval = create_shmem(config.shmem_key, sizeof(SCHED_SHMEM), &p); if (retval) { - write_log(MSG_CRITICAL, "can't create shmem\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't create shmem\n"); exit(1); } ssp = (SCHED_SHMEM*)p; @@ -256,12 +256,12 @@ int main(int argc, char** argv) { retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "boinc_db_open: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "boinc_db_open: %d\n", retval); exit(1); } ssp->scan_tables(); - write_log(MSG_NORMAL, + log_messages.printf(SchedMessages::NORMAL, "feeder: read " "%d platforms, " "%d apps, " diff --git a/sched/file_deleter.C b/sched/file_deleter.C index 617c159558..7161646f6a 100644 --- a/sched/file_deleter.C +++ b/sched/file_deleter.C @@ -55,7 +55,7 @@ int wu_delete_files(WORKUNIT& wu) { } else if (match_tag(p, "")) { if (!no_delete) { sprintf(pathname, "%s/%s", config.download_dir, filename); - write_log(MSG_NORMAL, "deleting %s\n", pathname); + log_messages.printf(SchedMessages::NORMAL, "deleting %s\n", pathname); unlink(pathname); } } @@ -81,7 +81,7 @@ int result_delete_files(RESULT& result) { } else if (match_tag(p, "")) { if (!no_delete) { sprintf(pathname, "%s/%s", config.upload_dir, filename); - write_log(MSG_NORMAL, "deleting %s\n", pathname); + log_messages.printf(SchedMessages::NORMAL, "deleting %s\n", pathname); unlink(pathname); } } @@ -130,15 +130,15 @@ int main(int argc, char** argv) { } else if (!strcmp(argv[i], "-one_pass")) { one_pass = true; } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else { - write_log(MSG_CRITICAL, "Unrecognized arg: %s\n", argv[i]); + log_messages.printf(SchedMessages::CRITICAL, "Unrecognized arg: %s\n", argv[i]); } } retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't parse config file\n"); exit(1); } @@ -150,15 +150,15 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of file deleter is running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of file deleter is running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "can't open DB\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't open DB\n"); exit(1); } install_sigint_handler(); diff --git a/sched/main.C b/sched/main.C index 1afc5ea062..5f60a4fc97 100644 --- a/sched/main.C +++ b/sched/main.C @@ -66,46 +66,46 @@ int main() { exit(1); } - set_debug_level(DEBUG_LEVEL); + log_messages.set_debug_level(DEBUG_LEVEL); retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't parse config file\n"); exit(1); } sprintf(path, "%s/code_sign_public", config.key_dir); retval = read_file_malloc(path, code_sign_key); if (retval) { - write_log(MSG_CRITICAL, "Can't read code sign key file (%s)\n", path); + log_messages.printf(SchedMessages::CRITICAL, "Can't read code sign key file (%s)\n", path); exit(1); } retval = attach_shmem(config.shmem_key, &p); if (retval) { - write_log(MSG_CRITICAL, "Can't attach shmem (feeder not running?)\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't attach shmem (feeder not running?)\n"); exit(1); } ssp = (SCHED_SHMEM*)p; retval = ssp->verify(); if (retval) { - write_log(MSG_CRITICAL, "shmem has wrong struct sizes - recompile\n"); + log_messages.printf(SchedMessages::CRITICAL, "shmem has wrong struct sizes - recompile\n"); exit(1); } for (i=0; i<10; i++) { if (ssp->ready) break; - write_log(MSG_DEBUG, "waiting for ready flag\n"); + log_messages.printf(SchedMessages::DEBUG, "waiting for ready flag\n"); sleep(1); } if (!ssp->ready) { - write_log(MSG_CRITICAL, "feeder doesn't seem to be running\n"); + log_messages.printf(SchedMessages::CRITICAL, "feeder doesn't seem to be running\n"); exit(1); } retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "can't open database\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't open database\n"); exit(1); } @@ -114,7 +114,7 @@ int main() { found = true; } if (!found) { - write_log(MSG_CRITICAL, "can't find project\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't find project\n"); exit(1); } @@ -135,19 +135,19 @@ int main() { sprintf(reply_path, "%s%d_%u", REPLY_FILE_PREFIX, pid, counter); fout = fopen(req_path, "w"); if (!fout) { - write_log(MSG_CRITICAL, "can't write request file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't write request file\n"); exit(1); } copy_stream(stdin, fout); fclose(fout); fin = fopen(req_path, "r"); if (!fin) { - write_log(MSG_CRITICAL, "can't read request file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't read request file\n"); exit(1); } fout = fopen(reply_path, "w"); if (!fout) { - write_log(MSG_CRITICAL, "can't write reply file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't write reply file\n"); exit(1); } handle_request(fin, fout, *ssp, code_sign_key); @@ -155,7 +155,7 @@ int main() { fclose(fout); fin = fopen(reply_path, "r"); if (!fin) { - write_log(MSG_CRITICAL, "can't read reply file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't read reply file\n"); exit(1); } copy_stream(fin, stdout); diff --git a/sched/make_work.C b/sched/make_work.C index 487805b554..11f56dbeb0 100644 --- a/sched/make_work.C +++ b/sched/make_work.C @@ -98,20 +98,20 @@ void make_work() { retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "can't read config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't read config file\n"); exit(1); } retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "can't open db\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't open db\n"); exit(1); } sprintf(buf, "where name='%s'", wu_name); retval = wu.lookup(buf); if (retval) { - write_log(MSG_CRITICAL, "can't find wu %s\n", wu_name); + log_messages.printf(SchedMessages::CRITICAL, "can't find wu %s\n", wu_name); exit(1); } @@ -120,13 +120,13 @@ void make_work() { sprintf(keypath, "%s/upload_private", config.key_dir); retval = read_key_file(keypath, key); if (retval) { - write_log(MSG_CRITICAL, "can't read key\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't read key\n"); exit(1); } retval = read_filename(result_template_file, result_template); if (retval) { - write_log(MSG_CRITICAL, "can't open result template\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't open result template\n"); exit(1); } nresults_left = 0; @@ -136,7 +136,7 @@ void make_work() { sprintf(buf, "where server_state=%d", RESULT_SERVER_STATE_UNSENT); retval = result.count(n, buf); if (retval) { - write_log(MSG_CRITICAL, "can't count results\n"); + log_messages.printf(SchedMessages::CRITICAL, "can't count results\n"); exit(1); } if (n > cushion) { @@ -164,11 +164,11 @@ void make_work() { ); sprintf(command,"ln %s %s", pathname, new_pathname); if (system(command)) { - write_log(MSG_CRITICAL, "system() error\n"); + log_messages.printf(SchedMessages::CRITICAL, "system() error\n"); perror(command); exit(1); } - write_log(MSG_NORMAL, "%s\n", command); + log_messages.printf(SchedMessages::NORMAL, "%s\n", command); strcpy(new_buf, starting_xml); replace_file_name( new_buf, file_name, new_file_name, config.download_url @@ -183,14 +183,14 @@ void make_work() { wu.create_time = time(0); retval = wu.insert(); wu.id = boinc_db_insert_id(); - write_log(MSG_DEBUG, "Created new WU: %s\n", wu.name); + log_messages.printf(SchedMessages::DEBUG, "Created new WU: %s\n", wu.name); } sprintf(suffix, "%d_%d", start_time, seqno++); create_result( wu, result_template, suffix, key, config.upload_url, config.download_url ); - write_log(MSG_DEBUG, "added result: %s_%s\n", wu.name, suffix); + log_messages.printf(SchedMessages::DEBUG, "added result: %s_%s\n", wu.name, suffix); nresults_left--; } } @@ -210,18 +210,18 @@ int main(int argc, char** argv) { } else if (!strcmp(argv[i], "-result_template")) { strcpy(result_template_file, argv[++i]); } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else if (!strcmp(argv[i], "-wu_name")) { strcpy(wu_name, argv[++i]); } } if (!strlen(result_template_file)) { - write_log(MSG_CRITICAL, "missing -result_template\n"); + log_messages.printf(SchedMessages::CRITICAL, "missing -result_template\n"); exit(1); } if (!strlen(wu_name)) { - write_log(MSG_CRITICAL, "missing -wu_name\n"); + log_messages.printf(SchedMessages::CRITICAL, "missing -wu_name\n"); exit(1); } @@ -233,11 +233,11 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of make_work is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of make_work is already running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); install_sigint_handler(); diff --git a/sched/sched_util.C b/sched/sched_util.C index 6758ead06f..4e6b62b6cf 100644 --- a/sched/sched_util.C +++ b/sched/sched_util.C @@ -30,76 +30,17 @@ using namespace std; #include "sched_util.h" #include "server_types.h" -int debug_level = 0; - -inline const char* msg_level_dscription(int msg_level) -{ - switch (msg_level) { - case MSG_CRITICAL: return "CRITICAL"; - case MSG_NORMAL: return "NORMAL"; - case MSG_DEBUG: return "DEBUG"; - default: return "*** internal error; unknown msg_level ***"; - } -} - -void write_log(int msg_level, const char* p, ...) { - if (debug_level < msg_level) return; - if (p == NULL) return; - - va_list ap; - va_start(ap, p); - fprintf(stderr, "%s [%s]: ", timestamp(), msg_level_dscription(msg_level)); - vfprintf(stderr, p, ap); - va_end(ap); -} - -void write_log_line(int msg_level, const char* p, ...) { - if (debug_level < msg_level) return; - if (p == NULL) return; - - va_list ap; - va_start(ap, p); - fprintf(stderr, "%s [%s]: ", timestamp(), msg_level_dscription(msg_level)); - vfprintf(stderr, p, ap); - fprintf(stderr, "\n"); - va_end(ap); -} - -// break a multi-line string into lines (so that we show prefix on each line) -void write_log_multiline(int msg_level, const char* p) { - if (debug_level < msg_level) return; - if (p == NULL) return; - - string line; - while (*p) { - if (*p == '\n') { - write_log(msg_level, " %s\n", line.c_str()); - line.erase(); - } else { - line += *p; - } - ++p; - } - if (!line.empty()) { - write_log(msg_level, " %s\n", line.c_str()); - } -} - void write_pid_file(const char* filename) { FILE* fpid = fopen(filename, "w"); if (!fpid) { - write_log(MSG_NORMAL, "Couldn't write pid\n"); + log_messages.printf(SchedMessages::NORMAL, "Couldn't write pid\n"); return; } fprintf(fpid, "%d\n", getpid()); fclose(fpid); } -void set_debug_level(int new_level) { - debug_level = new_level; -} - // sig_int will be set to true if SIGINT is caught. bool sig_int = false; static void sigint_handler(int) @@ -116,12 +57,12 @@ void install_sigint_handler() void check_stop_trigger() { if (sig_int) { - write_log(MSG_CRITICAL, "Quitting due to SIGINT\n"); + log_messages.printf(SchedMessages::CRITICAL, "Quitting due to SIGINT\n"); exit(0); } FILE* f = fopen(STOP_TRIGGER_FILENAME, "r"); if (f) { - write_log(MSG_NORMAL, "Quitting due to stop trigger\n"); + log_messages.printf(SchedMessages::NORMAL, "Quitting due to stop trigger\n"); exit(0); } } diff --git a/sched/sched_util.h b/sched/sched_util.h index 47f70c53e8..b15829bdcf 100644 --- a/sched/sched_util.h +++ b/sched/sched_util.h @@ -17,10 +17,11 @@ // Contributor(s): // -#ifndef _SCHED_UTIL_ -#define _SCHED_UTIL_ +#ifndef SCHED_UTIL_H +#define SCHED_UTIL_H #include +#include "util.h" // "average credit" uses an exponential decay so that recent // activity is weighted more heavily. @@ -39,12 +40,6 @@ #define STOP_TRIGGER_FILENAME "stop_server" -#define MSG_CRITICAL 0 -#define MSG_NORMAL 1 -#define MSG_DEBUG 2 - -void write_log(int, char const*, ...); -void write_log_multiline(int msg_level, const char* p); extern void write_pid_file(const char* filename); extern void set_debug_level(int); extern void check_stop_trigger(); @@ -52,5 +47,21 @@ extern void update_average(double, double, double&, double&); extern void install_sigint_handler(); extern bool sig_int; + +class SchedMessages : public Messages { + int debug_level; + const char* v_format_kind(int kind) const; + bool v_message_wanted(int kind) const; +public: + enum Kind { + CRITICAL, + NORMAL, + DEBUG + }; + SchedMessages(): Messages(stderr) {} + void set_debug_level(int new_level) { debug_level = new_level; } +}; +extern SchedMessages log_messages; + #endif diff --git a/sched/server_types.C b/sched/server_types.C index 402e2dde96..b219ef8ca8 100644 --- a/sched/server_types.C +++ b/sched/server_types.C @@ -96,7 +96,7 @@ int SCHEDULER_REQUEST::parse(FILE* fin) { copy_element_contents(fin, "", code_sign_key, sizeof(code_sign_key)); } else { - write_log(MSG_NORMAL, "SCHEDULER_REQUEST::parse(): unrecognized: %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "SCHEDULER_REQUEST::parse(): unrecognized: %s\n", buf); } } return 1; @@ -303,7 +303,7 @@ int RESULT::parse_from_client(FILE* fin) { } continue; } else { - write_log(MSG_NORMAL, "RESULT::parse_from_client(): unrecognized: %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "RESULT::parse_from_client(): unrecognized: %s\n", buf); } } return 1; @@ -341,7 +341,7 @@ int HOST::parse(FILE* fin) { else if (parse_double(buf, "", n_bwup)) continue; else if (parse_double(buf, "", n_bwdown)) continue; else { - write_log(MSG_NORMAL, "HOST::parse(): unrecognized: %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "HOST::parse(): unrecognized: %s\n", buf); } } return 1; @@ -357,7 +357,7 @@ int HOST::parse_time_stats(FILE* fin) { else if (parse_double(buf, "", connected_frac)) continue; else if (parse_double(buf, "", active_frac)) continue; else { - write_log(MSG_NORMAL, "HOST::parse_time_stats(): unrecognized: %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "HOST::parse_time_stats(): unrecognized: %s\n", buf); } } return 1; @@ -371,7 +371,7 @@ int HOST::parse_net_stats(FILE* fin) { else if (parse_double(buf, "", n_bwup)) continue; else if (parse_double(buf, "", n_bwdown)) continue; else { - write_log(MSG_NORMAL, "HOST::parse_net_stats(): unrecognized: %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "HOST::parse_net_stats(): unrecognized: %s\n", buf); } } return 1; @@ -386,7 +386,7 @@ int APP_FILE::parse(char*& in) { else if (parse_str(buf, "", open_name, sizeof(open_name))) continue; else if (parse_int(buf, "", timestamp)) continue; else { - write_log(MSG_NORMAL, "APP_FILE::parse(): unrecognized %s\n", buf); + log_messages.printf(SchedMessages::NORMAL, "APP_FILE::parse(): unrecognized %s\n", buf); } } return 1; diff --git a/sched/start_servers.C b/sched/start_servers.C index 233d1e2387..0c06f8d2b2 100644 --- a/sched/start_servers.C +++ b/sched/start_servers.C @@ -28,18 +28,24 @@ int main() { int i, retval; char* p; - write_log(MSG_NORMAL, "Starting servers.\n"); + log_messages.set_debug_level(3); + log_messages.printf(SchedMessages::NORMAL, "Starting servers.\n"); + ++log_messages; retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't read config\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't read config\n"); exit(1); } for (i=0; i<20; i++) { p = config.start_commands[i]; if (!p) break; - write_log(MSG_NORMAL, "Executing: %s\n", p); + log_messages.printf(SchedMessages::NORMAL, "Executing: %s\n", p); system(p); } + + --log_messages; + log_messages.printf(SchedMessages::NORMAL, "Done.\n"); + return 0; } diff --git a/sched/update_stats.C b/sched/update_stats.C index 542f873a16..137fa045ff 100644 --- a/sched/update_stats.C +++ b/sched/update_stats.C @@ -123,11 +123,11 @@ int main(int argc, char** argv) { } else if (!strcmp(argv[i], "-update_hosts")) { do_update_hosts = true; } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else if (!strcmp(argv[i], "-asynch")) { asynch = true; } else { - write_log(MSG_CRITICAL, "Unrecognized arg: %s\n", argv[i]); + log_messages.printf(SchedMessages::CRITICAL, "Unrecognized arg: %s\n", argv[i]); } } @@ -139,28 +139,28 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of update_stats is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of update_stats is already running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting\n"); + log_messages.printf(SchedMessages::NORMAL, "Starting\n"); retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't parse config file\n"); exit(1); } retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "Can't open DB\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't open DB\n"); exit(1); } if (do_update_users) { retval = update_users(); if (retval) { - write_log(MSG_CRITICAL, "update_users failed: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "update_users failed: %d\n", retval); exit(1); } } @@ -168,7 +168,7 @@ int main(int argc, char** argv) { if (do_update_hosts) { retval = update_hosts(); if (retval) { - write_log(MSG_CRITICAL, "update_hosts failed: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "update_hosts failed: %d\n", retval); exit(1); } } @@ -176,7 +176,7 @@ int main(int argc, char** argv) { if (do_update_teams) { retval = update_teams(); if (retval) { - write_log(MSG_CRITICAL, "update_teams failed: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "update_teams failed: %d\n", retval); exit(1); } } diff --git a/sched/validate.C b/sched/validate.C index f91146987f..6fea148603 100644 --- a/sched/validate.C +++ b/sched/validate.C @@ -95,7 +95,7 @@ void handle_wu(DB_WORKUNIT& wu) { char buf[256]; if (wu.canonical_resultid) { - write_log(MSG_NORMAL, + log_messages.printf(SchedMessages::NORMAL, "validating WU %s; already have canonical result\n", wu.name ); @@ -104,7 +104,7 @@ void handle_wu(DB_WORKUNIT& wu) { // retval = canonical_result.lookup_id(wu.canonical_resultid); if (retval) { - write_log(MSG_NORMAL, "can't read canonical result\n"); + log_messages.printf(SchedMessages::NORMAL, "can't read canonical result\n"); // Mark this WU as validated, otherwise we'll keep checking it goto mark_validated; } @@ -119,7 +119,7 @@ void handle_wu(DB_WORKUNIT& wu) { ) { retval = check_pair(result, canonical_result, match); if (retval) { - write_log(MSG_DEBUG, + log_messages.printf(SchedMessages::DEBUG, "validate: pair_check failed for result %d\n", result.id); continue; } else { @@ -134,12 +134,12 @@ void handle_wu(DB_WORKUNIT& wu) { } retval = result.update(); if (retval) { - write_log(MSG_CRITICAL, "Can't update result\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't update result\n"); continue; } retval = grant_credit(result, result.granted_credit); if (retval) { - write_log(MSG_NORMAL, "Can't grant credit\n"); + log_messages.printf(SchedMessages::NORMAL, "Can't grant credit\n"); continue; } } @@ -150,7 +150,7 @@ void handle_wu(DB_WORKUNIT& wu) { // Here if WU doesn't have a canonical result yet. // Try to get one - write_log(MSG_DEBUG, "validating WU %s; no canonical result\n", wu.name); + log_messages.printf(SchedMessages::DEBUG, "validating WU %s; no canonical result\n", wu.name); sprintf(buf, "where workunitid=%d", wu.id); while (!result.enumerate(buf)) { @@ -160,11 +160,11 @@ void handle_wu(DB_WORKUNIT& wu) { results.push_back(result); } } - write_log(MSG_DEBUG, "found %d successful results\n", results.size()); + log_messages.printf(SchedMessages::DEBUG, "found %d successful results\n", results.size()); if (results.size() >= (unsigned int)min_quorum) { retval = check_set(results, canonicalid, credit); if (!retval && canonicalid) { - write_log(MSG_DEBUG, "found a canonical result\n"); + log_messages.printf(SchedMessages::DEBUG, "found a canonical result\n"); wu.canonical_resultid = canonicalid; wu.canonical_credit = credit; wu.assimilate_state = ASSIMILATE_READY; @@ -178,10 +178,10 @@ void handle_wu(DB_WORKUNIT& wu) { update_result = true; retval = grant_credit(result, credit); if (retval) { - write_log(MSG_DEBUG, "validate: grant_credit %d\n", retval ); + log_messages.printf(SchedMessages::DEBUG, "validate: grant_credit %d\n", retval ); } result.granted_credit = credit; - write_log(MSG_NORMAL, + log_messages.printf(SchedMessages::NORMAL, "updating result %d to %d; credit %f\n", result.id, result.validate_state, credit ); } @@ -198,7 +198,7 @@ void handle_wu(DB_WORKUNIT& wu) { if (update_result) { retval = result.update(); if (retval) { - write_log(MSG_CRITICAL, "validate: boinc_db_result_update %d\n", retval ); + log_messages.printf(SchedMessages::CRITICAL, "validate: boinc_db_result_update %d\n", retval ); } } } @@ -212,7 +212,7 @@ void handle_wu(DB_WORKUNIT& wu) { wu.need_validate = 0; retval = wu.update(); if (retval) { - write_log(MSG_CRITICAL, "db_workunit_update: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "db_workunit_update: %d\n", retval); } } @@ -240,14 +240,14 @@ int main_loop(bool one_pass) { retval = boinc_db_open(config.db_name, config.db_passwd); if (retval) { - write_log(MSG_CRITICAL, "boinc_db_open: %d\n", retval); + log_messages.printf(SchedMessages::CRITICAL, "boinc_db_open: %d\n", retval); exit(1); } sprintf(buf, "where name='%s'", app_name); retval = app.lookup(buf); if (retval) { - write_log(MSG_CRITICAL, "can't find app %s\n", app.name); + log_messages.printf(SchedMessages::CRITICAL, "can't find app %s\n", app.name); exit(1); } @@ -277,22 +277,22 @@ int main(int argc, char** argv) { } else if (!strcmp(argv[i], "-app")) { strcpy(app_name, argv[++i]); } else if (!strcmp(argv[i], "-d")) { - set_debug_level(atoi(argv[++i])); + log_messages.set_debug_level(atoi(argv[++i])); } else if (!strcmp(argv[i], "-quorum")) { min_quorum = atoi(argv[++i]); } else { - write_log(MSG_CRITICAL, "unrecognized arg: %s\n", argv[i]); + log_messages.printf(SchedMessages::CRITICAL, "unrecognized arg: %s\n", argv[i]); } } if (min_quorum < 1 || min_quorum > 10) { - write_log(MSG_CRITICAL, "bad min_quorum: %d\n", min_quorum); + log_messages.printf(SchedMessages::CRITICAL, "bad min_quorum: %d\n", min_quorum); exit(1); } retval = config.parse_file(); if (retval) { - write_log(MSG_CRITICAL, "Can't parse config file\n"); + log_messages.printf(SchedMessages::CRITICAL, "Can't parse config file\n"); exit(1); } @@ -304,11 +304,11 @@ int main(int argc, char** argv) { // Call lock_file after fork(), because file locks are not always inherited if (lock_file(LOCKFILE)) { - write_log(MSG_NORMAL, "Another copy of validate is already running\n"); + log_messages.printf(SchedMessages::NORMAL, "Another copy of validate is already running\n"); exit(1); } write_pid_file(PIDFILE); - write_log(MSG_NORMAL, "Starting validator; min_quorum %d\n", min_quorum); + log_messages.printf(SchedMessages::NORMAL, "Starting validator; min_quorum %d\n", min_quorum); install_sigint_handler();