From: Pavel Tvrdík <pawel.tvrdik@gmail.com>
Date: Mon, 9 Nov 2015 07:40:11 +0000 (+0100)
Subject: RPKI: Improve log messages
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d00f9cf766a432d30e0a08fddfb4e4efdd5e4173;p=thirdparty%2Fbird.git

RPKI: Improve log messages
---

diff --git a/proto/rpki/rpki.c b/proto/rpki/rpki.c
index 7fa46d789..94fc1b174 100644
--- a/proto/rpki/rpki.c
+++ b/proto/rpki/rpki.c
@@ -40,7 +40,7 @@ get_rtr_socket_ident(const struct rtr_socket *socket)
 {
   return socket->tr_socket->ident_fp(socket->tr_socket->socket);
 }
-#define RPKI_CACHE_TRACE(p, rtr_socket, msg, args...) RPKI_TRACE(p, "%s " msg, get_rtr_socket_ident(rtr_socket), ## args);
+#define RPKI_CACHE_TRACE(level, p, rtr_socket, msg, args...) RPKI_TRACE(level, p, "%s " msg, get_rtr_socket_ident(rtr_socket), ## args);
 #define RPKI_CACHE_ERROR(p, rtr_socket, msg, args...) RPKI_ERROR(p, "%s " msg, get_rtr_socket_ident(rtr_socket), ## args);
 
 struct rpki_entry {
@@ -241,32 +241,38 @@ status_update_rtrlib_thread_hook(const struct rtr_mgr_group *group, enum rtr_mgr
     case RTR_SHUTDOWN:
       if (mgr_status == RTR_MGR_CLOSED)
       {
-	RPKI_CACHE_TRACE(p, socket, "%s", mgr_str_status_descript[mgr_status]);
+	RPKI_CACHE_TRACE(D_EVENTS, p, socket, "The group of cache servers is closed");
+      }
+      else
+      {
+	RPKI_CACHE_TRACE(D_EVENTS, p, socket, "[%s] %s", rtr_state_to_str_x(socket->state), mgr_str_status_descript[mgr_status]);
       }
       break;
     case RTR_ERROR_FATAL:
     case RTR_ERROR_TRANSPORT:
     case RTR_ERROR_NO_DATA_AVAIL: /** No validation records are available on the RTR server. */
     case RTR_ERROR_NO_INCR_UPDATE_AVAIL: /** Server was unable to answer the last serial or reset query. */
-      RPKI_CACHE_ERROR(p, socket, "%s", rtr_socket_states_descript[socket->state]);
+      RPKI_CACHE_TRACE(D_EVENTS, p, socket, "[%s] %s", rtr_state_to_str_x(socket->state), rtr_socket_states_descript[socket->state]);
       break;
     case RTR_FAST_RECONNECT:
     case RTR_SYNC:
     case RTR_RESET:
     case RTR_CONNECTING:
-      RPKI_CACHE_TRACE(p, socket, "[%s] %s", rtr_state_to_str_x(socket->state), rtr_socket_states_descript[socket->state]);
+      RPKI_CACHE_TRACE(D_EVENTS, p, socket, "[%s] %s", rtr_state_to_str_x(socket->state), rtr_socket_states_descript[socket->state]);
       if (mgr_status == RTR_MGR_CONNECTING || mgr_status == RTR_MGR_ERROR)
       {
 	pipe_kick_data(p->status_update.write->fd, &((int){PS_START}), sizeof(int));
       }
       break;
     case RTR_ESTABLISHED:
-      RPKI_CACHE_TRACE(p, socket, "%s", mgr_str_status_descript[mgr_status]);
+      RPKI_CACHE_TRACE(D_EVENTS, p, socket, "[%s] %s", rtr_state_to_str_x(socket->state), mgr_str_status_descript[mgr_status]);
       if (mgr_status == RTR_MGR_ESTABLISHED)
       {
 	pipe_kick_data(p->status_update.write->fd, &((int){PS_UP}), sizeof(int));
       }
       break;
+    default:
+      bug("Uncaught socket->state: %d", socket->state);
   }
 }
 
