Improved logging output with timestamps, level settings and more

This improves the logging output in several ways:

* New logging functions log_debug/info/warn/error(). Almost all
  output now uses one of these functions.
* Log messages start with timestamp.
* Log messages of level warn/error are printed in red when
  logging to console.
* New command line option: --log-level to set log level. Default
  is "info". The option -v, --verbose does the same as
  --log-level=debug.
* New option --log-progress=true/false/auto. The default is `auto`
  which enables progress logging on the console and disables it
  when stderr has been redirected to a file.
* Extra functions to log SQL commands/SQL COPY data. These can
  be activated by command line options --log-sql and --log-sql-data,
  respectively, instead of the compile time setting. Output is
  printed in blue when logging to console.

Most log messages are in level "info" at the moment, so they are shown
as before with the default settings. Many of these probably don't need
to be shown in normal operation and can be downgraded to "debug". I'll
leave this for a later commit.

There are several places in the code where the output is updated on the
screen while some longer process is running:

* The code displaying regular updates of a counter in the expire code
  has been removed. Writing out the expire data doesn't take that long,
  so it isn't important to have this. Instead a log message is now
  generated.
* The output of the objects being processed and the pending ways and
  relations output is now en/disabled by the `--log-progress` option.
  Otherwise it has not been touched. I'll leave cleaning that up
  for a later time.

Some error reporting code has also been changed. Usually errors should
be reported by throwing an exception that is then caught in the main()
function and written out. The exception should contain the whole
error message, sometimes additional logging lines are created before
throwing the error. There is probably some more cleanup needed here.

This introduces a new global object "the_logger". Otherwise we'd have to
add the logger as parameter to a lot of functions!

Fixes #202
Fixes #1246
Fixes #591

Author: joto

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;
             }
         }