improve logging

- connection failed message puts requeued in parens
- connection success message, idle connection closed by us message,
   idle connection closed by peer message, are all info not notice
- flush timeout autodefer message is info not warn if we have no
   conns as this is normal with lack of conns and lack of conns
   already reported
- new notice messages summarising number of conns
- normal processed batch thing says "batch" not "feedfile"
- innduct-stats-report: count messages of priority info too.

diff --git a/conn.c b/conn.c
index c99174c59317482768167b6f520e2e278471af6d..e38adb5f2bb0baae2b18a6574765138e337709ae 100644 (file)
--- a/conn.c
+++ b/conn.c
@@ -101,7 +101,8 @@ void vconnfail(Conn *conn, const char *fmt, va_list al) {
   LIST_REMOVE(conns,conn);
 
   char *m= xvasprintf(fmt,al);
-  warn("C%d (now %d) connection failed requeueing " RCI_TRIPLE_FMT_BASE ": %s",
+  warn("C%d (now %d) connection failed "
+       "(requeueing " RCI_TRIPLE_FMT_BASE "): %s",
        conn->fd, conns.count, RCI_TRIPLE_VALS_BASE(requeue, /*nothing*/), m);
   free(m);
 
@@ -188,6 +189,30 @@ void check_idle_conns(void) {
     conn_idle_close(conn, "low volume");
 }  
 
+/*---------- reporting numbers of connections ----------*/
+
+static int conns_max_reported, conns_idle_reported;
+
+void notice_conns_more(const char *new_kind) {
+  if (conns.count > conns_max_reported) {
+    notice("up to %d connections (%s)", conns.count, new_kind);
+    conns_max_reported= conns.count;
+  }
+}
+
+void notice_conns_fewer(void) {
+  if (!conns.count && !conns_idle_reported) {
+    notice("low volume, using intermittent connection");
+    conns_idle_reported= 1;
+  }
+}
+
+void notice_conns_stats(void) {
+  notice("currently %d connection(s)", conns.count);
+  conns_max_reported= conns.count;
+  conns_idle_reported= 0;
+}
+
 /*---------- making new connections ----------*/
 
 pid_t connecting_child;
@@ -308,8 +333,9 @@ static void *connchild_event(oop_source *lp, int fd, oop_event e, void *u) {
   if (r) syscrash("oop_rd_read for peer (fd=%d)",conn->fd);
 
   LIST_ADDHEAD(conns, conn);
-  notice("C%d (now %d) connected %s",
-        conn->fd, conns.count, conn->stream ? "streaming" : "plain");
+  const char *streamdesc= conn->stream ? "streaming" : "plain";
+  info("C%d (now %d) connected %s", conn->fd, conns.count, streamdesc);
+  notice_conns_more(streamdesc);
 
   connect_attempt_discard();
   check_assign_articles();

diff --git a/innduct-stats-report b/innduct-stats-report
index 62007edd97a67248bc79a65d3f36209fa7e75fb6..e6a7dcba081e93bf630a4bed3141979c1ec798ed 100755 (executable)
--- a/innduct-stats-report
+++ b/innduct-stats-report
@@ -20,7 +20,7 @@ while (<>) {
            \w+[ ]
            innduct\[\d+\]:[ ]
            ([^|<>: \t]+)\|[ ]
-           info:[ ]
+           (?: info | notice ):[ ]
            (?: completed | processed )[ ]
            .*?
            ( (?: [ ]

diff --git a/innduct.h b/innduct.h
index fc04d8a6688d93ba10c65d352e5ccc57f54077ff..00be640f73a33aca2e15ab2202cee214d6dab8df 100644 (file)
--- a/innduct.h
+++ b/innduct.h
@@ -391,6 +391,10 @@ void conn_dispose(Conn *conn);
 void vconnfail(Conn *conn, const char *fmt, va_list al) PRINTF(2,0);
 void connfail(Conn *conn, const char *fmt, ...)         PRINTF(2,3);
 
+void notice_conns_more(const char *new_kind);
+void notice_conns_fewer(void);
+void notice_conns_stats(void);
+
 int allow_connect_start(void);
 void connect_start(void);
 

diff --git a/recv.c b/recv.c
index 115a7831ab00c4ea7e5a5a2a8d95742264cf8b67..00ec7bc22adb4644846466e04d413bc8d0b4f785 100644 (file)
--- a/recv.c
+++ b/recv.c
@@ -185,8 +185,9 @@ void *peer_rd_ok(oop_source *lp, oop_read *oread, oop_rd_event ev,
               conn->quitting, sani);
     } else {
       LIST_REMOVE(conns,conn);
-      notice("C%d (now %d) idle connection closed (%s)",
+      info("C%d (now %d) idle connection closed (%s)",
             conn->fd, conns.count, conn->quitting);
+      notice_conns_fewer();
       assert(!busy);
       conn_dispose(conn);
     }
@@ -223,8 +224,9 @@ void *peer_rd_ok(oop_source *lp, oop_read *oread, oop_rd_event ev,
       PEERBADMSG("peer timed us out or stopped accepting articles");
 
     LIST_REMOVE(conns,conn);
-    notice("C%d (now %d) idle connection closed by peer",
-          conns.count, conn->fd);
+    info("C%d (now %d) idle connection closed by peer",
+        conns.count, conn->fd);
+    notice_conns_fewer();
     conn_dispose(conn);
     return OOP_CONTINUE;
 

diff --git a/statemc.c b/statemc.c
index 58aaefd6413fec8a5ee4a2ddd6109d01ef51c300..8d3e728c89a88d4258e36865f2967fe64351d1b1 100644 (file)
--- a/statemc.c
+++ b/statemc.c
@@ -190,8 +190,12 @@ int trigger_flush_ok(const char *why) {
 
   case sm_SEPARATED:
   case sm_DROPPING:
-    warn("abandoning old feedfile after flush (%s), autodeferring",
-        why ? why : "took too long to complete");
+    if (conns.count)
+      warn("abandoning old feedfile after flush (%s), autodeferring",
+          why ? why : "took too long to complete");
+    else
+      info("autodeferring after flush (%s)",
+          why ? why : "no connections");
     assert(flushing_input_file);
     autodefer_input_file(flushing_input_file);
     return 1;
@@ -234,7 +238,7 @@ static void notice_processed_counts(Counts *counts, int completed,
     ? xasprintf(" autodeferred=%ld", ipf_xtra->autodefer)
     : xasprintf("%s","");
 
-  info("%s %s read=%d (+bl=%d,+err=%d)%s%s"
+  notice("%s %s read=%d (+bl=%d,+err=%d)%s%s"
        " missing=%d offered=%d (ch=%d,nc=%d) accepted=%d (ch=%d,nc=%d)"
        RESULT_COUNTS(RCI_NOTHING, RCI_TRIPLE_FMT)
        ,
@@ -303,7 +307,7 @@ void statemc_check_flushing_done(void) {
 
   assert(sms==sm_SEPARATED || sms==sm_DROPPING);
 
-  notice_processed_inputfile(ipf,1,"feedfile");
+  notice_processed_inputfile(ipf,1,"batch");
 
   close_defer();
 
@@ -500,6 +504,7 @@ void preterminate(void) {
 }
 
 void showstats(void) {
+  notice_conns_stats();
   notice_processed_inputfile(main_input_file,     0, "feedfile");
   notice_processed_inputfile(flushing_input_file, 0, "flushing");