@@ -290,11 +296,11 @@ log_skipped_entry(struct rpki_proto *p, const struct pfx_record *rec, const bool
 
   if (added)
   {
-    RPKI_CACHE_TRACE(p, rec->socket, RPKI_LOG_SKIP_FMT(RPKI_LOG_ADD), ip_buf, rec->min_len, rec->max_len, rec->asn);
+    RPKI_CACHE_TRACE(D_ROUTES, p, rec->socket, RPKI_LOG_SKIP_FMT(RPKI_LOG_ADD), ip_buf, rec->min_len, rec->max_len, rec->asn);
   }
   else
   {
-    RPKI_CACHE_TRACE(p, rec->socket, RPKI_LOG_SKIP_FMT(RPKI_LOG_DEL), ip_buf, rec->min_len, rec->max_len, rec->asn);
+    RPKI_CACHE_TRACE(D_ROUTES, p, rec->socket, RPKI_LOG_SKIP_FMT(RPKI_LOG_DEL), ip_buf, rec->min_len, rec->max_len, rec->asn);
   }
 }
 
@@ -308,6 +314,7 @@ get_rpki_proto_by_rtr_socket(const struct rtr_socket *socket)
   unsigned int i, j;
 
   lock_rpki_proto_list();
+  /* TODO: Add lock for config->mutex -- It is impossible... */
   WALK_LIST(p_not_skipped_back, rpki_proto_list)
   {
     struct rpki_proto *p = SKIP_BACK(struct rpki_proto, rpki_node, p_not_skipped_back);
@@ -393,7 +400,7 @@ rpki_init(struct proto_config *C)
   struct rpki_proto *p = (struct rpki_proto *) P;
   p->cf = (struct rpki_config *) C;
 
-  RPKI_TRACE(p, "------------- rpki_init -------------");
+  RPKI_TRACE(D_EVENTS, p, "------------- rpki_init -------------");
 
   return P;
 }
@@ -424,7 +431,7 @@ status_update_bird_thread_hook(struct birdsock *sk, int size)
       case PS_UP:
 	if (proto_state != p->p.proto_state)
 	{
-	  RPKI_TRACE(p, "Change protokol state %s -> %s", p_states[p->p.proto_state], p_states[proto_state]);
+	  RPKI_TRACE(D_EVENTS, p, "Change protokol state %s -> %s", p_states[p->p.proto_state], p_states[proto_state]);
 	  proto_notify_state(&p->p, proto_state);
 	}
 	break;
diff --git a/proto/rpki/rpki.h b/proto/rpki/rpki.h
index b517070b8..20e859a90 100644
--- a/proto/rpki/rpki.h
+++ b/proto/rpki/rpki.h
@@ -26,14 +26,14 @@
 
 #define RPKI_DEFAULT_CACHE_PREFERENCE 		0xff /* the least preference */
 
-#define RPKI_LOG(log_level, p, msg, args...) 				\
+#define RPKI_LOG(log_level, rpki, msg, args...) 				\
   do { 									\
-    log(log_level "%s: " msg, p->p.name , ## args); 			\
+    log(log_level "%s: " msg, (rpki)->p.name , ## args); 			\
   } while(0)
-#define RPKI_TRACE(p, msg, args...) 					\
+#define RPKI_TRACE(level,rpki,msg,args...) 					\
   do {									\
-    if (p->p.debug)							\
-      RPKI_LOG(L_TRACE, p, msg, ## args);				\
+    if ((rpki)->p.debug & level)							\
+      RPKI_LOG(L_TRACE, rpki, msg, ## args);				\
   } while(0)
 #define RPKI_WARN(p, msg, args...) RPKI_LOG(L_WARN, p, msg, ## args);
 #define RPKI_ERROR(p, msg, args...) RPKI_LOG(L_ERR, p, msg, ## args);