Add option --logtimestamps=<when>

README.md

@@ -24,7 +24,7 @@ The program runs on GNU/Linux, MacOSX, FreeBSD, and Raspberry Pi.
 ```
 Availability of **wmbusmeters** for other Linux distributions can be checked on [release-monitoring](https://release-monitoring.org/project/88654/) project page.
 
-# Run as a daemon
+1# Run as a daemon
 
 Remove the wmbus dongle (im871a,amb8465,cul,rc1180) or the generic rtlsdr dongle (RTL2832U) from your computer.
 
@@ -162,6 +162,7 @@ Usage: wmbusmeters {options} <device> ( [meter_name] [meter_driver]{:<modes>} [m
 As <options> you can use:
 
     --addconversions=<unit>+ add conversion to these units to json and meter env variables (GJ)
+    --addtimestamps add a timestamp to each logged line
     --alarmexpectedactivity=mon-fri(08-17),sat-sun(09-12) Specify when the timeout is tested, default is mon-sun(00-23)
     --alarmshell=<cmdline> invokes cmdline when an alarm triggers
     --alarmtimeout=<time> Expect a telegram to arrive within <time> seconds, eg 60s, 60m, 24h during expected activity.

src/bus.cc

@@ -123,7 +123,7 @@ void BusManager::openBusDeviceAndPotentiallySetLinkmodes(Configuration *config,
     // A newly plugged in device has been manually configured or automatically detected! Start using it!
     if (config->use_auto_device_detect || detected->found_type != DEVICE_SIMULATION)
     {
-        notice("%s", started.c_str());
+        notice_timestamp("%s", started.c_str());
     }
     else
     {
@@ -259,7 +259,7 @@ void BusManager::checkForDeadWmbusDevices(Configuration *config)
             string id = w->getDeviceId();
             if (id != "") id = "["+id+"]";
 
-            notice("Lost %s closing %s%s\n",
+            notice_timestamp("Lost %s closing %s%s\n",
                    w->device().c_str(),
                    toLowerCaseString(w->type()),
                    id.c_str());

src/cmdline.cc

@@ -113,6 +113,30 @@ shared_ptr<Configuration> parseCommandLine(int argc, char **argv) {
             i++;
             continue;
         }
+        if (!strncmp(argv[i], "--logtimestamps=", 16))
+        {
+            string ts = string(argv[i]+16);
+            debug("(cmdline) add log timestamps \"%s\"\n", ts.c_str());
+            if (ts == "never")
+            {
+                c->addtimestamps = AddLogTimestamps::Never;
+            }
+            else if (ts == "always")
+            {
+                c->addtimestamps = AddLogTimestamps::Always;
+            }
+            else if (ts == "important")
+            {
+                c->addtimestamps = AddLogTimestamps::Important;
+            }
+            else
+            {
+                error("No such timestamp setting \"%s\" possible values are: never always important\n",
+                      ts.c_str());
+            }
+            i++;
+            continue;
+        }
         if (!strcmp(argv[i], "--internaltesting")) {
             c->internaltesting = true;
             i++;

src/config.cc

@@ -528,6 +528,27 @@ void handleConversions(Configuration *c, string s)
     }
 }
 
+void handleLogTimestamps(Configuration *c, string ts)
+{
+    if (ts == "never")
+    {
+        c->addtimestamps = AddLogTimestamps::Never;
+    }
+    else if (ts == "always")
+    {
+        c->addtimestamps = AddLogTimestamps::Always;
+    }
+    else if (ts == "important")
+    {
+        c->addtimestamps = AddLogTimestamps::Important;
+    }
+    else
+    {
+        warning("(warning) No such timestamp setting \"%s\" possible values are: never always important\n",
+                ts.c_str());
+    }
+}
+
 void handleSelectedFields(Configuration *c, string s)
 {
     char buf[s.length()+1];
@@ -597,6 +618,7 @@ shared_ptr<Configuration> loadConfiguration(string root, string device_override,
         else if (p.first == "alarmexpectedactivity") handleAlarmExpectedActivity(c, p.second);
         else if (p.first == "separator") handleSeparator(c, p.second);
         else if (p.first == "addconversions") handleConversions(c, p.second);
+        else if (p.first == "logtimestamps") handleLogTimestamps(c, p.second);
         else if (p.first == "selectfields") handleSelectedFields(c, p.second);
         else if (p.first == "shell") handleShell(c, p.second);
         else if (p.first == "resetafter") handleResetAfter(c, p.second);

src/config.h

@@ -61,6 +61,7 @@ struct Configuration
     bool license {};
     bool debug {};
     bool trace {};
+    AddLogTimestamps addtimestamps {};
     bool internaltesting {}; // Only for testing! When true, shorten all timeouts.
     bool logtelegrams {};
     bool meterfiles {};

src/main.cc

@@ -289,7 +289,7 @@ void regular_checkup(Configuration *config)
             string prss = humanReadableTwoDecimals(peak_rss);
 
             // Log memory usage once per day.
-            notice("(memory) rss %zu peak %s\n", curr_rss, prss.c_str());
+            notice_timestamp("(memory) rss %zu peak %s\n", curr_rss, prss.c_str());
         }
     }
 
@@ -363,6 +363,7 @@ bool start(Configuration *config)
     verboseEnabled(config->verbose);
     logTelegramsEnabled(config->logtelegrams);
     debugEnabled(config->debug);
+    setLogTimestamps(config->addtimestamps);
     internalTestingEnabled(config->internaltesting);
     traceEnabled(config->trace);
     stderrEnabled(config->use_stderr_for_log);

src/util.cc

@@ -287,6 +287,7 @@ bool logging_silenced_ = false;
 bool verbose_enabled_ = false;
 bool debug_enabled_ = false;
 bool trace_enabled_ = false;
+AddLogTimestamps log_timestamps_ {};
 bool stderr_enabled_ = false;
 bool log_telegrams_enabled_ = false;
 bool internal_testing_enabled_ = false;
@@ -351,6 +352,10 @@ void traceEnabled(bool b) {
     }
 }
 
+void setLogTimestamps(AddLogTimestamps ts) {
+    log_timestamps_ = ts;
+}
+
 void stderrEnabled(bool b) {
     stderr_enabled_ = b;
 }
@@ -384,39 +389,57 @@ bool isLogTelegramsEnabled() {
     return log_telegrams_enabled_;
 }
 
-void outputStuff(int syslog_level, const char *fmt, va_list args)
+void output_stuff(int syslog_level, bool use_timestamp, const char *fmt, va_list args)
 {
+    string timestamp;
+    bool add_timestamp = false;
+
+    if (log_timestamps_ == AddLogTimestamps::Always ||
+        (log_timestamps_ == AddLogTimestamps::Important && use_timestamp))
+    {
+        timestamp = currentSeconds();
+        add_timestamp = true;
+    }
     if (logfile_enabled_)
     {
         // Open close at every log occasion, should not be too big of
         // a performance issue, since normal reception speed of
         // wmbusmessages are quite low.
         FILE *output = fopen(log_file_.c_str(), "a");
-        if (output) {
+        if (output)
+        {
+            if (add_timestamp) fprintf(output, "[%s] ", timestamp.c_str());
             vfprintf(output, fmt, args);
             fclose(output);
-        } else {
+        }
+        else
+        {
             // Ouch, disable the log file.
             // Reverting to syslog or stdout depending on settings.
             logfile_enabled_ = false;
             // This warning might be written in syslog or stdout.
             warning("Log file could not be written!\n");
             // Try again with logfile disabled.
-            outputStuff(syslog_level, fmt, args);
+            output_stuff(syslog_level, use_timestamp, fmt, args);
             return;
         }
-    } else
-    if (syslog_enabled_) {
+    }
+    else
+    if (syslog_enabled_)
+    {
+        // Do not print timestamps in the syslog since it already adds timestamps.
         vsyslog(syslog_level, fmt, args);
     }
     else
     {
         if (stderr_enabled_)
         {
+            if (add_timestamp) fprintf(stderr, "[%s] ", timestamp.c_str());
             vfprintf(stderr, fmt, args);
         }
         else
         {
+            if (add_timestamp) printf("[%s] ", timestamp.c_str());
             vprintf(fmt, args);
         }
     }
@@ -426,7 +449,7 @@ void info(const char* fmt, ...) {
     if (!logging_silenced_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_INFO, fmt, args);
+        output_stuff(LOG_INFO, false, fmt, args);
         va_end(args);
     }
 }
@@ -435,7 +458,16 @@ void notice(const char* fmt, ...) {
     if (!logging_silenced_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_NOTICE, fmt, args);
+        output_stuff(LOG_NOTICE, false, fmt, args);
+        va_end(args);
+    }
+}
+
+void notice_timestamp(const char* fmt, ...) {
+    if (!logging_silenced_) {
+        va_list args;
+        va_start(args, fmt);
+        output_stuff(LOG_NOTICE, true, fmt, args);
         va_end(args);
     }
 }
@@ -444,7 +476,7 @@ void warning(const char* fmt, ...) {
     if (!logging_silenced_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_WARNING, fmt, args);
+        output_stuff(LOG_WARNING, true, fmt, args);
         va_end(args);
     }
 }
@@ -453,7 +485,7 @@ void verbose(const char* fmt, ...) {
     if (verbose_enabled_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_NOTICE, fmt, args);
+        output_stuff(LOG_NOTICE, false, fmt, args);
         va_end(args);
     }
 }
@@ -462,7 +494,7 @@ void debug(const char* fmt, ...) {
     if (debug_enabled_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_NOTICE, fmt, args);
+        output_stuff(LOG_NOTICE, false, fmt, args);
         va_end(args);
     }
 }
@@ -471,7 +503,7 @@ void trace(const char* fmt, ...) {
     if (trace_enabled_) {
         va_list args;
         va_start(args, fmt);
-        outputStuff(LOG_NOTICE, fmt, args);
+        output_stuff(LOG_NOTICE, false, fmt, args);
         va_end(args);
     }
 }
@@ -480,7 +512,7 @@ void error(const char* fmt, ...)
 {
     va_list args;
     va_start(args, fmt);
-    outputStuff(LOG_NOTICE, fmt, args);
+    output_stuff(LOG_NOTICE, true, fmt, args);
     va_end(args);
     exitHandler(0);
     exit(1);
@@ -1433,6 +1465,18 @@ string currentMinute()
     return string(datetime);
 }
 
+string currentSeconds()
+{
+    char datetime[40];
+    memset(datetime, 0, sizeof(datetime));
+
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+
+    strftime(datetime, 20, "%Y-%m-%d_%H:%M:%S", localtime(&tv.tv_sec));
+    return string(datetime);
+}
+
 string currentMicros()
 {
     char datetime[40];

src/util.h

@@ -73,11 +73,19 @@ void debug(const char* fmt, ...);
 void warning(const char* fmt, ...);
 void info(const char* fmt, ...);
 void notice(const char* fmt, ...);
+void notice_timestamp(const char* fmt, ...);
 
 void silentLogging(bool b);
 void verboseEnabled(bool b);
 void debugEnabled(bool b);
 void traceEnabled(bool b);
+
+enum class AddLogTimestamps
+{
+    Never, Always, Important
+};
+
+void setLogTimestamps(AddLogTimestamps ts);
 void stderrEnabled(bool b);
 void logTelegramsEnabled(bool b);
 void internalTestingEnabled(bool b);
@@ -178,6 +186,7 @@ std::string currentYear();
 std::string currentDay();
 std::string currentHour();
 std::string currentMinute();
+std::string currentSeconds();
 std::string currentMicros();
 
 #define CHECK(n) if (!hasBytes(n, pos, frame)) return expectedMore(__LINE__);

src/wmbus.cc

@@ -3610,6 +3610,8 @@ bool WMBusCommonImplementation::reset()
             resetting = true;
             serial()->resetInitiated();
             serial()->close();
+            notice_timestamp("(wmbus) resetting %s\n", device().c_str(), toString(type()));
+
             // Give the device 3 seconds to shut down properly.
             usleep(3000*1000);
         }

wmbusmeters.1

@@ -45,6 +45,8 @@ mqtt_publish) sent to a REST API (eg curl) or store it in a database
 
 \fB\--listento=\fR<mode>,<mode> listen to more than one link mode at the same time, assuming the dongle supports it.
 
+\fB\--logtimestamps=\fR<when> add timestamps to log entries: never always important.
+
 \fB\--c1 --t1 --s1 --s1m --n1a ... --n1f\fR listen to c1,t1,s1,s1m,n1a-n1f telegrams.
 
 \fB\--listenvs=\fR<meter_type> list the env variables available for the given meter type