Merge pull request ceph#15395 from liewegas/wip-log-entity

common/LogEntry: include EntityName in log entries

Reviewed-by: Kefu Chai <[email protected]>

qa/workunits/cephtool/test.sh

@@ -1928,11 +1928,11 @@ function test_mon_tell()
 
   ceph_watch_start debug
   ceph tell mon.a version
-  ceph_watch_wait 'mon.0 \[DBG\] from.*cmd=\[{"prefix": "version"}\]: dispatch'
+  ceph_watch_wait 'mon.a \[DBG\] from.*cmd=\[{"prefix": "version"}\]: dispatch'
 
   ceph_watch_start debug
   ceph tell mon.b version
-  ceph_watch_wait 'mon.1 \[DBG\] from.*cmd=\[{"prefix": "version"}\]: dispatch'
+  ceph_watch_wait 'mon.b \[DBG\] from.*cmd=\[{"prefix": "version"}\]: dispatch'
 }
 
 function test_mon_crushmap_validation()

src/common/LogClient.cc

@@ -223,6 +223,7 @@ void LogChannel::do_log(clog_type prio, const std::string& s)
   e.stamp = ceph_clock_now();
   // seq and who should be set for syslog/graylog/log_to_mon
   e.who = parent->get_myinst();
+  e.name = parent->get_myname();
   e.seq = parent->get_next_seq();
   e.prio = prio;
   e.msg = s;
@@ -342,6 +343,11 @@ const entity_inst_t& LogClient::get_myinst()
   return messenger->get_myinst();
 }
 
