[core] New formatting implementation using SFMT for the logging system

apps/logsupport.cpp

@@ -173,7 +173,7 @@ set<srt_logging::LogFA> SrtParseLogFA(string fa, set<string>* punknown)
 
 void ParseLogFASpec(const vector<string>& speclist, string& w_on, string& w_off)
 {
-    std::ostringstream son, soff;
+    srt::obufstream son, soff;
 
     for (auto& s: speclist)
     {

apps/uriparser.cpp

@@ -64,7 +64,7 @@ string UriParser::makeUri()
         prefix = m_proto + "://";
     }
 
-    std::ostringstream out;
+    srt::obufstream out;
 
     out << prefix << m_host;
     if ((m_port == "" || m_port == "0") && m_expect == EXPECT_FILE)

srtcore/api.cpp

@@ -231,7 +231,7 @@ string srt::CUDTUnited::CONID(SRTSOCKET sock)
     if (sock == 0)
         return "";
 
-    std::ostringstream os;
+    srt::obufstream os;
     os << "@" << sock << ":";
     return os.str();
 }
@@ -1209,7 +1209,7 @@ int srt::CUDTUnited::connect(SRTSOCKET u, const sockaddr* srcname, const sockadd
     if (!srcname || !tarname || namelen < int(sizeof(sockaddr_in)))
     {
         LOGC(aclog.Error,
-             log << "connect(with source): invalid call: srcname=" << srcname << " tarname=" << tarname
+             log << "connect(with source): invalid call: srcname=" << (void*)srcname << " tarname=" << (void*)tarname
                  << " namelen=" << namelen);
         throw CUDTException(MJ_NOTSUP, MN_INVAL);
     }
@@ -1253,7 +1253,7 @@ int srt::CUDTUnited::connect(const SRTSOCKET u, const sockaddr* name, int namele
 {
     if (!name || namelen < int(sizeof(sockaddr_in)))
     {
-        LOGC(aclog.Error, log << "connect(): invalid call: name=" << name << " namelen=" << namelen);
+        LOGC(aclog.Error, log << "connect(): invalid call: name=" << (void*)name << " namelen=" << namelen);
         throw CUDTException(MJ_NOTSUP, MN_INVAL);
     }
 
@@ -3249,7 +3249,7 @@ bool srt::CUDTUnited::updateListenerMux(CUDTSocket* s, const CUDTSocket* ls)
             CMultiplexer& m = i->second;
 
 #if ENABLE_HEAVY_LOGGING
-            ostringstream that_muxer;
+            srt::obufstream that_muxer;
             that_muxer << "id=" << m.m_iID << " port=" << m.m_iPort
                        << " ip=" << (m.m_iIPversion == AF_INET ? "v4" : "v6");
 #endif

srtcore/channel.cpp

@@ -1044,8 +1044,7 @@ srt::EReadStatus srt::CChannel::recvfrom(sockaddr_any& w_addr, CPacket& w_packet
     if (msg_flags != 0)
     {
 #if ENABLE_HEAVY_LOGGING
-
-        std::ostringstream flg;
+        obufstream flg;
 
 #if !defined(_WIN32)
 
@@ -1073,7 +1072,7 @@ srt::EReadStatus srt::CChannel::recvfrom(sockaddr_any& w_addr, CPacket& w_packet
 #endif
 
         HLOGC(krlog.Debug,
-              log << CONID() << "NET ERROR: packet size=" << recv_size << " msg_flags=0x" << hex << msg_flags
+              log << CONID() << "NET ERROR: packet size=" << recv_size << " msg_flags=0x" << sfmt(msg_flags, sfmc().hex())
                   << ", detected flags:" << flg.str());
 #endif
         status = RST_AGAIN;

srtcore/common.cpp

@@ -277,15 +277,12 @@ void srt::CIPAddress::pton(sockaddr_any& w_addr, const uint32_t ip[4], const soc
     }
     else
     {
-        LOGC(inlog.Error, log << "pton: IPE or net error: can't determine IPv4 carryover format: " << std::hex
-                << peeraddr16[0] << ":"
-                << peeraddr16[1] << ":"
-                << peeraddr16[2] << ":"
-                << peeraddr16[3] << ":"
-                << peeraddr16[4] << ":"
-                << peeraddr16[5] << ":"
-                << peeraddr16[6] << ":"
-                << peeraddr16[7] << std::dec);
+        obufstream peeraddr_form;
+        peeraddr_form << sfmt(peeraddr16[0], "04x");
+        for (int i = 1; i < 8; ++i)
+            peeraddr_form << ":" << sfmt(peeraddr16[i], "04x");
+
+        LOGC(inlog.Error, log << "pton: IPE or net error: can't determine IPv4 carryover format: " << peeraddr_form);
         *target_ipv4_addr = 0;
         if (peer.family() != AF_INET)
         {

srtcore/common.h

@@ -1437,7 +1437,7 @@ inline bool checkMappedIPv4(const sockaddr_in6& sa)
 
 inline std::string FormatLossArray(const std::vector< std::pair<int32_t, int32_t> >& lra)
 {
-    std::ostringstream os;
+    obufstream os;
 
     os << "[ ";
     for (std::vector< std::pair<int32_t, int32_t> >::const_iterator i = lra.begin(); i != lra.end(); ++i)

srtcore/congctl.cpp

@@ -595,7 +595,7 @@ class FileCC : public SrtCongestionControlBase
             {
                 m_dPktSndPeriod = m_dCWndSize / (m_parent->SRTT() + m_iRCInterval);
                 HLOGC(cclog.Debug, log << "FileCC: CHKTIMER, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS wndsize/(RTT+RCIV) (wndsize="
-                    << setprecision(6) << m_dCWndSize << " RTT=" << m_parent->SRTT() << " RCIV=" << m_iRCInterval << ")");
+                    << sfmt(m_dCWndSize, ".6") << " RTT=" << m_parent->SRTT() << " RCIV=" << m_iRCInterval << ")");
             }
         }
         else

srtcore/core.cpp

@@ -92,6 +92,9 @@ using namespace srt_logging;
 const SRTSOCKET UDT::INVALID_SOCK = srt::CUDT::INVALID_SOCK;
 const int       UDT::ERROR        = srt::CUDT::ERROR;
 
+static inline char fmt_onoff(bool val) { return val ? '+' : '-'; }
+static inline const char* fmt_yesno(bool a) { return a ? "yes" : "no"; }
+
 //#define SRT_CMD_HSREQ       1           /* SRT Handshake Request (sender) */
 #define SRT_CMD_HSREQ_MINSZ 8 /* Minumum Compatible (1.x.x) packet size (bytes) */
 #define SRT_CMD_HSREQ_SZ 12   /* Current version packet size */
@@ -1773,8 +1776,11 @@ bool srt::CUDT::createSrtHandshake(
             m_RejectReason = SRT_REJ_IPE;
             LOGC(cnlog.Error,
                  log << CONID() << "createSrtHandshake: IPE: need to send KM, but CryptoControl does not exist."
-                     << " Socket state: connected=" << boolalpha << m_bConnected << ", connecting=" << m_bConnecting
-                     << ", broken=" << m_bBroken << ", closing=" << m_bClosing << ".");
+                     << " Socket state: "
+                     << fmt_onoff(m_bConnected) << "connected, "
+                     << fmt_onoff(m_bConnecting) << "connecting, "
+                     << fmt_onoff(m_bBroken) << "broken, "
+                     << fmt_onoff(m_bClosing) << "closing.");
             return false;
         }
 
@@ -2102,8 +2108,9 @@ int srt::CUDT::processSrtMsg_HSREQ(const uint32_t *srtdata, size_t bytelen, uint
     }
 
     LOGC(cnlog.Debug, log << "HSREQ/rcv: cmd=" << SRT_CMD_HSREQ << "(HSREQ) len=" << bytelen
-                          << hex << " vers=0x" << srtdata[SRT_HS_VERSION] << " opts=0x" << srtdata[SRT_HS_FLAGS]
-                          << dec << " delay=" << SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY]));
+                          << " vers=0x" << sfmt(srtdata[SRT_HS_VERSION], "x")
+                          << " opts=0x" << sfmt(srtdata[SRT_HS_FLAGS], "x")
+                          << " delay=" << SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY]));
 
     m_uPeerSrtVersion = srtdata[SRT_HS_VERSION];
     m_uPeerSrtFlags   = srtdata[SRT_HS_FLAGS];
@@ -2337,8 +2344,8 @@ int srt::CUDT::processSrtMsg_HSRSP(const uint32_t *srtdata, size_t bytelen, uint
     m_uPeerSrtFlags   = srtdata[SRT_HS_FLAGS];
 
     HLOGC(cnlog.Debug, log << "HSRSP/rcv: Version: " << SrtVersionString(m_uPeerSrtVersion)
-                           << " Flags: SND:" << setw(8) << setfill('0') << hex << m_uPeerSrtFlags
-                           << setw(0) << " (" << SrtFlagString(m_uPeerSrtFlags) << ")");
+                           << " Flags: SND:" << sfmt(m_uPeerSrtFlags, "08x")
+                           << " (" << SrtFlagString(m_uPeerSrtFlags) << ")");
     // Basic version check
     if (m_uPeerSrtVersion < m_config.uMinimumPeerSrtVersion)
     {
@@ -3140,7 +3147,7 @@ bool srt::CUDT::interpretGroup(const int32_t groupdata[], size_t data_size SRT_A
     HLOGC(cnlog.Debug,
           log << CONID() << "interpretGroup: STATE: HsSide=" << hs_side_name[m_SrtHsSide]
               << " HS MSG: " << MessageTypeStr(UMSG_EXT, hsreq_type_cmd) << " $" << grpid << " type=" << gtp
-              << " weight=" << link_weight << " flags=0x" << std::hex << link_flags);
+              << " weight=" << link_weight << " flags=0x" << sfmt(link_flags, sfmc().hex()));
 #endif
 
     // XXX Here are two separate possibilities:
@@ -4101,8 +4108,12 @@ EConnectStatus srt::CUDT::craftKmResponse(uint32_t* aw_kmdata, size_t& w_kmdatas
             m_RejectReason = SRT_REJ_IPE;
             LOGC(cnlog.Error,
                  log << CONID() << "IPE: craftKmResponse needs to send KM, but CryptoControl does not exist."
-                     << " Socket state: connected=" << boolalpha << m_bConnected << ", connecting=" << m_bConnecting
-                     << ", broken=" << m_bBroken << ", opened " << m_bOpened << ", closing=" << m_bClosing << ".");
+                     << " Socket state: "
+                     << fmt_onoff(m_bConnected) << "connected, "
+                     << fmt_onoff(m_bConnecting) << "connecting, "
+                     << fmt_onoff(m_bBroken) << "broken, "
+                     << fmt_onoff(m_bOpened) << "opened, "
+                     << fmt_onoff(m_bClosing) << "closing.");
             return CONN_REJECT;
         }
         // This is a periodic handshake update, so you need to extract the KM data from the
@@ -4649,8 +4660,8 @@ EConnectStatus srt::CUDT::processConnectResponse(const CPacket& response, CUDTEx
         if (m_ConnRes.m_iReqType == URQ_INDUCTION)
         {
             HLOGC(cnlog.Debug,
-                  log << CONID() << "processConnectResponse: REQ-TIME LOW; got INDUCTION HS response (cookie:" << hex
-                      << m_ConnRes.m_iCookie << " version:" << dec << m_ConnRes.m_iVersion
+                  log << CONID() << "processConnectResponse: REQ-TIME LOW; got INDUCTION HS response (cookie:"
+                      << sfmt(m_ConnRes.m_iCookie, sfmc().hex()) << " version:" << m_ConnRes.m_iVersion
                       << "), sending CONCLUSION HS with this cookie");
 
             m_ConnReq.m_iCookie  = m_ConnRes.m_iCookie;
@@ -4757,7 +4768,8 @@ EConnectStatus srt::CUDT::postConnect(const CPacket* pResponse, bool rendezvous,
     // in rendezvous it's completed before calling this function.
     if (!rendezvous)
     {
-        HLOGC(cnlog.Debug, log << CONID() << boolalpha << "postConnect: packet:" << bool(pResponse) << " rendezvous:" << rendezvous);
+        HLOGC(cnlog.Debug, log << CONID() << "postConnect: packet:"
+                               << fmt_yesno(pResponse) << " rendezvous:" << fmt_yesno(rendezvous));
         // The "local storage depleted" case shouldn't happen here, but
         // this is a theoretical path that needs prevention.
         bool ok = pResponse;
@@ -5460,14 +5472,14 @@ void * srt::CUDT::tsbpd(void* param)
                 HLOGC(tslog.Debug,
                     log << self->CONID() << "tsbpd: DROPSEQ: up to seqno %" << CSeqNo::decseq(info.seqno) << " ("
                     << iDropCnt << " packets) playable at " << FormatTime(info.tsbpd_time) << " delayed "
-                    << (timediff_us / 1000) << "." << std::setw(3) << std::setfill('0') << (timediff_us % 1000) << " ms");
+                    << (timediff_us / 1000) << "." << sfmt(timediff_us % 1000, "03") << " ms");
 #endif
                 string why;
                 if (self->frequentLogAllowed(FREQLOGFA_RCV_DROPPED, tnow, (why)))
                 {
                     LOGC(brlog.Warn, log << self->CONID() << "RCV-DROPPED " << iDropCnt << " packet(s). Packet seqno %" << info.seqno
-                            << " delayed for " << (timediff_us / 1000) << "." << std::setw(3) << std::setfill('0')
-                            << (timediff_us % 1000) << " ms " << why);
+                            << " delayed for " << (timediff_us / 1000) << "."
+                            << sfmt(timediff_us % 1000, "03") << " ms " << why);
                 }
 #if SRT_ENABLE_FREQUENT_LOG_TRACE
                 else
@@ -7149,7 +7161,7 @@ int srt::CUDT::receiveMessage(char* data, int len, SRT_MSGCTRL& w_mctrl, int by_
 
                 HLOGC(tslog.Debug,
                       log << CONID() << "receiveMessage: fall asleep up to TS=" << FormatTime(exptime)
-                          << " lock=" << (&m_RecvLock) << " cond=" << (&m_RecvDataCond));
+                          << " lock=" << ((void*)&m_RecvLock) << " cond=" << ((void*)&m_RecvDataCond));
 
                 if (!recv_cond.wait_until(exptime))
                 {
@@ -7767,7 +7779,7 @@ bool srt::CUDT::updateCC(ETransmissionEvent evt, const EventVariant arg)
         HLOGC(rslog.Debug,
               log << CONID() << "updateCC: updated values from congctl: interval=" << FormatDuration<DUNIT_US>(m_tdSendInterval)
                   << " (cfg:" << m_CongCtl->pktSndPeriod_us() << "us) cgwindow="
-                  << std::setprecision(3) << cgwindow);
+                  << sfmt(cgwindow, sfmc().precision(3)));
 #endif
     }
 
@@ -8408,7 +8420,7 @@ void srt::CUDT::processCtrlAck(const CPacket &ctrlpkt, const steady_clock::time_
         // included, but it also triggers for any other kind of invalid value.
         // This check MUST BE DONE before making any operation on this number.
         LOGC(inlog.Error, log << CONID() << "ACK: IPE/EPE: received invalid ACK value: " << ackdata_seqno
-                << " " << std::hex << ackdata_seqno << " (IGNORED)");
+                << " " << sfmt(ackdata_seqno, "x") << " (IGNORED)");
         return;
     }
 
@@ -10002,12 +10014,11 @@ int srt::CUDT::checkLazySpawnTsbPdThread()
 
         HLOGP(qrlog.Debug, "Spawning Socket TSBPD thread");
 #if ENABLE_HEAVY_LOGGING
-        std::ostringstream tns1, tns2;
+        obufstream buf;
         // Take the last 2 ciphers from the socket ID.
-        tns1 << setfill('0') << setw(2) << m_SocketID;
-        std::string s = tns1.str();
-        tns2 << "SRT:TsbPd:@" << s.substr(s.size()-2, 2);
-        const string thname = tns2.str();
+        string s = sfmts(m_SocketID, "02");
+        buf << "SRT:TsbPd:@" << s.substr(s.size()-2, 2);
+        const string thname = buf.str();
 #else
         const string thname = "SRT:TsbPd";
 #endif
@@ -11055,7 +11066,7 @@ int srt::CUDT::processConnectRequest(const sockaddr_any& addr, CPacket& packet)
 
     int32_t cookie_val = bake(addr);
 
-    HLOGC(cnlog.Debug, log << CONID() << "processConnectRequest: new cookie: " << hex << cookie_val);
+    HLOGC(cnlog.Debug, log << CONID() << "processConnectRequest: new cookie: " << sfmt(cookie_val, sfmc().hex()));
 
     // Remember the incoming destination address here and use it as a source
     // address when responding. It's not possible to record this address yet
@@ -11135,7 +11146,7 @@ int srt::CUDT::processConnectRequest(const sockaddr_any& addr, CPacket& packet)
         if (hs.m_iCookie != cookie_val)
         {
             m_RejectReason = SRT_REJ_RDVCOOKIE;
-            HLOGC(cnlog.Debug, log << CONID() << "processConnectRequest: ...wrong cookie " << hex << cookie_val << ". Ignoring.");
+            HLOGC(cnlog.Debug, log << CONID() << "processConnectRequest: ...wrong cookie " << sfmt(cookie_val, sfmc().hex()) << ". Ignoring.");
             return m_RejectReason;
         }
 

srtcore/fec.cpp

@@ -533,13 +533,14 @@ void FECFilterBuiltin::ClipPacket(Group& g, const CPacket& pkt)
 
     ClipData(g, length_net, kflg, timestamp_hw, pkt.data(), pkt.size());
 
-    HLOGC(pflog.Debug, log << "FEC DATA PKT CLIP: " << hex
-            << "FLAGS=" << unsigned(kflg) << " LENGTH[ne]=" << (length_net)
-            << " TS[he]=" << timestamp_hw
-            << " CLIP STATE: FLAGS=" << unsigned(g.flag_clip)
-            << " LENGTH[ne]=" << g.length_clip
-            << " TS[he]=" << g.timestamp_clip
-            << " PL4=" << (*(uint32_t*)&g.payload_clip[0]));
+    HLOGC(pflog.Debug, log << "FEC DATA PKT CLIP: "
+            << "FLAGS=" << sfmt<unsigned>(kflg, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(length_net, sfmc().hex())
+            << " TS[he]=" << sfmt(timestamp_hw, sfmc().hex())
+            << " CLIP STATE: FLAGS=" << sfmt<unsigned>(g.flag_clip, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(g.length_clip, sfmc().hex())
+            << " TS[he]=" << sfmt(g.timestamp_clip, sfmc().hex())
+            << " PL4=" << sfmt(*(uint32_t*)&g.payload_clip[0], sfmc().hex()));
 }
 
 // Clipping a control packet does merely the same, just the packet has
@@ -560,13 +561,14 @@ void FECFilterBuiltin::ClipControlPacket(Group& g, const CPacket& pkt)
 
     ClipData(g, *length_clip, *flag_clip, timestamp_hw, payload, payload_clip_len);
 
-    HLOGC(pflog.Debug, log << "FEC/CTL CLIP: " << hex
-            << "FLAGS=" << unsigned(*flag_clip) << " LENGTH[ne]=" << (*length_clip)
-            << " TS[he]=" << timestamp_hw
-            << " CLIP STATE: FLAGS=" << unsigned(g.flag_clip)
-            << " LENGTH[ne]=" << g.length_clip
-            << " TS[he]=" << g.timestamp_clip
-            << " PL4=" << (*(uint32_t*)&g.payload_clip[0]));
+    HLOGC(pflog.Debug, log << "FEC/CTL CLIP: "
+            << "FLAGS=" << sfmt<unsigned>(*flag_clip, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(*length_clip, sfmc().hex())
+            << " TS[he]=" << sfmt(timestamp_hw, sfmc().hex())
+            << " CLIP STATE: FLAGS=" << sfmt<unsigned>(g.flag_clip, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(g.length_clip, sfmc().hex())
+            << " TS[he]=" << sfmt(g.timestamp_clip, sfmc().hex())
+            << " PL4=" << sfmt(*(uint32_t*)&g.payload_clip[0], sfmc().hex()));
 }
 
 void FECFilterBuiltin::ClipRebuiltPacket(Group& g, Receive::PrivPacket& pkt)
@@ -582,13 +584,14 @@ void FECFilterBuiltin::ClipRebuiltPacket(Group& g, Receive::PrivPacket& pkt)
 
     ClipData(g, length_net, kflg, timestamp_hw, pkt.buffer, pkt.length);
 
-    HLOGC(pflog.Debug, log << "FEC REBUILT DATA CLIP: " << hex
-            << "FLAGS=" << unsigned(kflg) << " LENGTH[ne]=" << (length_net)
-            << " TS[he]=" << timestamp_hw
-            << " CLIP STATE: FLAGS=" << unsigned(g.flag_clip)
-            << " LENGTH[ne]=" << g.length_clip
-            << " TS[he]=" << g.timestamp_clip
-            << " PL4=" << (*(uint32_t*)&g.payload_clip[0]));
+    HLOGC(pflog.Debug, log << "FEC REBUILT DATA CLIP: "
+            << "FLAGS=" << sfmt<unsigned>(kflg, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(length_net, sfmc().hex())
+            << " TS[he]=" << sfmt(timestamp_hw, sfmc().hex())
+            << " CLIP STATE: FLAGS=" << sfmt<unsigned>(g.flag_clip, sfmc().hex())
+            << " LENGTH[ne]=" << sfmt(g.length_clip, sfmc().hex())
+            << " TS[he]=" << sfmt(g.timestamp_clip, sfmc().hex())
+            << " PL4=" << sfmt(*(uint32_t*)&g.payload_clip[0], sfmc().hex()));
 }
 
 void FECFilterBuiltin::ClipData(Group& g, uint16_t length_net, uint8_t kflg,
@@ -765,11 +768,11 @@ void FECFilterBuiltin::PackControl(const Group& g, signed char index, SrtPacket&
 
     HLOGC(pflog.Debug, log << "FEC: PackControl: hdr("
             << (total_size - g.payload_clip.size()) << "): INDEX="
-            << int(index) << " LENGTH[ne]=" << hex << g.length_clip
-            << " FLAGS=" << int(g.flag_clip) << " TS=" << g.timestamp_clip
-            << " PL(" << dec << g.payload_clip.size() << ")[0-4]=" << hex
-            << (*(uint32_t*)&g.payload_clip[0]));
-
+            << int(index) << " LENGTH[ne]=" << sfmt(g.length_clip, sfmc().hex())
+            << " FLAGS=" << sfmt<unsigned>(g.flag_clip, sfmc().hex())
+            << " TS=" << sfmt(g.timestamp_clip, sfmc().hex())
+            << " PL(" << g.payload_clip.size() << ")[0-4]="
+            << sfmt(*(uint32_t*)&g.payload_clip[0], sfmc().hex()));
 }
 
 bool FECFilterBuiltin::receive(const CPacket& rpkt, loss_seqs_t& loss_seqs)
@@ -1464,7 +1467,7 @@ void FECFilterBuiltin::RcvRebuild(Group& g, int32_t seqno, Group::Type tp)
     HLOGC(pflog.Debug, log << "FEC: REBUILT: %" << seqno
             << " msgno=" << MSGNO_SEQ::unwrap(p.hdr[SRT_PH_MSGNO])
             << " flags=" << PacketMessageFlagStr(p.hdr[SRT_PH_MSGNO])
-            << " TS=" << p.hdr[SRT_PH_TIMESTAMP] << " ID=" << dec << p.hdr[SRT_PH_ID]
+            << " TS=" << p.hdr[SRT_PH_TIMESTAMP] << " ID=" << p.hdr[SRT_PH_ID]
             << " size=" << length_hw
             << " !" << BufferStamp(p.buffer, p.length));