Logging tweaks

Add a LOG_ONCE macro instead of reimplementing the "static int warned"
everywhere.

Mask mode: Avoid repeating a few log entries.

Replace existing old-style log-once with that macro in a few other files.

OpenCL: Prefix log entries with "OpenCL:" for clarity.

Author: magnumripper

src/gpu_common.c

@@ -473,10 +473,10 @@ void gpu_check_temp(void)
 
 		if (temp > 125 || temp < 10) {
 			if (!warned++) {
-				log_event("Device %d probably invalid temp reading (%d%sC).",
+				log_event("GPU device %d probably invalid temp reading (%d%sC).",
 				          dev + 1, temp, gpu_degree_sign);
 				fprintf(stderr,
-				        "Device %d probably invalid temp reading (%d%sC).\n",
+				        "GPU device %d probably invalid temp reading (%d%sC).\n",
 				        dev + 1, temp, gpu_degree_sign);
 			}
 			return;
@@ -492,7 +492,7 @@ void gpu_check_temp(void)
 				if (cool_gpu_down == 1)
 					warnedTemperature++;
 
-				log_event("Device %d overheat (%d%sC, fan %s), %s%s.",
+				log_event("GPU device %d overheat (%d%sC, fan %s), %s%s.",
 				          dev + 1, temp, gpu_degree_sign, s_fan,
 				          (cool_gpu_down > 0) ? "sleeping" : "aborting job",
 				          (hot_gpu) ? " again" : "");
@@ -532,10 +532,10 @@ void gpu_check_temp(void)
 				if (fan >= 0)
 					sprintf(s_fan, "%u%%", fan);
 
-				log_event("Device %d is waking up (%d%sC, fan %s).",
+				log_event("GPU device %d is waking up (%d%sC, fan %s).",
 				          dev + 1, temp, gpu_degree_sign, s_fan);
 				fprintf(stderr,
-				        "Device %d is waking up (%d%sC, fan %s).\n",
+				        "GPU device %d is waking up (%d%sC, fan %s).\n",
 				        dev + 1, temp, gpu_degree_sign, s_fan);
 			}
 			hot_gpu = 0;
@@ -557,15 +557,15 @@ void gpu_log_temp(void)
 
 		fan = temp = util = -1;
 		dev_get_temp[dev](temp_dev_id[dev], &temp, &fan, &util, &cl, &ml);
-		n = sprintf(s_gpu, "Device %d:", dev + 1);
+		n = sprintf(s_gpu, "GPU device %d:", dev + 1);
 		if (temp >= 0)
 			n += sprintf(s_gpu + n, " temp: %u%sC", temp, gpu_degree_sign);
 		if (util > 0)
 			n += sprintf(s_gpu + n, " util: %u%%", util);
 		if (fan >= 0)
 			n += sprintf(s_gpu + n, " fan: %u%%", fan);
 		if (temp >= 0 || util > 0 || fan > 0)
-			log_event("- %s", s_gpu);
+			log_event("%s", s_gpu);
 	}
 #endif
 }

src/logger.h

@@ -50,6 +50,18 @@ extern int log_lock(int fd, int cmd, int type, const char *name,
 #endif /* #if defined(F_SETLK) && defined(F_SETLKW) && defined(F_UNLCK)
 		&& defined(F_RDLCK) && defined(F_WRLCK) */
 
+/*
+ * Macro to only log something once per session.
+ */
+#define LOG_ONCE(...)	  \
+	do { \
+		static int warned; \
+		if (!warned) { \
+			log_event(__VA_ARGS__); \
+			warned++; \
+		} \
+	} while (0)
+
 /*
  * Initializes the logger (opens john.pot and a log file).
  */

src/mask.c

@@ -2436,12 +2436,12 @@ static void finalize_mask(int len)
 		format_cannot_reset = 0;
 		if (john_main_process) {
 			fprintf(stderr, "Note: Disabling internal mask due to stacked rules\n");
-			log_event("- Disabling internal mask due to stacked rules");
+			LOG_ONCE("- Disabling internal mask due to stacked rules");
 		}
 	}
 #if defined(HAVE_OPENCL) || defined(HAVE_ZTEX)
 	else if ((mask_fmt->params.flags & FMT_MASK) && options.req_int_cand_target > 0) {
-		log_event("- Overriding format's target internal mask factor of %d with user requested %d",
+		LOG_ONCE("- Overriding format's target internal mask factor of %d with user requested %d",
 		          mask_int_cand_target, options.req_int_cand_target);
 		mask_int_cand_target = options.req_int_cand_target;
 	}
@@ -2514,9 +2514,14 @@ static void finalize_mask(int len)
 	mask_tot_cand = cand * mask_int_cand.num_int_cand;
 
 	if ((john_main_process || !cfg_get_bool(SECTION_OPTIONS, SUBSECTION_MPI, "MPIAllGPUsSame", 0)) &&
-		mask_int_cand.num_int_cand > 1)
-		log_event("- Requested internal mask factor: %d, actual now %d",
-		          mask_int_cand_target, mask_int_cand.num_int_cand);
+	    mask_int_cand.num_int_cand > 1) {
+		static int old_factor = -1;
+		if (mask_int_cand.num_int_cand != old_factor) {
+			log_event("- Requested internal mask factor: %d, actual now %d",
+			          mask_int_cand_target, mask_int_cand.num_int_cand);
+			old_factor = mask_int_cand.num_int_cand;
+		}
+	}
 }
 
 void mask_crk_init(struct db_main *db)