+const EntityName& LogClient::get_myname()
+{
+  return cct->_conf->name;
+}
+
 bool LogClient::handle_log_ack(MLogAck *m)
 {
   Mutex::Locker l(log_lock);

src/common/LogClient.h

@@ -231,6 +231,7 @@ class LogClient
 
   uint64_t get_next_seq();
   const entity_inst_t& get_myinst();
+  const EntityName& get_myname();
   version_t queue(LogEntry &entry);
 
 private:

src/common/LogEntry.cc

@@ -181,20 +181,21 @@ void LogEntry::log_to_syslog(string level, string facility)
 
 void LogEntry::encode(bufferlist& bl, uint64_t features) const
 {
-  ENCODE_START(3, 2, bl);
+  ENCODE_START(4, 2, bl);
   __u16 t = prio;
   ::encode(who, bl, features);
   ::encode(stamp, bl);
   ::encode(seq, bl);
   ::encode(t, bl);
   ::encode(msg, bl);
   ::encode(channel, bl);
+  ::encode(name, bl);
   ENCODE_FINISH(bl);
 }
 
 void LogEntry::decode(bufferlist::iterator& bl)
 {
-  DECODE_START_LEGACY_COMPAT_LEN(3, 2, 2, bl);
+  DECODE_START_LEGACY_COMPAT_LEN(4, 2, 2, bl);
   __u16 t;
   ::decode(who, bl);
   ::decode(stamp, bl);
@@ -210,12 +211,16 @@ void LogEntry::decode(bufferlist::iterator& bl)
     // clue of what a 'channel' is.
     channel = CLOG_CHANNEL_CLUSTER;
   }
+  if (struct_v >= 4) {
+    ::decode(name, bl);
+  }
   DECODE_FINISH(bl);
 }
 
 void LogEntry::dump(Formatter *f) const
 {
   f->dump_stream("who") << who;
+  f->dump_stream("name") << name;
   f->dump_stream("stamp") << stamp;
   f->dump_unsigned("seq", seq);
   f->dump_string("channel", channel);

src/common/LogEntry.h

@@ -17,6 +17,7 @@
 
 #include "include/utime.h"
 #include "msg/msg_types.h" // for entity_inst_t
+#include "common/entity_name.h"
 
 namespace ceph {
   class Formatter;
@@ -73,6 +74,7 @@ static inline bool operator==(const LogEntryKey& l, const LogEntryKey& r) {
 
 struct LogEntry {
   entity_inst_t who;
+  EntityName name;
   utime_t stamp;
   uint64_t seq;
   clog_type prio;
@@ -139,7 +141,8 @@ inline ostream& operator<<(ostream& out, const clog_type t)
 
 inline ostream& operator<<(ostream& out, const LogEntry& e)
 {
-  return out << e.stamp << " " << e.who << " " << e.seq << " : "
+  return out << e.stamp << " " << e.name << " " << e.who
+	     << " " << e.seq << " : "
              << e.channel << " " << e.prio << " " << e.msg;
 }
 

src/common/entity_name.cc

@@ -76,9 +76,13 @@ set(uint32_t type_, const std::string &id_)
   type = type_;
   id = id_;
 
-  std::ostringstream oss;
-  oss << ceph_entity_type_name(type_) << "." << id_;
-  type_id = oss.str();
+  if (type) {
+    std::ostringstream oss;
+    oss << ceph_entity_type_name(type_) << "." << id_;
+    type_id = oss.str();
+  } else {
+    type_id.clear();
+  }
 }
 
 int EntityName::

src/include/rados/librados.h

@@ -3653,8 +3653,40 @@ typedef void (*rados_log_callback_t)(void *arg,
 				     uint64_t seq, const char *level,
 				     const char *msg);
 
+/*
+ * This is not a doxygen comment leadin, because doxygen breaks on
+ * a typedef with function params and returns, and I can't figure out
+ * how to fix it.
+ *
+ * Monitor cluster log
+ *
+ * Monitor events logged to the cluster log.  The callback get each
+ * log entry both as a single formatted line and with each field in a
+ * separate arg.
+ *
+ * Calling with a cb argument of NULL will deregister any previously
+ * registered callback.
+ *
+ * @param cluster cluster handle
+ * @param level minimum log level (debug, info, warn|warning, err|error)
+ * @param cb callback to run for each log message. It MUST NOT block
+ * nor call back into librados.
+ * @param arg void argument to pass to cb
+ *
+ * @returns 0 on success, negative code on error
+ */
+typedef void (*rados_log_callback2_t)(void *arg,
+				     const char *line,
+				     const char *who,
+				     const char *name,
+				     uint64_t sec, uint64_t nsec,
+				     uint64_t seq, const char *level,
+				     const char *msg);
+
 CEPH_RADOS_API int rados_monitor_log(rados_t cluster, const char *level,
                                      rados_log_callback_t cb, void *arg);
+CEPH_RADOS_API int rados_monitor_log2(rados_t cluster, const char *level,
+				      rados_log_callback2_t cb, void *arg);
 
 /** @} Mon/OSD/PG commands */
 

src/librados/RadosClient.cc

@@ -77,7 +77,7 @@ librados::RadosClient::RadosClient(CephContext *cct_)
     lock("librados::RadosClient::lock"),
     timer(cct, lock),
     refcnt(1),
-    log_last_version(0), log_cb(NULL), log_cb_arg(NULL),
+    log_last_version(0), log_cb(NULL), log_cb2(NULL), log_cb_arg(NULL),
     finisher(cct, "radosclient", "fn-radosclient")
 {
 }
@@ -920,20 +920,25 @@ int librados::RadosClient::pg_command(pg_t pgid, vector<string>& cmd,
   return ret;
 }
 
-int librados::RadosClient::monitor_log(const string& level, rados_log_callback_t cb, void *arg)
+int librados::RadosClient::monitor_log(const string& level,
+				       rados_log_callback_t cb,
+				       rados_log_callback2_t cb2,
+				       void *arg)
 {
   Mutex::Locker l(lock);
 
   if (state != CONNECTED) {
     return -ENOTCONN;
   }
 
-  if (cb == NULL) {
+  if (cb == NULL && cb2 == NULL) {
     // stop watch
-    ldout(cct, 10) << __func__ << " removing cb " << (void*)log_cb << dendl;
+    ldout(cct, 10) << __func__ << " removing cb " << (void*)log_cb
+		   << " " << (void*)log_cb2 << dendl;
     monclient.sub_unwant(log_watch);
     log_watch.clear();
     log_cb = NULL;
+    log_cb2 = NULL;
     log_cb_arg = NULL;
     return 0;
   }
@@ -954,15 +959,17 @@ int librados::RadosClient::monitor_log(const string& level, rados_log_callback_t
     return -EINVAL;
   }
 
-  if (log_cb)
+  if (log_cb || log_cb2)
     monclient.sub_unwant(log_watch);
 
   // (re)start watch
-  ldout(cct, 10) << __func__ << " add cb " << (void*)cb << " level " << level << dendl;
+  ldout(cct, 10) << __func__ << " add cb " << (void*)cb << " " << (void*)cb2
+		 << " level " << level << dendl;
   monclient.sub_want(watch_level, 0, 0);
 
   monclient.renew_subs();
   log_cb = cb;
+  log_cb2 = cb2;
   log_cb_arg = arg;
   log_watch = watch_level;
   return 0;
@@ -976,21 +983,27 @@ void librados::RadosClient::handle_log(MLog *m)
   if (log_last_version < m->version) {
     log_last_version = m->version;
 
-    if (log_cb) {
+    if (log_cb || log_cb2) {
       for (std::deque<LogEntry>::iterator it = m->entries.begin(); it != m->entries.end(); ++it) {
         LogEntry e = *it;
         ostringstream ss;
-        ss << e.stamp << " " << e.who.name << " " << e.prio << " " << e.msg;
+        ss << e.stamp << " " << e.name << " " << e.prio << " " << e.msg;
         string line = ss.str();
         string who = stringify(e.who);
+	string name = stringify(e.name);
         string level = stringify(e.prio);
         struct timespec stamp;
         e.stamp.to_timespec(&stamp);
 
         ldout(cct, 20) << __func__ << " delivering " << ss.str() << dendl;
-        log_cb(log_cb_arg, line.c_str(), who.c_str(),
-               stamp.tv_sec, stamp.tv_nsec,
-               e.seq, level.c_str(), e.msg.c_str());
+	if (log_cb)
+	  log_cb(log_cb_arg, line.c_str(), who.c_str(),
+		 stamp.tv_sec, stamp.tv_nsec,
+		 e.seq, level.c_str(), e.msg.c_str());
+	if (log_cb2)
+	  log_cb2(log_cb_arg, line.c_str(), who.c_str(), name.c_str(),
+		  stamp.tv_sec, stamp.tv_nsec,
+		  e.seq, level.c_str(), e.msg.c_str());
       }
     }
 

src/librados/RadosClient.h

@@ -74,6 +74,7 @@ class librados::RadosClient : public Dispatcher
 
   version_t log_last_version;
   rados_log_callback_t log_cb;
+  rados_log_callback2_t log_cb2;
   void *log_cb_arg;
   string log_watch;
 
@@ -144,7 +145,8 @@ class librados::RadosClient : public Dispatcher
 	         bufferlist *poutbl, string *prs);
 
   void handle_log(MLog *m);
-  int monitor_log(const string& level, rados_log_callback_t cb, void *arg);
+  int monitor_log(const string& level, rados_log_callback_t cb,
+		  rados_log_callback2_t cb2, void *arg);
 
   void get();
   bool put();

src/librados/librados.cc

@@ -3375,11 +3375,21 @@ extern "C" int rados_monitor_log(rados_t cluster, const char *level, rados_log_c
 {
   tracepoint(librados, rados_monitor_log_enter, cluster, level, cb, arg);
   librados::RadosClient *client = (librados::RadosClient *)cluster;
-  int retval = client->monitor_log(level, cb, arg);
+  int retval = client->monitor_log(level, cb, nullptr, arg);
   tracepoint(librados, rados_monitor_log_exit, retval);
   return retval;
 }
 
+extern "C" int rados_monitor_log2(rados_t cluster, const char *level,
+				  rados_log_callback2_t cb, void *arg)
+{
+  tracepoint(librados, rados_monitor_log2_enter, cluster, level, cb, arg);
+  librados::RadosClient *client = (librados::RadosClient *)cluster;
+  int retval = client->monitor_log(level, nullptr, cb, arg);
+  tracepoint(librados, rados_monitor_log2_exit, retval);
+  return retval;
+}
+
 extern "C" int rados_ioctx_create(rados_t cluster, const char *name, rados_ioctx_t *io)
 {
   tracepoint(librados, rados_ioctx_create_enter, cluster, name);

src/mon/LogMonitor.cc

@@ -63,6 +63,7 @@ void LogMonitor::create_initial()
   dout(10) << "create_initial -- creating initial map" << dendl;
   LogEntry e;
   memset(&e.who, 0, sizeof(e.who));
+  e.name = g_conf->name;
   e.stamp = ceph_clock_now();
   e.prio = CLOG_INFO;
   std::stringstream ss;
@@ -414,6 +415,7 @@ bool LogMonitor::prepare_command(MonOpRequestRef op)
     cmd_getval(g_ceph_context, cmdmap, "logtext", logtext);
     LogEntry le;
     le.who = m->get_orig_source_inst();
+    le.name = session->entity_name;
     le.stamp = m->get_recv_stamp();
     le.seq = 0;
     le.prio = CLOG_INFO;

src/pybind/rados/rados.pxd

@@ -16,6 +16,7 @@ cdef class Rados(object):
         rados_t cluster
         public object state
         public object monitor_callback
+        public object monitor_callback2
         public object parsed_args
         public object conf_defaults
         public object conffile