add route-specific debug logs that can be elevated per-route (#48064)

Co-authored-by: sima <[email protected]>
fastly · Sep 3, 2024 · 7408507 · 7408507
1 parent 826d8e4
commit 7408507
Show file tree

Hide file tree

Showing 17 changed files with 106 additions and 11 deletions.
diff --git a/src/core/logutil.cpp b/src/core/logutil.cpp
@@ -195,4 +195,15 @@ void logRequest(int level, const RequestData &data, const Config &config)
 	log(level, "%s", qPrintable(msg));
 }
 
+void logForRoute(const RouteInfo &routeInfo, const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	QString msg = QString::vasprintf(fmt, ap);
+	if(!routeInfo.id.isEmpty())
+		msg += QString(" route=%1").arg(routeInfo.id);
+	logPacket(routeInfo.logLevel, msg);
+	va_end(ap);
+}
+
 }
diff --git a/src/core/logutil.h b/src/core/logutil.h
@@ -1,5 +1,6 @@
 /*
  * Copyright (C) 2017 Fanout, Inc.
+ * Copyright (C) 2024 Fastly, Inc.
  *
  * This file is part of Pushpin.
  *
@@ -24,6 +25,7 @@
 #define LOGUTIL_H
 
 #include <QHostAddress>
+#include "log.h"
 #include "packet/httprequestdata.h"
 #include "packet/httpresponsedata.h"
 
@@ -73,10 +75,24 @@ class Config
 	}
 };
 
+class RouteInfo
+{
+public:
+	QString id;
+	int logLevel;
+
+	RouteInfo(const QString &initId = QString(), int initLogLevel = LOG_LEVEL_DEBUG) :
+		id(initId),
+		logLevel(initLogLevel)
+	{
+	}
+};
+
 void logVariant(int level, const QVariant &data, const char *fmt, ...);
 void logByteArray(int level, const QByteArray &content, const char *fmt, ...);
 void logVariantWithContent(int level, const QVariant &data, const QString &contentField, const char *fmt, ...);
 void logRequest(int level, const RequestData &data, const Config &config = Config());
+void logForRoute(const RouteInfo &routeInfo, const char *fmt, ...);
 
 }
 

diff --git a/src/core/packet/wscontrolpacket.cpp b/src/core/packet/wscontrolpacket.cpp
@@ -215,6 +215,9 @@ QVariant WsControlPacket::toVariant() const
 		if(!item.channelPrefix.isEmpty())
 			vitem["channel-prefix"] = item.channelPrefix;
 
+		if(item.logLevel >= 0)
+			vitem["log-level"] = item.logLevel;
+
 		if(!item.channel.isEmpty())
 			vitem["channel"] = item.channel;
 
@@ -384,6 +387,14 @@ bool WsControlPacket::fromVariant(const QVariant &in)
 				item.channelPrefix = channelPrefix;
 		}
 
+		if(vitem.contains("log-level"))
+		{
+			if(!canConvert(vitem["log-level"], QMetaType::Int))
+				return false;
+
+			item.logLevel = vitem["log-level"].toInt();
+		}
+
 		if(vitem.contains("channel"))
 		{
 			if(typeId(vitem["channel"]) != QMetaType::QByteArray)

diff --git a/src/core/packet/wscontrolpacket.h b/src/core/packet/wscontrolpacket.h
@@ -64,6 +64,7 @@ class WsControlPacket
 		QByteArray route;
 		bool separateStats;
 		QByteArray channelPrefix;
+		int logLevel;
 		QByteArray channel;
 		int ttl;
 		int timeout;
@@ -74,6 +75,7 @@ class WsControlPacket
 			queue(false),
 			code(-1),
 			separateStats(false),
+			logLevel(-1),
 			ttl(-1),
 			timeout(-1)
 		{

diff --git a/src/handler/handlerengine.cpp b/src/handler/handlerengine.cpp
@@ -38,6 +38,7 @@
 #include "tnetstring.h"
 #include "rtimer.h"
 #include "log.h"
+#include "logutil.h"
 #include "packet/httprequestdata.h"
 #include "packet/httpresponsedata.h"
 #include "packet/retryrequestpacket.h"
@@ -428,6 +429,7 @@ class AcceptWorker : public Deferred
 	QString route;
 	QString statsRoute;
 	QString channelPrefix;
+	int logLevel;
 	QStringList implicitChannels;
 	bool trusted;
 	QHash<ZhttpRequest::Rid, RequestState> requestStates;
@@ -454,6 +456,7 @@ class AcceptWorker : public Deferred
 		stats(_stats),
 		updateLimiter(_updateLimiter),
 		httpSessionUpdateManager(_httpSessionUpdateManager),
+		logLevel(-1),
 		trusted(false),
 		haveInspectInfo(false),
 		responseSent(false),
@@ -536,6 +539,17 @@ class AcceptWorker : public Deferred
 			channelPrefix = QString::fromUtf8(args["channel-prefix"].toByteArray());
 		}
 
+		if(args.contains("log-level"))
+		{
+			if(!canConvert(args["log-level"], QMetaType::Int))
+			{
+				respondError("bad-request");
+				return;
+			}
+
+			logLevel = args["log-level"].toInt();
+		}
+
 		if(args.contains("channels"))
 		{
 			if(typeId(args["channels"]) != QMetaType::QVariantList)
@@ -1107,6 +1121,7 @@ class AcceptWorker : public Deferred
 			adata.route = route;
 			adata.statsRoute = statsRoute;
 			adata.channelPrefix = channelPrefix;
+			adata.logLevel = logLevel;
 			adata.implicitChannels = implicitChannelsSet;
 			adata.sid = sid;
 			adata.responseSent = responseSent;
@@ -2687,6 +2702,8 @@ class HandlerEngine::Private : public QObject
 				s->route = item.route;
 				s->statsRoute = item.separateStats ? item.route : QString();
 				s->channelPrefix = QString::fromUtf8(item.channelPrefix);
+				if(item.logLevel >= 0)
+					s->logLevel = item.logLevel;
 
 				if(!s->sid.isEmpty())
 					updateSids[s->sid] = LastIds();
@@ -2761,7 +2778,8 @@ class HandlerEngine::Private : public QObject
 					}
 					else
 					{
-						log_warning("ws session %s: too many subscriptions", qPrintable(s->cid));
+						auto routeInfo = LogUtil::RouteInfo(s->route, s->logLevel);
+						LogUtil::logForRoute(routeInfo, "wssession: too many subscriptions");
 					}
 				}
 				else if(cm.type == WsControlMessage::Unsubscribe)

diff --git a/src/handler/httpsession.cpp b/src/handler/httpsession.cpp
@@ -148,6 +148,7 @@ class HttpSession::Private : public QObject
 	ZhttpRequest *req;
 	AcceptData adata;
 	Instruct instruct;
+	int logLevel;
 	QHash<QString, Instruct::Channel> channels;
 	RTimer *timer;
 	RTimer *retryTimer;
@@ -191,6 +192,7 @@ class HttpSession::Private : public QObject
 		QObject(_q),
 		q(_q),
 		req(_req),
+		logLevel(LOG_LEVEL_DEBUG),
 		stats(_stats),
 		outZhttp(_outZhttp),
 		outReq(0),
@@ -223,6 +225,9 @@ class HttpSession::Private : public QObject
 		adata = _adata;
 		instruct = _instruct;
 
+		if(adata.logLevel >= 0)
+			logLevel = adata.logLevel;
+
 		currentUri = req->requestUri();
 
 		if(!instruct.nextLink.isEmpty())
@@ -276,7 +281,9 @@ class HttpSession::Private : public QObject
 		if(instruct.channels.count() > connectionSubscriptionMax)
 		{
 			instruct.channels = instruct.channels.mid(0, connectionSubscriptionMax);
-			log_warning("httpsession: too many subscriptions");
+
+			auto routeInfo = LogUtil::RouteInfo(adata.route, logLevel);
+			LogUtil::logForRoute(routeInfo, "httpsession: too many subscriptions");
 		}
 
 		// need to send initial content?
@@ -1320,7 +1327,9 @@ class HttpSession::Private : public QObject
 				if(instruct.channels.count() > connectionSubscriptionMax)
 				{
 					instruct.channels = instruct.channels.mid(0, connectionSubscriptionMax);
-					log_warning("httpsession: too many subscriptions");
+
+					auto routeInfo = LogUtil::RouteInfo(adata.route, logLevel);
+					LogUtil::logForRoute(routeInfo, "httpsession: too many subscriptions");
 				}
 
 				if(instruct.holdMode == Instruct::StreamHold)

diff --git a/src/handler/httpsession.h b/src/handler/httpsession.h
@@ -66,6 +66,7 @@ class HttpSession : public QObject
 		QString route;
 		QString statsRoute;
 		QString channelPrefix;
+		int logLevel;
 		QSet<QString> implicitChannels;
 		bool trusted;
 		bool responseSent;
@@ -79,6 +80,7 @@ class HttpSession : public QObject
 			autoCrossOrigin(false),
 			jsonpExtendedResponse(false),
 			unreportedTime(-1),
+			logLevel(-1),
 			trusted(false),
 			responseSent(false),
 			haveInspectInfo(false)

diff --git a/src/handler/wssession.cpp b/src/handler/wssession.cpp
@@ -1,5 +1,6 @@
 /*
  * Copyright (C) 2020 Fanout, Inc.
+ * Copyright (C) 2024 Fastly, Inc.
  *
  * This file is part of Pushpin.
  *
@@ -30,7 +31,8 @@
 
 WsSession::WsSession(QObject *parent) :
 	QObject(parent),
-	nextReqId(0)
+	nextReqId(0),
+	logLevel(LOG_LEVEL_DEBUG)
 {
 	expireTimer = new QTimer(this);
 	expireTimer->setSingleShot(true);

diff --git a/src/handler/wssession.h b/src/handler/wssession.h
@@ -44,6 +44,7 @@ class WsSession : public QObject
 	QString cid;
 	int nextReqId;
 	QString channelPrefix;
+	int logLevel;
 	HttpRequestData requestData;
 	QString route;
 	QString statsRoute;

diff --git a/src/proxy/acceptdata.h b/src/proxy/acceptdata.h
@@ -1,6 +1,6 @@
 /*
  * Copyright (C) 2012-2023 Fanout, Inc.
- * Copyright (C) 2023 Fastly, Inc.
+ * Copyright (C) 2023-2024 Fastly, Inc.
  *
  * This file is part of Pushpin.
  *
@@ -83,6 +83,7 @@ class AcceptData
 	QByteArray route;
 	bool separateStats;
 	QByteArray channelPrefix;
+	int logLevel;
 	QList<QByteArray> channels;
 	bool trusted; // whether a trusted target was used
 	bool useSession;
@@ -93,6 +94,8 @@ class AcceptData
 		haveInspectData(false),
 		haveResponse(false),
 		separateStats(false),
+		logLevel(-1),
+		trusted(false),
 		useSession(false),
 		responseSent(false)
 	{

diff --git a/src/proxy/acceptrequest.cpp b/src/proxy/acceptrequest.cpp
@@ -194,6 +194,9 @@ static QVariant acceptDataToVariant(const AcceptData &adata)
 	if(!adata.channelPrefix.isEmpty())
 		obj["channel-prefix"] = adata.channelPrefix;
 
+	if(adata.logLevel >= 0)
+		obj["log-level"] = adata.logLevel;
+
 	if(!adata.channels.isEmpty())
 	{
 		QVariantList vchannels;

diff --git a/src/proxy/domainmap.cpp b/src/proxy/domainmap.cpp
@@ -78,6 +78,7 @@ class DomainMap::Worker : public QObject
 		HttpHeaders headers;
 		bool grip;
 		QList<Target> targets;
+		int logLevel;
 
 		Rule() :
 			proto(-1),
@@ -88,7 +89,8 @@ class DomainMap::Worker : public QObject
 			debug(false),
 			autoCrossOrigin(false),
 			session(false),
-			grip(true)
+			grip(true),
+			logLevel(LOG_LEVEL_DEBUG)
 		{
 		}
 
@@ -189,6 +191,7 @@ class DomainMap::Worker : public QObject
 			e.separateStats = explicitId;
 			e.grip = grip;
 			e.targets = targets;
+			e.logLevel = logLevel;
 			return e;
 		}
 	};
@@ -547,6 +550,11 @@ public slots:
 		if(props.contains("no_grip"))
 			r.grip = false;
 
+		if(props.contains("log_level"))
+		{
+			r.logLevel = props.value("log_level").toInt();
+		}
+
 		ok = true;
 		for(int n = 1; n < sections.count(); ++n)
 		{

diff --git a/src/proxy/domainmap.h b/src/proxy/domainmap.h
@@ -1,5 +1,6 @@
 /*
  * Copyright (C) 2012-2022 Fanout, Inc.
+ * Copyright (C) 2024 Fastly, Inc.
  *
  * This file is part of Pushpin.
  *
@@ -27,6 +28,7 @@
 #include <QPair>
 #include <QString>
 #include <QStringList>
+#include "log.h"
 #include "httpheaders.h"
 #include "jwt.h"
 #include <boost/signals2.hpp>
@@ -152,6 +154,7 @@ class DomainMap : public QObject
 		bool separateStats;
 		bool grip;
 		QList<Target> targets;
+		int logLevel;
 
 		bool isNull() const
 		{
@@ -173,7 +176,8 @@ class DomainMap : public QObject
 			autoCrossOrigin(false),
 			session(false),
 			separateStats(false),
-			grip(true)
+			grip(true),
+			logLevel(LOG_LEVEL_DEBUG)
 		{
 		}
 	};

diff --git a/src/proxy/proxysession.cpp b/src/proxy/proxysession.cpp
@@ -1330,6 +1330,7 @@ class ProxySession::Private : public QObject
 			adata.route = route.id;
 			adata.separateStats = route.separateStats;
 			adata.channelPrefix = route.prefix;
+			adata.logLevel = route.logLevel;
 			foreach(const QString &s, target.subscriptions)
 				adata.channels += s.toUtf8();
 			adata.trusted = target.trusted;