Replace previous hacky impl. of appending postfix to ostream with a safer one…

Replace previous hacky impl. of appending postfix to ostream with a safer one and lose the -log_as_json support for glog

src/brpc/controller.cpp

@@ -1507,7 +1507,7 @@ KVMap& Controller::SessionKV() {
     return *_session_kv.get();
 }
 
-#define BRPC_SESSION_END_MSG "Session ends"
+#define BRPC_SESSION_END_MSG "Session ends."
 #define BRPC_REQ_ID "@rid"
 #define BRPC_KV_SEP ":"
 
@@ -1522,62 +1522,43 @@ void Controller::FlushSessionKV(std::ostream& os) {
     }
 
     if (FLAGS_log_as_json) {
-        os << "\"M\":\"" BRPC_SESSION_END_MSG "\"";
         if (pRID) {
-            os << ",\"" BRPC_REQ_ID "\":\"" << *pRID << '"';
+            os << "\"" BRPC_REQ_ID "\":\"" << *pRID << "\",";
         }
+        os << "\"M\":\"" BRPC_SESSION_END_MSG "\"";
         for (auto it = _session_kv->Begin(); it != _session_kv->End(); ++it) {
             os << ",\"" << it->first << "\":\"" << it->second << '"';
         }
     } else {
-        os << BRPC_SESSION_END_MSG;
         if (pRID) {
-            os << " " BRPC_REQ_ID BRPC_KV_SEP << *pRID;
+            os << BRPC_REQ_ID BRPC_KV_SEP << *pRID << " ";
         }
+        os << BRPC_SESSION_END_MSG;
         for (auto it = _session_kv->Begin(); it != _session_kv->End(); ++it) {
             os << ' ' << it->first << BRPC_KV_SEP << it->second;
         }
     }
 }
 
