diff --git a/srtcore/api.cpp b/srtcore/api.cpp index 6b580b071..1b2b430d8 100644 --- a/srtcore/api.cpp +++ b/srtcore/api.cpp @@ -309,10 +309,9 @@ SRTSOCKET CUDTUnited::newSocket(int af, int) CGuard::enterCS(m_ControlLock); try { - LOGC(mglog.Debug) - << CONID(ns->m_SocketID) + LOGC(mglog.Debug, log << CONID(ns->m_SocketID) << "newSocket: mapping socket " - << ns->m_SocketID; + << ns->m_SocketID); m_Sockets[ns->m_SocketID] = ns; } catch (...) @@ -400,7 +399,7 @@ int CUDTUnited::newConnection(const SRTSOCKET listen, const sockaddr* peer, CHan CGuard::enterCS(m_IDLock); ns->m_SocketID = -- m_SocketIDGenerator; - LOGC(mglog.Debug).form("newConnection: generated socket id %d\n", ns->m_SocketID); + LOGF(mglog.Debug, "newConnection: generated socket id %d\n", ns->m_SocketID); CGuard::leaveCS(m_IDLock); ns->m_ListenSocket = listen; @@ -422,7 +421,7 @@ int CUDTUnited::newConnection(const SRTSOCKET listen, const sockaddr* peer, CHan // this call causes sending the SRT Handshake through this socket. // Without this mapping the socket cannot be found and therefore // the SRT Handshake message would fail. - LOGC(mglog.Debug).form( + LOGF(mglog.Debug, "newConnection: incoming %s, mapping socket %d\n", SockaddrToString(peer).c_str(), ns->m_SocketID); { @@ -447,7 +446,7 @@ int CUDTUnited::newConnection(const SRTSOCKET listen, const sockaddr* peer, CHan m_Sockets.erase(ns->m_SocketID); } error = 1; - LOGC(mglog.Debug).form( + LOGF(mglog.Debug, "newConnection: error while accepting, connection rejected"); goto ERR_ROLLBACK; } @@ -462,7 +461,7 @@ int CUDTUnited::newConnection(const SRTSOCKET listen, const sockaddr* peer, CHan CGuard::enterCS(m_ControlLock); try { - LOGC(mglog.Debug).form( + LOGF(mglog.Debug, "newConnection: mapping peer %d to that socket (%d)\n", ns->m_PeerID, ns->m_SocketID); m_PeerRec[ns->getPeerSpec()].insert(ns->m_SocketID); @@ -882,11 +881,11 @@ int CUDTUnited::close(const SRTSOCKET u) if (!s) throw CUDTException(MJ_NOTSUP, MN_SIDINVAL, 0); - LOGC(mglog.Debug) << s->m_pUDT->CONID() << " CLOSE. Acquiring control lock"; + LOGC(mglog.Debug, log << s->m_pUDT->CONID() << " CLOSE. Acquiring control lock"); CGuard socket_cg(s->m_ControlLock); - LOGC(mglog.Debug) << s->m_pUDT->CONID() << " CLOSING (removing from listening, closing CUDT)"; + LOGC(mglog.Debug, log << s->m_pUDT->CONID() << " CLOSING (removing from listening, closing CUDT)"); bool synch_close_snd = s->m_pUDT->m_bSynSending; //bool synch_close_rcv = s->m_pUDT->m_bSynRecving; @@ -910,7 +909,7 @@ int CUDTUnited::close(const SRTSOCKET u) // But there's no reason to destroy the world by occupying the // listener slot in the RcvQueue. - LOGC(mglog.Debug) << s->m_pUDT->CONID() << " CLOSING (removing listener immediately)"; + LOGC(mglog.Debug, log << s->m_pUDT->CONID() << " CLOSING (removing listener immediately)"); { CGuard cg(s->m_pUDT->m_ConnectionLock); s->m_pUDT->m_bListening = false; @@ -928,7 +927,7 @@ int CUDTUnited::close(const SRTSOCKET u) s->m_pUDT->close(); // synchronize with garbage collection. - LOGC(mglog.Debug) << "%" << id << " CUDT::close done. GLOBAL CLOSE: " << s->m_pUDT->CONID() << ". Acquiring GLOBAL control lock"; + LOGC(mglog.Debug, log << "%" << id << " CUDT::close done. GLOBAL CLOSE: " << s->m_pUDT->CONID() << ". Acquiring GLOBAL control lock"); CGuard manager_cg(m_ControlLock); // since "s" is located before m_ControlLock, locate it again in case @@ -952,7 +951,7 @@ int CUDTUnited::close(const SRTSOCKET u) CTimer::triggerEvent(); } - LOGC(mglog.Debug) << "%" << id << ": GLOBAL: CLOSING DONE"; + LOGC(mglog.Debug, log << "%" << id << ": GLOBAL: CLOSING DONE"); // Check if the ID is still in closed sockets before you access it // (the last triggerEvent could have deleted it). @@ -960,7 +959,7 @@ int CUDTUnited::close(const SRTSOCKET u) { #if SRT_ENABLE_CLOSE_SYNCH - LOGC(mglog.Debug) << "%" << id << " GLOBAL CLOSING: sync-waiting for releasing sender resources..."; + LOGC(mglog.Debug, log << "%" << id << " GLOBAL CLOSING: sync-waiting for releasing sender resources..."); for (;;) { CSndBuffer* sb = s->m_pUDT->m_pSndBuffer; @@ -968,14 +967,14 @@ int CUDTUnited::close(const SRTSOCKET u) // Disconnected from buffer - nothing more to check. if (!sb) { - LOGC(mglog.Debug) << "%" << id << " GLOBAL CLOSING: sending buffer disconnected. Allowed to close."; + LOGC(mglog.Debug, log << "%" << id << " GLOBAL CLOSING: sending buffer disconnected. Allowed to close."); break; } // Sender buffer empty if (sb->getCurrBufSize() == 0) { - LOGC(mglog.Debug) << "%" << id << " GLOBAL CLOSING: sending buffer depleted. Allowed to close."; + LOGC(mglog.Debug, log << "%" << id << " GLOBAL CLOSING: sending buffer depleted. Allowed to close."); break; } @@ -995,16 +994,16 @@ int CUDTUnited::close(const SRTSOCKET u) } if (isgone) { - LOGC(mglog.Debug) << "%" << id << " GLOBAL CLOSING: ... gone in the meantime, whatever. Exiting close()."; + LOGC(mglog.Debug, log << "%" << id << " GLOBAL CLOSING: ... gone in the meantime, whatever. Exiting close()."); break; } - LOGC(mglog.Debug) << "%" << id << " GLOBAL CLOSING: ... still waiting for any update."; + LOGC(mglog.Debug, log << "%" << id << " GLOBAL CLOSING: ... still waiting for any update."); CTimer::EWait wt = CTimer::waitForEvent(); if ( wt == CTimer::WT_ERROR ) { - LOGC(mglog.Debug) << "GLOBAL CLOSING: ... ERROR WHEN WAITING FOR EVENT. Exiting close() to prevent hangup."; + LOGC(mglog.Debug, log << "GLOBAL CLOSING: ... ERROR WHEN WAITING FOR EVENT. Exiting close() to prevent hangup."); break; } @@ -1425,7 +1424,7 @@ void CUDTUnited::checkBrokenSockets() { CUDTSocket* s = i->second; - // LOGC(mglog.Debug).form("checking EXISTING socket: %d\n", i->first); + // LOGF(mglog.Debug, "checking EXISTING socket: %d\n", i->first); // check broken connection if (s->m_pUDT->m_bBroken) { @@ -1436,7 +1435,7 @@ void CUDTUnited::checkBrokenSockets() // in case a client is connecting if (elapsed < 3000000) // XXX MAKE A SYMBOLIC CONSTANT HERE! { - // LOGC(mglog.Debug).form("STILL KEEPING socket %d + // LOGF(mglog.Debug, "STILL KEEPING socket %d // (listener, too early, w8 %fs)\n", i->first, // double(elapsed)/1000000); continue; @@ -1451,13 +1450,13 @@ void CUDTUnited::checkBrokenSockets() && s->m_pUDT->m_pRcvBuffer->isRcvDataAvailable() && (s->m_pUDT->m_iBrokenCounter -- > 0)) { - // LOGC(mglog.Debug).form("STILL KEEPING socket (still have data): + // LOGF(mglog.Debug, "STILL KEEPING socket (still have data): // %d\n", i->first); // if there is still data in the receiver buffer, wait longer continue; } - // LOGC(mglog.Debug).form("moving socket to CLOSED: %d\n", i->first); + // LOGF(mglog.Debug, "moving socket to CLOSED: %d\n", i->first); //close broken connections and start removal timer s->m_Status = SRTS_CLOSED; @@ -1485,7 +1484,7 @@ void CUDTUnited::checkBrokenSockets() for (map::iterator j = m_ClosedSockets.begin(); j != m_ClosedSockets.end(); ++ j) { - // LOGC(mglog.Debug).form("checking CLOSED socket: %d\n", j->first); + // LOGF(mglog.Debug, "checking CLOSED socket: %d\n", j->first); if (j->second->m_pUDT->m_ullLingerExpiration > 0) { // asynchronous close: @@ -1505,7 +1504,7 @@ void CUDTUnited::checkBrokenSockets() && ((!j->second->m_pUDT->m_pRNode) || !j->second->m_pUDT->m_pRNode->m_bOnList)) { - // LOGC(mglog.Debug).form("will unref socket: %d\n", j->first); + // LOGF(mglog.Debug, "will unref socket: %d\n", j->first); tbr.push_back(j->first); } } @@ -1568,9 +1567,9 @@ void CUDTUnited::removeSocket(const SRTSOCKET u) UDT_EPOLL_IN|UDT_EPOLL_OUT|UDT_EPOLL_ERR, false); // delete this one - LOGC(mglog.Debug) << "GC/removeSocket: closing associated UDT %" << u; + LOGC(mglog.Debug, log << "GC/removeSocket: closing associated UDT %" << u); i->second->m_pUDT->close(); - LOGC(mglog.Debug) << "GC/removeSocket: DELETING SOCKET %" << u; + LOGC(mglog.Debug, log << "GC/removeSocket: DELETING SOCKET %" << u); delete i->second; m_ClosedSockets.erase(i); @@ -1578,18 +1577,18 @@ void CUDTUnited::removeSocket(const SRTSOCKET u) m = m_mMultiplexer.find(mid); if (m == m_mMultiplexer.end()) { - LOGC(mglog.Fatal) << "IPE: For socket %" << u << " MUXER id=" << mid << " NOT FOUND!"; + LOGC(mglog.Fatal, log << "IPE: For socket %" << u << " MUXER id=" << mid << " NOT FOUND!"); return; } m->second.m_iRefCount --; - // LOGC(mglog.Debug).form("unrefing underlying socket for %u: %u\n", + // LOGF(mglog.Debug, "unrefing underlying socket for %u: %u\n", // u, m->second.m_iRefCount); if (0 == m->second.m_iRefCount) { - LOGC(mglog.Debug) << "MUXER id=" << mid << " lost last socket %" + LOGC(mglog.Debug, log << "MUXER id=" << mid << " lost last socket %" << u << " - deleting muxer bound to port " - << m->second.m_pChannel->bindAddressAny().hport(); + << m->second.m_pChannel->bindAddressAny().hport()); m->second.m_pChannel->close(); delete m->second.m_pSndQueue; delete m->second.m_pRcvQueue; @@ -1638,7 +1637,7 @@ void CUDTUnited::updateMux( { if (i->second.m_iPort == port) { - // LOGC(mglog.Debug).form("reusing multiplexer for port + // LOGF(mglog.Debug, "reusing multiplexer for port // %hd\n", port); // reuse the existing multiplexer ++ i->second.m_iRefCount; @@ -1714,7 +1713,7 @@ void CUDTUnited::updateMux( s->m_pUDT->m_pRcvQueue = m.m_pRcvQueue; s->m_iMuxID = m.m_iID; - LOGC(mglog.Debug).form( + LOGF(mglog.Debug, "creating new multiplexer for port %i\n", m.m_iPort); } @@ -1772,7 +1771,7 @@ void CUDTUnited::updateListenerMux(CUDTSocket* s, const CUDTSocket* ls) { if (i->second.m_iPort == port) { - LOGC(mglog.Debug).form( + LOGF(mglog.Debug, "updateMux: reusing multiplexer for port %i\n", port); // reuse the existing multiplexer ++ i->second.m_iRefCount; @@ -1897,10 +1896,9 @@ SRTSOCKET CUDT::socket(int af, int, int) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "socket: UNEXPECTED EXCEPTION: " + LOGC(mglog.Fatal, log << "socket: UNEXPECTED EXCEPTION: " << typeid(ee).name() - << ": " << ee.what(); + << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return INVALID_SOCK; } @@ -1924,10 +1922,9 @@ int CUDT::bind(SRTSOCKET u, const sockaddr* name, int namelen) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "bind: UNEXPECTED EXCEPTION: " + LOGC(mglog.Fatal, log << "bind: UNEXPECTED EXCEPTION: " << typeid(ee).name() - << ": " << ee.what(); + << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -1951,9 +1948,8 @@ int CUDT::bind(SRTSOCKET u, UDPSOCKET udpsock) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "bind/udp: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "bind/udp: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -1977,9 +1973,8 @@ int CUDT::listen(SRTSOCKET u, int backlog) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "listen: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "listen: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -1998,9 +1993,8 @@ SRTSOCKET CUDT::accept(SRTSOCKET u, sockaddr* addr, int* addrlen) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "accept: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "accept: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return INVALID_SOCK; } @@ -2025,9 +2019,8 @@ int CUDT::connect( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "connect: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "connect: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2046,9 +2039,8 @@ int CUDT::close(SRTSOCKET u) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "close: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "close: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2067,9 +2059,8 @@ int CUDT::getpeername(SRTSOCKET u, sockaddr* name, int* namelen) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "getpeername: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "getpeername: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2088,9 +2079,8 @@ int CUDT::getsockname(SRTSOCKET u, sockaddr* name, int* namelen) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "getsockname: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "getsockname: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2112,9 +2102,8 @@ int CUDT::getsockopt( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "getsockopt: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "getsockopt: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2135,9 +2124,8 @@ int CUDT::setsockopt(SRTSOCKET u, int, SRT_SOCKOPT optname, const void* optval, } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "setsockopt: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "setsockopt: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2162,9 +2150,8 @@ int CUDT::send(SRTSOCKET u, const char* buf, int len, int) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "send: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "send: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2184,9 +2171,8 @@ int CUDT::recv(SRTSOCKET u, char* buf, int len, int) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "recv: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "recv: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2213,9 +2199,8 @@ int CUDT::sendmsg( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "sendmsg: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "sendmsg: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2241,9 +2226,8 @@ int CUDT::sendmsg2( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "sendmsg: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "sendmsg: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2263,9 +2247,8 @@ int CUDT::recvmsg(SRTSOCKET u, char* buf, int len, uint64_t& srctime) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "recvmsg: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "recvmsg: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2285,9 +2268,8 @@ int CUDT::recvmsg2(SRTSOCKET u, char* buf, int len, ref_t r_m) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "recvmsg: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "recvmsg: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2312,9 +2294,8 @@ int64_t CUDT::sendfile( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "sendfile: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "sendfile: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2335,9 +2316,8 @@ int64_t CUDT::recvfile( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "recvfile: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "recvfile: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2372,9 +2352,8 @@ int CUDT::select( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "select: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "select: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2409,9 +2388,8 @@ int CUDT::selectEx( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "selectEx: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "selectEx: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN)); return ERROR; } @@ -2430,9 +2408,8 @@ int CUDT::epoll_create() } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_create: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_create: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2451,9 +2428,8 @@ int CUDT::epoll_add_usock(const int eid, const SRTSOCKET u, const int* events) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_add_usock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_add_usock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2472,9 +2448,8 @@ int CUDT::epoll_add_ssock(const int eid, const SYSSOCKET s, const int* events) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_add_ssock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_add_ssock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2494,9 +2469,8 @@ int CUDT::epoll_update_usock( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_update_usock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_update_usock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2516,9 +2490,8 @@ int CUDT::epoll_update_ssock( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_update_ssock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_update_ssock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2538,9 +2511,8 @@ int CUDT::epoll_remove_usock(const int eid, const SRTSOCKET u) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_remove_usock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_remove_usock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2559,9 +2531,8 @@ int CUDT::epoll_remove_ssock(const int eid, const SYSSOCKET s) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_remove_ssock: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_remove_ssock: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2587,9 +2558,8 @@ int CUDT::epoll_wait( } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_wait: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_wait: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2608,9 +2578,8 @@ int CUDT::epoll_release(const int eid) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "epoll_release: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "epoll_release: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2636,9 +2605,8 @@ int CUDT::perfmon(SRTSOCKET u, CPerfMon* perf, bool clear) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "perfmon: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "perfmon: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2659,9 +2627,8 @@ int CUDT::bstats(SRTSOCKET u, CBytePerfMon* perf, bool clear) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "bstats: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "bstats: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return ERROR; } @@ -2680,9 +2647,8 @@ CUDT* CUDT::getUDTHandle(SRTSOCKET u) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "getUDTHandle: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "getUDTHandle: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return NULL; } @@ -2713,9 +2679,8 @@ SRT_SOCKSTATUS CUDT::getsockstate(SRTSOCKET u) } catch (std::exception& ee) { - LOGC(mglog.Fatal) - << "getsockstate: UNEXPECTED EXCEPTION: " - << typeid(ee).name() << ": " << ee.what(); + LOGC(mglog.Fatal, log << "getsockstate: UNEXPECTED EXCEPTION: " + << typeid(ee).name() << ": " << ee.what()); s_UDTUnited.setError(new CUDTException(MJ_UNKNOWN, MN_NONE, 0)); return SRTS_NONEXIST; } diff --git a/srtcore/buffer.cpp b/srtcore/buffer.cpp index 1d5111db6..cd6ea1f2f 100644 --- a/srtcore/buffer.cpp +++ b/srtcore/buffer.cpp @@ -158,21 +158,21 @@ void CSndBuffer::addBuffer(const char* data, int len, int ttl, bool order, uint6 if ((len % m_iMSS) != 0) size ++; - LOGC(mglog.Debug) << "addBuffer: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes"; + LOGC(mglog.Debug, log << "addBuffer: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes"); // dynamically increase sender buffer while (size + m_iCount >= m_iSize) { - LOGC(mglog.Debug) << "addBuffer: ... still lacking " << (size + m_iCount - m_iSize) << " buffers..."; + LOGC(mglog.Debug, log << "addBuffer: ... still lacking " << (size + m_iCount - m_iSize) << " buffers..."); increase(); } uint64_t time = CTimer::getTime(); int32_t inorder = order ? MSGNO_PACKET_INORDER::mask : 0; - LOGC(dlog.Debug) << CONID() << "addBuffer: adding " + LOGC(dlog.Debug, log << CONID() << "addBuffer: adding " << size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo - << (inorder ? "" : " NOT") << " in order"; + << (inorder ? "" : " NOT") << " in order"); Block* s = m_pLastBlock; msgno = m_iNextMsgNo; @@ -182,7 +182,7 @@ void CSndBuffer::addBuffer(const char* data, int len, int ttl, bool order, uint6 if (pktlen > m_iMSS) pktlen = m_iMSS; - LOGC(dlog.Debug) << "addBuffer: spreading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData; + LOGC(dlog.Debug, log << "addBuffer: spreading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData); memcpy(s->m_pcData, data + i * m_iMSS, pktlen); s->m_iLength = pktlen; @@ -260,7 +260,7 @@ void CSndBuffer::updInputRate(uint64_t time, int pkts, int bytes) m_iInRateBytesCount += (m_iInRatePktsCount * CPacket::SRT_DATA_HDR_SIZE); m_iInRateBps = (int)(((int64_t)m_iInRateBytesCount * 1000000) / (time - m_InRateStartTime)); - LOGC(dlog.Debug).form("updInputRate: pkts:%d bytes:%d avg=%d rate=%d kbps interval=%llu\n", + LOGF(dlog.Debug, "updInputRate: pkts:%d bytes:%d avg=%d rate=%d kbps interval=%llu\n", m_iInRateBytesCount, m_iInRatePktsCount, m_iAvgPayloadSz, (m_iInRateBps*8)/1000, (unsigned long long)(time - m_InRateStartTime)); @@ -306,17 +306,17 @@ int CSndBuffer::addBufferFromFile(fstream& ifs, int len) if ((len % m_iMSS) != 0) size ++; - LOGC(mglog.Debug) << "addBufferFromFile: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes"; + LOGC(mglog.Debug, log << "addBufferFromFile: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes"); // dynamically increase sender buffer while (size + m_iCount >= m_iSize) { - LOGC(mglog.Debug) << "addBufferFromFile: ... still lacking " << (size + m_iCount - m_iSize) << " buffers..."; + LOGC(mglog.Debug, log << "addBufferFromFile: ... still lacking " << (size + m_iCount - m_iSize) << " buffers..."); increase(); } - LOGC(dlog.Debug) << CONID() << "addBufferFromFile: adding " - << size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo; + LOGC(dlog.Debug, log << CONID() << "addBufferFromFile: adding " + << size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo); Block* s = m_pLastBlock; int total = 0; @@ -329,7 +329,7 @@ int CSndBuffer::addBufferFromFile(fstream& ifs, int len) if (pktlen > m_iMSS) pktlen = m_iMSS; - LOGC(dlog.Debug) << "addBufferFromFile: reading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData; + LOGC(dlog.Debug, log << "addBufferFromFile: reading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData); ifs.read(s->m_pcData, pktlen); if ((pktlen = int(ifs.gcount())) <= 0) break; @@ -406,7 +406,7 @@ int CSndBuffer::readData(char** data, int32_t& msgno_bitset, uint64_t& srctime, m_pCurrBlock = m_pCurrBlock->m_pNext; - LOGC(dlog.Debug) << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send"; + LOGC(dlog.Debug, log << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send"); return readlen; } @@ -452,7 +452,7 @@ int CSndBuffer::readData(char** data, const int offset, int32_t& msgno_bitset, u msglen ++; } - LOGC(dlog.Debug) << "CSndBuffer::readData: due to TTL exceeded, " << msglen << " messages to drop, up to " << msgno; + LOGC(dlog.Debug, log << "CSndBuffer::readData: due to TTL exceeded, " << msglen << " messages to drop, up to " << msgno); // If readData returns -1, then msgno_bitset is understood as a Message ID to drop. // This means that in this case it should be written by the message sequence value only @@ -476,7 +476,7 @@ int CSndBuffer::readData(char** data, const int offset, int32_t& msgno_bitset, u p->m_ullSourceTime_us ? p->m_ullSourceTime_us : p->m_ullOriginTime_us; - LOGC(dlog.Debug) << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send [REXMIT]"; + LOGC(dlog.Debug, log << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send [REXMIT]"); return readlen; } @@ -552,7 +552,7 @@ void CSndBuffer::updAvgBufSize(uint64_t now) int bytescount; int count = getCurrBufSize(Ref(bytescount), Ref(instspan)); - LOGC(dlog.Debug).form("updAvgBufSize: %6llu: %6d %6d %6d ms\n", + LOGF(dlog.Debug, "updAvgBufSize: %6llu: %6d %6d %6d ms\n", (unsigned long long)elapsed, count, bytescount, instspan); m_iCountMAvg = (int)(((count * (1000 - elapsed)) + (count * elapsed)) / 1000); @@ -668,8 +668,8 @@ void CSndBuffer::increase() m_iSize += unitsize; - LOGC(dlog.Debug) << "CSndBuffer: BUFFER FULL - adding " << (unitsize*m_iMSS) << " bytes spread to " << unitsize << " blocks" - << " (total size: " << m_iSize << " bytes)"; + LOGC(dlog.Debug, log << "CSndBuffer: BUFFER FULL - adding " << (unitsize*m_iMSS) << " bytes spread to " << unitsize << " blocks" + << " (total size: " << m_iSize << " bytes)"); } @@ -812,16 +812,18 @@ int CRcvBuffer::readBuffer(char* data, int len) int p = m_iStartPos; int lastack = m_iLastAckPos; int rs = len; - char* begin = data; // logging only +#if ENABLE_LOGGING + char* begin = data; +#endif uint64_t now = (m_bTsbPdMode ? CTimer::getTime() : 0LL); - LOGC(dlog.Debug) << CONID() << "readBuffer: start=" << p << " lastack=" << lastack; + LOGC(dlog.Debug, log << CONID() << "readBuffer: start=" << p << " lastack=" << lastack); while ((p != lastack) && (rs > 0)) { if (m_bTsbPdMode) { - LOGC(dlog.Debug) << CONID() << "readBuffer: chk if time2play: NOW=" << now << " PKT TS=" << getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp()); + LOGC(dlog.Debug, log << CONID() << "readBuffer: chk if time2play: NOW=" << now << " PKT TS=" << getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp())); if ((getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp()) > now)) break; /* too early for this unit, return whatever was copied */ } @@ -830,8 +832,8 @@ int CRcvBuffer::readBuffer(char* data, int len) if (unitsize > rs) unitsize = rs; - LOGC(dlog.Debug) << CONID() << "readBuffer: copying buffer #" << p - << " targetpos=" << int(data-begin) << " sourcepos=" << m_iNotch << " size=" << unitsize << " left=" << (unitsize-rs); + LOGC(dlog.Debug, log << CONID() << "readBuffer: copying buffer #" << p + << " targetpos=" << int(data-begin) << " sourcepos=" << m_iNotch << " size=" << unitsize << " left=" << (unitsize-rs)); memcpy(data, m_pUnit[p]->m_Packet.m_pcData + m_iNotch, unitsize); data += unitsize; @@ -1080,7 +1082,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t tsbpdtime, ref_t curpkt int64_t towait = (*tsbpdtime - CTimer::getTime()); if (towait > 0) { - LOGC(mglog.Debug) << "getRcvReadyMsg: found packet, but not ready to play (only in " << (towait/1000.0) << "ms)"; + LOGC(mglog.Debug, log << "getRcvReadyMsg: found packet, but not ready to play (only in " << (towait/1000.0) << "ms)"); return false; } @@ -1091,7 +1093,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t tsbpdtime, ref_t curpkt } else { - LOGC(mglog.Debug) << "getRcvReadyMsg: packet seq=" << curpktseq.get() << " ready to play (delayed " << (-towait/1000.0) << "ms)"; + LOGC(mglog.Debug, log << "getRcvReadyMsg: packet seq=" << curpktseq.get() << " ready to play (delayed " << (-towait/1000.0) << "ms)"); return true; } } @@ -1110,7 +1112,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t tsbpdtime, ref_t curpkt } } - LOGC(mglog.Debug) << "getRcvReadyMsg: nothing to deliver: " << reason; + LOGC(mglog.Debug, log << "getRcvReadyMsg: nothing to deliver: " << reason); /* removed skipped, dropped, undecryptable bytes from rcv buffer */ countBytes(-rmpkts, -rmbytes, true); return false; @@ -1214,7 +1216,7 @@ void CRcvBuffer::updRcvAvgDataSize(uint64_t now) m_iCountMAvg = getRcvDataSize(m_iBytesCountMAvg, m_TimespanMAvg); m_LastSamplingTime = now; - LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms elapsed:%5llu ms\n", m_iCountMAvg, m_iBytesCountMAvg, m_TimespanMAvg, (unsigned long long)elapsed); + LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms elapsed:%5llu ms\n", m_iCountMAvg, m_iBytesCountMAvg, m_TimespanMAvg, (unsigned long long)elapsed); } else if ((1000000 / SRT_MAVG_SAMPLING_RATE) / 1000 <= elapsed) { @@ -1234,7 +1236,7 @@ void CRcvBuffer::updRcvAvgDataSize(uint64_t now) m_TimespanMAvg = (int)(((instspan * (1000 - elapsed)) + (instspan * elapsed)) / 1000); m_LastSamplingTime = now; - LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms elapsed: %5llu ms\n", count, bytescount, instspan, (unsigned long long)elapsed); + LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms elapsed: %5llu ms\n", count, bytescount, instspan, (unsigned long long)elapsed); } } #endif /* SRT_ENABLE_RCVBUFSZ_MAVG */ @@ -1310,7 +1312,7 @@ int CRcvBuffer::getRcvDataSize(int &bytes, int ×pan) timespan += 1; } } - LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms\n", m_iAckedPktsCount, m_iAckedBytesCount, timespan); + LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms\n", m_iAckedPktsCount, m_iAckedBytesCount, timespan); bytes = m_iAckedBytesCount; return m_iAckedPktsCount; } @@ -1607,8 +1609,8 @@ int CRcvBuffer::readMsg(char* data, int len, ref_t r_msgctl) int64_t nowdiff = prev_now ? (nowtime - prev_now) : 0; uint64_t srctimediff = prev_srctime ? (srctime - prev_srctime) : 0; - LOGC(dlog.Debug) << CONID() << "readMsg: DELIVERED seq=" << seq << " T=" << logging::FormatTime(srctime) << " in " << (timediff/1000.0) << "ms - " - "TIME-PREVIOUS: PKT: " << (srctimediff/1000.0) << " LOCAL: " << (nowdiff/1000.0); + LOGC(dlog.Debug, log << CONID() << "readMsg: DELIVERED seq=" << seq << " T=" << logging::FormatTime(srctime) << " in " << (timediff/1000.0) << "ms - " + "TIME-PREVIOUS: PKT: " << (srctimediff/1000.0) << " LOCAL: " << (nowdiff/1000.0)); prev_now = nowtime; prev_srctime = srctime; @@ -1645,7 +1647,7 @@ bool CRcvBuffer::scanMsg(ref_t r_p, ref_t r_q, ref_t passack) // empty buffer if ((m_iStartPos == m_iLastAckPos) && (m_iMaxPos <= 0)) { - LOGC(mglog.Debug) << "scanMsg: empty buffer"; + LOGC(mglog.Debug, log << "scanMsg: empty buffer"); return false; } @@ -1790,7 +1792,7 @@ bool CRcvBuffer::scanMsg(ref_t r_p, ref_t r_q, ref_t passack) // the msg has to be ack'ed or it is allowed to read out of order, and was not read before if (!*passack || !m_pUnit[q]->m_Packet.getMsgOrderFlag()) { - LOGC(mglog.Debug) << "scanMsg: found next-to-broken message, delivering OUT OF ORDER."; + LOGC(mglog.Debug, log << "scanMsg: found next-to-broken message, delivering OUT OF ORDER."); break; } @@ -1816,17 +1818,17 @@ bool CRcvBuffer::scanMsg(ref_t r_p, ref_t r_q, ref_t passack) // if the message is larger than the receiver buffer, return part of the message if ((p != -1) && ((q + 1) % m_iSize == p)) { - LOGC(mglog.Debug) << "scanMsg: BUFFER FULL and message is INCOMPLETE. Returning PARTIAL MESSAGE."; + LOGC(mglog.Debug, log << "scanMsg: BUFFER FULL and message is INCOMPLETE. Returning PARTIAL MESSAGE."); found = true; } else { - LOGC(mglog.Debug) << "scanMsg: PARTIAL or NO MESSAGE found: p=" << p << " q=" << q; + LOGC(mglog.Debug, log << "scanMsg: PARTIAL or NO MESSAGE found: p=" << p << " q=" << q); } } else { - LOGC(mglog.Debug) << "scanMsg: extracted message p=" << p << " q=" << q << " (" << ((q-p+m_iSize+1)%m_iSize) << " packets)"; + LOGC(mglog.Debug, log << "scanMsg: extracted message p=" << p << " q=" << q << " (" << ((q-p+m_iSize+1)%m_iSize) << " packets)"); } return found; diff --git a/srtcore/channel.cpp b/srtcore/channel.cpp index f4d5f0221..3fd5ff689 100644 --- a/srtcore/channel.cpp +++ b/srtcore/channel.cpp @@ -179,7 +179,7 @@ void CChannel::open(const sockaddr* addr) ::freeaddrinfo(res); } - LOGC(mglog.Debug) << "CHANNEL: Bound to local address: " << SockaddrToString(&m_BindAddr); + LOGC(mglog.Debug, log << "CHANNEL: Bound to local address: " << SockaddrToString(&m_BindAddr)); setUDPSockOpt(); } @@ -358,9 +358,9 @@ int CChannel::sendto(const sockaddr* addr, CPacket& packet) const spec << " [REXMIT]"; } - LOGC(mglog.Debug) << "CChannel::sendto: SENDING NOW DST=" << SockaddrToString(addr) + LOGC(mglog.Debug, log << "CChannel::sendto: SENDING NOW DST=" << SockaddrToString(addr) << " target=%" << packet.m_iID - << spec.str(); + << spec.str()); #endif // convert control information into network order @@ -474,7 +474,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const } else { - LOGC(mglog.Debug) << CONID() << "(sys)recvmsg: " << SysStrError(err) << " [" << err << "]"; + LOGC(mglog.Debug, log << CONID() << "(sys)recvmsg: " << SysStrError(err) << " [" << err << "]"); status = RST_ERROR; } @@ -528,7 +528,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const int err = NET_ERROR; if (std::find(fatals, fatals_end, err) != fatals_end) { - LOGC(mglog.Debug) << CONID() << "(sys)WSARecvFrom: " << SysStrError(err) << " [" << err << "]"; + LOGC(mglog.Debug, log << CONID() << "(sys)WSARecvFrom: " << SysStrError(err) << " [" << err << "]"); status = RST_ERROR; } else @@ -550,7 +550,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const if ( size_t(res) < CPacket::HDR_SIZE ) { status = RST_AGAIN; - LOGC(mglog.Debug) << CONID() << "POSSIBLE ATTACK: received too short packet with " << res << " bytes"; + LOGC(mglog.Debug, log << CONID() << "POSSIBLE ATTACK: received too short packet with " << res << " bytes"); goto Return_error; } @@ -571,8 +571,8 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const if ( msg_flags != 0 ) { - LOGC(mglog.Debug) << CONID() << "NET ERROR: packet size=" << res - << " msg_flags=0x" << hex << msg_flags << ", possibly MSG_TRUNC (0x" << hex << int(MSG_TRUNC) << ")"; + LOGC(mglog.Debug, log << CONID() << "NET ERROR: packet size=" << res + << " msg_flags=0x" << hex << msg_flags << ", possibly MSG_TRUNC (0x" << hex << int(MSG_TRUNC) << ")"); status = RST_AGAIN; goto Return_error; } diff --git a/srtcore/common.cpp b/srtcore/common.cpp index 0b37c7f92..1d9e269cb 100644 --- a/srtcore/common.cpp +++ b/srtcore/common.cpp @@ -847,11 +847,11 @@ std::string logging::FormatTime(uint64_t time) logging::LogDispatcher::Proxy::Proxy(LogDispatcher& guy) : that(guy), that_enabled(that.CheckEnabled()) { - i_file = ""; - i_line = 0; - flags = that.flags; if (that_enabled) { + i_file = ""; + i_line = 0; + flags = that.flags; // Create logger prefix that.CreateLogLinePrefix(os); } diff --git a/srtcore/core.cpp b/srtcore/core.cpp index 82b4e5202..650a06f7c 100644 --- a/srtcore/core.cpp +++ b/srtcore/core.cpp @@ -499,7 +499,7 @@ void CUDT::setOpt(SRT_SOCKOPT optName, const void* optval, int optlen) case SRTO_MAXBW: m_llMaxBW = *(int64_t*)optval; - LOGC(mglog.Debug) << "OPTION:SRTO_MAXBW set to " << m_llMaxBW << " - calling updateCC TEV_INIT RESET"; + LOGC(mglog.Debug, log << "OPTION:SRTO_MAXBW set to " << m_llMaxBW << " - calling updateCC TEV_INIT RESET"); // This can be done on both connected and unconnected socket. // When not connected, this will do nothing, however this @@ -677,7 +677,7 @@ void CUDT::setOpt(SRT_SOCKOPT optName, const void* optval, int optlen) if (*(int*)optval > SRT_LIVE_MAX_PLSIZE) { - LOGC(mglog.Error) << "SRTO_PAYLOADSIZE: value exceeds SRT_LIVE_MAX_PLSIZE, maximum payload per MTU."; + LOGC(mglog.Error, log << "SRTO_PAYLOADSIZE: value exceeds SRT_LIVE_MAX_PLSIZE, maximum payload per MTU."); throw CUDTException(MJ_NOTSUP, MN_INVAL, 0); } @@ -1051,7 +1051,7 @@ void CUDT::clearData() int udpsize = m_iMSS - CPacket::UDP_HDR_SIZE; m_iMaxSRTPayloadSize = udpsize - CPacket::HDR_SIZE; - LOGC(mglog.Debug) << "clearData: PAYLOAD SIZE: " << m_iMaxSRTPayloadSize; + LOGC(mglog.Debug, log << "clearData: PAYLOAD SIZE: " << m_iMaxSRTPayloadSize); m_iEXPCount = 1; m_iBandwidth = 1; //pkts/sec @@ -1204,7 +1204,7 @@ size_t CUDT::fillSrtHandshake(uint32_t* srtdata, size_t srtlen, int msgtype, int { if ( srtlen < SRT_HS__SIZE ) { - LOGC(mglog.Fatal) << "IPE: fillSrtHandshake: buffer too small: " << srtlen << " (expected: " << SRT_HS__SIZE << ")"; + LOGC(mglog.Fatal, log << "IPE: fillSrtHandshake: buffer too small: " << srtlen << " (expected: " << SRT_HS__SIZE << ")"); return 0; } @@ -1219,7 +1219,7 @@ size_t CUDT::fillSrtHandshake(uint32_t* srtdata, size_t srtlen, int msgtype, int { case SRT_CMD_HSREQ: return fillSrtHandshake_HSREQ(srtdata, srtlen, hs_version); case SRT_CMD_HSRSP: return fillSrtHandshake_HSRSP(srtdata, srtlen, hs_version); - default: LOGC(mglog.Fatal) << "IPE: createSrtHandshake/sendSrtMsg called with value " << msgtype; return 0; + default: LOGC(mglog.Fatal, log << "IPE: createSrtHandshake/sendSrtMsg called with value " << msgtype); return 0; } } @@ -1276,9 +1276,9 @@ size_t CUDT::fillSrtHandshake_HSREQ(uint32_t* srtdata, size_t /* srtlen - unused if (!m_bMessageAPI) srtdata[SRT_HS_FLAGS] |= SRT_OPT_STREAM; - LOGC(mglog.Debug) << "HSREQ/snd: LATENCY[SND:" << SRT_HS_LATENCY_SND::unwrap(srtdata[SRT_HS_LATENCY]) + LOGC(mglog.Debug, log << "HSREQ/snd: LATENCY[SND:" << SRT_HS_LATENCY_SND::unwrap(srtdata[SRT_HS_LATENCY]) << " RCV:" << SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY]) << "] FLAGS[" - << SrtFlagString(srtdata[SRT_HS_FLAGS]) << "]"; + << SrtFlagString(srtdata[SRT_HS_FLAGS]) << "]"); return 3; } @@ -1314,7 +1314,7 @@ size_t CUDT::fillSrtHandshake_HSRSP(uint32_t* srtdata, size_t /* srtlen - unused } else { - LOGC(mglog.Debug) << "HSRSP/snd: TSBPD off, NOT responding TSBPDRCV flag."; + LOGC(mglog.Debug, log << "HSRSP/snd: TSBPD off, NOT responding TSBPDRCV flag."); } // Hsv5, only when peer has declared TSBPD mode. @@ -1326,12 +1326,12 @@ size_t CUDT::fillSrtHandshake_HSRSP(uint32_t* srtdata, size_t /* srtlen - unused srtdata[SRT_HS_FLAGS] |= SRT_OPT_TSBPDSND; srtdata[SRT_HS_LATENCY] |= SRT_HS_LATENCY_SND::wrap(m_iPeerTsbPdDelay_ms); - LOGC(mglog.Debug) << "HSRSP/snd: HSv5 peer uses TSBPD, responding TSBPDSND latency=" << m_iPeerTsbPdDelay_ms; + LOGC(mglog.Debug, log << "HSRSP/snd: HSv5 peer uses TSBPD, responding TSBPDSND latency=" << m_iPeerTsbPdDelay_ms); } else { - LOGC(mglog.Debug) << "HSRSP/snd: HSv" << (hs_version == CUDT::HS_VERSION_UDT4 ? 4 : 5) - << " with peer TSBPD=" << (m_bPeerTsbPd ? "on" : "off") << " - NOT responding TSBPDSND"; + LOGC(mglog.Debug, log << "HSRSP/snd: HSv" << (hs_version == CUDT::HS_VERSION_UDT4 ? 4 : 5) + << " with peer TSBPD=" << (m_bPeerTsbPd ? "on" : "off") << " - NOT responding TSBPDSND"); } if (m_bTLPktDrop) @@ -1339,7 +1339,7 @@ size_t CUDT::fillSrtHandshake_HSRSP(uint32_t* srtdata, size_t /* srtlen - unused } else { - LOGC(mglog.Fatal) << "IPE: fillSrtHandshake_HSRSP: m_ullRcvPeerStartTime NOT SET!"; + LOGC(mglog.Fatal, log << "IPE: fillSrtHandshake_HSRSP: m_ullRcvPeerStartTime NOT SET!"); return 0; } @@ -1368,25 +1368,25 @@ size_t CUDT::fillSrtHandshake_HSRSP(uint32_t* srtdata, size_t /* srtlen - unused { // Peer does not request to use rexmit flag, if so, // we won't use as well. - LOGC(mglog.Debug) << "HSRSP/snd: AGENT understands REXMIT flag, but PEER DOES NOT. NOT setting."; + LOGC(mglog.Debug, log << "HSRSP/snd: AGENT understands REXMIT flag, but PEER DOES NOT. NOT setting."); } else { // Request that the rexmit bit be used as a part of msgno. srtdata[SRT_HS_FLAGS] |= SRT_OPT_REXMITFLG; - LOGC(mglog.Debug).form("HSRSP/snd: AGENT UNDERSTANDS REXMIT flag and PEER reported that it does, too." ); + LOGF(mglog.Debug, "HSRSP/snd: AGENT UNDERSTANDS REXMIT flag and PEER reported that it does, too." ); } } else { // Since this is now in the code, it can occur only in case when you change the // version specification in the build configuration. - LOGC(mglog.Debug).form("HSRSP/snd: AGENT DOES NOT UNDERSTAND REXMIT flag" ); + LOGF(mglog.Debug, "HSRSP/snd: AGENT DOES NOT UNDERSTAND REXMIT flag" ); } - LOGC(mglog.Debug) << "HSRSP/snd: LATENCY[SND:" << SRT_HS_LATENCY_SND::unwrap(srtdata[SRT_HS_LATENCY]) + LOGC(mglog.Debug, log << "HSRSP/snd: LATENCY[SND:" << SRT_HS_LATENCY_SND::unwrap(srtdata[SRT_HS_LATENCY]) << " RCV:" << SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY]) << "] FLAGS[" - << SrtFlagString(srtdata[SRT_HS_FLAGS]) << "]"; + << SrtFlagString(srtdata[SRT_HS_FLAGS]) << "]"); return 3; } @@ -1394,7 +1394,7 @@ size_t CUDT::fillSrtHandshake_HSRSP(uint32_t* srtdata, size_t /* srtlen - unused size_t CUDT::prepareSrtHsMsg(int cmd, uint32_t* srtdata, size_t size) { size_t srtlen = fillSrtHandshake(srtdata, size, cmd, handshakeVersion()); - LOGC(mglog.Debug).form("CMD:%s(%d) Len:%d Version: %s Flags: %08X (%s) sdelay:%d", + LOGF(mglog.Debug, "CMD:%s(%d) Len:%d Version: %s Flags: %08X (%s) sdelay:%d", MessageTypeStr(UMSG_EXT, cmd).c_str(), cmd, (int)(srtlen * sizeof(int32_t)), SrtVersionString(srtdata[SRT_HS_VERSION]).c_str(), srtdata[SRT_HS_FLAGS], @@ -1449,7 +1449,7 @@ void CUDT::sendSrtMsg(int cmd, uint32_t *srtdata_in, int srtlen_in) break; default: - LOGC(mglog.Error).form( "sndSrtMsg: cmd=%d unsupported", cmd); + LOGF(mglog.Error, "sndSrtMsg: cmd=%d unsupported", cmd); break; } @@ -1473,7 +1473,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, CPacket& pkt = *r_pkt; CHandShake& hs = *r_hs; - LOGC(mglog.Debug) << "createSrtHandshake: have buffer size=" << pkt.getLength() << " kmdata_wordsize=" << kmdata_wordsize; + LOGC(mglog.Debug, log << "createSrtHandshake: have buffer size=" << pkt.getLength() << " kmdata_wordsize=" << kmdata_wordsize); // values > URQ_CONCLUSION include also error types // if (hs.m_iVersion == HS_VERSION_UDT4 || hs.m_iReqType > URQ_CONCLUSION) <--- This condition was checked b4 and it's only valid for caller-listener mode @@ -1493,7 +1493,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, size_t hs_size = pkt.getLength(); hs.store_to(pkt.m_pcData, Ref(hs_size)); pkt.setLength(hs_size); - LOGC(mglog.Debug) << "createSrtHandshake: (no HSREQ/KMREQ ext) data: " << hs.show(); + LOGC(mglog.Debug, log << "createSrtHandshake: (no HSREQ/KMREQ ext) data: " << hs.show()); return true; } @@ -1533,7 +1533,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, // from the peer, but no such thing happened. In result, also don't // send any KMRSP. The connection will be unable to handle any sending // from Agent to Peer, but still sending Peer to Agent should work. - LOGC(mglog.Error) << "createSrtHandshake: Agent/responder declares encryption, but Peer/initiator did not. NOT SENDING KMRSP."; + LOGC(mglog.Error, log << "createSrtHandshake: Agent/responder declares encryption, but Peer/initiator did not. NOT SENDING KMRSP."); } else { @@ -1543,7 +1543,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, } } - LOGC(mglog.Debug) << "createSrtHandshake: (ext: " << logext << ") data: " << hs.show(); + LOGC(mglog.Debug, log << "createSrtHandshake: (ext: " << logext << ") data: " << hs.show()); // NOTE: The HSREQ is practically always required, although may happen // in future that CONCLUSION can be sent multiple times for a separate @@ -1572,7 +1572,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, ra_size = fillSrtHandshake(p+offset, total_ra_size - offset, srths_cmd, HS_VERSION_SRT1); *pcmdspec = HS_CMDSPEC_CMD::wrap(srths_cmd) | HS_CMDSPEC_SIZE::wrap(ra_size); - LOGC(mglog.Debug) << "createSrtHandshake: after HSREQ: offset=" << offset << " HSREQ size=" << ra_size << " space left: " << (total_ra_size - offset); + LOGC(mglog.Debug, log << "createSrtHandshake: after HSREQ: offset=" << offset << " HSREQ size=" << ra_size << " space left: " << (total_ra_size - offset)); if (have_sid) { @@ -1588,7 +1588,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, if ( m_sStreamName.size() >= size_limit ) { - LOGC(mglog.Error) << "createSrtHandshake: stream id too long, limited to " << (size_limit-1) << " bytes"; + LOGC(mglog.Error, log << "createSrtHandshake: stream id too long, limited to " << (size_limit-1) << " bytes"); return false; } @@ -1601,8 +1601,8 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, ra_size = wordsize; *pcmdspec = HS_CMDSPEC_CMD::wrap(SRT_CMD_SID) | HS_CMDSPEC_SIZE::wrap(ra_size); - LOGC(mglog.Debug) << "createSrtHandshake: after SID [" << m_sStreamName << "] length=" << m_sStreamName.size() << " alignedln=" << aligned_bytesize - << ": offset=" << offset << " SID size=" << ra_size << " space left: " << (total_ra_size - offset); + LOGC(mglog.Debug, log << "createSrtHandshake: after SID [" << m_sStreamName << "] length=" << m_sStreamName.size() << " alignedln=" << aligned_bytesize + << ": offset=" << offset << " SID size=" << ra_size << " space left: " << (total_ra_size - offset)); } if (have_smoother) @@ -1624,14 +1624,14 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, ra_size = wordsize; *pcmdspec = HS_CMDSPEC_CMD::wrap(SRT_CMD_SMOOTHER) | HS_CMDSPEC_SIZE::wrap(ra_size); - LOGC(mglog.Debug) << "createSrtHandshake: after SMOOTHER [" << sm << "] length=" << sm.size() << " alignedln=" << aligned_bytesize - << ": offset=" << offset << " SMOOTHER size=" << ra_size << " space left: " << (total_ra_size - offset); + LOGC(mglog.Debug, log << "createSrtHandshake: after SMOOTHER [" << sm << "] length=" << sm.size() << " alignedln=" << aligned_bytesize + << ": offset=" << offset << " SMOOTHER size=" << ra_size << " space left: " << (total_ra_size - offset)); } // When encryption turned on if (have_kmreq) { - LOGC(mglog.Debug) << "createSrtHandshake: Agent uses ENCRYPTION"; + LOGC(mglog.Debug, log << "createSrtHandshake: Agent uses ENCRYPTION"); if ( srtkm_cmd == SRT_CMD_KMREQ ) { bool have_any_keys = false; @@ -1659,8 +1659,8 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, // is ALREADY in network order. const uint32_t* keydata = reinterpret_cast(m_pCryptoControl->getKmMsg_data(ki)); - LOGC(mglog.Debug) << "createSrtHandshake: KMREQ: adding key #" << ki - << " length=" << ra_size << " words (KmMsg_size=" << msglen << ")"; + LOGC(mglog.Debug, log << "createSrtHandshake: KMREQ: adding key #" << ki + << " length=" << ra_size << " words (KmMsg_size=" << msglen << ")"); // XXX INSECURE ": [" << FormatBinaryString((uint8_t*)keydata, msglen) << "]"; // Yes, I know HtoNLA and NtoHLA do exactly the same operation, but I want @@ -1671,7 +1671,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, if ( !have_any_keys ) { - LOGC(mglog.Error) << "createSrtHandshake: IPE: all keys have expired, no KM to send."; + LOGC(mglog.Error, log << "createSrtHandshake: IPE: all keys have expired, no KM to send."); return false; } } @@ -1679,7 +1679,7 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, { if ( !kmdata || kmdata_wordsize == 0 ) { - LOGC(mglog.Fatal) << "createSrtHandshake: IPE: srtkm_cmd=SRT_CMD_KMRSP and no kmdata!"; + LOGC(mglog.Fatal, log << "createSrtHandshake: IPE: srtkm_cmd=SRT_CMD_KMRSP and no kmdata!"); return false; } @@ -1690,15 +1690,15 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, ra_size = kmdata_wordsize; *(p + offset) = HS_CMDSPEC_CMD::wrap(srtkm_cmd) | HS_CMDSPEC_SIZE::wrap(ra_size); ++offset; - LOGC(mglog.Debug) << "createSrtHandshake: KMRSP: applying returned key length=" - << ra_size; // XXX INSECURE << " words: [" << FormatBinaryString((uint8_t*)kmdata, kmdata_wordsize*sizeof(uint32_t)) << "]"; + LOGC(mglog.Debug, log << "createSrtHandshake: KMRSP: applying returned key length=" + << ra_size); // XXX INSECURE << " words: [" << FormatBinaryString((uint8_t*)kmdata, kmdata_wordsize*sizeof(uint32_t)) << "]"; const uint32_t* keydata = reinterpret_cast(kmdata); NtoHLA(p + offset, keydata, ra_size); } else { - LOGC(mglog.Fatal) << "createSrtHandshake: IPE: wrong value of srtkm_cmd: " << srtkm_cmd; + LOGC(mglog.Fatal, log << "createSrtHandshake: IPE: wrong value of srtkm_cmd: " << srtkm_cmd); return false; } } @@ -1707,8 +1707,8 @@ bool CUDT::createSrtHandshake(ref_t r_pkt, ref_t r_hs, // Switch it again to byte unit. pkt.setLength((ra_size + offset) * sizeof(int32_t)); - LOGC(mglog.Debug) << "createSrtHandshake: filled HSv5 handshake flags: " - << hs.m_iType << " length: " << pkt.getLength() << " bytes"; + LOGC(mglog.Debug, log << "createSrtHandshake: filled HSv5 handshake flags: " + << hs.m_iType << " length: " << pkt.getLength() << " bytes"); return true; } @@ -1778,7 +1778,7 @@ bool CUDT::processSrtMsg(const CPacket *ctrlpkt) int res = SRT_CMD_NONE; - LOGC(mglog.Debug) << "Dispatching message type=" << etype << " data length=" << (len/sizeof(int32_t)); + LOGC(mglog.Debug, log << "Dispatching message type=" << etype << " data length=" << (len/sizeof(int32_t))); switch (etype) { case SRT_CMD_HSREQ: @@ -1801,12 +1801,12 @@ bool CUDT::processSrtMsg(const CPacket *ctrlpkt) res = m_pCryptoControl->processSrtMsg_KMREQ(srtdata, len, srtdata_out, Ref(len_out), CUDT::HS_VERSION_UDT4); if ( res == SRT_CMD_KMRSP ) { - LOGC(mglog.Debug) << "KMREQ -> requested to send KMRSP length=" << len_out; + LOGC(mglog.Debug, log << "KMREQ -> requested to send KMRSP length=" << len_out); sendSrtMsg(SRT_CMD_KMRSP, srtdata_out, len_out); } else { - LOGC(mglog.Error) << "KMREQ failed to process the request - ignoring"; + LOGC(mglog.Error, log << "KMREQ failed to process the request - ignoring"); } return true; // already done what's necessary @@ -1847,7 +1847,7 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, uint64_t oldPeerStartTime = m_ullRcvPeerStartTime; m_ullRcvPeerStartTime = CTimer::getTime() - (uint64_t)((uint32_t)ts); if (oldPeerStartTime) { - LOGC(mglog.Note).form( "rcvSrtMsg: 2nd PeerStartTime diff=%lld usec", + LOGF(mglog.Note, "rcvSrtMsg: 2nd PeerStartTime diff=%lld usec", (long long)(m_ullRcvPeerStartTime - oldPeerStartTime)); } } @@ -1863,11 +1863,11 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, if (len < SRT_CMD_HSREQ_MINSZ) { /* Packet smaller than minimum compatible packet size */ - LOGC(mglog.Error).form( "HSREQ/rcv: cmd=%d(HSREQ) len=%zu invalid", SRT_CMD_HSREQ, len); + LOGF(mglog.Error, "HSREQ/rcv: cmd=%d(HSREQ) len=%zu invalid", SRT_CMD_HSREQ, len); return SRT_CMD_NONE; } - LOGC(mglog.Note).form( "HSREQ/rcv: cmd=%d(HSREQ) len=%zu vers=0x%x opts=0x%x delay=%d", + LOGF(mglog.Note, "HSREQ/rcv: cmd=%d(HSREQ) len=%zu vers=0x%x opts=0x%x delay=%d", SRT_CMD_HSREQ, len, srtdata[SRT_HS_VERSION], srtdata[SRT_HS_FLAGS], SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY])); @@ -1878,8 +1878,8 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, { if ( m_lPeerSrtVersion >= SRT_VERSION_FEAT_HSv5 ) { - LOGC(mglog.Error) << "HSREQ/rcv: With HSv4 version >= " - << SrtVersionString(SRT_VERSION_FEAT_HSv5) << " is not acceptable."; + LOGC(mglog.Error, log << "HSREQ/rcv: With HSv4 version >= " + << SrtVersionString(SRT_VERSION_FEAT_HSv5) << " is not acceptable."); return SRT_CMD_REJECT; } } @@ -1887,8 +1887,8 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, { if ( m_lPeerSrtVersion < SRT_VERSION_FEAT_HSv5 ) { - LOGC(mglog.Error) << "HSREQ/rcv: With HSv5 version must be >= " - << SrtVersionString(SRT_VERSION_FEAT_HSv5) << " ."; + LOGC(mglog.Error, log << "HSREQ/rcv: With HSv5 version must be >= " + << SrtVersionString(SRT_VERSION_FEAT_HSv5) << " ."); return SRT_CMD_REJECT; } } @@ -1896,26 +1896,26 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, // Check also if the version satisfies the minimum required version if ( m_lPeerSrtVersion < m_lMinimumPeerSrtVersion ) { - LOGC(mglog.Error) << "HSREQ/rcv: Peer version: " << SrtVersionString(m_lPeerSrtVersion) - << " is too old for requested: " << SrtVersionString(m_lMinimumPeerSrtVersion) << " - REJECTING"; + LOGC(mglog.Error, log << "HSREQ/rcv: Peer version: " << SrtVersionString(m_lPeerSrtVersion) + << " is too old for requested: " << SrtVersionString(m_lMinimumPeerSrtVersion) << " - REJECTING"); return SRT_CMD_REJECT; } - LOGC(mglog.Debug) << "HSREQ/rcv: PEER Version: " + LOGC(mglog.Debug, log << "HSREQ/rcv: PEER Version: " << SrtVersionString(m_lPeerSrtVersion) << " Flags: " << peer_srt_options - << "(" << SrtFlagString(peer_srt_options) << ")"; + << "(" << SrtFlagString(peer_srt_options) << ")"); m_bPeerRexmitFlag = IsSet(peer_srt_options, SRT_OPT_REXMITFLG); - LOGC(mglog.Debug).form("HSREQ/rcv: peer %s REXMIT flag", m_bPeerRexmitFlag ? "UNDERSTANDS" : "DOES NOT UNDERSTAND" ); + LOGF(mglog.Debug, "HSREQ/rcv: peer %s REXMIT flag", m_bPeerRexmitFlag ? "UNDERSTANDS" : "DOES NOT UNDERSTAND" ); // Check if both use the same API type. Reject if not. bool peer_message_api = !IsSet(peer_srt_options, SRT_OPT_STREAM); if ( peer_message_api != m_bMessageAPI ) { - LOGC(mglog.Error) << "HSREQ/rcv: Agent uses " + LOGC(mglog.Error, log << "HSREQ/rcv: Agent uses " << (m_bMessageAPI ? "MESSAGE" : "STREAM") << " API, but the Peer declares " - << (peer_message_api ? "MESSAGE" : "STREAM") << " API. Not compatible transmission type, rejecting."; + << (peer_message_api ? "MESSAGE" : "STREAM") << " API. Not compatible transmission type, rejecting."); return SRT_CMD_REJECT; } @@ -1926,11 +1926,11 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, // as the latency flags aren't set. if ( IsSet(peer_srt_options, SRT_OPT_TSBPDSND) || IsSet(peer_srt_options, SRT_OPT_TSBPDRCV) ) { - LOGC(mglog.Error) << "HSREQ/rcv: Peer sent only VERSION + FLAGS HSREQ, but TSBPD flags are set. Rejecting."; + LOGC(mglog.Error, log << "HSREQ/rcv: Peer sent only VERSION + FLAGS HSREQ, but TSBPD flags are set. Rejecting."); return SRT_CMD_REJECT; } - LOGC(mglog.Warn) << "HSREQ/rcv: Peer sent only VERSION + FLAGS HSREQ, not getting any TSBPD settings."; + LOGC(mglog.Warn, log << "HSREQ/rcv: Peer sent only VERSION + FLAGS HSREQ, not getting any TSBPD settings."); // Don't process any further settings in this case. Turn off TSBPD, just for a case. m_bTsbPd = false; m_bPeerTsbPd = false; @@ -1944,7 +1944,7 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, //TimeStamp-based Packet Delivery feature enabled if ( !m_bTsbPd ) { - LOGC(mglog.Warn) << "HSREQ/rcv: Agent did not set rcv-TSBPD - ignoring proposed latency from peer"; + LOGC(mglog.Warn, log << "HSREQ/rcv: Agent did not set rcv-TSBPD - ignoring proposed latency from peer"); // Note: also don't set the peer TSBPD flag HERE because // - in HSv4 it will be a sender, so it doesn't matter anyway @@ -1972,15 +1972,15 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, // Use the maximum latency out of latency from our settings and the latency // "proposed" by the peer. int maxdelay = std::max(m_iTsbPdDelay_ms, peer_decl_latency); - LOGC(mglog.Debug) << "HSREQ/rcv: LOCAL/RCV LATENCY: Agent:" << m_iTsbPdDelay_ms - << " Peer:" << peer_decl_latency << " Selecting:" << maxdelay; + LOGC(mglog.Debug, log << "HSREQ/rcv: LOCAL/RCV LATENCY: Agent:" << m_iTsbPdDelay_ms + << " Peer:" << peer_decl_latency << " Selecting:" << maxdelay); m_iTsbPdDelay_ms = maxdelay; } } else { std::string how_about_agent = m_bTsbPd ? "BUT AGENT DOES" : "and nor does Agent"; - LOGC(mglog.Debug) << "HSREQ/rcv: Peer DOES NOT USE latency for sending - " << how_about_agent; + LOGC(mglog.Debug, log << "HSREQ/rcv: Peer DOES NOT USE latency for sending - " << how_about_agent); } // This happens when the HSv5 RESPONDER receives the HSREQ message; it declares @@ -1998,14 +1998,14 @@ int CUDT::processSrtMsg_HSREQ(const uint32_t* srtdata, size_t len, uint32_t ts, // and select the maximum of this one and our proposed latency for the peer. int peer_decl_latency = SRT_HS_LATENCY_RCV::unwrap(latencystr); int maxdelay = std::max(m_iPeerTsbPdDelay_ms, peer_decl_latency); - LOGC(mglog.Debug) << "HSREQ/rcv: PEER/RCV LATENCY: Agent:" << m_iPeerTsbPdDelay_ms - << " Peer:" << peer_decl_latency << " Selecting:" << maxdelay; + LOGC(mglog.Debug, log << "HSREQ/rcv: PEER/RCV LATENCY: Agent:" << m_iPeerTsbPdDelay_ms + << " Peer:" << peer_decl_latency << " Selecting:" << maxdelay); m_iPeerTsbPdDelay_ms = maxdelay; } else { std::string how_about_agent = m_bTsbPd ? "BUT AGENT DOES" : "and nor does Agent"; - LOGC(mglog.Debug) << "HSREQ/rcv: Peer DOES NOT USE latency for receiving - " << how_about_agent; + LOGC(mglog.Debug, log << "HSREQ/rcv: Peer DOES NOT USE latency for receiving - " << how_about_agent); } if ( hsv > CUDT::HS_VERSION_UDT4 ) @@ -2034,14 +2034,14 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, // With HSv4 we accept only version less than 1.2.0 if ( hsv == CUDT::HS_VERSION_UDT4 && srtdata[SRT_HS_VERSION] >= SRT_VERSION_FEAT_HSv5 ) { - LOGC(mglog.Error) << "HSRSP/rcv: With HSv4 version >= 1.2.0 is not acceptable."; + LOGC(mglog.Error, log << "HSRSP/rcv: With HSv4 version >= 1.2.0 is not acceptable."); return SRT_CMD_NONE; } if (len < SRT_CMD_HSRSP_MINSZ) { /* Packet smaller than minimum compatible packet size */ - LOGC(mglog.Error).form( "HSRSP/rcv: cmd=%d(HSRSP) len=%zu invalid", SRT_CMD_HSRSP, len); + LOGF(mglog.Error, "HSRSP/rcv: cmd=%d(HSRSP) len=%zu invalid", SRT_CMD_HSRSP, len); return SRT_CMD_NONE; } @@ -2059,7 +2059,7 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, uint64_t oldPeerStartTime = m_ullRcvPeerStartTime; m_ullRcvPeerStartTime = CTimer::getTime() - (uint64_t)((uint32_t)ts); if (oldPeerStartTime) { - LOGC(mglog.Note).form( "rcvSrtMsg: 2nd PeerStartTime diff=%lld usec", + LOGF(mglog.Note, "rcvSrtMsg: 2nd PeerStartTime diff=%lld usec", (long long)(m_ullRcvPeerStartTime - oldPeerStartTime)); } } @@ -2070,7 +2070,7 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, m_lPeerSrtVersion = srtdata[SRT_HS_VERSION]; uint32_t peer_srt_options = srtdata[SRT_HS_FLAGS]; - LOGC(mglog.Debug).form("HSRSP/rcv: Version: %s Flags: SND:%08X (%s)", + LOGF(mglog.Debug, "HSRSP/rcv: Version: %s Flags: SND:%08X (%s)", SrtVersionString(m_lPeerSrtVersion).c_str(), peer_srt_options, SrtFlagString(peer_srt_options).c_str()); @@ -2084,8 +2084,8 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, //TsbPd feature enabled m_bPeerTsbPd = true; m_iPeerTsbPdDelay_ms = SRT_HS_LATENCY_LEG::unwrap(srtdata[SRT_HS_LATENCY]); - LOGC(mglog.Debug) << "HSRSP/rcv: LATENCY: Peer/snd:" << m_iPeerTsbPdDelay_ms - << " (Agent: declared:" << m_iTsbPdDelay_ms << " rcv:" << m_iTsbPdDelay_ms << ")"; + LOGC(mglog.Debug, log << "HSRSP/rcv: LATENCY: Peer/snd:" << m_iPeerTsbPdDelay_ms + << " (Agent: declared:" << m_iTsbPdDelay_ms << " rcv:" << m_iTsbPdDelay_ms << ")"); } // TSBPDSND isn't set in HSv4 by the RESPONDER, because HSv4 RESPONDER is always RECEIVER. } @@ -2098,25 +2098,25 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, //TsbPd feature enabled m_bPeerTsbPd = true; m_iPeerTsbPdDelay_ms = SRT_HS_LATENCY_RCV::unwrap(srtdata[SRT_HS_LATENCY]); - LOGC(mglog.Debug) << "HSRSP/rcv: LATENCY: Peer/snd:" << m_iPeerTsbPdDelay_ms << "ms"; + LOGC(mglog.Debug, log << "HSRSP/rcv: LATENCY: Peer/snd:" << m_iPeerTsbPdDelay_ms << "ms"); } else { - LOGC(mglog.Debug) << "HSRSP/rcv: Peer (responder) DOES NOT USE latency"; + LOGC(mglog.Debug, log << "HSRSP/rcv: Peer (responder) DOES NOT USE latency"); } if (IsSet(peer_srt_options, SRT_OPT_TSBPDSND)) { if (!m_bTsbPd) { - LOGC(mglog.Warn) << "HSRSP/rcv: BUG? Peer (responder) declares sending latency, but Agent turned off TSBPD."; + LOGC(mglog.Warn, log << "HSRSP/rcv: BUG? Peer (responder) declares sending latency, but Agent turned off TSBPD."); } else { // Take this value as a good deal. In case when the Peer did not "correct" the latency // because it has TSBPD turned off, just stay with the present value defined in options. m_iTsbPdDelay_ms = SRT_HS_LATENCY_SND::unwrap(srtdata[SRT_HS_LATENCY]); - LOGC(mglog.Debug) << "HSRSP/rcv: LATENCY Agent/rcv: " << m_iTsbPdDelay_ms << "ms"; + LOGC(mglog.Debug, log << "HSRSP/rcv: LATENCY Agent/rcv: " << m_iTsbPdDelay_ms << "ms"); } } } @@ -2148,7 +2148,7 @@ int CUDT::processSrtMsg_HSRSP(const uint32_t* srtdata, size_t len, uint32_t ts, } else { - LOGC(mglog.Debug).form("HSRSP/rcv: <1.2.0 Agent DOESN'T understand REXMIT flag"); + LOGF(mglog.Debug, "HSRSP/rcv: <1.2.0 Agent DOESN'T understand REXMIT flag"); } handshakeDone(); @@ -2167,7 +2167,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // The HSv4 sends the AGREEMENT handshake message with version=0, do not misinterpret it. if ( m_ConnRes.m_iVersion > HS_VERSION_UDT4 && hs.m_iVersion == 0 ) { - LOGC(mglog.Error) << "HS VERSION = 0, meaning the handshake has been rejected."; + LOGC(mglog.Error, log << "HS VERSION = 0, meaning the handshake has been rejected."); return false; } @@ -2179,7 +2179,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin { // This would mean that the handshake was at least HSv5, but somehow no extras were added. // Dismiss it then, however this has to be logged. - LOGC(mglog.Error) << "HS VERSION=" << hs.m_iVersion << " but no handshake extension found!"; + LOGC(mglog.Error, log << "HS VERSION=" << hs.m_iVersion << " but no handshake extension found!"); return false; } @@ -2188,11 +2188,11 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin if ( ext_flags == 0 ) { - LOGC(mglog.Error) << "HS VERSION=" << hs.m_iVersion << " but no handshake extension flags are set!"; + LOGC(mglog.Error, log << "HS VERSION=" << hs.m_iVersion << " but no handshake extension flags are set!"); return false; } - LOGC(mglog.Debug) << "HS VERSION=" << hs.m_iVersion << " EXTENSIONS: " << CHandShake::ExtensionFlagStr(ext_flags); + LOGC(mglog.Debug, log << "HS VERSION=" << hs.m_iVersion << " EXTENSIONS: " << CHandShake::ExtensionFlagStr(ext_flags)); // Ok, now find the beginning of an int32_t array that follows the UDT handshake. uint32_t* p = reinterpret_cast(hspkt.m_pcData + CHandShake::m_iContentSize); @@ -2200,7 +2200,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin if ( IsSet(ext_flags, CHandShake::HS_EXT_HSREQ) ) { - LOGC(mglog.Debug) << "interpretSrtHandshake: extracting HSREQ/RSP type extension"; + LOGC(mglog.Debug, log << "interpretSrtHandshake: extracting HSREQ/RSP type extension"); uint32_t* begin = p; uint32_t* next = 0; size_t length = size / sizeof(uint32_t); @@ -2218,8 +2218,8 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // the proper function. if ( blocklen < SRT_HS__SIZE ) { - LOGC(mglog.Error) << "HS-ext HSREQ found but invalid size: " << bytelen - << " (expected: " << SRT_HS__SIZE << ")"; + LOGC(mglog.Error, log << "HS-ext HSREQ found but invalid size: " << bytelen + << " (expected: " << SRT_HS__SIZE << ")"); return false; // don't interpret } @@ -2227,7 +2227,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // Interpreted? Then it should be responded with SRT_CMD_HSRSP. if ( rescmd != SRT_CMD_HSRSP ) { - LOGC(mglog.Error) << "interpretSrtHandshake: process HSREQ returned unexpected value " << rescmd; + LOGC(mglog.Error, log << "interpretSrtHandshake: process HSREQ returned unexpected value " << rescmd); return false; } handshakeDone(); @@ -2239,8 +2239,8 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // the proper function. if ( blocklen < SRT_HS__SIZE ) { - LOGC(mglog.Error) << "HS-ext HSRSP found but invalid size: " << bytelen - << " (expected: " << SRT_HS__SIZE << ")"; + LOGC(mglog.Error, log << "HS-ext HSRSP found but invalid size: " << bytelen + << " (expected: " << SRT_HS__SIZE << ")"); return false; // don't interpret } @@ -2250,7 +2250,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // (nothing to be responded for HSRSP, unless there was some kinda problem) if ( rescmd != SRT_CMD_NONE ) { - LOGC(mglog.Error) << "interpretSrtHandshake: process HSRSP returned unexpected value " << rescmd; + LOGC(mglog.Error, log << "interpretSrtHandshake: process HSRSP returned unexpected value " << rescmd); return false; } handshakeDone(); @@ -2258,7 +2258,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin } else if ( cmd == SRT_CMD_NONE ) { - LOGC(mglog.Error) << "interpretSrtHandshake: no HSREQ/HSRSP block found in the handshake msg!"; + LOGC(mglog.Error, log << "interpretSrtHandshake: no HSREQ/HSRSP block found in the handshake msg!"); // This means that there can be no more processing done by FindExtensionBlock(). // And we haven't found what we need - otherwise one of the above cases would pass // and lead to exit this loop immediately. @@ -2277,7 +2277,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin } } - LOGC(mglog.Debug) << "interpretSrtHandshake: HSREQ done, checking KMREQ"; + LOGC(mglog.Debug, log << "interpretSrtHandshake: HSREQ done, checking KMREQ"); // Now check the encrypted @@ -2285,11 +2285,11 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin if ( IsSet(ext_flags, CHandShake::HS_EXT_KMREQ) ) { - LOGC(mglog.Debug) << "interpretSrtHandshake: extracting KMREQ/RSP type extension"; + LOGC(mglog.Debug, log << "interpretSrtHandshake: extracting KMREQ/RSP type extension"); if (m_iSndCryptoKeyLen <= 0) { - LOGC(mglog.Error) << "HS KMREQ: Peer declares encryption, but agent does not."; + LOGC(mglog.Error, log << "HS KMREQ: Peer declares encryption, but agent does not."); // Still allow for connection, and allow Agent to send unencrypted stream to the peer. return true; @@ -2304,14 +2304,14 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin { int cmd = FindExtensionBlock(begin, length, Ref(blocklen), Ref(next)); - LOGC(mglog.Debug) << "interpretSrtHandshake: found extension: (" << cmd << ") " << MessageTypeStr(UMSG_EXT, cmd); + LOGC(mglog.Debug, log << "interpretSrtHandshake: found extension: (" << cmd << ") " << MessageTypeStr(UMSG_EXT, cmd)); size_t bytelen = blocklen*sizeof(uint32_t); if ( cmd == SRT_CMD_KMREQ ) { if ( !out_data || !out_len ) { - LOGC(mglog.Fatal) << "IPE: HS/KMREQ extracted without passing target buffer!"; + LOGC(mglog.Fatal, log << "IPE: HS/KMREQ extracted without passing target buffer!"); return false; } @@ -2319,7 +2319,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin if ( res != SRT_CMD_KMRSP ) { // Something went wrong. - LOGC(mglog.Debug) << "interpretSrtHandshake: KMREQ processing failed - returned " << res; + LOGC(mglog.Debug, log << "interpretSrtHandshake: KMREQ processing failed - returned " << res); return false; } encrypted = true; @@ -2332,12 +2332,12 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin } else if ( cmd == SRT_CMD_NONE ) { - LOGC(mglog.Error) << "HS KMREQ expected - none found!"; + LOGC(mglog.Error, log << "HS KMREQ expected - none found!"); return false; } else { - LOGC(mglog.Debug) << "interpretSrtHandshake: ... skipping " << MessageTypeStr(UMSG_EXT, cmd); + LOGC(mglog.Debug, log << "interpretSrtHandshake: ... skipping " << MessageTypeStr(UMSG_EXT, cmd)); if (NextExtensionBlock(Ref(begin), next, Ref(length))) continue; } @@ -2356,7 +2356,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin if ( IsSet(ext_flags, CHandShake::HS_EXT_CONFIG) ) { - LOGC(mglog.Debug) << "interpretSrtHandshake: extracting various CONFIG extensions"; + LOGC(mglog.Debug, log << "interpretSrtHandshake: extracting various CONFIG extensions"); uint32_t* begin = p; uint32_t* next = 0; @@ -2367,7 +2367,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin { int cmd = FindExtensionBlock(begin, length, Ref(blocklen), Ref(next)); - LOGC(mglog.Debug) << "interpretSrtHandshake: found extension: (" << cmd << ") " << MessageTypeStr(UMSG_EXT, cmd); + LOGC(mglog.Debug, log << "interpretSrtHandshake: found extension: (" << cmd << ") " << MessageTypeStr(UMSG_EXT, cmd)); size_t bytelen = blocklen*sizeof(uint32_t); if ( cmd == SRT_CMD_SID ) @@ -2384,13 +2384,13 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin memset(target, 0, MAX_SID_LENGTH+1); memcpy(target, begin+1, bytelen); m_sStreamName = target; - LOGC(mglog.Debug) << "CONNECTOR'S REQUESTED SID [" << m_sStreamName << "] (bytelen=" << bytelen << " blocklen=" << blocklen << ")"; + LOGC(mglog.Debug, log << "CONNECTOR'S REQUESTED SID [" << m_sStreamName << "] (bytelen=" << bytelen << " blocklen=" << blocklen << ")"); } else if ( cmd == SRT_CMD_SMOOTHER ) { if (have_smoother) { - LOGC(mglog.Error) << "SMOOTHER BLOCK REPEATED!"; + LOGC(mglog.Error, log << "SMOOTHER BLOCK REPEATED!"); return false; } // Declare that smoother has been received @@ -2406,11 +2406,11 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // sm cannot be empty, but the agent's sm can be empty meaning live. if (sm != agsm) { - LOGC(mglog.Error) << "PEER'S SMOOTHER '" << sm << "' does not match AGENT'S SMOOTHER '" << agsm << "'"; + LOGC(mglog.Error, log << "PEER'S SMOOTHER '" << sm << "' does not match AGENT'S SMOOTHER '" << agsm << "'"); return false; } - LOGC(mglog.Debug) << "CONNECTOR'S SMOOTHER [" << sm << "] (bytelen=" << bytelen << " blocklen=" << blocklen << ")"; + LOGC(mglog.Debug, log << "CONNECTOR'S SMOOTHER [" << sm << "] (bytelen=" << bytelen << " blocklen=" << blocklen << ")"); } else if ( cmd == SRT_CMD_NONE ) { @@ -2419,7 +2419,7 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin else { // Found some block that is not interesting here. Skip this and get the next one. - LOGC(mglog.Debug) << "interpretSrtHandshake: ... skipping " << MessageTypeStr(UMSG_EXT, cmd); + LOGC(mglog.Debug, log << "interpretSrtHandshake: ... skipping " << MessageTypeStr(UMSG_EXT, cmd)); } if ( !NextExtensionBlock(Ref(begin), next, Ref(length)) ) @@ -2431,14 +2431,14 @@ bool CUDT::interpretSrtHandshake(const CHandShake& hs, const CPacket& hspkt, uin // Check if peer declared encryption if ( !encrypted && m_iSndCryptoKeyLen > 0 ) { - LOGC(mglog.Error) << "HS EXT: Agent declares encryption, but Peer does not (Agent can still receive unencrypted packets from Peer)."; + LOGC(mglog.Error, log << "HS EXT: Agent declares encryption, but Peer does not (Agent can still receive unencrypted packets from Peer)."); return true; } // If agent has set some nondefault smoother, then smoother is expected from the peer. if (agsm != "live" && !have_smoother) { - LOGC(mglog.Error) << "HS EXT: Agent uses '" << agsm << "' smoother, but peer DID NOT DECLARE smoother (assuming 'live')."; + LOGC(mglog.Error, log << "HS EXT: Agent uses '" << agsm << "' smoother, but peer DID NOT DECLARE smoother (assuming 'live')."); return false; } @@ -2450,7 +2450,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) { CGuard cg(m_ConnectionLock); - LOGC(mglog.Debug) << "startConnect: -> " << SockaddrToString(serv_addr) << "..."; + LOGC(mglog.Debug, log << "startConnect: -> " << SockaddrToString(serv_addr) << "..."); if (!m_bOpened) throw CUDTException(MJ_NOTSUP, MN_NONE, 0); @@ -2576,7 +2576,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) uint64_t now = CTimer::getTime(); reqpkt.m_iTimeStamp = int32_t(now - m_StartTime); - LOGC(mglog.Debug) << CONID() << "CUDT::startConnect: REQ-TIME HIGH. SENDING HS: " << m_ConnReq.show(); + LOGC(mglog.Debug, log << CONID() << "CUDT::startConnect: REQ-TIME HIGH. SENDING HS: " << m_ConnReq.show()); /* * Race condition if non-block connect response thread scheduled before we set m_bConnecting to true? @@ -2627,7 +2627,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) // the next iteration. if (tdiff > 250000) { - LOGC(mglog.Debug) << "startConnect: LOOP: time to send (" << tdiff << " > 250000). size=" << reqpkt.getLength(); + LOGC(mglog.Debug, log << "startConnect: LOOP: time to send (" << tdiff << " > 250000). size=" << reqpkt.getLength()); if (m_bRendezvous) reqpkt.m_iID = m_ConnRes.m_iID; @@ -2636,7 +2636,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) { CHandShake debughs; debughs.load_from(reqpkt.m_pcData, reqpkt.getLength()); - LOGC(mglog.Debug) << CONID() << "startConnect: REQ-TIME HIGH. cont/sending HS to peer: " << debughs.show(); + LOGC(mglog.Debug, log << CONID() << "startConnect: REQ-TIME HIGH. cont/sending HS to peer: " << debughs.show()); } #endif @@ -2647,24 +2647,24 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) } else { - LOGC(mglog.Debug) << "startConnect: LOOP: too early to send - " << tdiff << " < 250000"; + LOGC(mglog.Debug, log << "startConnect: LOOP: too early to send - " << tdiff << " < 250000"); } EConnectStatus cst = CONN_CONTINUE; response.setLength(m_iMaxSRTPayloadSize); if (m_pRcvQueue->recvfrom(m_SocketID, Ref(response)) > 0) { - LOGC(mglog.Debug) << CONID() << "startConnect: got response for connect request"; + LOGC(mglog.Debug, log << CONID() << "startConnect: got response for connect request"); cst = processConnectResponse(response, &e, true /*synchro*/); - LOGC(mglog.Debug) << CONID() << "startConnect: response processing result: " + LOGC(mglog.Debug, log << CONID() << "startConnect: response processing result: " << (cst == CONN_CONTINUE ? "INDUCED/CONCLUDING" : cst == CONN_ACCEPT ? "ACCEPTED" : cst == CONN_RENDEZVOUS ? "RENDEZVOUS (HSv5)" - : "REJECTED"); + : "REJECTED")); // Expected is that: // - the peer responded with URQ_INDUCTION + cookie. This above function @@ -2708,7 +2708,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) // [[using assert(m_pCryptoControl != nullptr)]]; // new request/response should be sent out immediately on receving a response - LOGC(mglog.Debug) << "startConnect: REQ-TIME: LOW, should resend request quickly."; + LOGC(mglog.Debug, log << "startConnect: REQ-TIME: LOW, should resend request quickly."); m_llLastReqTime = 0; // (if security needed, set the SECURING state) @@ -2730,7 +2730,7 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) // small to store the CONCLUSION handshake (with HSv5 extensions). reqpkt.setLength(m_iMaxSRTPayloadSize); - LOGC(mglog.Debug) << "startConnect: creating HS CONCLUSION: buffer size=" << reqpkt.getLength(); + LOGC(mglog.Debug, log << "startConnect: creating HS CONCLUSION: buffer size=" << reqpkt.getLength()); // NOTE: BUGFIX: SERIALIZE AGAIN. // The original UDT code didn't do it, so it was theoretically @@ -2781,15 +2781,15 @@ void CUDT::startConnect(const sockaddr* serv_addr, int32_t forced_isn) if (e.getErrorCode() != 0) throw e; - LOGC(mglog.Debug) << CONID() << "startConnect: handshake exchange succeeded"; + LOGC(mglog.Debug, log << CONID() << "startConnect: handshake exchange succeeded"); // Parameters at the end. - LOGC(mglog.Debug) << "startConnect: END. Parameters:" + LOGC(mglog.Debug, log << "startConnect: END. Parameters:" " mss=" << m_iMSS << " max-cwnd-size=" << m_Smoother->cgWindowMaxSize() << " cwnd-size=" << m_Smoother->cgWindowSize() << " rtt=" << m_iRTT << - " bw=" << m_iBandwidth; + " bw=" << m_iBandwidth); } // Asynchronous connection @@ -2799,11 +2799,11 @@ EConnectStatus CUDT::processAsyncConnectResponse(const CPacket& pkt) ATR_NOEXCEP CUDTException e; CGuard cg(m_ConnectionLock); // FIX - LOGC(mglog.Debug) << CONID() << "processAsyncConnectResponse: got response for connect request, processing"; + LOGC(mglog.Debug, log << CONID() << "processAsyncConnectResponse: got response for connect request, processing"); cst = processConnectResponse(pkt, &e, false); - LOGC(mglog.Debug) << CONID() << "processAsyncConnectResponse: response processing result: " - << ConnectStatusStr(cst); + LOGC(mglog.Debug, log << CONID() << "processAsyncConnectResponse: response processing result: " + << ConnectStatusStr(cst)); return cst; } @@ -2823,41 +2823,38 @@ bool CUDT::processAsyncConnectRequest(EConnectStatus cst, const CPacket& respons uint64_t now = CTimer::getTime(); request.m_iTimeStamp = int(now - this->m_StartTime); - LOGC(mglog.Debug) << "startConnect: REQ-TIME: HIGH. Should prevent too quick responses."; + LOGC(mglog.Debug, log << "startConnect: REQ-TIME: HIGH. Should prevent too quick responses."); m_llLastReqTime = now; // ID = 0, connection request request.m_iID = !m_bRendezvous ? 0 : m_ConnRes.m_iID; if ( cst == CONN_RENDEZVOUS ) { - LOGC(mglog.Debug) << "processAsyncConnectRequest: passing to processRendezvous"; + LOGC(mglog.Debug, log << "processAsyncConnectRequest: passing to processRendezvous"); cst = processRendezvous(Ref(request), response, serv_addr, false /*asynchro*/); if (cst == CONN_ACCEPT) { - LOGC(mglog.Debug) << "processAsyncConnectRequest: processRendezvous completed the process and responded by itself. Done."; + LOGC(mglog.Debug, log << "processAsyncConnectRequest: processRendezvous completed the process and responded by itself. Done."); return true; } if (cst != CONN_CONTINUE) { - LOGC(mglog.Error) << "processAsyncConnectRequest: REJECT reported from processRendezvous, not processing further."; + LOGC(mglog.Error, log << "processAsyncConnectRequest: REJECT reported from processRendezvous, not processing further."); return false; } } else { // (this procedure will be also run for HSv4 rendezvous) - size_t hs_size = m_iMaxSRTPayloadSize; - LOGC(mglog.Debug) << "processAsyncConnectRequest: serializing HS: buffer size=" << request.getLength(); + LOGC(mglog.Debug, log << "processAsyncConnectRequest: serializing HS: buffer size=" << request.getLength()); if (!createSrtHandshake(Ref(request), Ref(m_ConnReq), SRT_CMD_HSREQ, SRT_CMD_KMREQ, 0, 0)) { - LOGC(mglog.Error) << "IPE: processAsyncConnectRequest: createSrtHandshake failed, dismissing."; + LOGC(mglog.Error, log << "IPE: processAsyncConnectRequest: createSrtHandshake failed, dismissing."); return false; } - hs_size = request.getLength(); - - LOGC(mglog.Debug) << "processAsyncConnectRequest: sending HS reqtype=" << RequestTypeStr(m_ConnReq.m_iReqType) - << " to socket " << request.m_iID << " size=" << hs_size; + LOGC(mglog.Debug, log << "processAsyncConnectRequest: sending HS reqtype=" << RequestTypeStr(m_ConnReq.m_iReqType) + << " to socket " << request.m_iID << " size=" << request.getLength()); } m_pSndQueue->sendto(serv_addr, request); @@ -2911,7 +2908,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res { if ( m_RdvState == CHandShake::RDV_CONNECTED ) { - LOGC(mglog.Debug) << "processRendezvous: already in CONNECTED state."; + LOGC(mglog.Debug, log << "processRendezvous: already in CONNECTED state."); return CONN_ACCEPT; } @@ -2941,7 +2938,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res if (rsp_type > URQ_FAILURE_TYPES) { - LOGC(mglog.Debug) << "processRendezvous: rejecting due to switch-state response: " << RequestTypeStr(rsp_type); + LOGC(mglog.Debug, log << "processRendezvous: rejecting due to switch-state response: " << RequestTypeStr(rsp_type)); return CONN_REJECT; } @@ -2951,7 +2948,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // This must be done before interpreting and creating HSv5 extensions. if ( !prepareConnectionObjects(m_ConnRes, m_SrtHsSide, 0)) { - LOGC(mglog.Debug) << "processRendezvous: rejecting due to problems in prepareConnectionObjects."; + LOGC(mglog.Debug, log << "processRendezvous: rejecting due to problems in prepareConnectionObjects."); return CONN_REJECT; } @@ -2968,13 +2965,13 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // Case 2. if ( needs_hsrsp ) { - LOGC(mglog.Debug) << "startConnect: REQ-TIME: LOW. Respond immediately."; + LOGC(mglog.Debug, log << "startConnect: REQ-TIME: LOW. Respond immediately."); m_llLastReqTime = 0; // This means that we have received HSREQ extension with the handshake, so we need to interpret // it and craft the response. if ( !interpretSrtHandshake(m_ConnRes, response, kmdata, &kmdatasize) ) { - LOGC(mglog.Debug) << "processRendezvous: rejecting due to problems in interpretSrtHandshake."; + LOGC(mglog.Debug, log << "processRendezvous: rejecting due to problems in interpretSrtHandshake."); return CONN_REJECT; } @@ -2982,12 +2979,12 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // when HSREQ was interpreted (to store HSRSP extension). m_ConnReq.m_extension = true; - LOGC(mglog.Debug) << "processConnectResponse: HSREQ extension ok, creating HSRSP response. kmdatasize=" << kmdatasize; + LOGC(mglog.Debug, log << "processConnectResponse: HSREQ extension ok, creating HSRSP response. kmdatasize=" << kmdatasize); rpkt.setLength(m_iMaxSRTPayloadSize); if (!createSrtHandshake(reqpkt, Ref(m_ConnReq), SRT_CMD_HSRSP, SRT_CMD_KMRSP, kmdata, kmdatasize)) { - LOGC(mglog.Debug) << "processRendezvous: rejecting due to problems in createSrtHandshake."; + LOGC(mglog.Debug, log << "processRendezvous: rejecting due to problems in createSrtHandshake."); return CONN_REJECT; } @@ -3004,7 +3001,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // The same is done in CUDT::postConnect(), however this section will // not be done in case of rendezvous. The section in postConnect() is // predicted to run only in regular CALLER handling. - LOGC(mglog.Debug) << "processRendezvous: INITIATOR, will send AGREEMENT - interpreting HSRSP extension"; + LOGC(mglog.Debug, log << "processRendezvous: INITIATOR, will send AGREEMENT - interpreting HSRSP extension"); if ( !interpretSrtHandshake(m_ConnRes, response, 0, 0) ) { m_ConnReq.m_iReqType = URQ_ERROR_REJECT; @@ -3012,21 +3009,25 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // This should be false, make a kinda assert here. if ( needs_extension ) { - LOGC(mglog.Fatal) << "IPE: INITIATOR responding AGREEMENT should declare no extensions to HS"; + LOGC(mglog.Fatal, log << "IPE: INITIATOR responding AGREEMENT should declare no extensions to HS"); m_ConnReq.m_extension = false; } } - LOGC(mglog.Debug) << CONID() << "processRendezvous: COOKIES Agent/Peer: " + LOGC(mglog.Debug, log << CONID() << "processRendezvous: COOKIES Agent/Peer: " << m_ConnReq.m_iCookie << "/" << m_ConnRes.m_iCookie << " HSD:" << (m_SrtHsSide == HSD_INITIATOR ? "initiator" : "responder") - << " STATE:" << CHandShake::RdvStateStr(m_RdvState) << " ..."; + << " STATE:" << CHandShake::RdvStateStr(m_RdvState) << " ..."); if ( rsp_type == URQ_DONE ) - LOGC(mglog.Debug) << "... WON'T SEND any response, both sides considered connected"; + { + LOGC(mglog.Debug, log << "... WON'T SEND any response, both sides considered connected"); + } else - LOGC(mglog.Debug) << "... WILL SEND " << RequestTypeStr(rsp_type) << " " - << (m_ConnReq.m_extension ? "with" : "without") << " SRT HS extensions"; + { + LOGC(mglog.Debug, log << "... WILL SEND " << RequestTypeStr(rsp_type) << " " + << (m_ConnReq.m_extension ? "with" : "without") << " SRT HS extensions"); + } // This marks the information for the serializer that // the SRT handshake extension is required. @@ -3048,7 +3049,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res int cst = postConnect(response, true, 0, synchro); if ( cst == CONN_REJECT ) { - LOGC(mglog.Debug) << "processRendezvous: rejecting due to problems in postConnect."; + LOGC(mglog.Debug, log << "processRendezvous: rejecting due to problems in postConnect."); return CONN_REJECT; } } @@ -3059,7 +3060,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // this time with URQ_AGREEMENT message, but still consider yourself connected. if ( rsp_type == URQ_DONE ) { - LOGC(mglog.Debug) << "processRendezvous: rsp=DONE, reporting ACCEPT (nothing to respond)"; + LOGC(mglog.Debug, log << "processRendezvous: rsp=DONE, reporting ACCEPT (nothing to respond)"); return CONN_ACCEPT; } @@ -3079,7 +3080,7 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res // catalyzer here and may turn the entity on the right track faster. When // AGREEMENT is missed, it may have kinda initial tearing. - LOGC(mglog.Debug) << "processRendezvous: rsp=AGREEMENT, reporting ACCEPT and sending just this one, REQ-TIME HIGH."; + LOGC(mglog.Debug, log << "processRendezvous: rsp=AGREEMENT, reporting ACCEPT and sending just this one, REQ-TIME HIGH."); uint64_t now = CTimer::getTime(); m_llLastReqTime = now; rpkt.m_iTimeStamp = int32_t(now - m_StartTime); @@ -3089,9 +3090,9 @@ EConnectStatus CUDT::processRendezvous(ref_t reqpkt, const CPacket& res } // the request time must be updated so that the next handshake can be sent out immediately. - LOGC(mglog.Debug) << "startConnect: REQ-TIME: LOW. Respond immediately."; + LOGC(mglog.Debug, log << "startConnect: REQ-TIME: LOW. Respond immediately."); m_llLastReqTime = 0; - LOGC(mglog.Debug) << "processRendezvous: rsp=" << RequestTypeStr(m_ConnReq.m_iReqType) << " SENDING response, but consider yourself conencted"; + LOGC(mglog.Debug, log << "processRendezvous: rsp=" << RequestTypeStr(m_ConnReq.m_iReqType) << " SENDING response, but consider yourself conencted"); return CONN_CONTINUE; } @@ -3110,7 +3111,7 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti // This is required in HSv5 rendezvous, in which it should send the URQ_AGREEMENT message to // the peer, however switch to connected state. - LOGC(mglog.Debug) << "processConnectResponse: TYPE:" << MessageTypeStr(response.getType(), response.getExtendedType()); + LOGC(mglog.Debug, log << "processConnectResponse: TYPE:" << MessageTypeStr(response.getType(), response.getExtendedType())); //ConnectStatus res = CONN_REJECT; // used later for status - must be declared here due to goto POST_CONNECT. // For HSv4, the data sender is INITIATOR, and the data receiver is RESPONDER, @@ -3146,7 +3147,7 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti //a data packet or a keep-alive packet comes, which means the peer side is already connected // in this situation, the previously recorded response will be used // In HSv5 this situation is theoretically possible if this party has missed the URQ_AGREEMENT message. - LOGC(mglog.Debug) << CONID() << "processConnectResponse: already connected - pinning in"; + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: already connected - pinning in"); if (hsv5) { m_RdvState = CHandShake::RDV_CONNECTED; @@ -3157,19 +3158,19 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti if ( !response.isControl(UMSG_HANDSHAKE) ) { - LOGC(mglog.Error) << CONID() << "processConnectResponse: received non-addresed packet not UMSG_HANDSHAKE: " - << MessageTypeStr(response.getType(), response.getExtendedType()); + LOGC(mglog.Error, log << CONID() << "processConnectResponse: received non-addresed packet not UMSG_HANDSHAKE: " + << MessageTypeStr(response.getType(), response.getExtendedType())); return CONN_REJECT; } if ( m_ConnRes.load_from(response.m_pcData, response.getLength()) == -1 ) { // Handshake data were too small to reach the Handshake structure. Reject. - LOGC(mglog.Error) << CONID() << "processConnectResponse: HANDSHAKE data buffer too small - possible blueboxing. Rejecting."; + LOGC(mglog.Error, log << CONID() << "processConnectResponse: HANDSHAKE data buffer too small - possible blueboxing. Rejecting."); return CONN_REJECT; } - LOGC(mglog.Debug) << CONID() << "processConnectResponse: HS RECEIVED: " << m_ConnRes.show(); + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: HS RECEIVED: " << m_ConnRes.show()); if ( m_ConnRes.m_iReqType > URQ_FAILURE_TYPES ) { return CONN_REJECT; @@ -3179,7 +3180,7 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti { // Yes, we do abort to prevent buffer overrun. Set your MSS correctly // and you'll avoid problems. - LOGC(mglog.Fatal) << "MSS size " << m_iMSS << "exceeds MTU size!"; + LOGC(mglog.Fatal, log << "MSS size " << m_iMSS << "exceeds MTU size!"); return CONN_REJECT; } @@ -3193,7 +3194,7 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti // SANITY CHECK: A rendezvous socket should reject any caller requests (it's not a listener) if (m_ConnRes.m_iReqType == URQ_INDUCTION) { - LOGC(mglog.Error) << CONID() << "processConnectResponse: Rendezvous-point received INDUCTION handshake (expected WAVEAHAND). Rejecting."; + LOGC(mglog.Error, log << CONID() << "processConnectResponse: Rendezvous-point received INDUCTION handshake (expected WAVEAHAND). Rejecting."); return CONN_REJECT; } @@ -3202,11 +3203,11 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti if ( m_ConnRes.m_iVersion > HS_VERSION_UDT4 ) { - LOGC(mglog.Debug) << CONID() << "processConnectResponse: Rendezvous HSv5 DETECTED."; + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: Rendezvous HSv5 DETECTED."); return CONN_RENDEZVOUS; // --> will continue in CUDT::processRendezvous(). } - LOGC(mglog.Debug) << CONID() << "processConnectResponse: Rendsezvous HSv4 DETECTED."; + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: Rendsezvous HSv4 DETECTED."); // So, here it has either received URQ_WAVEAHAND handshake message (while it should be in URQ_WAVEAHAND itself) // or it has received URQ_CONCLUSION/URQ_AGREEMENT message while this box has already sent URQ_WAVEAHAND to the peer, // and DID NOT send the URQ_CONCLUSION yet. @@ -3214,8 +3215,8 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti if ( m_ConnReq.m_iReqType == URQ_WAVEAHAND || m_ConnRes.m_iReqType == URQ_WAVEAHAND ) { - LOGC(mglog.Debug) << CONID() << "processConnectResponse: REQ-TIME LOW. got HS RDV. Agent state:" << RequestTypeStr(m_ConnReq.m_iReqType) - << " Peer HS:" << m_ConnRes.show(); + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: REQ-TIME LOW. got HS RDV. Agent state:" << RequestTypeStr(m_ConnReq.m_iReqType) + << " Peer HS:" << m_ConnRes.show()); // Here we could have received WAVEAHAND or CONCLUSION. // For HSv4 simply switch to CONCLUSION for the sake of further handshake rolling. @@ -3231,7 +3232,7 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti } else { - LOGC(mglog.Debug) << CONID() << "processConnectResponse: Rendezvous HSv4 PAST waveahand"; + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: Rendezvous HSv4 PAST waveahand"); } } else @@ -3239,8 +3240,8 @@ EConnectStatus CUDT::processConnectResponse(const CPacket& response, CUDTExcepti // set cookie if (m_ConnRes.m_iReqType == URQ_INDUCTION) { - LOGC(mglog.Debug) << CONID() << "processConnectResponse: REQ-TIME LOW; got INDUCTION HS response (cookie:" - << hex << m_ConnRes.m_iCookie << " version:" << dec << m_ConnRes.m_iVersion << "), sending CONCLUSION HS with this cookie"; + LOGC(mglog.Debug, log << CONID() << "processConnectResponse: REQ-TIME LOW; got INDUCTION HS response (cookie:" + << hex << m_ConnRes.m_iCookie << " version:" << dec << m_ConnRes.m_iVersion << "), sending CONCLUSION HS with this cookie"); m_ConnReq.m_iCookie = m_ConnRes.m_iCookie; m_ConnReq.m_iReqType = URQ_CONCLUSION; @@ -3300,11 +3301,11 @@ void CUDT::applyResponseSettings() m_PeerID = m_ConnRes.m_iID; memcpy(m_piSelfIP, m_ConnRes.m_piPeerIP, 16); - LOGC(mglog.Debug) << CONID() << "applyResponseSettings: HANSHAKE CONCLUDED. SETTING: payload-size=" << m_iMaxSRTPayloadSize + LOGC(mglog.Debug, log << CONID() << "applyResponseSettings: HANSHAKE CONCLUDED. SETTING: payload-size=" << m_iMaxSRTPayloadSize << " mss=" << m_ConnRes.m_iMSS << " flw=" << m_ConnRes.m_iFlightFlagSize << " isn=" << m_ConnRes.m_iISN - << " peerID=" << m_ConnRes.m_iID; + << " peerID=" << m_ConnRes.m_iID); } EConnectStatus CUDT::postConnect(const CPacket& response, bool rendezvous, CUDTException* eout, bool synchro) @@ -3425,7 +3426,7 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need #if ENABLE_LOGGING - LOGC(mglog.Debug) << "rendezvousSwitchState: HS: " << m_ConnRes.show(); + LOGC(mglog.Debug, log << "rendezvousSwitchState: HS: " << m_ConnRes.show()); struct LogAtTheEnd { @@ -3440,10 +3441,10 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need ost(st), orq(rq), nst(rst), nrq(rrq), needext(needx), reason(rsn) {} ~LogAtTheEnd() { - LOGC(mglog.Debug) << "rendezvousSwitchState: STATE[" + LOGC(mglog.Debug, log << "rendezvousSwitchState: STATE[" << CHandShake::RdvStateStr(ost) << "->" << CHandShake::RdvStateStr(nst) << "] REQTYPE[" << RequestTypeStr(orq) << "->" << RequestTypeStr(nrq) << "] " - << (needext ? "HSREQ-ext" : "") << (reason == "" ? string() : "reason:" + reason); + << (needext ? "HSREQ-ext" : "") << (reason == "" ? string() : "reason:" + reason)); } } l_logend(m_RdvState, req, m_RdvState, *rsptype, *needs_extension, reason); @@ -3509,8 +3510,8 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need // If no HSRSP attached, stay in this state. if (m_ConnRes.m_iType == 0) { - LOGC(mglog.Debug) << "rendezvousSwitchState: " - "{INITIATOR}[ATTENTION] awaits CONCLUSION+HSRSP, got CONCLUSION, remain in [ATTENTION]"; + LOGC(mglog.Debug, log << "rendezvousSwitchState: " + "{INITIATOR}[ATTENTION] awaits CONCLUSION+HSRSP, got CONCLUSION, remain in [ATTENTION]"); *rsptype = URQ_CONCLUSION; return false; } @@ -3585,7 +3586,7 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need { // Received REPEATED empty conclusion that has initially switched it into FINE state. // To exit FINE state we need the CONCLUSION message with HSRSP. - LOGC(mglog.Debug) << "rendezvousSwitchState: {INITIATOR}[FINE] rsptype, ref_t need // it to FINE state. That CONCLUSION message should have contained extension, // so if this is a repeated CONCLUSION+HSREQ, it should be responded with // CONCLUSION+HSRSP. - LOGC(mglog.Debug) << "rendezvousSwitchState: {RESPONDER}[FINE] rsptype, ref_t need *rsptype = URQ_CONCLUSION; if ( hsd == HSD_RESPONDER ) { - LOGC(mglog.Debug) << "rendezvousSwitchState: " + LOGC(mglog.Debug, log << "rendezvousSwitchState: " "{RESPONDER}[INITIATED] awaits AGREEMENT, " - "got CONCLUSION, sending CONCLUSION+HSRSP"; + "got CONCLUSION, sending CONCLUSION+HSRSP"); *needs_extension = true; return true; } @@ -3665,16 +3666,16 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need // HSREQ, and set responding HSRSP in that case. if ( m_ConnRes.m_iType == 0 ) { - LOGC(mglog.Debug) << "rendezvousSwitchState: " + LOGC(mglog.Debug, log << "rendezvousSwitchState: " "{INITIATOR}[INITIATED] awaits AGREEMENT, " - "got empty CONCLUSION, responding empty CONCLUSION"; + "got empty CONCLUSION, responding empty CONCLUSION"); *needs_extension = false; return false; } - LOGC(mglog.Debug) << "rendezvousSwitchState: " + LOGC(mglog.Debug, log << "rendezvousSwitchState: " "{INITIATOR}[INITIATED] awaits AGREEMENT, " - "got CONCLUSION+HSREQ, responding CONCLUSION+HSRSP"; + "got CONCLUSION+HSREQ, responding CONCLUSION+HSRSP"); *needs_extension = true; return true; } @@ -3689,7 +3690,7 @@ bool CUDT::rendezvousSwitchState(ref_t rsptype, ref_t need return false; } - LOGC(mglog.Debug) << "rendezvousSwitchState: INVALID STATE TRANSITION, result: INVALID"; + LOGC(mglog.Debug, log << "rendezvousSwitchState: INVALID STATE TRANSITION, result: INVALID"); // All others are treated as errors m_RdvState = CHandShake::RDV_WAVING; *rsptype = URQ_ERROR_INVALID; @@ -3761,15 +3762,16 @@ void* CUDT::tsbpd(void* param) self->m_iRcvLastSkipAck = skiptoseqno; +#if ENABLE_LOGGING uint64_t now = CTimer::getTime(); - int64_t timediff = 0; if ( tsbpdtime ) timediff = int64_t(now) - int64_t(tsbpdtime); - LOGC(tslog.Note) << self->CONID() << "tsbpd: DROPSEQ: up to seq=" << CSeqNo::decseq(skiptoseqno) + LOGC(tslog.Note, log << self->CONID() << "tsbpd: DROPSEQ: up to seq=" << CSeqNo::decseq(skiptoseqno) << " (" << seqlen << " packets) playable at " << logging::FormatTime(tsbpdtime) << " delayed " - << (timediff/1000) << "." << (timediff%1000) << " ms"; + << (timediff/1000) << "." << (timediff%1000) << " ms"); +#endif tsbpdtime = 0; //Next sent ack will unblock rxready = false; @@ -3790,9 +3792,8 @@ void* CUDT::tsbpd(void* param) if (rxready) { - int seq = current_pkt_seq; - LOGC(tslog.Debug) << self->CONID() << "tsbpd: PLAYING PACKET seq=" << seq - << " (belated " << ((CTimer::getTime() - tsbpdtime)/1000.0) << "ms)"; + LOGC(tslog.Debug, log << self->CONID() << "tsbpd: PLAYING PACKET seq=" << current_pkt_seq + << " (belated " << ((CTimer::getTime() - tsbpdtime)/1000.0) << "ms)"); /* * There are packets ready to be delivered * signal a waiting "recv" call if there is any data available @@ -3819,10 +3820,8 @@ void* CUDT::tsbpd(void* param) timespec locktime; locktime.tv_sec = tsbpdtime / 1000000; locktime.tv_nsec = (tsbpdtime % 1000000) * 1000; - int seq = current_pkt_seq; - uint64_t now = CTimer::getTime(); - LOGC(tslog.Debug) << self->CONID() << "tsbpd: FUTURE PACKET seq=" << seq - << " T=" << logging::FormatTime(tsbpdtime) << " - waiting " << ((tsbpdtime - now)/1000.0) << "ms"; + LOGC(tslog.Debug, log << self->CONID() << "tsbpd: FUTURE PACKET seq=" << current_pkt_seq + << " T=" << logging::FormatTime(tsbpdtime) << " - waiting " << ((tsbpdtime - CTimer::getTime())/1000.0) << "ms"); pthread_cond_timedwait(&self->m_RcvTsbPdCond, &self->m_RecvLock, &locktime); THREAD_RESUMED(); } @@ -3838,7 +3837,7 @@ void* CUDT::tsbpd(void* param) * - New buffers ACKed * - Closing the connection */ - LOGC(tslog.Debug) << self->CONID() << "tsbpd: no data, scheduling wakeup at ack"; + LOGC(tslog.Debug, log << self->CONID() << "tsbpd: no data, scheduling wakeup at ack"); self->m_bTsbPdAckWakeup = true; THREAD_PAUSED(); pthread_cond_wait(&self->m_RcvTsbPdCond, &self->m_RecvLock); @@ -3847,7 +3846,7 @@ void* CUDT::tsbpd(void* param) } CGuard::leaveCS(self->m_RecvLock); THREAD_EXIT(); - LOGC(tslog.Debug) << self->CONID() << "tsbpd: EXITING"; + LOGC(tslog.Debug, log << self->CONID() << "tsbpd: EXITING"); return NULL; } @@ -3859,7 +3858,7 @@ bool CUDT::prepareConnectionObjects(const CHandShake& hs, HandshakeSide hsd, CUD // be run once in the whole connection process. if (m_pSndBuffer) { - LOGC(mglog.Debug) << "prepareConnectionObjects: (lazy) already created."; + LOGC(mglog.Debug, log << "prepareConnectionObjects: (lazy) already created."); return true; } @@ -3911,7 +3910,7 @@ bool CUDT::prepareConnectionObjects(const CHandShake& hs, HandshakeSide hsd, CUD void CUDT::acceptAndRespond(const sockaddr* peer, CHandShake* hs, const CPacket& hspkt) { - LOGC(mglog.Debug) << "acceptAndRespond: setting up data according to handshake"; + LOGC(mglog.Debug, log << "acceptAndRespond: setting up data according to handshake"); CGuard cg(m_ConnectionLock); @@ -3968,7 +3967,7 @@ void CUDT::acceptAndRespond(const sockaddr* peer, CHandShake* hs, const CPacket& int udpsize = m_iMSS - CPacket::UDP_HDR_SIZE; m_iMaxSRTPayloadSize = udpsize - CPacket::HDR_SIZE; - LOGC(mglog.Debug) << "acceptAndRespond: PAYLOAD SIZE: " << m_iMaxSRTPayloadSize; + LOGC(mglog.Debug, log << "acceptAndRespond: PAYLOAD SIZE: " << m_iMaxSRTPayloadSize); // Prepare all structures prepareConnectionObjects(*hs, HSD_DRAW, 0); @@ -3991,7 +3990,7 @@ void CUDT::acceptAndRespond(const sockaddr* peer, CHandShake* hs, const CPacket& size_t kmdatasize = SRTDATA_MAXSIZE; if ( !interpretSrtHandshake(*hs, hspkt, kmdata, &kmdatasize) ) { - LOGC(mglog.Debug) << "acceptAndRespond: interpretSrtHandshake failed - responding with REJECT."; + LOGC(mglog.Debug, log << "acceptAndRespond: interpretSrtHandshake failed - responding with REJECT."); // If the SRT Handshake extension was provided and wasn't interpreted // correctly, the connection should be rejected. // @@ -4026,7 +4025,7 @@ void CUDT::acceptAndRespond(const sockaddr* peer, CHandShake* hs, const CPacket& response.allocate(size); // This will serialize the handshake according to its current form. - LOGC(mglog.Debug) << "acceptAndRespond: creating CONCLUSION response (HSv5: with HSRSP/KMRSP) buffer size=" << size; + LOGC(mglog.Debug, log << "acceptAndRespond: creating CONCLUSION response (HSv5: with HSRSP/KMRSP) buffer size=" << size); if (!createSrtHandshake(Ref(response), Ref(*hs), SRT_CMD_HSRSP, SRT_CMD_KMRSP, kmdata, kmdatasize)) { throw CUDTException(MJ_SETUP, MN_REJECTED, 0); @@ -4038,10 +4037,10 @@ void CUDT::acceptAndRespond(const sockaddr* peer, CHandShake* hs, const CPacket& // data that have been just written into the buffer. CHandShake debughs; debughs.load_from(response.m_pcData, response.getLength()); - LOGC(mglog.Debug) << CONID() << "acceptAndRespond: sending HS to peer, reqtype=" + LOGC(mglog.Debug, log << CONID() << "acceptAndRespond: sending HS to peer, reqtype=" << RequestTypeStr(debughs.m_iReqType) << " version=" << debughs.m_iVersion << " (connreq:" << RequestTypeStr(m_ConnReq.m_iReqType) - << "), target_socket=" << response.m_iID << ", my_socket=" << debughs.m_iID; + << "), target_socket=" << response.m_iID << ", my_socket=" << debughs.m_iID); } #endif m_pSndQueue->sendto(peer, response); @@ -4106,11 +4105,11 @@ void CUDT::setupCC() if ( min_nak_tk ) m_ullMinNakInt_tk = min_nak_tk; - LOGC(mglog.Debug) << "setupCC: setting parameters: mss=" << m_iMSS + LOGC(mglog.Debug, log << "setupCC: setting parameters: mss=" << m_iMSS << " maxCWNDSize/FlowWindowSize=" << m_iFlowWindowSize << " rcvrate=" << m_iDeliveryRate << "p/s (" << m_iByteDeliveryRate << "B/S)" << " rtt=" << m_iRTT - << " bw=" << m_iBandwidth; + << " bw=" << m_iBandwidth); updateCC(TEV_INIT, TEV_INIT_RESET); } @@ -4180,13 +4179,13 @@ void CUDT::close() return; } - LOGC(mglog.Debug) << CONID() << " - closing socket:"; + LOGC(mglog.Debug, log << CONID() << " - closing socket:"); if (m_Linger.l_onoff != 0) { uint64_t entertime = CTimer::getTime(); - LOGC(mglog.Debug) << CONID() << " ... (linger)"; + LOGC(mglog.Debug, log << CONID() << " ... (linger)"); while (!m_bBroken && m_bConnected && (m_pSndBuffer->getCurrBufSize() > 0) && (CTimer::getTime() - entertime < m_Linger.l_linger * 1000000ULL)) { // linger has been checked by previous close() call and has expired @@ -4245,14 +4244,14 @@ void CUDT::close() // Inform the threads handler to stop. m_bClosing = true; - LOGC(mglog.Debug) << CONID() << "CLOSING STATE. Acquiring connection lock"; + LOGC(mglog.Debug, log << CONID() << "CLOSING STATE. Acquiring connection lock"); CGuard cg(m_ConnectionLock); // Signal the sender and recver if they are waiting for data. releaseSynch(); - LOGC(mglog.Debug) << CONID() << "CLOSING, removing from listener/connector"; + LOGC(mglog.Debug, log << CONID() << "CLOSING, removing from listener/connector"); if (m_bListening) { @@ -4268,7 +4267,7 @@ void CUDT::close() { if (!m_bShutdown) { - LOGC(mglog.Debug) << CONID() << "CLOSING - sending SHUTDOWN to the peer"; + LOGC(mglog.Debug, log << CONID() << "CLOSING - sending SHUTDOWN to the peer"); sendCtrl(UMSG_SHUTDOWN); } @@ -4287,13 +4286,13 @@ void CUDT::close() if ( m_bTsbPd && !pthread_equal(m_RcvTsbPdThread, pthread_t())) { - LOGC(mglog.Debug) << "CLOSING, joining TSBPD thread..."; + LOGC(mglog.Debug, log << "CLOSING, joining TSBPD thread..."); void* retval; - int ret = pthread_join(m_RcvTsbPdThread, &retval); - LOGC(mglog.Debug) << "... " << (ret == 0 ? "SUCCEEDED" : "FAILED"); + int ret SRT_ATR_UNUSED = pthread_join(m_RcvTsbPdThread, &retval); + LOGC(mglog.Debug, log << "... " << (ret == 0 ? "SUCCEEDED" : "FAILED")); } - LOGC(mglog.Debug) << "CLOSING, joining send/receive threads"; + LOGC(mglog.Debug, log << "CLOSING, joining send/receive threads"); // waiting all send and recv calls to stop CGuard sendguard(m_SendLock); @@ -4440,10 +4439,10 @@ int CUDT::receiveBuffer(char* data, int len) // make this function return 0, potentially also without breaking // the connection and potentially also with losing no ability to // send some larger portion of data next time. - LOGC(mglog.Debug) << "STREAM API, SHUTDOWN: marking as EOF"; + LOGC(mglog.Debug, log << "STREAM API, SHUTDOWN: marking as EOF"); return 0; } - LOGC(mglog.Debug) << (m_bMessageAPI ? "MESSAGE" : "STREAM") << " API, " << (m_bShutdown?"":"no") << " SHUTDOWN. Reporting as BROKEN."; + LOGC(mglog.Debug, log << (m_bMessageAPI ? "MESSAGE" : "STREAM") << " API, " << (m_bShutdown?"":"no") << " SHUTDOWN. Reporting as BROKEN."); throw CUDTException(MJ_CONNECTION, MN_CONNLOST, 0); } @@ -4496,10 +4495,10 @@ int CUDT::receiveBuffer(char* data, int len) // See at the beginning if (!m_bMessageAPI && m_bShutdown) { - LOGC(mglog.Debug) << "STREAM API, SHUTDOWN: marking as EOF"; + LOGC(mglog.Debug, log << "STREAM API, SHUTDOWN: marking as EOF"); return 0; } - LOGC(mglog.Debug) << (m_bMessageAPI ? "MESSAGE" : "STREAM") << " API, " << (m_bShutdown?"":"no") << " SHUTDOWN. Reporting as BROKEN."; + LOGC(mglog.Debug, log << (m_bMessageAPI ? "MESSAGE" : "STREAM") << " API, " << (m_bShutdown?"":"no") << " SHUTDOWN. Reporting as BROKEN."); throw CUDTException(MJ_CONNECTION, MN_CONNLOST, 0); } @@ -4534,7 +4533,7 @@ void CUDT::checkNeedDrop(ref_t bCongestion) if (!m_bMessageAPI) { - LOGC(dlog.Error) << "The SRTO_TLPKTDROP flag can only be used with message API."; + LOGC(dlog.Error, log << "The SRTO_TLPKTDROP flag can only be used with message API."); throw CUDTException(MJ_NOTSUP, MN_INVALBUFFERAPI, 0); } @@ -4562,7 +4561,9 @@ void CUDT::checkNeedDrop(ref_t bCongestion) m_ullTraceSndBytesDrop += dbytes; m_ullSndBytesDropTotal += dbytes; - int32_t realack = m_iSndLastDataAck; // needed for log only +#if ENABLE_LOGGING + int32_t realack = m_iSndLastDataAck; +#endif int32_t fakeack = CSeqNo::incseq(m_iSndLastDataAck, dpkts); m_iSndLastAck = fakeack; @@ -4576,7 +4577,7 @@ void CUDT::checkNeedDrop(ref_t bCongestion) { m_iSndCurrSeqNo = minlastack; } - LOGC(dlog.Debug).form("drop,now %lluus,%d-%d seqs,%d pkts,%d bytes,%d ms", + LOGF(dlog.Debug, "drop,now %lluus,%d-%d seqs,%d pkts,%d bytes,%d ms", (unsigned long long)CTimer::getTime(), realack, m_iSndCurrSeqNo, dpkts, dbytes, timespan_ms); @@ -4586,7 +4587,7 @@ void CUDT::checkNeedDrop(ref_t bCongestion) } else if (timespan_ms > (m_iPeerTsbPdDelay_ms/2)) { - LOGC(mglog.Debug).form("cong, NOW: %lluus, BYTES %d, TMSPAN %dms", (unsigned long long)CTimer::getTime(), bytes, timespan_ms); + LOGF(mglog.Debug, "cong, NOW: %lluus, BYTES %d, TMSPAN %dms", (unsigned long long)CTimer::getTime(), bytes, timespan_ms); *bCongestion = true; } } @@ -4614,7 +4615,7 @@ int CUDT::sendmsg2(const char* data, int len, ref_t r_mctrl) if (len <= 0) { - LOGC(dlog.Error) << "INVALID: Data size for sending declared with length: " << len; + LOGC(dlog.Error, log << "INVALID: Data size for sending declared with length: " << len); return 0; } @@ -4657,8 +4658,8 @@ int CUDT::sendmsg2(const char* data, int len, ref_t r_mctrl) if (m_bMessageAPI && len > int(m_iSndBufSize * m_iMaxSRTPayloadSize)) { - LOGC(dlog.Error) << "Message length (" << len << ") exceeds the size of sending buffer: " - << (m_iSndBufSize * m_iMaxSRTPayloadSize) << ". Use SRTO_SNDBUF if needed."; + LOGC(dlog.Error, log << "Message length (" << len << ") exceeds the size of sending buffer: " + << (m_iSndBufSize * m_iMaxSRTPayloadSize) << ". Use SRTO_SNDBUF if needed."); throw CUDTException(MJ_NOTSUP, MN_XSIZE, 0); } @@ -4755,7 +4756,7 @@ int CUDT::sendmsg2(const char* data, int len, ref_t r_mctrl) // - m_bPeerHealth condition is checked and responded with PEERERROR // // ERGO: never happens? - LOGC(mglog.Fatal) << "IPE: sendmsg: the loop exited, while not enough size, still connected, peer healthy. Impossible."; + LOGC(mglog.Fatal, log << "IPE: sendmsg: the loop exited, while not enough size, still connected, peer healthy. Impossible."); return 0; } @@ -4787,7 +4788,7 @@ int CUDT::sendmsg2(const char* data, int len, ref_t r_mctrl) } #endif m_pSndBuffer->addBuffer(data, size, mctrl.msgttl, mctrl.inorder, mctrl.srctime, Ref(mctrl.msgno)); - LOGC(dlog.Debug) << CONID() << "sock:SENDING srctime: " << mctrl.srctime << "us DATA SIZE: " << size; + LOGC(dlog.Debug, log << CONID() << "sock:SENDING srctime: " << mctrl.srctime << "us DATA SIZE: " << size); // insert this socket to the snd list if it is not on the list yet m_pSndQueue->m_pSndUList->update(this, CSndUList::rescheduleIf(bCongestion)); @@ -4812,7 +4813,7 @@ int CUDT::recv(char* data, int len) if (len <= 0) { - LOGC(dlog.Error) << "Length of '" << len << "' supplied to srt_recv."; + LOGC(dlog.Error, log << "Length of '" << len << "' supplied to srt_recv."); throw CUDTException(MJ_NOTSUP, MN_INVAL, 0); } @@ -4832,7 +4833,7 @@ int CUDT::recvmsg(char* data, int len, uint64_t& srctime) if (len <= 0) { - LOGC(dlog.Error) << "Length of '" << len << "' supplied to srt_recvmsg."; + LOGC(dlog.Error, log << "Length of '" << len << "' supplied to srt_recvmsg."); throw CUDTException(MJ_NOTSUP, MN_INVAL, 0); } @@ -4854,7 +4855,7 @@ int CUDT::recvmsg2(char* data, int len, ref_t mctrl) if (len <= 0) { - LOGC(dlog.Error) << "Length of '" << len << "' supplied to srt_recvmsg."; + LOGC(dlog.Error, log << "Length of '" << len << "' supplied to srt_recvmsg."); throw CUDTException(MJ_NOTSUP, MN_INVAL, 0); } @@ -4941,8 +4942,8 @@ int CUDT::receiveMessage(char* data, int len, ref_t r_mctrl) s_UDTUnited.m_EPoll.update_events(m_SocketID, m_sPollID, UDT_EPOLL_IN, false); // After signaling the tsbpd for ready data, report the bandwidth. - double bw = Bps2Mbps( m_iBandwidth * m_iMaxSRTPayloadSize ); - LOGC(mglog.Debug) << CONID() << "CURRENT BANDWIDTH: " << bw << "Mbps (" << m_iBandwidth << " buffers per second)"; + double bw SRT_ATR_UNUSED = Bps2Mbps( m_iBandwidth * m_iMaxSRTPayloadSize ); + LOGC(mglog.Debug, log << CONID() << "CURRENT BANDWIDTH: " << bw << "Mbps (" << m_iBandwidth << " buffers per second)"); } return res; } @@ -5175,7 +5176,7 @@ int64_t CUDT::recvfile(fstream& ofs, int64_t& offset, int64_t size, int block) if (m_bTsbPd) { - LOGC(dlog.Error) << "Reading from file is incompatible with TSBPD mode and would cause a deadlock\n"; + LOGC(dlog.Error, log << "Reading from file is incompatible with TSBPD mode and would cause a deadlock\n"); throw CUDTException(MJ_NOTSUP, MN_INVALBUFFERAPI, 0); } @@ -5527,17 +5528,15 @@ void CUDT::updateCC(ETransmissionEvent evt, EventVariant arg) // time when the sending buffer. For sanity check, check both first. if (!m_Smoother.ready() || !m_pSndBuffer) { - bool both = !m_Smoother.ready() && !m_pSndBuffer; - LOGC(mglog.Error) << "updateCC: CAN'T DO UPDATE - smoother " + LOGC(mglog.Error, log << "updateCC: CAN'T DO UPDATE - smoother " << (m_Smoother.ready() ? "ready" : "NOT READY") - << (both ? ", and " : ", but ") - << " sending buffer " - << (m_pSndBuffer ? "NOT CREATED" : "created"); + << "; sending buffer " + << (m_pSndBuffer ? "NOT CREATED" : "created")); return; } - LOGC(mglog.Debug) << "updateCC: EVENT:" << TransmissionEventStr(evt); + LOGC(mglog.Debug, log << "updateCC: EVENT:" << TransmissionEventStr(evt)); if (evt == TEV_INIT) { @@ -5550,7 +5549,7 @@ void CUDT::updateCC(ETransmissionEvent evt, EventVariant arg) if (only_input && m_llMaxBW) { - LOGC(mglog.Debug) << "updateCC/TEV_INIT: non-RESET stage and m_llMaxBW already set to " << m_llMaxBW; + LOGC(mglog.Debug, log << "updateCC/TEV_INIT: non-RESET stage and m_llMaxBW already set to " << m_llMaxBW); // Don't change } else // either m_llMaxBW == 0 or only_input == TEV_INIT_RESET @@ -5578,9 +5577,9 @@ void CUDT::updateCC(ETransmissionEvent evt, EventVariant arg) m_pSndBuffer->setInputRateSmpPeriod(bw == 0 ? 500000 : 0); } - LOGC(mglog.Debug) << "updateCC/TEV_INIT: updating BW=" << m_llMaxBW + LOGC(mglog.Debug, log << "updateCC/TEV_INIT: updating BW=" << m_llMaxBW << (only_input == TEV_INIT_RESET ? " (UNCHANGED)" - : only_input == TEV_INIT_OHEADBW ? " (only Overhead)": " (updated sampling rate)"); + : only_input == TEV_INIT_OHEADBW ? " (only Overhead)": " (updated sampling rate)")); } } @@ -5615,7 +5614,7 @@ void CUDT::updateCC(ETransmissionEvent evt, EventVariant arg) } } - LOGC(mglog.Debug) << "udpateCC: emitting signal for EVENT:" << TransmissionEventStr(evt); + LOGC(mglog.Debug, log << "udpateCC: emitting signal for EVENT:" << TransmissionEventStr(evt)); // Now execute a smoother-defined action for that event. EmitSignal(evt, arg); @@ -5631,13 +5630,13 @@ void CUDT::updateCC(ETransmissionEvent evt, EventVariant arg) m_ullInterval_tk = (uint64_t)(m_Smoother->pktSndPeriod_us() * m_ullCPUFrequency); m_dCongestionWindow = m_Smoother->cgWindowSize(); #if ENABLE_LOGGING - LOGC(mglog.Debug) << "updateCC: updated values from smoother: interval=" << m_ullInterval_tk + LOGC(mglog.Debug, log << "updateCC: updated values from smoother: interval=" << m_ullInterval_tk << "tk (" << m_Smoother->pktSndPeriod_us() << "us) cgwindow=" - << std::setprecision(3) << m_dCongestionWindow; + << std::setprecision(3) << m_dCongestionWindow); #endif } - LOGC(mglog.Debug) << "udpateCC: finished handling for EVENT:" << TransmissionEventStr(evt); + LOGC(mglog.Debug, log << "udpateCC: finished handling for EVENT:" << TransmissionEventStr(evt)); #if 0//debug static int callcnt = 0; @@ -5706,7 +5705,7 @@ static void DebugAck(string hdr, int prev, int ack) { if ( !prev ) { - LOGC(mglog.Debug) << hdr << "ACK " << ack; + LOGC(mglog.Debug, log << hdr << "ACK " << ack); return; } @@ -5714,7 +5713,7 @@ static void DebugAck(string hdr, int prev, int ack) int diff = CSeqNo::seqcmp(ack, prev); if ( diff < 0 ) { - LOGC(mglog.Debug) << hdr << "ACK ERROR: " << prev << "-" << ack << "(diff " << CSeqNo::seqcmp(ack, prev) << ")"; + LOGC(mglog.Debug, log << hdr << "ACK ERROR: " << prev << "-" << ack << "(diff " << CSeqNo::seqcmp(ack, prev) << ")"); return; } @@ -5727,7 +5726,7 @@ static void DebugAck(string hdr, int prev, int ack) ackv << prev << " "; if ( shorted ) ackv << "..."; - LOGC(mglog.Debug) << hdr << "ACK (" << (diff+1) << "): " << ackv.str() << ack; + LOGC(mglog.Debug, log << hdr << "ACK (" << (diff+1) << "): " << ackv.str() << ack); } #else static inline void DebugAck(string, int, int) {} @@ -6050,8 +6049,8 @@ void CUDT::processCtrl(CPacket& ctrlpkt) m_ullLastRspTime_tk = currtime_tk; bool using_rexmit_flag = m_bPeerRexmitFlag; - LOGC(mglog.Debug) << CONID() << "incoming UMSG:" << ctrlpkt.getType() << " (" - << MessageTypeStr(ctrlpkt.getType(), ctrlpkt.getExtendedType()) << ") socket=%" << ctrlpkt.m_iID; + LOGC(mglog.Debug, log << CONID() << "incoming UMSG:" << ctrlpkt.getType() << " (" + << MessageTypeStr(ctrlpkt.getType(), ctrlpkt.getExtendedType()) << ") socket=%" << ctrlpkt.m_iID); switch (ctrlpkt.getType()) { @@ -6067,7 +6066,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) if (CSeqNo::seqcmp(ack, m_iSndLastAck) >= 0) { m_iFlowWindowSize -= CSeqNo::seqoff(m_iSndLastAck, ack); - LOGC(mglog.Debug) << CONID() << "ACK covers: " << m_iSndLastDataAck << " - " << ack << " [ACK=" << m_iSndLastAck << "] (FLW: " << m_iFlowWindowSize << ") [LITE]"; + LOGC(mglog.Debug, log << CONID() << "ACK covers: " << m_iSndLastDataAck << " - " << ack << " [ACK=" << m_iSndLastAck << "] (FLW: " << m_iFlowWindowSize << ") [LITE]"); m_iSndLastAck = ack; m_ullLastRspAckTime_tk = currtime_tk; @@ -6104,7 +6103,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) { CGuard::leaveCS(m_AckLock); //this should not happen: attack or bug - LOGC(glog.Error) << CONID() << "ATTACK/IPE: incoming ack seq " << ack << " exceeds current " << m_iSndCurrSeqNo << " by " << seqdiff << "!"; + LOGC(glog.Error, log << CONID() << "ATTACK/IPE: incoming ack seq " << ack << " exceeds current " << m_iSndCurrSeqNo << " by " << seqdiff << "!"); m_bBroken = true; m_iBrokenCounter = 0; break; @@ -6149,10 +6148,10 @@ void CUDT::processCtrl(CPacket& ctrlpkt) m_llSndDurationTotal += currtime - m_llSndDurationCounter; m_llSndDurationCounter = currtime; - LOGC(mglog.Debug) << CONID() << "ACK covers: " << m_iSndLastDataAck << " - " << ack + LOGC(mglog.Debug, log << CONID() << "ACK covers: " << m_iSndLastDataAck << " - " << ack << " [ACK=" << m_iSndLastAck << "] BUFr=" << m_iFlowWindowSize << " RTT=" << ackdata[ACKD_RTT] << " RTT*=" << ackdata[ACKD_RTTVAR] - << " BW=" << ackdata[ACKD_BANDWIDTH] << " Vrec=" << ackdata[ACKD_RCVSPEED]; + << " BW=" << ackdata[ACKD_BANDWIDTH] << " Vrec=" << ackdata[ACKD_RCVSPEED]); // update sending variables m_iSndLastDataAck = ack; @@ -6227,13 +6226,13 @@ void CUDT::processCtrl(CPacket& ctrlpkt) if ( wrongsize ) { // Issue a log, but don't do anything but skipping the "odd" bytes from the payload. - LOGC(mglog.Error) << CONID() << "Received UMSG_ACK payload is not evened up to 4-byte based field size - cutting to " << acksize << " fields"; + LOGC(mglog.Error, log << CONID() << "Received UMSG_ACK payload is not evened up to 4-byte based field size - cutting to " << acksize << " fields"); } // Start with checking the base size. if ( acksize < ACKD_TOTAL_SIZE_SMALL ) { - LOGC(mglog.Error) << CONID() << "Invalid ACK size " << acksize << " fields - less than minimum required!"; + LOGC(mglog.Error, log << CONID() << "Invalid ACK size " << acksize << " fields - less than minimum required!"); // Ack is already interpreted, just skip further parts. break; } @@ -6309,8 +6308,8 @@ void CUDT::processCtrl(CPacket& ctrlpkt) rtt = m_ACKWindow.acknowledge(ctrlpkt.getAckSeqNo(), ack); if (rtt <= 0) { - LOGC(mglog.Error) << "IPE: ACK node overwritten when acknowledging " << - ctrlpkt.getAckSeqNo() << " (ack extracted: " << ack << ")"; + LOGC(mglog.Error, log << "IPE: ACK node overwritten when acknowledging " << + ctrlpkt.getAckSeqNo() << " (ack extracted: " << ack << ")"); break; } @@ -6360,7 +6359,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) // specification means that the consecutive cell has been already interpreted. ++ i; - LOGC(mglog.Debug).form("received UMSG_LOSSREPORT: %d-%d (%d packets)...", losslist_lo, losslist_hi, CSeqNo::seqcmp(losslist_hi, losslist_lo)+1); + LOGF(mglog.Debug, "received UMSG_LOSSREPORT: %d-%d (%d packets)...", losslist_lo, losslist_hi, CSeqNo::seqcmp(losslist_hi, losslist_lo)+1); if ((CSeqNo::seqcmp(losslist_lo, losslist_hi) > 0) || (CSeqNo::seqcmp(losslist_hi, m_iSndCurrSeqNo) > 0)) { @@ -6392,7 +6391,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) } else if (CSeqNo::seqcmp(losslist[i], m_iSndLastAck) >= 0) { - LOGC(mglog.Debug).form("received UMSG_LOSSREPORT: %d (1 packet)...", losslist[i]); + LOGF(mglog.Debug, "received UMSG_LOSSREPORT: %d (1 packet)...", losslist[i]); if (CSeqNo::seqcmp(losslist[i], m_iSndCurrSeqNo) > 0) { @@ -6412,7 +6411,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) if (!secure) { - LOGC(mglog.Debug).form("WARNING: out-of-band LOSSREPORT received; considered bug or attack"); + LOGF(mglog.Debug, "WARNING: out-of-band LOSSREPORT received; considered bug or attack"); //this should not happen: attack or bug m_bBroken = true; m_iBrokenCounter = 0; @@ -6450,7 +6449,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) CHandShake req; req.load_from(ctrlpkt.m_pcData, ctrlpkt.getLength()); - LOGC(mglog.Debug) << "processCtrl: got HS: " << req.show(); + LOGC(mglog.Debug, log << "processCtrl: got HS: " << req.show()); if ((req.m_iReqType > URQ_INDUCTION_TYPES) // acually it catches URQ_INDUCTION and URQ_ERROR_* symbols...??? || (m_bRendezvous && (req.m_iReqType != URQ_AGREEMENT))) // rnd sends AGREEMENT in rsp to CONCLUSION @@ -6480,7 +6479,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) initdata.m_iVersion = HS_VERSION_SRT1; // if I remember correctly, this is induction/listener... if ( req.m_iType != 0 ) // has SRT extensions { - LOGC(mglog.Debug) << "processCtrl/HS: got HS reqtype=" << RequestTypeStr(req.m_iReqType) << " WITH SRT ext"; + LOGC(mglog.Debug, log << "processCtrl/HS: got HS reqtype=" << RequestTypeStr(req.m_iReqType) << " WITH SRT ext"); have_hsreq = interpretSrtHandshake(req, ctrlpkt, kmdata, &kmdatasize); if ( !have_hsreq ) { @@ -6494,7 +6493,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) } else { - LOGC(mglog.Debug) << "processCtrl/HS: got HS reqtype=" << RequestTypeStr(req.m_iReqType); + LOGC(mglog.Debug, log << "processCtrl/HS: got HS reqtype=" << RequestTypeStr(req.m_iReqType)); } } else @@ -6504,7 +6503,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) initdata.m_extension = have_hsreq; - LOGC(mglog.Debug) << CONID() << "processCtrl: responding HS reqtype=" << RequestTypeStr(initdata.m_iReqType) << (have_hsreq ? " WITH SRT HS response extensions" : ""); + LOGC(mglog.Debug, log << CONID() << "processCtrl: responding HS reqtype=" << RequestTypeStr(initdata.m_iReqType) << (have_hsreq ? " WITH SRT HS response extensions" : "")); // XXX here interpret SRT handshake extension CPacket response; @@ -6531,7 +6530,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) } else { - LOGC(mglog.Debug) << "processCtrl: ... not INDUCTION, not ERROR, not rendezvous - IGNORED."; + LOGC(mglog.Debug, log << "processCtrl: ... not INDUCTION, not ERROR, not rendezvous - IGNORED."); } break; @@ -6580,7 +6579,7 @@ void CUDT::processCtrl(CPacket& ctrlpkt) break; case UMSG_EXT: //0x7FFF - reserved and user defined messages - LOGC(mglog.Debug).form("CONTROL EXT MSG RECEIVED: %08X\n", ctrlpkt.getExtendedType()); + LOGF(mglog.Debug, "CONTROL EXT MSG RECEIVED: %08X\n", ctrlpkt.getExtendedType()); { // This has currently two roles in SRT: // - HSv4 (legacy) handshake @@ -6618,13 +6617,13 @@ void CUDT::updateSrtRcvSettings() m_pRcvBuffer->setRcvTsbPdMode(m_ullRcvPeerStartTime, m_iTsbPdDelay_ms * 1000); CGuard::leaveCS(m_RecvLock); - LOGC(mglog.Debug).form( "AFTER HS: Set Rcv TsbPd mode: delay=%u.%03u secs", + LOGF(mglog.Debug, "AFTER HS: Set Rcv TsbPd mode: delay=%u.%03u secs", m_iTsbPdDelay_ms/1000, m_iTsbPdDelay_ms%1000); } else { - LOGC(mglog.Debug) << "AFTER HS: Rcv TsbPd mode not set"; + LOGC(mglog.Debug, log << "AFTER HS: Rcv TsbPd mode not set"); } } @@ -6639,13 +6638,13 @@ void CUDT::updateSrtSndSettings() * For sender to apply Too-Late Packet Drop * option (m_bTLPktDrop) must be enabled and receiving peer shall support it */ - LOGC(mglog.Debug).form( "AFTER HS: Set Snd TsbPd mode %s: delay=%d.%03d secs", + LOGF(mglog.Debug, "AFTER HS: Set Snd TsbPd mode %s: delay=%d.%03d secs", m_bPeerTLPktDrop ? "with TLPktDrop" : "without TLPktDrop", m_iPeerTsbPdDelay_ms/1000, m_iPeerTsbPdDelay_ms%1000); } else { - LOGC(mglog.Debug) << "AFTER HS: Snd TsbPd mode not set"; + LOGC(mglog.Debug, log << "AFTER HS: Snd TsbPd mode not set"); } } @@ -6823,8 +6822,8 @@ int CUDT::packData(CPacket& packet, uint64_t& ts_tk) } else { - LOGC(dlog.Debug) << "packData: CONGESTED: cwnd=min(" << m_iFlowWindowSize << "," << m_dCongestionWindow - << ")=" << cwnd << " seqlen=(" << m_iSndLastAck << "-" << m_iSndCurrSeqNo << ")=" << seqdiff; + LOGC(dlog.Debug, log << "packData: CONGESTED: cwnd=min(" << m_iFlowWindowSize << "," << m_dCongestionWindow + << ")=" << cwnd << " seqlen=(" << m_iSndLastAck << "-" << m_iSndCurrSeqNo << ")=" << seqdiff); m_ullTargetTime_tk = 0; m_ullTimeDiff_tk = 0; ts_tk = 0; @@ -6873,9 +6872,9 @@ int CUDT::packData(CPacket& packet, uint64_t& ts_tk) } #if ENABLE_LOGGING // Required because of referring to MessageFlagStr() - LOGC(mglog.Debug) << CONID() << "packData: " << reason << " packet seq=" << packet.m_iSeqNo + LOGC(mglog.Debug, log << CONID() << "packData: " << reason << " packet seq=" << packet.m_iSeqNo << " (ACK=" << m_iSndLastAck << " ACKDATA=" << m_iSndLastDataAck - << " MSG/FLAGS: " << packet.MessageFlagStr() << ")"; + << " MSG/FLAGS: " << packet.MessageFlagStr() << ")"); #endif // Fix keepalive @@ -6990,7 +6989,7 @@ int CUDT::processData(CUnit* unit) } - LOGC(dlog.Debug) << CONID() << "processData: RECEIVED DATA: size=" << packet.getLength() << " seq=" << packet.getSeqNo(); + LOGC(dlog.Debug, log << CONID() << "processData: RECEIVED DATA: size=" << packet.getLength() << " seq=" << packet.getSeqNo()); // << "(" << rexmitstat[pktrexmitflag] << rexmit_reason << ")"; updateCC(TEV_RECEIVE, &packet); @@ -7040,7 +7039,7 @@ int CUDT::processData(CUnit* unit) int avail_bufsize = m_pRcvBuffer->getAvailBufSize(); if (offset >= avail_bufsize) { - LOGC(mglog.Error) << CONID() << "No room to store incoming packet: offset=" << offset << " avail=" << avail_bufsize; + LOGC(mglog.Error, log << CONID() << "No room to store incoming packet: offset=" << offset << " avail=" << avail_bufsize); return -1; } @@ -7053,10 +7052,10 @@ int CUDT::processData(CUnit* unit) } } - LOGC(mglog.Debug) << CONID() << "RECEIVED: seq=" << packet.m_iSeqNo << " offset=" << offset + LOGC(mglog.Debug, log << CONID() << "RECEIVED: seq=" << packet.m_iSeqNo << " offset=" << offset << (excessive ? " EXCESSIVE" : " ACCEPTED") << " (" << exc_type << "/" << rexmitstat[pktrexmitflag] << rexmit_reason << ") FLAGS: " - << packet.MessageFlagStr(); + << packet.MessageFlagStr()); if ( excessive ) { @@ -7084,7 +7083,7 @@ int CUDT::processData(CUnit* unit) } else { - LOGC(dlog.Debug) << "crypter: data not encrypted, returning as plain"; + LOGC(dlog.Debug, log << "crypter: data not encrypted, returning as plain"); } } /* End of offsetcg */ @@ -7114,7 +7113,7 @@ int CUDT::processData(CUnit* unit) * Do no ask loss packets retransmission */ ; - LOGC(mglog.Debug) << CONID() << "ERROR: packet not decrypted, dropping data."; + LOGC(mglog.Debug, log << CONID() << "ERROR: packet not decrypted, dropping data."); } else // Loss detection. @@ -7132,7 +7131,7 @@ int CUDT::processData(CUnit* unit) // pack loss list for (possibly belated) NAK // The LOSSREPORT will be sent in a while. m_FreshLoss.push_back(CRcvFreshLoss(seqlo, seqhi, initial_loss_ttl)); - LOGC(mglog.Debug).form("added loss sequence %d-%d (%d) with tolerance %d", seqlo, seqhi, 1+CSeqNo::seqcmp(seqhi, seqlo), initial_loss_ttl); + LOGF(mglog.Debug, "added loss sequence %d-%d (%d) with tolerance %d", seqlo, seqhi, 1+CSeqNo::seqcmp(seqhi, seqlo), initial_loss_ttl); } else { @@ -7146,7 +7145,7 @@ int CUDT::processData(CUnit* unit) seq[0] |= LOSSDATA_SEQNO_RANGE_FIRST; sendCtrl(UMSG_LOSSREPORT, NULL, seq, 2); } - LOGC(mglog.Debug).form("lost packets %d-%d (%d packets): sending LOSSREPORT", seqlo, seqhi, 1+CSeqNo::seqcmp(seqhi, seqlo)); + LOGF(mglog.Debug, "lost packets %d-%d (%d packets): sending LOSSREPORT", seqlo, seqhi, 1+CSeqNo::seqcmp(seqhi, seqlo)); } int loss = CSeqNo::seqlen(m_iRcvCurrSeqNo, packet.m_iSeqNo) - 2; @@ -7199,7 +7198,7 @@ int CUDT::processData(CUnit* unit) // into two records. for( ; i != m_FreshLoss.end() && i->ttl <= 0; ++i ) { - LOGC(mglog.Debug).form("Packet seq %d-%d (%d packets) considered lost - sending LOSSREPORT", + LOGF(mglog.Debug, "Packet seq %d-%d (%d packets) considered lost - sending LOSSREPORT", i->seq[0], i->seq[1], CSeqNo::seqcmp(i->seq[1], i->seq[0])+1); addLossRecord(lossdata, i->seq[0], i->seq[1]); } @@ -7212,11 +7211,15 @@ int CUDT::processData(CUnit* unit) } if ( m_FreshLoss.empty() ) - LOGC(mglog.Debug).form("NO MORE FRESH LOSS RECORDS."); + { + LOGP(mglog.Debug, "NO MORE FRESH LOSS RECORDS."); + } else - LOGC(mglog.Debug).form("STILL %zu FRESH LOSS RECORDS, FIRST: %d-%d (%d) TTL: %d", m_FreshLoss.size(), + { + LOGF(mglog.Debug, "STILL %zu FRESH LOSS RECORDS, FIRST: %d-%d (%d) TTL: %d", m_FreshLoss.size(), i->seq[0], i->seq[1], 1+CSeqNo::seqcmp(i->seq[1], i->seq[0]), i->ttl); + } // Phase 2: rest of the records should have TTL decreased. for ( ; i != m_FreshLoss.end(); ++i ) @@ -7262,7 +7265,7 @@ int CUDT::processData(CUnit* unit) { m_iReorderTolerance--; m_iTraceReorderDistance--; - LOGC(mglog.Debug).form( "ORDERED DELIVERY of 50 packets in a row - decreasing tolerance to %d", m_iReorderTolerance); + LOGF(mglog.Debug, "ORDERED DELIVERY of 50 packets in a row - decreasing tolerance to %d", m_iReorderTolerance); } } } @@ -7306,27 +7309,27 @@ void CUDT::unlose(const CPacket& packet) was_reordered = !packet.getRexmitFlag(); if ( was_reordered ) { - LOGC(mglog.Debug).form("received out-of-band packet seq %d", sequence); + LOGF(mglog.Debug, "received out-of-band packet seq %d", sequence); int seqdiff = abs(CSeqNo::seqcmp(m_iRcvCurrSeqNo, packet.m_iSeqNo)); m_iTraceReorderDistance = max(seqdiff, m_iTraceReorderDistance); if ( seqdiff > m_iReorderTolerance ) { - int prev = m_iReorderTolerance; + int prev SRT_ATR_UNUSED = m_iReorderTolerance; m_iReorderTolerance = min(seqdiff, m_iMaxReorderTolerance); - LOGC(mglog.Debug).form("Belated by %d seqs - Reorder tolerance %s %d", seqdiff, + LOGF(mglog.Debug, "Belated by %d seqs - Reorder tolerance %s %d", seqdiff, (prev == m_iReorderTolerance) ? "REMAINS with" : "increased to", m_iReorderTolerance); has_increased_tolerance = true; // Yes, even if reorder tolerance is already at maximum - this prevents decreasing tolerance. } } else { - LOGC(mglog.Debug) << CONID() << "received reXmitted packet seq=" << sequence; + LOGC(mglog.Debug, log << CONID() << "received reXmitted packet seq=" << sequence); } } else { - LOGC(mglog.Debug).form("received reXmitted or belated packet seq %d (distinction not supported by peer)", sequence); + LOGF(mglog.Debug, "received reXmitted or belated packet seq %d (distinction not supported by peer)", sequence); } @@ -7393,7 +7396,7 @@ breakbreak: ; if (i != m_FreshLoss.size()) { - LOGC(mglog.Debug).form("sequence %d removed from belated lossreport record", sequence); + LOGF(mglog.Debug, "sequence %d removed from belated lossreport record", sequence); } if ( was_reordered ) @@ -7406,7 +7409,7 @@ breakbreak: ; else if ( had_ttl > 2 ) { ++m_iConsecEarlyDelivery; // otherwise, and if it arrived quite earlier, increase counter - LOGC(mglog.Debug).form("... arrived at TTL %d case %d", had_ttl, m_iConsecEarlyDelivery); + LOGF(mglog.Debug, "... arrived at TTL %d case %d", had_ttl, m_iConsecEarlyDelivery); // After 10 consecutive if ( m_iConsecEarlyDelivery >= 10 ) @@ -7416,7 +7419,7 @@ breakbreak: ; { m_iReorderTolerance--; m_iTraceReorderDistance--; - LOGC(mglog.Debug).form("... reached %d times - decreasing tolerance to %d", m_iConsecEarlyDelivery, m_iReorderTolerance); + LOGF(mglog.Debug, "... reached %d times - decreasing tolerance to %d", m_iConsecEarlyDelivery, m_iReorderTolerance); } } @@ -7431,7 +7434,7 @@ void CUDT::unlose(int32_t from, int32_t to) CGuard lg(m_RcvLossLock); m_pRcvLossList->remove(from, to); - LOGC(mglog.Debug).form("TLPKTDROP seq %d-%d (%d packets)", from, to, CSeqNo::seqoff(from, to)); + LOGF(mglog.Debug, "TLPKTDROP seq %d-%d (%d packets)", from, to, CSeqNo::seqoff(from, to)); // All code below concerns only "belated lossreport" feature. @@ -7531,11 +7534,11 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) // XXX ASSUMPTIONS: // [[using assert(packet.m_iID == 0)]] - LOGC(mglog.Debug) << "processConnectRequest: received a connection request"; + LOGC(mglog.Debug, log << "processConnectRequest: received a connection request"); if (m_bClosing) { - LOGC(mglog.Debug) << "processConnectRequest: ... NOT. Rejecting because closing."; + LOGC(mglog.Debug, log << "processConnectRequest: ... NOT. Rejecting because closing."); return int(URQ_ERROR_REJECT); } @@ -7546,7 +7549,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) */ if (m_bBroken) { - LOGC(mglog.Debug) << "processConnectRequest: ... NOT. Rejecting because broken."; + LOGC(mglog.Debug, log << "processConnectRequest: ... NOT. Rejecting because broken."); return int(URQ_ERROR_REJECT); } size_t exp_len = CHandShake::m_iContentSize; // When CHandShake::m_iContentSize is used in log, the file fails to link! @@ -7559,7 +7562,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) // more data, depending on what's inside. if (packet.getLength() < exp_len) { - LOGC(mglog.Debug) << "processConnectRequest: ... NOT. Wrong size: " << packet.getLength() << " (expected: " << exp_len << ")"; + LOGC(mglog.Debug, log << "processConnectRequest: ... NOT. Wrong size: " << packet.getLength() << " (expected: " << exp_len << ")"); return int(URQ_ERROR_INVALID); } @@ -7568,7 +7571,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) // sure that the packet contains the handshake at all! if ( !packet.isControl(UMSG_HANDSHAKE) ) { - LOGC(mglog.Error) << "processConnectRequest: the packet received as handshake is not a handshake message"; + LOGC(mglog.Error, log << "processConnectRequest: the packet received as handshake is not a handshake message"); return int(URQ_ERROR_INVALID); } @@ -7577,14 +7580,14 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) int32_t cookie_val = bake(addr); - LOGC(mglog.Debug) << "processConnectRequest: new cookie: " << hex << cookie_val; + LOGC(mglog.Debug, log << "processConnectRequest: new cookie: " << hex << cookie_val); // REQUEST:INDUCTION. // Set a cookie, a target ID, and send back the same as // RESPONSE:INDUCTION. if (hs.m_iReqType == URQ_INDUCTION) { - LOGC(mglog.Debug) << "processConnectRequest: received type=induction, sending back with cookie+socket"; + LOGC(mglog.Debug, log << "processConnectRequest: received type=induction, sending back with cookie+socket"); // XXX That looks weird - the calculated md5 sum out of the given host/port/timestamp // is 16 bytes long, but CHandShake::m_iCookie has 4 bytes. This then effectively copies @@ -7624,22 +7627,22 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) // set in the above INDUCTION, in the HS_VERSION_SRT1 // should also contain extra data. - LOGC(mglog.Debug) << "processConnectRequest: received type=" << RequestTypeStr(hs.m_iReqType) << " - checking cookie..."; + LOGC(mglog.Debug, log << "processConnectRequest: received type=" << RequestTypeStr(hs.m_iReqType) << " - checking cookie..."); if (hs.m_iCookie != cookie_val) { cookie_val = bake(addr, cookie_val, -1); // SHOULD generate an earlier, distracted cookie if (hs.m_iCookie != cookie_val) { - LOGC(mglog.Debug) << "processConnectRequest: ...wrong cookie " << hex << cookie_val << ". Ignoring."; + LOGC(mglog.Debug, log << "processConnectRequest: ...wrong cookie " << hex << cookie_val << ". Ignoring."); return int(URQ_CONCLUSION); // Don't look at me, I just change integers to symbols! } - LOGC(mglog.Debug) << "processConnectRequest: ... correct (FIXED) cookie. Proceeding."; + LOGC(mglog.Debug, log << "processConnectRequest: ... correct (FIXED) cookie. Proceeding."); } else { - LOGC(mglog.Debug) << "processConnectRequest: ... correct (ORIGINAL) cookie. Proceeding."; + LOGC(mglog.Debug, log << "processConnectRequest: ... correct (ORIGINAL) cookie. Proceeding."); } int32_t id = hs.m_iID; @@ -7679,7 +7682,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) if (!accepted_hs) { - LOGC(mglog.Debug) << "processConnectRequest: version/type mismatch. Sending URQ_ERROR_REJECT."; + LOGC(mglog.Debug, log << "processConnectRequest: version/type mismatch. Sending URQ_ERROR_REJECT."); // mismatch, reject the request hs.m_iReqType = URQ_ERROR_REJECT; size_t size = CHandShake::m_iContentSize; @@ -7697,7 +7700,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) if (result == -1) { hs.m_iReqType = URQ_ERROR_REJECT; - LOGC(mglog.Error).form("UU:newConnection: rsp(REJECT): %d", URQ_ERROR_REJECT); + LOGF(mglog.Error, "UU:newConnection: rsp(REJECT): %d", URQ_ERROR_REJECT); } // XXX developer disorder warning! @@ -7729,7 +7732,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) // new connection response should be sent in acceptAndRespond() if (result != 1) { - LOGC(mglog.Debug) << CONID() << "processConnectRequest: sending ABNORMAL handshake info req=" << RequestTypeStr(hs.m_iReqType); + LOGC(mglog.Debug, log << CONID() << "processConnectRequest: sending ABNORMAL handshake info req=" << RequestTypeStr(hs.m_iReqType)); size_t size = CHandShake::m_iContentSize; hs.store_to(packet.m_pcData, Ref(size)); packet.m_iID = id; @@ -7742,7 +7745,7 @@ int CUDT::processConnectRequest(const sockaddr* addr, CPacket& packet) s_UDTUnited.m_EPoll.update_events(m_SocketID, m_sPollID, UDT_EPOLL_OUT, true); } } - LOGC(mglog.Note) << "listen ret: " << hs.m_iReqType << " - " << RequestTypeStr(hs.m_iReqType); + LOGC(mglog.Note, log << "listen ret: " << hs.m_iReqType << " - " << RequestTypeStr(hs.m_iReqType)); return hs.m_iReqType; } @@ -7772,9 +7775,9 @@ void CUDT::checkTimers() // This is a very heavy log, unblock only for temporary debugging! #if 0 - LOGC(mglog.Debug) << CONID() << "checkTimers: nextacktime=" << logging::FormatTime(m_ullNextACKTime_tk) + LOGC(mglog.Debug, log << CONID() << "checkTimers: nextacktime=" << logging::FormatTime(m_ullNextACKTime_tk) << " AckInterval=" << m_iACKInterval - << " pkt-count=" << m_iPktCount << " liteack-count=" << m_iLightACKCount; + << " pkt-count=" << m_iPktCount << " liteack-count=" << m_iLightACKCount); #endif if (currtime_tk > m_ullNextACKTime_tk // ACK time has come @@ -7864,7 +7867,7 @@ void CUDT::checkTimers() // UDT does not signal any information about this instead of to stop quietly. // Application will detect this when it calls any UDT methods next time. // - LOGC(mglog.Debug) << "CONNECTION EXPIRED after " << ((currtime_tk - m_ullLastRspTime_tk)/m_ullCPUFrequency) << "ms"; + LOGC(mglog.Debug, log << "CONNECTION EXPIRED after " << ((currtime_tk - m_ullLastRspTime_tk)/m_ullCPUFrequency) << "ms"); m_bClosing = true; m_bBroken = true; m_iBrokenCounter = 30; @@ -7882,8 +7885,8 @@ void CUDT::checkTimers() return; } - LOGC(mglog.Debug) << "EXP TIMER: count=" << m_iEXPCount << "/" << (+COMM_RESPONSE_MAX_EXP) - << " elapsed=" << ((currtime_tk - m_ullLastRspTime_tk)*m_ullCPUFrequency) << "/" << (+COMM_RESPONSE_TIMEOUT_US) << "us"; + LOGC(mglog.Debug, log << "EXP TIMER: count=" << m_iEXPCount << "/" << (+COMM_RESPONSE_MAX_EXP) + << " elapsed=" << ((currtime_tk - m_ullLastRspTime_tk)*m_ullCPUFrequency) << "/" << (+COMM_RESPONSE_TIMEOUT_US) << "us"); /* * This part is only used with FileSmoother. This retransmits @@ -7913,8 +7916,8 @@ void CUDT::checkTimers() m_iTraceSndLoss += 1; // num; m_iSndLossTotal += 1; // num; - LOGC(mglog.Debug) << CONID() << "ENFORCED LATEREXMIT by ACK-TMOUT (scheduling): " << CSeqNo::incseq(m_iSndLastAck) << "-" << csn - << " (" << CSeqNo::seqcmp(csn, m_iSndLastAck) << " packets)"; + LOGC(mglog.Debug, log << CONID() << "ENFORCED LATEREXMIT by ACK-TMOUT (scheduling): " << CSeqNo::incseq(m_iSndLastAck) << "-" << csn + << " (" << CSeqNo::seqcmp(csn, m_iSndLastAck) << " packets)"); } } // protect packet retransmission @@ -7972,10 +7975,10 @@ void CUDT::checkTimers() int32_t csn = m_iSndCurrSeqNo; int num = m_pSndLossList->insert(m_iSndLastAck, csn); #if ENABLE_LOGGING - LOGC(mglog.Debug) << CONID() << "ENFORCED FASTREXMIT by ACK-TMOUT PREPARED: " << m_iSndLastAck << "-" << csn - << " (" << CSeqNo::seqcmp(csn, m_iSndLastAck) << " packets)"; + LOGC(mglog.Debug, log << CONID() << "ENFORCED FASTREXMIT by ACK-TMOUT PREPARED: " << m_iSndLastAck << "-" << csn + << " (" << CSeqNo::seqcmp(csn, m_iSndLastAck) << " packets)"); - LOGC(mglog.Debug).form( "timeout lost: pkts=%d rtt+4*var=%d cnt=%d diff=%llu", num, + LOGF(mglog.Debug, "timeout lost: pkts=%d rtt+4*var=%d cnt=%d diff=%llu", num, m_iRTT + 4 * m_iRTTVar, m_iReXmitCount, (unsigned long long)(currtime_tk - (m_ullLastRspAckTime_tk + exp_int))); #endif if (num > 0) { diff --git a/srtcore/crypto.cpp b/srtcore/crypto.cpp index 67513fe9e..2df746ad7 100644 --- a/srtcore/crypto.cpp +++ b/srtcore/crypto.cpp @@ -51,6 +51,7 @@ extern logging::Logger mglog, dlog; // 10* HAICRYPT_DEF_KM_PRE_ANNOUNCE const int SRT_CRYPT_KM_PRE_ANNOUNCE = 0x10000; +#if ENABLE_LOGGING static std::string KmStateStr(SRT_KM_STATE state) { switch (state) @@ -66,7 +67,9 @@ static std::string KmStateStr(SRT_KM_STATE state) } } -static std::string FormatKmMessage(std::string hdr, bool isrcv, int cmd, size_t srtlen, SRT_KM_STATE agt_state, SRT_KM_STATE peer_state) + +static std::string FormatKmMessage(std::string hdr, bool isrcv, int cmd, + size_t srtlen, SRT_KM_STATE agt_state, SRT_KM_STATE peer_state) { std::ostringstream os; os << hdr << ": cmd=" << cmd << "(" << (cmd == SRT_CMD_KMREQ ? "KMREQ":"KMRSP") <<") len=" @@ -82,8 +85,9 @@ static std::string FormatKmMessage(std::string hdr, bool isrcv, int cmd, size_t return os.str(); } +#endif -void CCryptoControl::updateKmState(int cmd, size_t srtlen) +void CCryptoControl::updateKmState(int cmd, size_t srtlen SRT_ATR_UNUSED) { if (cmd == SRT_CMD_KMREQ) { @@ -140,7 +144,7 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, // function normally return SRT_CMD_KMRSP. if ( bytelen <= HCRYPT_MSG_KM_OFS_SALT ) //Sanity on message { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: size of the KM (" << bytelen << ") is too small, must be >" << HCRYPT_MSG_KM_OFS_SALT; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: size of the KM (" << bytelen << ") is too small, must be >" << HCRYPT_MSG_KM_OFS_SALT); KMREQ_RESULT_REJECTION(); } @@ -148,22 +152,22 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, // received when Agent does not declare encryption. if (m_KmSecret.len == 0) //We have a shared secret <==> encryption is on { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: Agent does not declare encryption - REJECTING!"; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: Agent does not declare encryption - REJECTING!"); KMREQ_RESULT_REJECTION(); } - LOGC(mglog.Debug) << "KMREQ: getting SEK and creating receiver crypto"; + LOGC(mglog.Debug, log << "KMREQ: getting SEK and creating receiver crypto"); sek_len = hcryptMsg_KM_GetSekLen(kmdata); if ( sek_len == 0 ) { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: Received SEK is empty - REJECTING!"; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: Received SEK is empty - REJECTING!"); KMREQ_RESULT_REJECTION(); } m_iRcvKmKeyLen = sek_len; if (!createCryptoCtx(Ref(m_hRcvCrypto), m_iRcvKmKeyLen, HAICRYPT_CRYPTO_DIR_RX)) { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: Can't create RCV CRYPTO CTX - must reject..."; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: Can't create RCV CRYPTO CTX - must reject..."); KMREQ_RESULT_REJECTION(); } @@ -172,7 +176,7 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, m_iSndKmKeyLen = m_iRcvKmKeyLen; if (!createCryptoCtx(Ref(m_hSndCrypto), m_iSndKmKeyLen, HAICRYPT_CRYPTO_DIR_TX)) { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: Can't create SND CRYPTO CTX - must reject..."; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: Can't create SND CRYPTO CTX - must reject..."); KMREQ_RESULT_REJECTION(); } } @@ -184,8 +188,8 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, m_iRcvKmState = SRT_KM_S_NOSECRET; else m_iRcvKmState = SRT_KM_S_SECURING; - LOGC(mglog.Debug) << "processSrtMsg_KMREQ: RCV unsecured - changing state to " - << (m_iRcvKmState == SRT_KM_S_SECURING ? "SECURING" : "NOSECRET"); + LOGC(mglog.Debug, log << "processSrtMsg_KMREQ: RCV unsecured - changing state to " + << (m_iRcvKmState == SRT_KM_S_SECURING ? "SECURING" : "NOSECRET")); } rc = HaiCrypt_Rx_Process(m_hRcvCrypto, kmdata, bytelen, NULL, NULL, 0); @@ -194,21 +198,21 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, case HAICRYPT_OK: m_iRcvPeerKmState = SRT_KM_S_SECURED; m_iRcvKmState = SRT_KM_S_SECURED; - LOGC(mglog.Debug) << "KMREQ/rcv: (snd) Rx process successful - SECURED"; + LOGC(mglog.Debug, log << "KMREQ/rcv: (snd) Rx process successful - SECURED"); //Send back the whole message to confirm break; case HAICRYPT_ERROR_WRONG_SECRET: //Unmatched shared secret to decrypt wrapped key m_iRcvKmState = SRT_KM_S_BADSECRET; //Send status KMRSP message to tel error srtlen = 1; - LOGC(mglog.Error) << "KMREQ/rcv: (snd) Rx process failure - BADSECRET"; + LOGC(mglog.Error, log << "KMREQ/rcv: (snd) Rx process failure - BADSECRET"); break; case HAICRYPT_ERROR: //Other errors default: m_iRcvKmState = SRT_KM_S_SECURING; //Send status KMRSP message to tel error srtlen = 1; - LOGC(mglog.Error) << "KMREQ/rcv: (snd) Rx process failure - SECURING"; + LOGC(mglog.Error, log << "KMREQ/rcv: (snd) Rx process failure - SECURING"); break; } @@ -224,7 +228,7 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, m_iSndKmKeyLen = m_iRcvKmKeyLen; if (HaiCrypt_Clone(m_hRcvCrypto, HAICRYPT_CRYPTO_DIR_TX, &m_hSndCrypto)) { - LOGC(mglog.Error) << "processSrtMsg_KMREQ: Can't create SND CRYPTO CTX - must reject..."; + LOGC(mglog.Error, log << "processSrtMsg_KMREQ: Can't create SND CRYPTO CTX - must reject..."); KMREQ_RESULT_REJECTION(); } if (m_iSndPeerKmState == SRT_KM_S_UNSECURED) @@ -234,8 +238,8 @@ int CCryptoControl::processSrtMsg_KMREQ(const uint32_t* srtdata, size_t bytelen, m_iSndKmState = SRT_KM_S_NOSECRET; else m_iSndKmState = SRT_KM_S_SECURING; - LOGC(mglog.Debug) << "processSrtMsg_KMREQ: SND unsecured - changing state to " - << (m_iSndKmState == SRT_KM_S_SECURING ? "SECURING" : "NOSECRET"); + LOGC(mglog.Debug, log << "processSrtMsg_KMREQ: SND unsecured - changing state to " + << (m_iSndKmState == SRT_KM_S_SECURING ? "SECURING" : "NOSECRET")); } LOGP(mglog.Note, FormatKmMessage("processSrtMsg_KMREQ", false, SRT_CMD_KMREQ, bytelen, m_iSndKmState, m_iSndPeerKmState)); @@ -270,11 +274,11 @@ int CCryptoControl::processSrtMsg_KMRSP(const uint32_t* srtdata, size_t len, int m_iSndPeerKmState = SRT_KM_STATE(srtd[SRT_KMR_KMSTATE]); /* Bad or no passphrase */ m_SndKmMsg[0].iPeerRetry = 0; m_SndKmMsg[1].iPeerRetry = 0; - LOGC(mglog.Error) << "processSrtMsg_KMRSP: received failure report. STATE: " << KmStateStr(m_iSndPeerKmState); + LOGC(mglog.Error, log << "processSrtMsg_KMRSP: received failure report. STATE: " << KmStateStr(m_iSndPeerKmState)); } else { - LOGC(mglog.Debug) << "processSrtMsg_KMRSP: received key response len=" << len; + LOGC(mglog.Debug, log << "processSrtMsg_KMRSP: received key response len=" << len); // XXX INSECURE << ": [" << FormatBinaryString((uint8_t*)srtd, len) << "]"; bool key1 = getKmMsg_acceptResponse(0, srtd, len); bool key2 = true; @@ -285,15 +289,15 @@ int CCryptoControl::processSrtMsg_KMRSP(const uint32_t* srtdata, size_t len, int { m_iSndKmState = SRT_KM_S_SECURED; m_iSndPeerKmState = SRT_KM_S_SECURED; - LOGC(mglog.Debug) << "processSrtMsg_KMRSP: KM response matches key " << (key1 ? 1 : 2); + LOGC(mglog.Debug, log << "processSrtMsg_KMRSP: KM response matches key " << (key1 ? 1 : 2)); } else { - LOGC(mglog.Error) << "processSrtMsg_KMRSP: KM response key matches no key"; + LOGC(mglog.Error, log << "processSrtMsg_KMRSP: KM response key matches no key"); /* XXX INSECURE - LOGC(mglog.Error) << "processSrtMsg_KMRSP: KM response: [" << FormatBinaryString((uint8_t*)srtd, len) + LOGC(mglog.Error, log << "processSrtMsg_KMRSP: KM response: [" << FormatBinaryString((uint8_t*)srtd, len) << "] matches no key 0=[" << FormatBinaryString((uint8_t*)m_SndKmMsg[0].Msg, m_SndKmMsg[0].MsgLen) - << "] 1=[" << FormatBinaryString((uint8_t*)m_SndKmMsg[1].Msg, m_SndKmMsg[1].MsgLen) << "]"; + << "] 1=[" << FormatBinaryString((uint8_t*)m_SndKmMsg[1].Msg, m_SndKmMsg[1].MsgLen) << "]"); */ } } @@ -352,7 +356,7 @@ void CCryptoControl::regenCryptoKm(bool sendit, bool bidirectional) int nbo = HaiCrypt_Tx_ManageKeys(m_hSndCrypto, out_p, out_len_p, 2); int sent = 0; - LOGC(mglog.Debug) << "regenCryptoKm: regenerating crypto keys nbo=" << nbo; + LOGC(mglog.Debug, log << "regenCryptoKm: regenerating crypto keys nbo=" << nbo); for (int i = 0; i < nbo && i < 2; i++) { @@ -367,8 +371,8 @@ void CCryptoControl::regenCryptoKm(bool sendit, bool bidirectional) || (0 != memcmp(out_p[i], m_SndKmMsg[ki].Msg, m_SndKmMsg[ki].MsgLen))) { - uint8_t* oldkey = m_SndKmMsg[ki].Msg; - LOGC(mglog.Debug).form("new key[%d] len=%zd,%zd msg=%0x,%0x\n", + uint8_t* oldkey SRT_ATR_UNUSED = m_SndKmMsg[ki].Msg; + LOGF(mglog.Debug, "new key[%d] len=%zd,%zd msg=%0x,%0x\n", ki, out_len_p[i], m_SndKmMsg[ki].MsgLen, *(int32_t *)out_p[i], *(int32_t *)oldkey); @@ -384,7 +388,7 @@ void CCryptoControl::regenCryptoKm(bool sendit, bool bidirectional) int rc = HaiCrypt_Rx_Process(m_hRcvCrypto, m_SndKmMsg[ki].Msg, m_SndKmMsg[ki].MsgLen, NULL, NULL, 0); if ( rc < 0 ) { - LOGC(mglog.Fatal) << "regenCryptoKm: IPE: applying key generated in snd crypto into rcv crypto: failed code=" << rc; + LOGC(mglog.Fatal, log << "regenCryptoKm: IPE: applying key generated in snd crypto into rcv crypto: failed code=" << rc); // The party won't be able to decrypt incoming data! // Not sure if anything has to be reported. } @@ -432,9 +436,9 @@ bool CCryptoControl::init(HandshakeSide side, bool bidirectional) // Acceptor creates nothing - it will create appropriate // contexts when receiving KMREQ from the initiator. - LOGC(mglog.Debug) << "CCryptoControl::init: HS SIDE:" + LOGC(mglog.Debug, log << "CCryptoControl::init: HS SIDE:" << (side == HSD_INITIATOR ? "INITIATOR" : "RESPONDER") - << " DIRECTION:" << (bidirectional ? "BOTH" : (side == HSD_INITIATOR) ? "SENDER" : "RECEIVER"); + << " DIRECTION:" << (bidirectional ? "BOTH" : (side == HSD_INITIATOR) ? "SENDER" : "RECEIVER")); if (bidirectional) m_bDataSender = true; // both directions on, so you are always a sender @@ -444,13 +448,13 @@ bool CCryptoControl::init(HandshakeSide side, bool bidirectional) if (m_iSndKmKeyLen > 0) { bool ok = createCryptoCtx(Ref(m_hSndCrypto), m_iSndKmKeyLen, HAICRYPT_CRYPTO_DIR_TX); - LOGC(mglog.Debug) << "CCryptoControl::init: creating SND crypto context: " << ok; + LOGC(mglog.Debug, log << "CCryptoControl::init: creating SND crypto context: " << ok); if (ok && bidirectional) { m_iRcvKmKeyLen = m_iSndKmKeyLen; int st = HaiCrypt_Clone(m_hSndCrypto, HAICRYPT_CRYPTO_DIR_RX, &m_hRcvCrypto); - LOGC(mglog.Debug) << "CCryptoControl::init: creating CLONED RCV crypto context: status=" << st; + LOGC(mglog.Debug, log << "CCryptoControl::init: creating CLONED RCV crypto context: status=" << st); ok = st == 0; } @@ -461,12 +465,12 @@ bool CCryptoControl::init(HandshakeSide side, bool bidirectional) } else { - LOGC(mglog.Debug) << "CCryptoControl::init: CAN'T CREATE crypto: key length for SND = " << m_iSndKmKeyLen; + LOGC(mglog.Debug, log << "CCryptoControl::init: CAN'T CREATE crypto: key length for SND = " << m_iSndKmKeyLen); } } else { - LOGC(mglog.Debug) << "CCryptoControl::init: NOT creating crypto contexts - will be created upon reception of KMREQ"; + LOGC(mglog.Debug, log << "CCryptoControl::init: NOT creating crypto contexts - will be created upon reception of KMREQ"); } return true; @@ -489,6 +493,7 @@ std::string CCryptoControl::CONID() const return os.str(); } +#if ENABLE_LOGGING static std::string CryptoFlags(int flg) { using namespace std; @@ -505,6 +510,7 @@ static std::string CryptoFlags(int flg) copy(f.begin(), f.end(), ostream_iterator(os, "|")); return os.str(); } +#endif bool CCryptoControl::createCryptoCtx(ref_t hCrypto, size_t keylen, HaiCrypt_CryptoDir cdir) { @@ -521,7 +527,7 @@ bool CCryptoControl::createCryptoCtx(ref_t hCrypto, size_t keyl if ((m_KmSecret.len <= 0) || (keylen <= 0)) { - LOGC(mglog.Error) << CONID() << "cryptoCtx: missing secret (" << m_KmSecret.len << ") or key length (" << keylen << ")"; + LOGC(mglog.Error, log << CONID() << "cryptoCtx: missing secret (" << m_KmSecret.len << ") or key length (" << keylen << ")"); return false; } @@ -539,16 +545,16 @@ bool CCryptoControl::createCryptoCtx(ref_t hCrypto, size_t keyl crypto_cfg.secret = m_KmSecret; //memcpy(&crypto_cfg.secret, &m_KmSecret, sizeof(crypto_cfg.secret)); - LOGC(mglog.Debug) << "CRYPTO CFG: flags=" << CryptoFlags(crypto_cfg.flags) << " xport=" << crypto_cfg.xport << " cipher=" << crypto_cfg.cipher - << " keylen=" << crypto_cfg.key_len << " passphrase_length=" << crypto_cfg.secret.len; + LOGC(mglog.Debug, log << "CRYPTO CFG: flags=" << CryptoFlags(crypto_cfg.flags) << " xport=" << crypto_cfg.xport << " cipher=" << crypto_cfg.cipher + << " keylen=" << crypto_cfg.key_len << " passphrase_length=" << crypto_cfg.secret.len); if (HaiCrypt_Create(&crypto_cfg, &hCrypto.get()) != HAICRYPT_OK) { - LOGC(mglog.Error) << CONID() << "cryptoCtx: could not create " << (cdir == HAICRYPT_CRYPTO_DIR_TX ? "tx" : "rx") << " crypto ctx"; + LOGC(mglog.Error, log << CONID() << "cryptoCtx: could not create " << (cdir == HAICRYPT_CRYPTO_DIR_TX ? "tx" : "rx") << " crypto ctx"); return false; } - LOGC(mglog.Debug) << CONID() << "cryptoCtx: CREATED crypto for dir=" << (cdir == HAICRYPT_CRYPTO_DIR_TX ? "tx" : "rx") << " keylen=" << keylen; + LOGC(mglog.Debug, log << CONID() << "cryptoCtx: CREATED crypto for dir=" << (cdir == HAICRYPT_CRYPTO_DIR_TX ? "tx" : "rx") << " keylen=" << keylen); return true; } @@ -577,7 +583,7 @@ HaiCrypt_Handle CCryptoControl::getRcvCryptoCtx() } } - LOGC(mglog.Warn) << "getRcvCryptoCtx: NOT RCV SECURE. States agent=" << KmStateStr(m_iRcvKmState) << " peer=" << KmStateStr(m_iRcvPeerKmState); + LOGC(mglog.Warn, log << "getRcvCryptoCtx: NOT RCV SECURE. States agent=" << KmStateStr(m_iRcvKmState) << " peer=" << KmStateStr(m_iRcvPeerKmState)); return(NULL); } @@ -609,7 +615,7 @@ EncryptionStatus CCryptoControl::decrypt(ref_t r_packet) if (packet.getMsgCryptoFlags() == EK_NOENC) { - LOGC(mglog.Debug) << "CPacket::decrypt: packet not encrypted"; + LOGC(mglog.Debug, log << "CPacket::decrypt: packet not encrypted"); return ENCS_CLEAR; // not encrypted, no need do decrypt, no flags to be modified } @@ -629,7 +635,7 @@ EncryptionStatus CCryptoControl::decrypt(ref_t r_packet) m_iRcvKmState = SRT_KM_S_NOSECRET; } - LOGC(mglog.Error) << "DECRYPTION FAILED: KM not configured or not yet received"; + LOGC(mglog.Error, log << "DECRYPTION FAILED: KM not configured or not yet received"); return ENCS_FAILED; } } @@ -637,7 +643,7 @@ EncryptionStatus CCryptoControl::decrypt(ref_t r_packet) int rc = HaiCrypt_Rx_Data(m_hRcvCrypto, (uint8_t *)packet.getHeader(), (uint8_t *)packet.m_pcData, packet.getLength()); if ( rc <= 0 ) { - LOGC(mglog.Debug) << "decrypt ERROR: HaiCrypt_Rx_Data failure=" << rc << " - returning failed decryption"; + LOGC(mglog.Debug, log << "decrypt ERROR: HaiCrypt_Rx_Data failure=" << rc << " - returning failed decryption"); // -1: decryption failure // 0: key not received yet return ENCS_FAILED; @@ -648,7 +654,7 @@ EncryptionStatus CCryptoControl::decrypt(ref_t r_packet) // Decryption succeeded. Update flags. packet.setMsgCryptoFlags(EK_NOENC); - LOGC(mglog.Debug) << "decrypt: successfully decrypted, resulting length=" << rc; + LOGC(mglog.Debug, log << "decrypt: successfully decrypted, resulting length=" << rc); return ENCS_CLEAR; } diff --git a/srtcore/logging.h b/srtcore/logging.h index 36b1057cd..b18f1da46 100644 --- a/srtcore/logging.h +++ b/srtcore/logging.h @@ -54,11 +54,22 @@ written by #define PRINTF_LIKE #endif +#if ENABLE_LOGGING + // Usage: LOGC(mglog.Debug) << param1 << param2 << param3; -#define LOGC(logdes) logdes().setloc(__FILE__, __LINE__, __FUNCTION__) +#define LOGC(logdes, args) if (logdes.CheckEnabled()) { logging::LogDispatcher::Proxy log(logdes); log.setloc(__FILE__, __LINE__, __FUNCTION__); args; } +#define LOGF(logdes, ...) if (logdes.CheckEnabled()) logdes().setloc(__FILE__, __LINE__, __FUNCTION__).form(__VA_ARGS__) // LOGP is C++11 only OR with only one string argument. // Usage: LOGP(mglog.Debug, param1, param2, param3); -#define LOGP(logdes, ...) logdes.printloc(__FILE__, __LINE__, __FUNCTION__,##__VA_ARGS__) +#define LOGP(logdes, ...) if (logdes.CheckEnabled()) logdes.printloc(__FILE__, __LINE__, __FUNCTION__,##__VA_ARGS__) + +#else + +#define LOGC(...) +#define LOGF(...) +#define LOGP(...) + +#endif namespace logging { @@ -138,19 +149,13 @@ struct SRT_API LogDispatcher template void operator()(Arg1&& arg1, Args&&... args) { - if ( CheckEnabled() ) - { - PrintLogLine("UNKNOWN.c++", 0, "UNKNOWN", arg1, args...); - } + PrintLogLine("UNKNOWN.c++", 0, "UNKNOWN", arg1, args...); } template void printloc(const char* file, int line, const std::string& area, Arg1&& arg1, Args&&... args) { - if ( CheckEnabled() ) - { - PrintLogLine(file, line, area, arg1, args...); - } + PrintLogLine(file, line, area, arg1, args...); } #else template @@ -160,18 +165,12 @@ struct SRT_API LogDispatcher template void operator()(const Arg& arg) { - if ( CheckEnabled() ) - { - PrintLogLine("UNKNOWN.c++", 0, "UNKNOWN", arg); - } + PrintLogLine("UNKNOWN.c++", 0, "UNKNOWN", arg); } void printloc(const char* file, int line, const std::string& area, const std::string& arg1) { - if ( CheckEnabled() ) - { - PrintLogLine(file, line, area, arg1); - } + PrintLogLine(file, line, area, arg1); } #endif diff --git a/srtcore/packet.cpp b/srtcore/packet.cpp index ca5b04359..5ff166ade 100644 --- a/srtcore/packet.cpp +++ b/srtcore/packet.cpp @@ -429,7 +429,7 @@ EncryptionStatus CPacket::encrypt(HaiCrypt_Handle hcrypto) { if ( !hcrypto ) { - LOGC(mglog.Error) << "IPE: NULL crypto passed to CPacket::encrypt!"; + LOGC(mglog.Error, log << "IPE: NULL crypto passed to CPacket::encrypt!"); return ENCS_FAILED; } @@ -449,13 +449,13 @@ EncryptionStatus CPacket::decrypt(HaiCrypt_Handle hcrypto) { if (getMsgCryptoFlags() == EK_NOENC) { - //LOGC(mglog.Debug) << "CPacket::decrypt: packet not encrypted"; + //LOGC(mglog.Debug, log << "CPacket::decrypt: packet not encrypted"); return ENCS_CLEAR; // not encrypted, no need do decrypt, no flags to be modified } if (!hcrypto) { - LOGC(mglog.Error) << "IPE: NULL crypto passed to CPacket::decrypt!"; + LOGC(mglog.Error, log << "IPE: NULL crypto passed to CPacket::decrypt!"); return ENCS_FAILED; // "invalid argument" (leave encryption flags untouched) } diff --git a/srtcore/queue.cpp b/srtcore/queue.cpp index e53695e7f..c205b99bd 100644 --- a/srtcore/queue.cpp +++ b/srtcore/queue.cpp @@ -577,11 +577,11 @@ void* CSndQueue::worker(void* param) } if ( pkt.isControl() ) { - LOGC(mglog.Debug) << self->CONID() << "chn:SENDING: " << MessageTypeStr(pkt.getType(), pkt.getExtendedType()); + LOGC(mglog.Debug, log << self->CONID() << "chn:SENDING: " << MessageTypeStr(pkt.getType(), pkt.getExtendedType())); } else { - LOGC(dlog.Debug) << self->CONID() << "chn:SENDING SIZE " << pkt.getLength() << " SEQ: " << pkt.getSeqNo(); + LOGC(dlog.Debug, log << self->CONID() << "chn:SENDING SIZE " << pkt.getLength() << " SEQ: " << pkt.getSeqNo()); } self->m_pChannel->sendto(addr, pkt); @@ -886,7 +886,7 @@ void CRendezvousQueue::updateConnStatus(EConnectStatus cst, const CPacket& respo int debug_nupd = 0; int debug_nrun = 0; - LOGC(mglog.Debug) << "updateConnStatus: updating after getting pkt id=" << response.m_iID << " status: " << ConnectStatusStr(cst); + LOGC(mglog.Debug, log << "updateConnStatus: updating after getting pkt id=" << response.m_iID << " status: " << ConnectStatusStr(cst)); list::iterator i = m_lRendezvousID.begin(); while (i != m_lRendezvousID.end()) @@ -902,8 +902,8 @@ void CRendezvousQueue::updateConnStatus(EConnectStatus cst, const CPacket& respo uint64_t then = i->m_pUDT->m_llLastReqTime; bool nowstime = (now - then) > 250000; - LOGC(mglog.Debug) << "RID:%" << i->m_iID << " then=" << then << " now=" << now << " passed=" << (now-then) - << " -- now's " << (nowstime ? "" : "NOT ") << "the time"; + LOGC(mglog.Debug, log << "RID:%" << i->m_iID << " then=" << then << " now=" << now << " passed=" << (now-then) + << " -- now's " << (nowstime ? "" : "NOT ") << "the time"); if (nowstime) { @@ -916,7 +916,7 @@ void CRendezvousQueue::updateConnStatus(EConnectStatus cst, const CPacket& respo // This must be somehow fixed! if (CTimer::getTime() >= i->m_ullTTL) { - LOGC(mglog.Debug) << "RendezvousQueue: EXPIRED. removing from queue"; + LOGC(mglog.Debug, log << "RendezvousQueue: EXPIRED. removing from queue"); // connection timer expired, acknowledge app via epoll i->m_pUDT->m_bConnecting = false; CUDT::s_UDTUnited.m_EPoll.update_events(i->m_iID, i->m_pUDT->m_sPollID, UDT_EPOLL_ERR, true); @@ -956,7 +956,7 @@ void CRendezvousQueue::updateConnStatus(EConnectStatus cst, const CPacket& respo This debug log is blocked because it is sent multiple times in a millisecond without a good reason. else { - LOGC(mglog.Debug) << "updateConnStatus: RendezvousQueue not to send CONCLUSION for the non-rdv sokket."; + LOGC(mglog.Debug, log << "updateConnStatus: RendezvousQueue not to send CONCLUSION for the non-rdv sokket."); } // */ } @@ -964,7 +964,7 @@ void CRendezvousQueue::updateConnStatus(EConnectStatus cst, const CPacket& respo i++; } - LOGC(mglog.Debug) << "updateConnStatus: total of " << debug_nupd << " sockets updated, the loop ran " << (debug_nrun-debug_nupd) << " uselessly."; + LOGC(mglog.Debug, log << "updateConnStatus: total of " << debug_nupd << " sockets updated, the loop ran " << (debug_nrun-debug_nupd) << " uselessly."); } // @@ -1063,7 +1063,7 @@ void* CRcvQueue::worker(void* param) { // User error on peer. May log something, but generally can only ignore it. // XXX Think maybe about sending some "connection rejection response". - LOGC(mglog.Debug) << self->CONID() << "RECEIVED negative socket id '" << id << "', rejecting (POSSIBLE ATTACK)"; + LOGC(mglog.Debug, log << self->CONID() << "RECEIVED negative socket id '" << id << "', rejecting (POSSIBLE ATTACK)"); continue; } @@ -1086,7 +1086,7 @@ void* CRcvQueue::worker(void* param) // - a socket connected to a peer cst = self->worker_ProcessAddressedPacket(id, unit, &sa); } - LOGC(mglog.Debug) << self->CONID() << "worker: result for the unit: " << ConnectStatusStr(cst); + LOGC(mglog.Debug, log << self->CONID() << "worker: result for the unit: " << ConnectStatusStr(cst)); have_received = true; } else if (rst == RST_ERROR) @@ -1098,11 +1098,11 @@ void* CRcvQueue::worker(void* param) // Check that just to report possible errors, but interrupt the loop anyway. if (self->m_bClosing) { - LOGC(mglog.Debug) << self->CONID() << "CChannel reported error, but Queue is closing - INTERRUPTING worker."; + LOGC(mglog.Debug, log << self->CONID() << "CChannel reported error, but Queue is closing - INTERRUPTING worker."); } else { - LOGC(mglog.Fatal) << self->CONID() << "CChannel reported ERROR DURING TRANSMISSION - IPE. INTERRUPTING worker anyway."; + LOGC(mglog.Fatal, log << self->CONID() << "CChannel reported ERROR DURING TRANSMISSION - IPE. INTERRUPTING worker anyway."); } cst = CONN_REJECT; break; @@ -1137,7 +1137,9 @@ void* CRcvQueue::worker(void* param) } if ( have_received ) - LOGC(mglog.Debug) << "worker: updateConnStatus (after received packet from the party)"; + { + LOGC(mglog.Debug, log << "worker: updateConnStatus (after received packet from the party)"); + } // Check connection requests status for all sockets in the RendezvousQueue. // Pass the connection status from the last call of: @@ -1152,6 +1154,7 @@ void* CRcvQueue::worker(void* param) return NULL; } +#if ENABLE_LOGGING static string PacketInfo(const CPacket& pkt) { ostringstream os; @@ -1172,6 +1175,7 @@ static string PacketInfo(const CPacket& pkt) return os.str(); } +#endif EReadStatus CRcvQueue::worker_RetrieveUnit(ref_t r_id, ref_t r_unit, sockaddr* addr) { @@ -1201,7 +1205,7 @@ EReadStatus CRcvQueue::worker_RetrieveUnit(ref_t r_id, ref_t r_ EReadStatus rst = m_pChannel->recvfrom(addr, temp); THREAD_RESUMED(); #if ENABLE_LOGGING - LOGC(mglog.Error) << CONID() << "LOCAL STORAGE DEPLETED. Dropping 1 packet: " << PacketInfo(temp); + LOGC(mglog.Error, log << CONID() << "LOCAL STORAGE DEPLETED. Dropping 1 packet: " << PacketInfo(temp)); #endif delete [] temp.m_pcData; @@ -1220,14 +1224,14 @@ EReadStatus CRcvQueue::worker_RetrieveUnit(ref_t r_id, ref_t r_ if (rst == RST_OK) { *r_id = r_unit->m_Packet.m_iID; - LOGC(mglog.Debug) << "INCOMING PACKET: BOUND=" << SockaddrToString(m_pChannel->bindAddress()) << " " << PacketInfo(r_unit->m_Packet); + LOGC(mglog.Debug, log << "INCOMING PACKET: BOUND=" << SockaddrToString(m_pChannel->bindAddress()) << " " << PacketInfo(r_unit->m_Packet)); } return rst; } EConnectStatus CRcvQueue::worker_ProcessConnectionRequest(CUnit* unit, const sockaddr* addr) { - LOGC(mglog.Debug) << "Got sockID=0 from " << SockaddrToString(addr) << " - trying to resolve it as a connection request..."; + LOGC(mglog.Debug, log << "Got sockID=0 from " << SockaddrToString(addr) << " - trying to resolve it as a connection request..."); // Introduced protection because it may potentially happen // that another thread could have closed the socket at // the same time and inject a bug between checking the @@ -1238,7 +1242,7 @@ EConnectStatus CRcvQueue::worker_ProcessConnectionRequest(CUnit* unit, const soc CGuard cg(m_LSLock); if (m_pListener) { - LOGC(mglog.Note) << "... PASSING request from: " << SockaddrToString(addr) << " to agent:" << m_pListener->socketID(); + LOGC(mglog.Note, log << "... PASSING request from: " << SockaddrToString(addr) << " to agent:" << m_pListener->socketID()); listener_ret = m_pListener->processConnectRequest(addr, unit->m_Packet); // XXX This returns some very significant return value, which // is completely ignored here. @@ -1273,8 +1277,8 @@ EConnectStatus CRcvQueue::worker_ProcessConnectionRequest(CUnit* unit, const soc if ( have_listener ) // That is, the above block with m_pListener->processConnectRequest was executed { - LOGC(mglog.Note) << CONID() << "listener managed the connection request from: " << SockaddrToString(addr) - << " result:" << RequestTypeStr(UDTRequestType(listener_ret)); + LOGC(mglog.Note, log << CONID() << "listener managed the connection request from: " << SockaddrToString(addr) + << " result:" << RequestTypeStr(UDTRequestType(listener_ret))); return (listener_ret >= URQ_FAILURE_TYPES ? CONN_REJECT : CONN_CONTINUE); } @@ -1289,7 +1293,7 @@ EConnectStatus CRcvQueue::worker_ProcessAddressedPacket(int32_t id, CUnit* unit, { // Pass this to either async rendezvous connection, // or store the packet in the queue. - LOGC(mglog.Debug) << "worker_ProcessAddressedPacket: resending to target socket %" << id; + LOGC(mglog.Debug, log << "worker_ProcessAddressedPacket: resending to target socket %" << id); return worker_TryAsyncRend_OrStore(id, unit, addr); } @@ -1297,8 +1301,8 @@ EConnectStatus CRcvQueue::worker_ProcessAddressedPacket(int32_t id, CUnit* unit, // addressed to an associated socket. if (!CIPAddress::ipcmp(addr, u->m_pPeerAddr, u->m_iIPversion)) { - LOGC(mglog.Debug) << CONID() << "Packet for SID=" << id << " asoc with " << SockaddrToString(u->m_pPeerAddr) - << " received from " << SockaddrToString(addr) << " (CONSIDERED ATTACK ATTEMPT)"; + LOGC(mglog.Debug, log << CONID() << "Packet for SID=" << id << " asoc with " << SockaddrToString(u->m_pPeerAddr) + << " received from " << SockaddrToString(addr) << " (CONSIDERED ATTACK ATTEMPT)"); // This came not from the address that is the peer associated // with the socket. Reject. return CONN_REJECT; @@ -1344,11 +1348,15 @@ EConnectStatus CRcvQueue::worker_TryAsyncRend_OrStore(int32_t id, CUnit* unit, c // XXX this socket is then completely unknown to the system. // May be nice to send some rejection info to the peer. if ( id == 0 ) - LOGC(mglog.Debug) << CONID() << "AsyncOrRND: no sockets expect connection from " - << SockaddrToString(addr) << " - POSSIBLE ATTACK"; + { + LOGC(mglog.Debug, log << CONID() << "AsyncOrRND: no sockets expect connection from " + << SockaddrToString(addr) << " - POSSIBLE ATTACK"); + } else - LOGC(mglog.Debug) << CONID() << "AsyncOrRND: no sockets expect socket " << id << " from " - << SockaddrToString(addr) << " - POSSIBLE ATTACK"; + { + LOGC(mglog.Debug, log << CONID() << "AsyncOrRND: no sockets expect socket " << id << " from " + << SockaddrToString(addr) << " - POSSIBLE ATTACK"); + } return CONN_REJECT; } @@ -1356,14 +1364,14 @@ EConnectStatus CRcvQueue::worker_TryAsyncRend_OrStore(int32_t id, CUnit* unit, c // otherwise wait for the UDT socket to retrieve this packet if (!u->m_bSynRecving) { - LOGC(mglog.Debug) << "AsyncOrRND: packet RESOLVED TO ID=" << id << " -- continuing as ASYNC CONNECT"; + LOGC(mglog.Debug, log << "AsyncOrRND: packet RESOLVED TO ID=" << id << " -- continuing as ASYNC CONNECT"); // This is practically same as processConnectResponse, just this applies // appropriate mutex lock - which can't be done here because it's intentionally private. // OTOH it can't be applied to processConnectResponse because the synchronous // call to this method applies the lock by itself, and same-thread-double-locking is nonportable (crashable). return u->processAsyncConnectResponse(unit->m_Packet); } - LOGC(mglog.Debug) << "AsyncOrRND: packet RESOLVED TO ID=" << id << " -- continuing through CENTRAL PACKET QUEUE"; + LOGC(mglog.Debug, log << "AsyncOrRND: packet RESOLVED TO ID=" << id << " -- continuing through CENTRAL PACKET QUEUE"); // This is where also the packets for rendezvous connection will be landing, // in case of a synchronous connection. storePkt(id, unit->m_Packet.clone()); @@ -1456,7 +1464,7 @@ void CRcvQueue::registerConnector(const SRTSOCKET& id, CUDT* u, int ipv, const s void CRcvQueue::removeConnector(const SRTSOCKET& id, bool should_lock) { - LOGC(mglog.Debug) << "removeConnector: removing %" << id; + LOGC(mglog.Debug, log << "removeConnector: removing %" << id); m_pRendezvousQueue->remove(id, should_lock); CGuard bufferlock(m_PassLock); @@ -1464,7 +1472,7 @@ void CRcvQueue::removeConnector(const SRTSOCKET& id, bool should_lock) map >::iterator i = m_mBuffer.find(id); if (i != m_mBuffer.end()) { - LOGC(mglog.Debug) << "removeConnector: ... and its packet queue with " << i->second.size() << " packets collected"; + LOGC(mglog.Debug, log << "removeConnector: ... and its packet queue with " << i->second.size() << " packets collected"); while (!i->second.empty()) { delete [] i->second.front()->m_pcData; diff --git a/srtcore/smoother.cpp b/srtcore/smoother.cpp index 5ae54aadf..5ed1a7858 100644 --- a/srtcore/smoother.cpp +++ b/srtcore/smoother.cpp @@ -89,7 +89,7 @@ class LiveSmoother: public SmootherBase m_iMinNakInterval_us = 20000; //Minimum NAK Report Period (usec) m_iNakReportAccel = 2; //Default NAK Report Period (RTT) accelerator - LOGC(mglog.Debug) << "Creating LiveSmoother: bw=" << m_llSndMaxBW << " avgplsize=" << m_iSndAvgPayloadSize; + LOGC(mglog.Debug, log << "Creating LiveSmoother: bw=" << m_llSndMaxBW << " avgplsize=" << m_iSndAvgPayloadSize); updatePktSndPeriod(); @@ -109,7 +109,7 @@ class LiveSmoother: public SmootherBase { if (api != Smoother::STA_MESSAGE) { - LOGC(mglog.Error) << "LiveSmoother: invalid API use. Only sendmsg/recvmsg allowed."; + LOGC(mglog.Error, log << "LiveSmoother: invalid API use. Only sendmsg/recvmsg allowed."); return false; } @@ -118,7 +118,7 @@ class LiveSmoother: public SmootherBase // For sending, check if the size of data doesn't exceed the maximum live packet size. if (size > m_zMaxPayloadSize) { - LOGC(mglog.Error) << "LiveSmoother: payload size: " << size << " exceeds maximum allowed " << m_zMaxPayloadSize; + LOGC(mglog.Error, log << "LiveSmoother: payload size: " << size << " exceeds maximum allowed " << m_zMaxPayloadSize); return false; } } @@ -127,7 +127,7 @@ class LiveSmoother: public SmootherBase // For receiving, check if the buffer has enough space to keep the payload. if (size < m_zMaxPayloadSize) { - LOGC(mglog.Error) << "LiveSmoother: buffer size: " << size << " is too small for the maximum possible " << m_zMaxPayloadSize; + LOGC(mglog.Error, log << "LiveSmoother: buffer size: " << size << " is too small for the maximum possible " << m_zMaxPayloadSize); return false; } } @@ -156,7 +156,7 @@ class LiveSmoother: public SmootherBase // thread will pick up a "slightly outdated" average value from this // field - this is insignificant. m_iSndAvgPayloadSize = avg_iir<128, int>(m_iSndAvgPayloadSize, packet.getLength()); - LOGC(mglog.Debug) << "LiveSmoother: avg payload size updated: " << m_iSndAvgPayloadSize; + LOGC(mglog.Debug, log << "LiveSmoother: avg payload size updated: " << m_iSndAvgPayloadSize); } void updatePktSndPeriod_onTimer(ETransmissionEvent , EventVariant var) @@ -175,7 +175,7 @@ class LiveSmoother: public SmootherBase // packet = payload + header double pktsize = m_iSndAvgPayloadSize + CPacket::SRT_DATA_HDR_SIZE; m_dPktSndPeriod = 1000*1000.0 * (pktsize/m_llSndMaxBW); - LOGC(mglog.Debug) << "LiveSmoother: sending period updated: " << m_iSndAvgPayloadSize; + LOGC(mglog.Debug, log << "LiveSmoother: sending period updated: " << m_iSndAvgPayloadSize); } void setMaxBW(int64_t maxbw) @@ -305,7 +305,7 @@ class FileSmoother: public SmootherBase parent->ConnectSignal(TEV_LOSSREPORT, SSLOT(slowdownSndPeriod)); parent->ConnectSignal(TEV_CHECKTIMER, SSLOT(speedupToWindowSize)); - LOGC(mglog.Debug) << "Creating FileSmoother"; + LOGC(mglog.Debug, log << "Creating FileSmoother"); } bool checkTransArgs(Smoother::TransAPI, Smoother::TransDir, const char* , size_t , int , bool ) ATR_OVERRIDE @@ -332,7 +332,7 @@ class FileSmoother: public SmootherBase if (maxbw != 0) { m_maxSR = maxbw; - LOGC(mglog.Debug) << "FileSmoother: updated BW: " << m_maxSR; + LOGC(mglog.Debug, log << "FileSmoother: updated BW: " << m_maxSR); } } @@ -363,25 +363,25 @@ class FileSmoother: public SmootherBase if (m_parent->deliveryRate() > 0) { m_dPktSndPeriod = 1000000.0 / m_parent->deliveryRate(); - LOGC(mglog.Debug) << "FileSmoother: UPD (slowstart:ENDED) wndsize=" + LOGC(mglog.Debug, log << "FileSmoother: UPD (slowstart:ENDED) wndsize=" << m_dCWndSize << "/" << m_dMaxCWndSize << " sndperiod=" << m_dPktSndPeriod << "us = mega/(" - << m_parent->deliveryRate() << "B/s)"; + << m_parent->deliveryRate() << "B/s)"); } else { m_dPktSndPeriod = m_dCWndSize / (m_parent->RTT() + m_iRCInterval); - LOGC(mglog.Debug) << "FileSmoother: UPD (slowstart:ENDED) wndsize=" + LOGC(mglog.Debug, log << "FileSmoother: UPD (slowstart:ENDED) wndsize=" << m_dCWndSize << "/" << m_dMaxCWndSize << " sndperiod=" << m_dPktSndPeriod << "us = wndsize/(RTT+RCIV) RTT=" - << m_parent->RTT() << " RCIV=" << m_iRCInterval; + << m_parent->RTT() << " RCIV=" << m_iRCInterval); } } else { - LOGC(mglog.Debug) << "FileSmoother: UPD (slowstart:KEPT) wndsize=" + LOGC(mglog.Debug, log << "FileSmoother: UPD (slowstart:KEPT) wndsize=" << m_dCWndSize << "/" << m_dMaxCWndSize - << " sndperiod=" << m_dPktSndPeriod << "us"; + << " sndperiod=" << m_dPktSndPeriod << "us"); } } else @@ -438,10 +438,10 @@ class FileSmoother: public SmootherBase int udp_buffer_free = -1; #endif - LOGC(mglog.Debug) << "FileSmoother: UPD (slowstart:" + LOGC(mglog.Debug, log << "FileSmoother: UPD (slowstart:" << (m_bSlowStart ? "ON" : "OFF") << ") wndsize=" << m_dCWndSize << " sndperiod=" << m_dPktSndPeriod << "us BANDWIDTH USED:" << usedbw << " (limit: " << m_maxSR << ")" - " SYSTEM BUFFER LEFT: " << udp_buffer_free; + " SYSTEM BUFFER LEFT: " << udp_buffer_free); #endif //set maximum transfer rate @@ -451,8 +451,8 @@ class FileSmoother: public SmootherBase if (m_dPktSndPeriod < minSP) { m_dPktSndPeriod = minSP; - LOGC(mglog.Debug) << "FileSmoother: BW limited to " << m_maxSR - << " - SLOWDOWN sndperiod=" << m_dPktSndPeriod << "us"; + LOGC(mglog.Debug, log << "FileSmoother: BW limited to " << m_maxSR + << " - SLOWDOWN sndperiod=" << m_dPktSndPeriod << "us"); } } @@ -469,7 +469,7 @@ class FileSmoother: public SmootherBase // is called with a nonempty loss list. if ( losslist_size == 0 ) { - LOGC(mglog.Error) << "IPE: FileSmoother: empty loss list!"; + LOGC(mglog.Error, log << "IPE: FileSmoother: empty loss list!"); return; } @@ -480,14 +480,14 @@ class FileSmoother: public SmootherBase if (m_parent->deliveryRate() > 0) { m_dPktSndPeriod = 1000000.0 / m_parent->deliveryRate(); - LOGC(mglog.Debug) << "FileSmoother: LOSS, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS mega/rate (rate=" - << m_parent->deliveryRate() << ")"; + LOGC(mglog.Debug, log << "FileSmoother: LOSS, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS mega/rate (rate=" + << m_parent->deliveryRate() << ")"); } else { m_dPktSndPeriod = m_dCWndSize / (m_parent->RTT() + m_iRCInterval); - LOGC(mglog.Debug) << "FileSmoother: LOSS, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS wndsize/(RTT+RCIV) (RTT=" - << m_parent->RTT() << " RCIV=" << m_iRCInterval << ")"; + LOGC(mglog.Debug, log << "FileSmoother: LOSS, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS wndsize/(RTT+RCIV) (RTT=" + << m_parent->RTT() << " RCIV=" << m_iRCInterval << ")"); } } @@ -518,31 +518,31 @@ class FileSmoother: public SmootherBase m_iDecRandom = (int)ceil(m_iAvgNAKNum * (double(rand()) / RAND_MAX)); if (m_iDecRandom < 1) m_iDecRandom = 1; - LOGC(mglog.Debug) << "FileSmoother: LOSS:NEW lastseq=" << m_iLastDecSeq + LOGC(mglog.Debug, log << "FileSmoother: LOSS:NEW lastseq=" << m_iLastDecSeq << ", rand=" << m_iDecRandom << " avg NAK:" << m_iAvgNAKNum - << ", sndperiod=" << m_dPktSndPeriod << "us"; + << ", sndperiod=" << m_dPktSndPeriod << "us"); } else if ((m_iDecCount ++ < 5) && (0 == (++ m_iNAKCount % m_iDecRandom))) { // 0.875^5 = 0.51, rate should not be decreased by more than half within a congestion period m_dPktSndPeriod = ceil(m_dPktSndPeriod * 1.125); m_iLastDecSeq = m_parent->sndSeqNo(); - LOGC(mglog.Debug) << "FileSmoother: LOSS:PERIOD lseq=" << lossbegin + LOGC(mglog.Debug, log << "FileSmoother: LOSS:PERIOD lseq=" << lossbegin << ", dseq=" << m_iLastDecSeq << ", seqdiff=" << seqdiff << ", deccnt=" << m_iDecCount << ", decrnd=" << m_iDecRandom - << ", sndperiod=" << m_dPktSndPeriod << "us"; + << ", sndperiod=" << m_dPktSndPeriod << "us"); } else { - LOGC(mglog.Debug) << "FileSmoother: LOSS:STILL lseq=" << lossbegin + LOGC(mglog.Debug, log << "FileSmoother: LOSS:STILL lseq=" << lossbegin << ", dseq=" << m_iLastDecSeq << ", seqdiff=" << seqdiff << ", deccnt=" << m_iDecCount << ", decrnd=" << m_iDecRandom - << ", sndperiod=" << m_dPktSndPeriod << "us"; + << ", sndperiod=" << m_dPktSndPeriod << "us"); } } @@ -563,14 +563,14 @@ class FileSmoother: public SmootherBase if (m_parent->deliveryRate() > 0) { m_dPktSndPeriod = 1000000.0 / m_parent->deliveryRate(); - LOGC(mglog.Debug) << "FileSmoother: CHKTIMER, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS mega/rate (rate=" - << m_parent->deliveryRate() << ")"; + LOGC(mglog.Debug, log << "FileSmoother: CHKTIMER, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS mega/rate (rate=" + << m_parent->deliveryRate() << ")"); } else { m_dPktSndPeriod = m_dCWndSize / (m_parent->RTT() + m_iRCInterval); - LOGC(mglog.Debug) << "FileSmoother: CHKTIMER, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS wndsize/(RTT+RCIV) (wndsize=" - << setprecision(6) << m_dCWndSize << " RTT=" << m_parent->RTT() << " RCIV=" << m_iRCInterval << ")"; + LOGC(mglog.Debug, log << "FileSmoother: CHKTIMER, SLOWSTART:OFF, sndperiod=" << m_dPktSndPeriod << "us AS wndsize/(RTT+RCIV) (wndsize=" + << setprecision(6) << m_dCWndSize << " RTT=" << m_parent->RTT() << " RCIV=" << m_iRCInterval << ")"); } } else