Merge pull request #1326 from joto/logging

Improved logging output with timestamps, level settings and more

Author: lonvia

docs/osm2pgsql.1

@@ -56,6 +56,23 @@ Add \f[B]\-v, \-\-verbose\f[] to display more verbose help.
 Print osm2pgsql version.
 .RS
 .RE
+.SH LOGGING OPTIONS
+.TP
+.B \-\-log\-level=LEVEL
+Set log level (`debug', `info' (default), `warn', or `error').
+.RS
+.RE
+.TP
+.B \-\-log\-sql
+Enable logging of SQL commands for debugging.
+.RS
+.RE
+.TP
+.B \-\-log\-sql\-data
+Enable logging of all data added to the database.
+This will write out a huge amount of data! For debugging.
+.RS
+.RE
 .SH DATABASE OPTIONS
 .TP
 .B \-d, \-\-database=NAME

docs/osm2pgsql.md

@@ -47,6 +47,26 @@ Mandatory arguments to long options are mandatory for short options too.
 -V, \--version
 :   Print osm2pgsql version.
 
+# LOGGING OPTIONS
+
+\--log-level=LEVEL
+:   Set log level ('debug', 'info' (default), 'warn', or 'error').
+
+\--log-progress=VALUE
+:   Enable (`true`) or disable (`false`) progress logging. The default is
+    `auto` which will enable progress logging on the console and disable it
+    if the output is redirected to a file.
+
+\--log-sql
+:   Enable logging of SQL commands for debugging.
+
+\--log-sql-data
+:   Enable logging of all data added to the database. This will write out
+    a huge amount of data! For debugging.
+
+-v, \--verbose
+:   Same as `--log-level=debug`.
+
 # DATABASE OPTIONS
 
 -d, \--database=NAME

src/CMakeLists.txt

@@ -9,6 +9,7 @@ set(osm2pgsql_lib_SOURCES
   geometry-processor.cpp
   id-tracker.cpp
   input-handler.cpp
+  logging.cpp
   middle-pgsql.cpp
   middle-ram.cpp
   node-persistent-cache.cpp

src/db-check.cpp

@@ -1,5 +1,5 @@
 #include "db-check.hpp"
-#include "format.hpp"
+#include "logging.hpp"
 #include "pgsql.hpp"
 #include "version.hpp"
 
@@ -28,7 +28,7 @@ void check_db(options_t const &options)
     auto const settings = get_postgresql_settings(db_connection);
 
     try {
-        fmt::print("Database version: {}\n", settings.at("server_version"));
+        log_info("Database version: {}", settings.at("server_version"));
 
         auto const version_str = settings.at("server_version_num");
         auto const version = std::strtoul(version_str.c_str(), nullptr, 10);

src/db-copy.cpp

@@ -2,6 +2,7 @@
 
 #include "db-copy.hpp"
 #include "format.hpp"
+#include "logging.hpp"
 #include "pgsql.hpp"
 
 void db_deleter_by_id_t::delete_rows(std::string const &table,
@@ -151,7 +152,7 @@ void db_copy_thread_t::thread_t::operator()()
 
         m_conn.reset();
     } catch (std::runtime_error const &e) {
-        fmt::print(stderr, "DB copy thread failed: {}\n", e.what());
+        log_error("DB copy thread failed: {}", e.what());
         exit(2);
     }
 }

src/expire-tiles.cpp

@@ -16,6 +16,7 @@
 
 #include "expire-tiles.hpp"
 #include "format.hpp"
+#include "logging.hpp"
 #include "options.hpp"
 #include "reprojection.hpp"
 #include "table.hpp"
@@ -31,10 +32,9 @@ tile_output_t::tile_output_t(char const *filename)
 : outfile(fopen(filename, "a"))
 {
     if (outfile == nullptr) {
-        fmt::print(stderr,
-                   "Failed to open expired tiles file ({}).  Tile expiry "
-                   "list will not be written!\n",
-                   std::strerror(errno));
+        log_error("Failed to open expired tiles file ({}).  Tile expiry "
+                  "list will not be written!",
+                  std::strerror(errno));
     }
 }
 
@@ -52,10 +52,6 @@ void tile_output_t::output_dirty_tile(uint32_t x, uint32_t y, uint32_t zoom)
     }
 
     fmt::print(outfile, "{}/{}/{}\n", zoom, x, y);
-    ++outcount;
-    if (outcount % 1000 == 0) {
-        fmt::print(stderr, "\rWriting dirty tile list ({}K)", outcount / 1000);
-    }
 }
 
 void expire_tiles::output_and_destroy(char const *filename, uint32_t minzoom)
@@ -297,8 +293,7 @@ void expire_tiles::from_wkb(char const *wkb, osmid_t osm_id)
         break;
     }
     default:
-        fmt::print(stderr, "OSM id {}: Unknown geometry type, cannot expire.\n",
-                   osm_id);
+        log_warn("OSM id {}: Unknown geometry type, cannot expire.", osm_id);
     }
 }
 
@@ -359,10 +354,9 @@ void expire_tiles::from_wkb_polygon(ewkb::parser_t *wkb, osmid_t osm_id)
 
     if (from_bbox(min.x, min.y, max.x, max.y)) {
         /* Bounding box too big - just expire tiles on the line */
-        fmt::print(stderr,
-                   "\rLarge polygon ({:.0f} x {:.0f} metres, OSM ID {}"
-                   ") - only expiring perimeter\n",
-                   max.x - min.x, max.y - min.y, osm_id);
+        log_info("Large polygon ({:.0f} x {:.0f} metres, OSM ID {})"
+                 " - only expiring perimeter",
+                 max.x - min.x, max.y - min.y, osm_id);
         wkb->rewind(start);
         for (unsigned ring = 0; ring < num_rings; ++ring) {
             from_wkb_line(wkb);

src/expire-tiles.hpp

@@ -4,6 +4,7 @@
 #include <memory>
 #include <unordered_set>
 
+#include "logging.hpp"
 #include "osmtypes.hpp"
 #include "pgsql.hpp"
 
@@ -30,7 +31,6 @@ struct xy_coord_t
 class tile_output_t
 {
     FILE *outfile;
-    uint32_t outcount = 0;
 
 public:
     tile_output_t(char const *filename);
@@ -93,6 +93,7 @@ struct expire_tiles
          * last_quadkey is initialized with a value which is not expected to exist
          * (larger than largest possible quadkey). */
         uint64_t last_quadkey = 1ULL << (2 * maxzoom);
+        std::size_t count = 0;
         for (std::vector<uint64_t>::const_iterator it = tiles_maxzoom.cbegin();
              it != tiles_maxzoom.cend(); ++it) {
             for (uint32_t dz = 0; dz <= maxzoom - minzoom; ++dz) {
@@ -107,9 +108,11 @@ struct expire_tiles
                 }
                 xy_coord_t xy = quadkey_to_xy(qt_current, maxzoom - dz);
                 output_writer.output_dirty_tile(xy.x, xy.y, maxzoom - dz);
+                ++count;
             }
             last_quadkey = *it;
         }
+        log_info("Wrote {} entries to expired tiles list", count);
     }
 
     /**

src/flex-table.cpp

@@ -1,5 +1,6 @@
 #include "flex-table.hpp"
 #include "format.hpp"
+#include "logging.hpp"
 #include "pgsql-helper.hpp"
 #include "util.hpp"
 
@@ -174,8 +175,8 @@ void table_connection_t::start(bool append)
 
         for (auto const &column : table()) {
             if (res.get_column_number(column.name()) < 0) {
-                fmt::print(stderr, "Adding new column '{}' to '{}'\n",
-                           column.name(), table().name());
+                log_info("Adding new column '{}' to '{}'", column.name(),
+                         table().name());
                 m_db_connection->exec(
                     "ALTER TABLE {} ADD COLUMN \"{}\" {}"_format(
                         table().full_name(), column.name(),
@@ -204,8 +205,7 @@ void table_connection_t::stop(bool updateable, bool append)
     util::timer_t timer;
 
     if (table().has_geom_column()) {
-        fmt::print(stderr, "Clustering table '{}' by geometry...\n",
-                   table().name());
+        log_info("Clustering table '{}' by geometry...", table().name());
 
         // Notices about invalid geometries are expected and can be ignored
         // because they say nothing about the validity of the geometry in OSM.
@@ -229,7 +229,7 @@ void table_connection_t::stop(bool updateable, bool append)
 
         sql += " ORDER BY ";
         if (postgis_version.major == 2 && postgis_version.minor < 4) {
-            fmt::print(stderr, "Using GeoHash for clustering\n");
+            log_info("Using GeoHash for clustering");
             if (table().geom_column().srid() == 4326) {
                 sql += "ST_GeoHash({},10)"_format(table().geom_column().name());
             } else {
@@ -239,7 +239,7 @@ void table_connection_t::stop(bool updateable, bool append)
             }
             sql += " COLLATE \"C\"";
         } else {
-            fmt::print(stderr, "Using native order for clustering\n");
+            log_info("Using native order for clustering");
             // Since Postgis 2.4 the order function for geometries gives
             // useful results.
             sql += table().geom_column().name();
@@ -252,8 +252,7 @@ void table_connection_t::stop(bool updateable, bool append)
             table().full_tmp_name(), table().name()));
         m_id_index_created = false;
 
-        fmt::print(stderr, "Creating geometry index on table '{}'...\n",
-                   table().name());
+        log_info("Creating geometry index on table '{}'...", table().name());
 
         // Use fillfactor 100 for un-updateable imports
         m_db_connection->exec(
@@ -273,11 +272,11 @@ void table_connection_t::stop(bool updateable, bool append)
         }
     }
 
-    fmt::print(stderr, "Analyzing table '{}'...\n", table().name());
+    log_info("Analyzing table '{}'...", table().name());
     m_db_connection->exec("ANALYZE " + table().full_name());
 
-    fmt::print(stderr, "All postprocessing on table '{}' done in {}.\n",
-               table().name(), util::human_readable_duration(timer.stop()));
+    log_info("All postprocessing on table '{}' done in {}.", table().name(),
+             util::human_readable_duration(timer.stop()));
 
     teardown();
 }
@@ -293,11 +292,9 @@ void table_connection_t::prepare()
 void table_connection_t::create_id_index()
 {
     if (m_id_index_created) {
-        fmt::print(stderr, "Id index on table '{}' already created.\n",
-                   table().name());
+        log_info("Id index on table '{}' already created.", table().name());
     } else {
-        fmt::print(stderr, "Creating id index on table '{}'...\n",
-                   table().name());
+        log_info("Creating id index on table '{}'...", table().name());
         m_db_connection->exec(table().build_sql_create_id_index());
         m_id_index_created = true;
     }

src/gazetteer-style.cpp

@@ -8,6 +8,7 @@
 #include "domain-matcher.hpp"
 #include "format.hpp"
 #include "gazetteer-style.hpp"
+#include "logging.hpp"
 #include "pgsql.hpp"
 #include "wkb.hpp"
 
@@ -81,7 +82,7 @@ std::string gazetteer_style_t::class_list() const
 
 void gazetteer_style_t::load_style(std::string const &filename)
 {
-    fmt::print(stderr, "Parsing gazetteer style file '{}'.\n", filename);
+    log_info("Parsing gazetteer style file '{}'.", filename);
     pt::ptree root;
 
     pt::read_json(filename, root);

src/geom-transform.cpp

@@ -1,5 +1,6 @@
 
 #include "geom-transform.hpp"
+#include "logging.hpp"
 
 #include <osmium/osm.hpp>
 
@@ -160,10 +161,9 @@ void init_geom_transform(geom_transform_t *transform, lua_State *lua_state)
 
         if (std::strcmp(field, "create") != 0) {
             if (!transform->set_param(field, lua_state) && show_warning) {
-                fmt::print(stderr,
-                           "\nWarning! Ignoring unknown field '{}' in geometry "
-                           "transformation description.\n",
-                           field);
+                log_warn("Ignoring unknown field '{}' in geometry "
+                         "transformation description.",
+                         field);
                 show_warning = false;
             }
         }