From: Ian Jackson <ian@liberator.relativity.greenend.org.uk>
Date: Mon, 31 May 2010 16:46:03 +0000 (+0100)
Subject: improve logging
X-Git-Url: http://www.chiark.greenend.org.uk/ucgi/~ian/git?p=innduct.git;a=commitdiff_plain;h=854f19ae391120e6dd11c33c66250745b3d21aa7

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 c99174c..e38adb5 100644
--- 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 62007ed..e6a7dcb 100755
--- 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 fc04d8a..00be640 100644
--- 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 115a783..00ec7bc 100644
--- 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 58aaefd..8d3e728 100644
--- 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");