imtcp: Improve peer logging to include source ports (#6198)

* imtcp: include peer ports in runtime log messages

Ensure tcpsrv and session diagnostics report the sender's source port alongside the existing host/IP fields so administrators can pinpoint connections precisely. This updates imtcp connection notices, close/error paths, and framing warnings to use a consistent "host (ip:port)" style already present in TLS mismatch logs.

With the help of AI-Agent: Codex
This commit is contained in:
Rainer Gerhards 2025-09-29 10:39:28 +02:00 committed by GitHub
parent 31fd3d3ac2
commit 62bfaa152c
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 49 additions and 36 deletions

View File

@ -66,6 +66,14 @@ static inline uchar *__attribute__((unused)) ATTR_NONNULL(1) propGetSzStr(prop_t
return (pThis->len < CONF_PROP_BUFSIZE) ? pThis->szVal.sz : pThis->szVal.psz;
}
static inline const char *__attribute__((unused)) propGetSzStrOrDefault(prop_t *pThis, const char *dflt) {
return (pThis != NULL) ? (const char *)propGetSzStr(pThis) : dflt;
}
static inline const char *__attribute__((unused)) szStrOrDefault(const uchar *psz, const char *dflt) {
return (psz != NULL) ? (const char *)psz : dflt;
}
/* prototypes */
PROTOTYPEObj(prop);

View File

@ -201,12 +201,9 @@ static ATTR_NONNULL() rsRetVal maybeDetectTlsClientHello(tcps_sess_t *pThis, con
if (pThis->tlsProbeBytes >= sizeof(pThis->tlsProbeBuf)) {
if (!pThis->tlsMismatchWarned && isLikelyTlsClientHello(pThis->tlsProbeBuf)) {
const char *const host =
(pThis->fromHost != NULL) ? (const char *)propGetSzStr(pThis->fromHost) : "(host unknown)";
const char *const ip =
(pThis->fromHostIP != NULL) ? (const char *)propGetSzStr(pThis->fromHostIP) : "(IP unknown)";
const char *const port =
(pThis->fromHostPort != NULL) ? (const char *)propGetSzStr(pThis->fromHostPort) : "(port unknown)";
const char *const host = propGetSzStrOrDefault(pThis->fromHost, "(host unknown)");
const char *const ip = propGetSzStrOrDefault(pThis->fromHostIP, "(IP unknown)");
const char *const port = propGetSzStrOrDefault(pThis->fromHostPort, "(port unknown)");
LogError(0, RS_RET_SERVER_NO_TLS,
"imtcp: TLS handshake detected from %s (%s:%s) but listener is not TLS-enabled. "
"Enable TLS on this listener or disable TLS on the client. "
@ -495,26 +492,23 @@ static rsRetVal ATTR_NONNULL(1) processDataRcvd(tcps_sess_t *pThis,
*(pThis->pMsg + pThis->iMsg++) = c;
}
} else { /* done with the octet count, so this must be the SP terminator */
uchar *propPeerName = NULL;
uchar *propPeerIP = NULL;
int lenPeerName = 0;
int lenPeerIP = 0;
DBGPRINTF("TCP Message with octet-counter, size %d.\n", pThis->iOctetsRemain);
prop.GetString(pThis->fromHost, &propPeerName, &lenPeerName);
prop.GetString(pThis->fromHost, &propPeerIP, &lenPeerIP);
const char *const peerName = propGetSzStrOrDefault(pThis->fromHost, "(hostname unknown)");
const char *const peerIP = propGetSzStrOrDefault(pThis->fromHostIP, "(IP unknown)");
const char *const peerPort = propGetSzStrOrDefault(pThis->fromHostPort, "(port unknown)");
if (c != ' ') {
LogError(0, NO_ERRCODE,
"imtcp %s: Framing Error in received TCP message from "
"peer: (hostname) %s, (ip) %s: delimiter is not SP but has "
"peer: (hostname) %s, (ip) %s, (port) %s: delimiter is not SP but has "
"ASCII value %d.",
cnf_params->pszInputName, propPeerName, propPeerIP, c);
cnf_params->pszInputName, peerName, peerIP, peerPort, c);
}
if (pThis->iOctetsRemain < 1) {
/* TODO: handle the case where the octet count is 0! */
LogError(0, NO_ERRCODE,
"imtcp %s: Framing Error in received TCP message from "
"peer: (hostname) %s, (ip) %s: invalid octet count %d.",
cnf_params->pszInputName, propPeerName, propPeerIP, pThis->iOctetsRemain);
"peer: (hostname) %s, (ip) %s, (port) %s: invalid octet count %d.",
cnf_params->pszInputName, peerName, peerIP, peerPort, pThis->iOctetsRemain);
pThis->eFraming = TCP_FRAMING_OCTET_STUFFING;
} else if (pThis->iOctetsRemain > pThis->iMaxLine) {
/* while we can not do anything against it, we can at least log an indication
@ -522,16 +516,16 @@ static rsRetVal ATTR_NONNULL(1) processDataRcvd(tcps_sess_t *pThis,
*/
LogError(0, NO_ERRCODE,
"imtcp %s: received oversize message from peer: "
"(hostname) %s, (ip) %s: size is %d bytes, max msg size "
"(hostname) %s, (ip) %s, (port) %s: size is %d bytes, max msg size "
"is %d, truncating...",
cnf_params->pszInputName, propPeerName, propPeerIP, pThis->iOctetsRemain, pThis->iMaxLine);
cnf_params->pszInputName, peerName, peerIP, peerPort, pThis->iOctetsRemain, pThis->iMaxLine);
}
if (pThis->iOctetsRemain > pThis->pSrv->maxFrameSize) {
LogError(0, NO_ERRCODE,
"imtcp %s: Framing Error in received TCP message from "
"peer: (hostname) %s, (ip) %s: frame too large: %d, change "
"peer: (hostname) %s, (ip) %s, (port) %s: frame too large: %d, change "
"to octet stuffing",
cnf_params->pszInputName, propPeerName, propPeerIP, pThis->iOctetsRemain);
cnf_params->pszInputName, peerName, peerIP, peerPort, pThis->iOctetsRemain);
pThis->eFraming = TCP_FRAMING_OCTET_STUFFING;
} else {
pThis->iMsg = 0;

View File

@ -657,6 +657,9 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
uchar *fromHostFQDN = NULL;
prop_t *fromHostIP = NULL;
prop_t *fromHostPort = NULL;
const char *fromHostNameStr = "(hostname unknown)";
const char *fromHostIPStr = "(IP unknown)";
const char *fromHostPortStr = "(port unknown)";
ISOBJ_TYPE_assert(pThis, tcpsrv);
assert(pLstnInfo != NULL);
@ -689,6 +692,7 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
/* get the host name */
CHKiRet(netstrm.GetRemoteHName(pNewStrm, &fromHostFQDN));
fromHostNameStr = szStrOrDefault(fromHostFQDN, "(hostname unknown)");
if (!cnf_params->bPreserveCase) {
/* preserve_case = off */
uchar *p;
@ -699,6 +703,7 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
}
}
CHKiRet(netstrm.GetRemoteIP(pNewStrm, &fromHostIP));
fromHostIPStr = propGetSzStrOrDefault(fromHostIP, "(IP unknown)");
CHKiRet(netstrm.GetRemAddr(pNewStrm, &addr));
char portbuf[8];
uint16_t port;
@ -712,6 +717,7 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
CHKiRet(prop.Construct(&fromHostPort));
CHKiRet(prop.SetString(fromHostPort, (uchar *)portbuf, strlen(portbuf)));
CHKiRet(prop.ConstructFinalize(fromHostPort));
fromHostPortStr = propGetSzStrOrDefault(fromHostPort, "(port unknown)");
/* Here we check if a host is permitted to send us messages. If it isn't, we do not further
* process the message but log a warning (if we are configured to do this).
* rgerhards, 2005-09-26
@ -722,8 +728,8 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
errno = 0;
LogError(0, RS_RET_HOST_NOT_PERMITTED,
"connection request from disallowed "
"sender %s discarded",
fromHostFQDN);
"sender %s (%s:%s) discarded",
fromHostNameStr, fromHostIPStr, fromHostPortStr);
}
ABORT_FINALIZE(RS_RET_HOST_NOT_PERMITTED);
}
@ -733,8 +739,12 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
*/
CHKiRet(tcps_sess.SetHost(pSess, fromHostFQDN));
fromHostFQDN = NULL; /* we handed this string over */
fromHostNameStr = propGetSzStrOrDefault(pSess->fromHost, "(hostname unknown)");
CHKiRet(tcps_sess.SetHostIP(pSess, fromHostIP));
fromHostIPStr = propGetSzStrOrDefault(pSess->fromHostIP, "(IP unknown)");
fromHostIP = NULL;
CHKiRet(tcps_sess.SetHostPort(pSess, fromHostPort));
fromHostPortStr = propGetSzStrOrDefault(pSess->fromHostPort, "(port unknown)");
fromHostPort = NULL;
CHKiRet(tcps_sess.SetStrm(pSess, pNewStrm));
pNewStrm = NULL; /* prevent it from being freed in error handler, now done in tcps_sess! */
@ -753,7 +763,8 @@ static ATTR_NONNULL() rsRetVal SessAccept(tcpsrv_t *const pThis,
pSess = NULL; /* this is now also handed over */
if (pThis->bEmitMsgOnOpen) {
LogMsg(0, RS_RET_NO_ERRCODE, LOG_INFO, "imtcp: connection established with host: %s", propGetSzStr(fromHostIP));
LogMsg(0, RS_RET_NO_ERRCODE, LOG_INFO, "imtcp: connection established with host: %s (%s:%s)", fromHostNameStr,
fromHostIPStr, fromHostPortStr);
}
finalize_it:
@ -761,8 +772,8 @@ finalize_it:
if (iRet != RS_RET_HOST_NOT_PERMITTED && pThis->bEmitMsgOnOpen) {
LogError(0, NO_ERRCODE,
"imtcp: connection could not be "
"established with host: %s",
fromHostIP == NULL ? "(IP unknown)" : (const char *)propGetSzStr(fromHostIP));
"established with host: %s (%s:%s)",
fromHostNameStr, fromHostIPStr, fromHostPortStr);
}
if (pSess != NULL) tcps_sess.Destruct(&pSess);
if (pNewStrm != NULL) netstrm.Destruct(&pNewStrm);
@ -899,8 +910,6 @@ static rsRetVal ATTR_NONNULL(1)
ssize_t iRcvd;
rsRetVal localRet;
DEFiRet;
uchar *pszPeer;
int lenPeer;
int oserr = 0;
unsigned read_calls = 0;
tcps_sess_t *const pSess = pioDescr->ptr.pSess;
@ -908,8 +917,9 @@ static rsRetVal ATTR_NONNULL(1)
const unsigned maxReads = pThis->starvationMaxReads;
ISOBJ_TYPE_assert(pThis, tcpsrv);
prop.GetString((pSess)->fromHostIP, &pszPeer, &lenPeer);
DBGPRINTF("netstream %p with new data from remote peer %s\n", (pSess)->pStrm, pszPeer);
const char *const peerIP = propGetSzStrOrDefault(pSess->fromHostIP, "(IP unknown)");
const char *const peerPort = propGetSzStrOrDefault(pSess->fromHostPort, "(port unknown)");
DBGPRINTF("netstream %p with new data from remote peer %s:%s\n", (pSess)->pStrm, peerIP, peerPort);
if (pThis->workQueue.numWrkr > 1) {
pthread_mutex_lock(&pSess->mut);
@ -927,8 +937,8 @@ static rsRetVal ATTR_NONNULL(1)
socklen_t len = sizeof(error);
const int sock = pioDescr->sock;
if (getsockopt(sock, SOL_SOCKET, SO_ERROR, &error, &len) == 0) {
LogError(error, RS_RET_IO_ERROR, "epoll subsystem signaled EPOLLERR for stream %p, peer %s", (pSess)->pStrm,
pszPeer);
LogError(error, RS_RET_IO_ERROR, "epoll subsystem signaled EPOLLERR for stream %p, peer %s:%s",
(pSess)->pStrm, peerIP, peerPort);
}
}
#endif
@ -947,8 +957,9 @@ static rsRetVal ATTR_NONNULL(1)
case RS_RET_CLOSED:
if (pThis->bEmitMsgOnClose) {
errno = 0;
LogError(0, RS_RET_PEER_CLOSED_CONN, "Netstream session %p closed by remote peer %s.",
(pSess)->pStrm, pszPeer);
LogError(0, RS_RET_PEER_CLOSED_CONN,
"Netstream session %p closed by remote peer %s:%s.", (pSess)->pStrm, peerIP,
peerPort);
}
state = RS_DONECLOSE;
break;
@ -969,14 +980,14 @@ static rsRetVal ATTR_NONNULL(1)
}
localRet = tcps_sess.DataRcvd(pSess, buf, iRcvd);
if (localRet != RS_RET_OK && localRet != RS_RET_QUEUE_FULL) {
LogError(oserr, localRet, "Tearing down TCP Session from %s", pszPeer);
LogError(oserr, localRet, "Tearing down TCP Session from %s:%s", peerIP, peerPort);
state = RS_DONECLOSE;
}
break;
default:
LogError(oserr, iRet, "netstream session %p from %s will be closed due to error",
pSess->pStrm, pszPeer);
LogError(oserr, iRet, "netstream session %p from %s:%s will be closed due to error",
pSess->pStrm, peerIP, peerPort);
state = RS_DONECLOSE;
break;
}