Improved --verbose messaging for render_expired (openstreetmap#461)

Author: hummeltech

src/render_expired.c

@@ -380,14 +380,14 @@ int main(int argc, char **argv)
 			}
 
 			if (verbose) {
-				g_logger(G_LOG_LEVEL_WARNING, "bad line %d: %s", num_all, tmp);
+				g_logger(G_LOG_LEVEL_WARNING, "Read invalid line: %s", tmp);
 			}
 
 			continue;
 		}
 
 		if (verbose) {
-			g_logger(G_LOG_LEVEL_MESSAGE, "read: x=%d y=%d z=%d", x, y, z);
+			g_logger(G_LOG_LEVEL_MESSAGE, "Read valid line: %d/%d/%d", z, x, y);
 		}
 
 		while (z > max_zoom) {
@@ -402,35 +402,35 @@ int main(int argc, char **argv)
 			z++;
 		}
 
-		if (verbose) {
-			g_logger(G_LOG_LEVEL_MESSAGE, "loop: x=%d y=%d z=%d up to z=%d", x, y, z, min_zoom);
-		}
-
 		num_read++;
 
 		if (progress && (num_read % 100) == 0) {
 			g_logger(G_LOG_LEVEL_INFO, "Read and expanded %i tiles from list.", num_read);
 		}
 
+		if (verbose) {
+			g_logger(G_LOG_LEVEL_MESSAGE, "Starting loop on %d/%d/%d for zoom levels %d to %d", z, x, y, min_zoom, max_zoom);
+		}
+
 		for (; z >= min_zoom; z--, x >>= 1, y >>= 1) {
 			char name[PATH_MAX];
 
-			if (verbose) {
-				g_logger(G_LOG_LEVEL_MESSAGE, "process: x=%d y=%d z=%d", x, y, z);
-			}
-
 			// don't do anything if this tile was already requested.
 			// renderd does keep a list internally to avoid enqueing the same tile
 			// twice but in case it has already rendered the tile we don't want to
 			// cause extra work.
 			if (TILE_REQUESTED(z - excess_zoomlevels, x >> excess_zoomlevels, y >> excess_zoomlevels)) {
 				if (verbose) {
-					g_logger(G_LOG_LEVEL_MESSAGE, "already requested");
+					g_logger(G_LOG_LEVEL_MESSAGE, "Already requested metatile containing '%d/%d/%d', moving on to next input line", z, x, y);
 				}
 
 				break;
 			}
 
+			if (verbose) {
+				g_logger(G_LOG_LEVEL_MESSAGE, "Processing: %d/%d/%d", z, x, y);
+			}
+
 			// mark tile as requested. (do this even if, below, the tile is not
 			// actually requested due to not being present on disk, to avoid
 			// unnecessary later stat'ing).
@@ -442,34 +442,35 @@ int main(int argc, char **argv)
 
 			num_all++;
 			s = store->tile_stat(store, mapname, "", x, y, z);
+			store->tile_storage_id(store, mapname, "", x, y, z, name);
 
 			if (s.size > 0) { // Tile exists
 				// tile exists on disk; delete/touch/render it
 				if (delete_from_passed && z >= delete_from) {
 					if (progress) {
-						g_logger(G_LOG_LEVEL_MESSAGE, "delete: %s", store->tile_storage_id(store, mapname, "", x, y, z, name));
+						g_logger(G_LOG_LEVEL_MESSAGE, "Deleting '%s'", name);
 					}
 
 					store->metatile_delete(store, mapname, x, y, z);
 					num_unlink++;
 				} else if (touch_from_passed && z >= touch_from) {
 					if (progress) {
-						g_logger(G_LOG_LEVEL_MESSAGE, "touch: %s", store->tile_storage_id(store, mapname, "", x, y, z, name));
+						g_logger(G_LOG_LEVEL_MESSAGE, "Touching '%s'", name);
 					}
 
 					store->metatile_expire(store, mapname, x, y, z);
 					num_touch++;
 				} else if (doRender) {
 					if (progress) {
-						g_logger(G_LOG_LEVEL_MESSAGE, "render: %s", store->tile_storage_id(store, mapname, "", x, y, z, name));
+						g_logger(G_LOG_LEVEL_MESSAGE, "Rendering '%s'", name);
 					}
 
 					enqueue(mapname, x, y, z);
 					num_render++;
 				}
 			} else {
 				if (verbose) {
-					g_logger(G_LOG_LEVEL_MESSAGE, "not on disk: %s", store->tile_storage_id(store, mapname, "", x, y, z, name));
+					g_logger(G_LOG_LEVEL_MESSAGE, "Skipping '%s' (metatile does not exist)", name);
 				}
 
 				num_ignore++;

tests/render_expired_test.cpp

@@ -103,15 +103,32 @@ TEST_CASE("render_expired specific", "specific testing")
 	}
 
 	SECTION("--config with valid --map, --verbose and bad input lines", "should return 0") {
+		std::string input = "z/x/y\nx y z\n";
 		std::string map = "example-map";
 		std::string tile_dir = P_tmpdir;
 		std::vector<std::string> argv = {"--config", renderd_conf, "--map", map, "--tile-dir", tile_dir, "--verbose"};
-		std::string input = "z/x/y\nx y z\n";
 
 		int status = run_command(test_binary, argv, input);
 		REQUIRE(WEXITSTATUS(status) == 0);
-		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("bad line 0: z/x/y"));
-		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("bad line 0: x y z"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read invalid line: z/x/y"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read invalid line: x y z"));
+	}
+
+	SECTION("--touch-from 0 with --max-zoom 19, --verbose and overlapping input lines", "should return 0") {
+		std::string input = "16/56715/4908\n17/113420/9816\n18/226860/19632\n19/453726/39265\n";
+		std::string tile_dir = P_tmpdir;
+		std::vector<std::string> argv = {"--max-zoom", std::to_string(19), "--tile-dir", tile_dir, "--touch-from", std::to_string(0), "--verbose"};
+
+		int status = run_command(test_binary, argv, input);
+		REQUIRE(WEXITSTATUS(status) == 0);
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Raising --min-zoom from '0' to '3'"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read valid line: 16/56715/4908"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read valid line: 17/113420/9816"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Already requested metatile containing '15/28355/2454'"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read valid line: 18/226860/19632"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Already requested metatile containing '19/453720/39264'"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Read valid line: 19/453726/39265"));
+		REQUIRE_THAT(err_log_lines, Catch::Matchers::Contains("Already requested metatile containing '19/453726/39265'"));
 	}
 
 	SECTION("--tile-dir with invalid option", "should return 1") {