@@ -2633,6 +2638,7 @@ int do_mask_crack(const char *extern_key)
 			}
 
 			mask_cur_len = i;
+			log_event("- Mask length now %u", mask_cur_len);
 
 			if (format_cannot_reset)
 				save_restore(&cpu_mask_ctx, 0, RESTORE);

src/opencl_autotune.h

@@ -234,7 +234,7 @@ static void autotune_run_extra(struct fmt_main *self, unsigned int rounds,
 		uint32_t lws, gws, mpi_lws, mpi_gws;
 
 		if (john_main_process)
-			log_event("- Enforcing same work sizes on all MPI nodes");
+			log_event("OpenCL: Enforcing same work sizes on all MPI nodes");
 		lws = local_work_size;
 		gws = global_work_size;
 		MPI_Allreduce(&lws, &mpi_lws, 1, MPI_UNSIGNED, MPI_MIN, MPI_COMM_WORLD);
@@ -276,7 +276,7 @@ static void autotune_run_extra(struct fmt_main *self, unsigned int rounds,
 	create_clobj(global_work_size, self);
 
 	if (!self_test_running && (!homogenous || john_main_process))
-		log_event("- OpenCL LWS: "Zu"%s, GWS: "Zu" %s("Zu" blocks)",
+		log_event("OpenCL: LWS: "Zu"%s, GWS: "Zu" %s("Zu" blocks)",
 		          local_work_size,
 		          (need_best_lws && !needed_best_gws) ? " (auto-tuned)" : "",
 		          global_work_size,

src/opencl_common.c

@@ -423,7 +423,7 @@ static void load_opencl_environment()
 		num_platforms = 0;
 
 	if (num_platforms < 1 && options.verbosity > VERB_LEGACY)
-		fprintf(stderr, "%u: No OpenCL platforms were found: %s\n",
+		fprintf(stderr, "%u: OpenCL: No platforms were found: %s\n",
 		        NODE, get_error_name(ret));
 
 	for (i = 0; i < num_platforms; i++) {
@@ -439,7 +439,7 @@ static void load_opencl_environment()
 
 		if (num_devices < 1 && options.verbosity > VERB_LEGACY)
 			fprintf(stderr,
-			        "%u: No OpenCL devices were found on platform #%d: %s\n",
+			        "%u: OpenCL: No devices were found on platform #%d: %s\n",
 			        NODE, i, get_error_name(ret));
 
 		// Save platform and devices information
@@ -562,7 +562,7 @@ static int start_opencl_device(int sequential_id, int *err_type)
 			&devices[sequential_id], NULL, NULL, &ret_code);
 
 		if (ret_code != CL_SUCCESS) {
-			fprintf(stderr, "%u: Error creating context for device %d "
+			fprintf(stderr, "%u: Error creating OpenCL context for device %d "
 			        "(%d:%d): %s\n",
 			        NODE, sequential_id + 1,
 			        get_platform_id(sequential_id),
@@ -575,7 +575,7 @@ static int start_opencl_device(int sequential_id, int *err_type)
 		                       devices[sequential_id], 0, &ret_code);
 
 		if (ret_code != CL_SUCCESS) {
-			fprintf(stderr, "%u: Error creating command queue for "
+			fprintf(stderr, "%u: Error creating OpenCL command queue for "
 			        "device %d (%d:%d): %s\n", NODE,
 			        sequential_id + 1, get_platform_id(sequential_id),
 			        get_device_id(sequential_id), get_error_name(ret_code));
@@ -620,7 +620,7 @@ static void add_device_to_list(int sequential_id)
 			if (options.fork)
 				fprintf(stderr, "%u: ", options.node_min);
 #endif
-			fprintf(stderr, "Device id %d not working correctly,"
+			fprintf(stderr, "OpenCL device id %d not working correctly,"
 			        " skipping.\n", sequential_id + 1);
 			return;
 		}
@@ -1123,7 +1123,7 @@ static void print_device_info(int sequential_id)
 		        "", "",
 #endif
 		        device_name, board_name);
-	log_event("Device %d: %s%s", sequential_id + 1, device_name, board_name);
+	log_event("OpenCL: Device %d: %s%s", sequential_id + 1, device_name, board_name);
 }
 
 static char *get_build_opts(int sequential_id, const char *opts)
@@ -1267,7 +1267,7 @@ void opencl_build(int sequential_id, const char *opts, int save, const char *fil
 	               "clGetProgramBuildInfo II");
 
 	uint64_t end = john_get_nano();
-	log_event("- build time: %ss", ns2string(end - start));
+	log_event("OpenCL: Kernel build time: %ss", ns2string(end - start));
 
 	char *cleaned_log = build_log;
 	if (cfg_get_bool(SECTION_OPTIONS, SUBSECTION_OPENCL, "MuteBogusWarnings", 1) &&
@@ -1380,9 +1380,9 @@ cl_int opencl_build_from_binary(int sequential_id, cl_program *program, const ch
 	}
 	// Nvidia may return a single '\n' that we ignore
 	else if (options.verbosity >= LOG_VERB && strlen(build_log) > 1)
-		fprintf(stderr, "Binary Build log: %s\n", build_log);
+		fprintf(stderr, "Binary build log: %s\n", build_log);
 
-	log_event("- build time: %ss", ns2string(end - start));
+	log_event("OpenCL: Kernel build time: %ss", ns2string(end - start));
 	if (options.verbosity >= VERB_MAX)
 		fprintf(stderr, "Build time: %ss\n", ns2string(end - start));
 	MEM_FREE(build_log);
@@ -2185,7 +2185,7 @@ size_t opencl_read_source(const char *kernel_filename, char **kernel_source)
 	read_size = fread(*kernel_source, sizeof(char), source_size, fp);
 	if (read_size != source_size)
 		fprintf(stderr,
-		        "Error reading source: expected "Zu", got "Zu" bytes (%s).\n",
+		        "OpenCL error reading kernel source: expected "Zu", got "Zu" bytes (%s).\n",
 		        source_size, read_size,
 		        feof(fp) ? "EOF" : strerror(errno));
 	fclose(fp);
@@ -2285,38 +2285,38 @@ void opencl_build_kernel(const char *kernel_filename, int sequential_id, const c
 	 */
 	if (gpu_nvidia(device_info[sequential_id]) && !platform_apple(get_platform_id(sequential_id))) {
 		if (john_main_process || !cfg_get_bool(SECTION_OPTIONS, SUBSECTION_MPI, "MPIAllGPUsSame", 0))
-			log_event("- Kernel binary caching disabled for this platform/device");
+			LOG_ONCE("OpenCL: Kernel binary caching disabled for this platform/device");
 		use_cache = 0;
 	} else
 #endif
 	if (getenv("DUMP_BINARY")) {
-		log_event("- DUMP_BINARY is set, ignoring cached kernel");
+		LOG_ONCE("OpenCL: DUMP_BINARY is set, ignoring cached kernel");
 		use_cache = 0;
 	} else {
 		use_cache = !stat(path_expand(bin_name), &bin_stat);
 
 		if (use_cache && !stat(path_expand(kernel_filename), &source_stat) &&
 		    source_stat.st_mtime > bin_stat.st_mtime) {
 			use_cache = 0;
-			log_event("- cached kernel may be stale, ignoring");
+			log_event("OpenCL: Cached kernel may be stale, ignoring");
 		}
 	}
 
 	// Select the kernel to run.
 	if (use_cache) {
 		size_t program_size = opencl_read_source(bin_name, &kernel_source);
 
-		log_event("- Building kernel from cached binary");
+		log_event("OpenCL: Building kernel from cached binary");
 		ret_code = opencl_build_from_binary(sequential_id, &program[sequential_id], kernel_source, program_size);
 		if (ret_code != CL_SUCCESS)
-			log_event("- Build from cached binary failed");
+			log_event("OpenCL: Build from cached binary failed");
 	}
 
 	if (!use_cache || ret_code != CL_SUCCESS) {
-		log_event("- Building kernel from source and caching binary");
+		log_event("OpenCL: Building kernel from source and caching binary");
 		if (warn && options.verbosity > VERB_DEFAULT) {
 			fflush(stdout);
-			fprintf(stderr, "Building the kernel, this could take a while\n");
+			fprintf(stderr, "Building the OpenCL kernel, this could take a while\n");
 		}
 		opencl_read_source(kernel_filename, &kernel_source);
 		opencl_build(sequential_id, opts, 1, bin_name, &program[sequential_id], kernel_filename, kernel_source);
@@ -2374,14 +2374,9 @@ int opencl_prepare_dev(int sequential_id)
 	if (gpu_nvidia(device_info[sequential_id])) {
 		opencl_avoid_busy_wait[sequential_id] = cfg_get_bool(SECTION_OPTIONS, SUBSECTION_GPU,
 		                                                     "AvoidBusyWait", 1);
-		static int warned;
-
 		/* Remove next line once (nearly) all formats has got the macros */
 		if (!opencl_avoid_busy_wait[sequential_id])
-		if (!warned) {
-			warned = 1;
-			log_event("- Busy-wait reduction %sabled", opencl_avoid_busy_wait[sequential_id] ? "en" : "dis");
-		}
+			LOG_ONCE("OpenCL: Busy-wait reduction %sabled", opencl_avoid_busy_wait[sequential_id] ? "en" : "dis");
 	}
 #endif
 
@@ -2900,8 +2895,7 @@ void opencl_list_devices(void)
 	ret = clGetPlatformIDs(MAX_PLATFORMS, platform_list, &num_platforms);
 
 	if (!num_platforms)
-		fprintf(stderr, "Error: No OpenCL-capable platforms were detected"
-		        " by the installed OpenCL driver.\n");
+		fprintf(stderr, "Error: No platforms were detected by the installed OpenCL driver.\n");
 
 	if (ret != CL_SUCCESS && options.verbosity > VERB_LEGACY)
 		fprintf(stderr, "Throw clError: clGetPlatformIDs() = %s\n",
@@ -2940,8 +2934,7 @@ void opencl_list_devices(void)
 					printf("    Platform extensions:    %s\n", dname);
 			}
 		}
-		fprintf(stderr, "Error: No OpenCL-capable devices were detected"
-		        " by the installed OpenCL driver.\n\n");
+		fprintf(stderr, "Error: No devices were detected by the installed OpenCL driver.\n\n");
 		return;
 	}
 	/* Initialize OpenCL environment */

src/rpp.c

@@ -134,10 +134,7 @@ static void rpp_process_rule(struct rpp_context *ctx)
 			if (strlen(conv) == strlen8(input))
 				strcpy(ctx->input->data, conv); /* Always shorter than original */
 			else {
-				static int warned;
-
-				if (!warned++)
-					log_event("- Rule preprocessor: Rejected rule(s) not fitting current internal codepage");
+				LOG_ONCE("- Rule preprocessor: Rejected rule(s) not fitting current internal codepage");
 				input[1] = '-';
 			}
 		}