-Controller::LogPostfixDummy::~LogPostfixDummy() {
-    if (osptr != nullptr) {
-        *osptr << postfix;
-    }
-}
-
-std::ostream& operator<<(std::ostream& os, const Controller::LogPostfixDummy& p) {
-    const_cast<brpc::Controller::LogPostfixDummy&>(p).osptr = &os;
-    if (FLAGS_log_as_json) {
-        os << "\"M\":\"";
-    }
+std::ostream& operator<<(std::ostream& os, const Controller::LogPrefixDummy& p) {
+    p.DoPrintLogPrefix(os);
     return os;
 }
-
-
-Controller::LogPostfixDummy Controller::LogPostfix() const {
-    Controller::LogPostfixDummy result;
-    std::string& p = result.postfix;
-    if (FLAGS_log_as_json) {
-        p.push_back('"');
-    }
+void Controller::DoPrintLogPrefix(std::ostream& os) const {
     const std::string* pRID = nullptr;
     if (_http_request) {
         pRID = _http_request->GetHeader(FLAGS_request_id_header);
         if (pRID) {
             if (FLAGS_log_as_json) {
-                p.append(",\"" BRPC_REQ_ID "\":\"");
-                p.append(*pRID);
-                p.push_back('"');
+                os << BRPC_REQ_ID "\":\"" << *pRID << "\",";
             } else {
-                p.reserve(5 + pRID->size());
-                p.append(" " BRPC_REQ_ID BRPC_KV_SEP);
-                p.append(*pRID);
+                os << BRPC_REQ_ID BRPC_KV_SEP << *pRID << " ";
             }
-
         }
     }
-    return result;
+    if (FLAGS_log_as_json) {
+        os << "\"M\":\"";
+    }
 }
 
 } // namespace brpc

src/brpc/controller.h

@@ -491,13 +491,15 @@ public:
     void FlushSessionKV(std::ostream& os);
 
     // Contextual prefixes for LOGD/LOGI/LOGW/LOGE/LOGF macros
-    struct LogPostfixDummy {
-        LogPostfixDummy() : osptr(nullptr) {}
-        ~LogPostfixDummy();
-        std::string postfix;
-        std::ostream* osptr;
+    class LogPrefixDummy {
+    public:
+        LogPrefixDummy(const Controller* cntl) : _cntl(cntl) {}
+        void DoPrintLogPrefix(std::ostream& os) const { _cntl->DoPrintLogPrefix(os); }
+    private:
+        const Controller* _cntl;
     };
-    LogPostfixDummy LogPostfix() const;
+    friend class LogPrefixDummy;
+    LogPrefixDummy LogPrefix() const { return LogPrefixDummy(this); }
 
     // Return true if the remote side creates a stream.
     bool has_remote_stream() { return _remote_stream_settings != NULL; }
@@ -677,6 +679,8 @@ private:
     std::string& protocol_param() { return _thrift_method_name; }
     const std::string& protocol_param() const { return _thrift_method_name; }
 
+    void DoPrintLogPrefix(std::ostream& os) const;
+
 private:
     // NOTE: align and group fields to make Controller as compact as possible.
 
@@ -806,16 +810,16 @@ bool IsAskedToQuit();
 // Send Ctrl-C to current process.
 void AskToQuit();
 
-std::ostream& operator<<(std::ostream& os, const Controller::LogPostfixDummy& p);
+std::ostream& operator<<(std::ostream& os, const Controller::LogPrefixDummy& p);
 
 } // namespace brpc
 
 // Print logs appended with @rid which is got from "x-request-id"(set 
 // -request_id_header to change) in http header by default
-#define LOGD(cntl) LOG(DEBUG) << (cntl)->LogPostfix()
-#define LOGI(cntl) LOG(INFO) << (cntl)->LogPostfix()
-#define LOGW(cntl) LOG(WARNING) << (cntl)->LogPostfix()
-#define LOGE(cntl) LOG(ERROR) << (cntl)->LogPostfix()
-#define LOGF(cntl) LOG(FATAL) << (cntl)->LogPostfix()
+#define LOGD(cntl) LOG(DEBUG) << (cntl)->LogPrefix()
+#define LOGI(cntl) LOG(INFO) << (cntl)->LogPrefix()
+#define LOGW(cntl) LOG(WARNING) << (cntl)->LogPrefix()
+#define LOGE(cntl) LOG(ERROR) << (cntl)->LogPrefix()
+#define LOGF(cntl) LOG(FATAL) << (cntl)->LogPrefix()
 
 #endif  // BRPC_CONTROLLER_H

src/butil/logging.cc

@@ -565,6 +565,33 @@ static void PrintLogPrefixAsJSON(
     os << "\"C\":\"" << file << ':' << line << "\"";
 }
 
+static void PrintLog(std::ostream& os,
+                     int severity, const char* file, int line,
+                     const butil::StringPiece& content) {
+    if (!FLAGS_log_as_json) {
+        PrintLogPrefix(os, severity, file, line);
+        os.write(content.data(), content.size());
+    } else {
+        os << '{';
+        PrintLogPrefixAsJSON(os, severity, file, line);
+        bool pair_quote = false;
+        if (content.empty() || content[0] != '"') {
+            // not a json, add a 'M' field
+            os << ",\"M\":\"";
+            pair_quote = true;
+        } else {
+            os << ',';
+        }
+        os.write(content.data(), content.size());
+        if (pair_quote) {
+            os << '"';
+        } else if (!content.empty() && content[content.size()-1] != '"') {
+            // Controller may write `"M":"...` which misses the last quote
+            os << '"';
+        }
+        os << '}';
+    }
+}
 
 // A log message handler that gets notified of every log message we process.
 class DoublyBufferedLogSink : public butil::DoublyBufferedData<LogSink*> {
@@ -669,33 +696,12 @@ void DisplayDebugMessageInDialog(const std::string& str) {
 
 bool StringSink::OnLogMessage(int severity, const char* file, int line, 
                               const butil::StringPiece& content) {
-    std::ostringstream prefix_os;
-    bool pair_quote = false;
-    if (FLAGS_log_as_json) {
-        prefix_os << '{';
-        PrintLogPrefixAsJSON(prefix_os, severity, file, line);
-        if (content.empty() || content[0] != '"') {
-            // not a json, add 'M' field
-            prefix_os << ",\"M\":\"";
-            pair_quote = true;
-        } else {
-            prefix_os << ',';
-        }
-    } else {
-        PrintLogPrefix(prefix_os, severity, file, line);
-    }
-    const std::string prefix = prefix_os.str();
+    std::ostringstream os;
+    PrintLog(os, severity, file, line, content);
+    const std::string msg = os.str();
     {
         butil::AutoLock lock_guard(_lock);
-        reserve(size() + prefix.size() + content.size());
-        append(prefix);
-        append(content.data(), content.size());
-        if (FLAGS_log_as_json) {
-            if (pair_quote) {
-                push_back('"');
-            }
-            push_back('}');
-        }
+        append(msg);
     }
     return true;
 }
@@ -849,27 +855,8 @@ public:
         // A LogSink focused on performance should also be able to handle
         // non-continuous inputs which is a must to maximize performance.
         std::ostringstream os;
-        if (!FLAGS_log_as_json) {
-            PrintLogPrefix(os, severity, file, line);
-            os.write(content.data(), content.size());
-            os << '\n';
-        } else {
-            os << '{';
-            PrintLogPrefixAsJSON(os, severity, file, line);
-            bool pair_quote = false;
-            if (content.empty() || content[0] != '"') {
-                // not a json, add a 'M' field
-                os << ",\"M\":\"";
-                pair_quote = true;
-            } else {
-                os << ',';
-            }
-            os.write(content.data(), content.size());
-            if (pair_quote) {
-                os << '"';
-            }
-            os << "}\n";
-        }
+        PrintLog(os, severity, file, line, content);
+        os << '\n';
         std::string log = os.str();
         
         if ((logging_destination & LOG_TO_SYSTEM_DEBUG_LOG) != 0) {

test/brpc_controller_unittest.cpp

@@ -95,13 +95,27 @@ TEST_F(ControllerTest, SessionKV) {
     FLAGS_log_as_json = false;
     logging::StringSink sink1;
     auto oldSink = logging::SetLogSink(&sink1);
-    //brpc::SetGlobalSessionLogFormatter(new MyFormatter);
     {
         brpc::Controller cntl;
         cntl.set_log_id(123); // not working now
-        cntl.SessionKV().Set("Apple", 1);    
-        cntl.SessionKV().Set("Baidu", "22");
-        cntl.SessionKV().Set("Cisco", 33.3);
+        // set
+        cntl.SessionKV().Set("Apple", 1234567);    
+        cntl.SessionKV().Set("Baidu", "Building");
+        // get
+        auto v1 = cntl.SessionKV().Get("Apple");
+        ASSERT_TRUE(v1);
+        ASSERT_EQ("1234567", *v1);
+        auto v2 = cntl.SessionKV().Get("Baidu");
+        ASSERT_TRUE(v2);
+        ASSERT_EQ("Building", *v2);
+
+        // override
+        cntl.SessionKV().Set("Baidu", "NewStuff");
+        v2 = cntl.SessionKV().Get("Baidu");
+        ASSERT_TRUE(v2);
+        ASSERT_EQ("NewStuff", *v2);
+
+        cntl.SessionKV().Set("Cisco", 33.33);
 
         LOGW(&cntl) << "My WARNING Log";
         ASSERT_TRUE(endsWith(sink1, "] My WARNING Log")) << sink1;
@@ -110,13 +124,13 @@ TEST_F(ControllerTest, SessionKV) {
 
         cntl.http_request().SetHeader("x-request-id", "abcdEFG-456");
         LOGE(&cntl) << "My ERROR Log";
-        ASSERT_TRUE(endsWith(sink1, "] My ERROR Log @rid:abcdEFG-456")) << sink1;
+        ASSERT_TRUE(endsWith(sink1, "] @rid:abcdEFG-456 My ERROR Log")) << sink1;
         ASSERT_TRUE(startsWith(sink1, "E")) << sink1;
         sink1.clear();
 
         FLAGS_log_as_json = true;
     }
-    ASSERT_TRUE(endsWith(sink1, R"(,"M":"Session ends","@rid":"abcdEFG-456","Baidu":"22","Cisco":"33.300000","Apple":"1"})")) << sink1;
+    ASSERT_TRUE(endsWith(sink1, R"(,"@rid":"abcdEFG-456","M":"Session ends.","Baidu":"NewStuff","Cisco":"33.330000","Apple":"1234567"})")) << sink1;
     ASSERT_TRUE(startsWith(sink1, R"({"L":"I",)")) << sink1;
 
     logging::SetLogSink(oldSink);