Skip to content

Commit

Permalink
Merge pull request #18556 from rpastrana/HPCC-29334-60traceidlogs
Browse files Browse the repository at this point in the history 
HPCC-29334 Associate log entries with Active JTrace info

Reviewed-by: Gavin Halliday <[email protected]>
Merged-by: Gavin Halliday <[email protected]>
  • Loading branch information
@ghalliday
ghalliday authored May 17, 2024
2 parents f273103 + 0d3a29c commit 4a181eb
Show file tree
Hide file tree
Showing 7 changed files with 202 additions and 16 deletions.
7 changes: 5 additions & 2 deletions helm/examples/logging/README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -94,9 +94,12 @@ Log output verbosity can be adjusted from "critical messages only" (1) up to "re

### Log Data Column Configuration

The available log data columns include messageid(MID), audience(AUD), class(CLS), date(DAT), time(TIM), millitime(MLT), microtime(MCT), nanotime(NNT), processid(PID), threadid(TID), node(NOD), job(JOB), use(USE), session(SES), code(COD), component(COM), quotedmessage(QUO), prefix(PFX), all(ALL), and standard(STD). The log data columns (or fields) configuration is controlled by the `<section>`.logging.fields value, comprised of 3 letter codes delimited by the aggregation operator (+) or the removal operator (-).
The available log data columns include traceid(TRC), spanid(SPN), messageid(MID), audience(AUD), class(CLS), date(DAT), time(TIM), millitime(MLT), microtime(MCT), nanotime(NNT), processid(PID), threadid(TID), node(NOD), job(JOB), use(USE), session(SES), code(COD), component(COM), quotedmessage(QUO), prefix(PFX), all(ALL), and standard(STD). The log data columns (or fields) configuration is controlled by the `<section>`.logging.fields value, comprised of 3 letter codes delimited by the aggregation operator (+) or the removal operator (-).

For example, all component log output should include the standard columns except the job ID column:
Example: all component log output should include the standard columns except the job ID column:
helm install myhpcc ./hpcc --set global.logging.fields="STD-JOB"

Example: Include trace and span info in addition to the standard columns:
helm install myhpcc ./hpcc --set global.logging.fields="STD-JOB"

Adjustment of per-component logging values can require assertion of multiple component specific values, which can be inconvinient to do via the --set command line parameter. In these cases, a custom values file could be used to set all required fields.
Expand Down
50 changes: 45 additions & 5 deletions system/jlib/jlog.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,7 @@ void LogMsgSysInfo::deserialize(MemoryBuffer & in)

class LoggingFieldColumns
{
const EnumMapping MsgFieldMap[16] =
const EnumMapping MsgFieldMap[18] =
{
{ MSGFIELD_msgID, "MsgID " },
{ MSGFIELD_audience, "Audience " },
Expand All @@ -148,6 +148,8 @@ class LoggingFieldColumns
{ MSGFIELD_job, "JobID " },
{ MSGFIELD_user, "UserID " },
{ MSGFIELD_component, "Compo " },
{ MSGFIELD_trace, "Trace " },
{ MSGFIELD_span, "Span " },
{ MSGFIELD_quote, "Quoted "}
};
const unsigned sizeMsgFieldMap = arraysize(MsgFieldMap);
Expand Down Expand Up @@ -298,6 +300,10 @@ static const LogMsgJobInfo queryDefaultJobInfo()
return LogMsgJobInfo(queryThreadedJobId(), UnknownUser);
}

static const LogMsgTraceInfo queryActiveTraceInfo()
{
return LogMsgTraceInfo(queryThreadedActiveSpan());
}

LogMsg::LogMsg(LogMsgJobId id, const char *job) : category(MSGAUD_programmer, job ? MSGCLS_addid : MSGCLS_removeid), sysInfo(), jobInfo(id), remoteFlag(false)
{
Expand All @@ -306,20 +312,20 @@ LogMsg::LogMsg(LogMsgJobId id, const char *job) : category(MSGAUD_programmer, jo
}

LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, const char * _text, unsigned port, LogMsgSessionId session)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()), msgCode(_code), remoteFlag(false)
{
text.append(_text);
}

LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, size32_t sz, const char * _text, unsigned port, LogMsgSessionId session)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()), msgCode(_code), remoteFlag(false)
{
text.append(sz, _text);
}

LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, const char * format, va_list args,
unsigned port, LogMsgSessionId session)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
: category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()), msgCode(_code), remoteFlag(false)
{
text.valist_appendf(format, args);
}
Expand Down Expand Up @@ -387,6 +393,16 @@ StringBuffer & LogMsg::toStringPlain(StringBuffer & out, unsigned fields) const
else
out.appendf("usr=%" I64F "u ", jobInfo.queryUserID());
}
if(fields & MSGFIELD_trace)
{
//it seems the existing convention is to use 3 char abbreviation
out.appendf("trc=%s ", traceInfo.queryTraceID());
}
if (fields & MSGFIELD_span)
{
//it seems the existing convention is to use 3 char abbreviation
out.appendf("spn=%s ", traceInfo.querySpanID());
}
if (fields & MSGFIELD_quote)
out.append('"');
if (fields & MSGFIELD_prefix)
Expand Down Expand Up @@ -471,6 +487,14 @@ StringBuffer & LogMsg::toStringXML(StringBuffer & out, unsigned fields) const
else
out.append("UserID=\"").append(jobInfo.queryUserID()).append("\" ");
}
if(fields & MSGFIELD_trace)
{
out.append("TraceID=\"").append(traceInfo.queryTraceID()).append("\" ");
}
if (fields & MSGFIELD_span)
{
out.append("SpanID=\"").append(traceInfo.querySpanID()).append("\" ");
}
#ifdef LOG_MSG_NEWLINE
if(fields & MSGFIELD_allJobInfo) out.append("\n ");
#endif
Expand Down Expand Up @@ -546,6 +570,14 @@ StringBuffer & LogMsg::toStringJSON(StringBuffer & out, unsigned fields) const
else
out.append(", \"USER\": \"").append(jobInfo.queryUserID()).append("\"");
}
if(fields & MSGFIELD_trace)
{
out.appendf("\"TRACEID\"=\"%s\"", traceInfo.queryTraceID());
}
if (fields & MSGFIELD_span)
{
out.appendf("\"SPANID\"=\"%s\"",traceInfo.querySpanID());
}
if((fields & MSGFIELD_code) && (msgCode != NoLogMsgCode))
out.append(", \"CODE\": \"").append(msgCode).append("\"");

Expand Down Expand Up @@ -610,6 +642,14 @@ StringBuffer & LogMsg::toStringTable(StringBuffer & out, unsigned fields) const
{
out.appendf("%-7s ", jobInfo.queryJobIDStr());
}
if(fields & MSGFIELD_trace)
{
out.appendf("%s ", traceInfo.queryTraceID());
}
if(fields & MSGFIELD_span)
{
out.appendf("%s ", traceInfo.querySpanID());
}
if(fields & MSGFIELD_user)
{
if(jobInfo.queryUserID() == UnknownUser)
Expand Down Expand Up @@ -2300,7 +2340,7 @@ void setupContainerizedLogMsgHandler()

if (logConfig->hasProp(logFieldsAtt))
{
//Supported logging fields: AUD,CLS,DET,MID,TIM,DAT,PID,TID,NOD,JOB,USE,SES,COD,MLT,MCT,NNT,COM,QUO,PFX,ALL,STD
//Supported logging fields: TRC,SPN,AUD,CLS,DET,MID,TIM,DAT,PID,TID,NOD,JOB,USE,SES,COD,MLT,MCT,NNT,COM,QUO,PFX,ALL,STD
const char *logFields = logConfig->queryProp(logFieldsAtt);
if (!isEmptyString(logFields))
theStderrHandler->setMessageFields(logMsgFieldsFromAbbrevs(logFields));
Expand Down
53 changes: 49 additions & 4 deletions system/jlib/jlog.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -318,19 +318,20 @@ typedef enum
MSGFIELD_component = 0x010000,
MSGFIELD_quote = 0x020000,
MSGFIELD_prefix = 0x040000,
MSGFIELD_last = 0x040000,
MSGFIELD_trace = 0x080000,
MSGFIELD_span = 0x100000,
MSGFIELD_last = 0x100000,
MSGFIELD_all = 0xFFFFFF
} LogMsgField;

#ifdef _WIN32
#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_timeDate | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
#define MSGFIELD_LEGACY LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix)
#else

#ifdef _CONTAINERIZED
#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_job | MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_class | MSGFIELD_audience)
#define MSGFIELD_STANDARD LogMsgField( MSGFIELD_job | MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_class | MSGFIELD_audience)
#else
#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
#define MSGFIELD_STANDARD LogMsgField( MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
#endif
#define MSGFIELD_LEGACY LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix)
#endif
Expand Down Expand Up @@ -375,6 +376,10 @@ inline const char * LogMsgFieldToString(LogMsgField field)
return("Component");
case MSGFIELD_quote:
return("Quote");
case MSGFIELD_trace:
return("Trace ID");
case MSGFIELD_span:
return("Span ID");
default:
return("UNKNOWN");
}
Expand Down Expand Up @@ -404,6 +409,10 @@ inline unsigned LogMsgFieldFromAbbrev(char const * abbrev)
return MSGFIELD_job;
if(strnicmp(abbrev, "USE", 3)==0)
return MSGFIELD_user;
if(strnicmp(abbrev, "TRC", 3)==0)
return MSGFIELD_trace;
if(strnicmp(abbrev, "SPN", 3)==0)
return MSGFIELD_span;
if(strnicmp(abbrev, "SES", 3)==0)
return MSGFIELD_session;
if(strnicmp(abbrev, "COD", 3)==0)
Expand Down Expand Up @@ -588,6 +597,41 @@ class jlib_decl LogMsgJobInfo
bool isDeserialized = false;
};

#define UNK_LOG_ENTRY "UNK"
class jlib_decl LogMsgTraceInfo
{
public:
LogMsgTraceInfo() = default;
LogMsgTraceInfo(ISpan * _span) : span(_span)
{
}

const char * queryTraceID() const
{
if (span)
{
const char * traceId = span->queryTraceId();
if (traceId)
return traceId;
}
return UNK_LOG_ENTRY;
}

const char * querySpanID() const
{
if (span)
{
const char * spanId = span->querySpanId();
if (spanId)
return spanId;
}
return UNK_LOG_ENTRY;
}

private:
Linked<ISpan> span;
};

class jlib_decl LogMsg : public CInterface
{
public:
Expand Down Expand Up @@ -615,6 +659,7 @@ class jlib_decl LogMsg : public CInterface
LogMsgCategory category;
LogMsgSysInfo sysInfo;
LogMsgJobInfo jobInfo;
LogMsgTraceInfo traceInfo;
LogMsgCode msgCode = NoLogMsgCode;
StringBuffer text;
bool remoteFlag = false;
Expand Down
15 changes: 14 additions & 1 deletion system/jlib/jtrace.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -791,6 +791,16 @@ class CSpan : public CInterfaceOf<ISpan>
recordError(SpanError(msg.str(), e->errorCode(), spanFailed, escapedScope));
};

virtual const char * queryTraceId() const override
{
return traceID.get();
}

virtual const char * querySpanId() const override
{
return spanID.get();
}

protected:
CSpan(const char * spanName)
{
Expand Down Expand Up @@ -901,6 +911,9 @@ class CNullSpan final : public CInterfaceOf<ISpan>
virtual void recordError(const SpanError & error) override {};
virtual void setSpanStatusSuccess(bool spanSucceeded, const char * statusMessage) override {}

virtual const char * queryTraceId() const override { return nullptr; }
virtual const char * querySpanId() const override { return nullptr; }

virtual const char* queryGlobalId() const override { return nullptr; }
virtual const char* queryCallerId() const override { return nullptr; }
virtual const char* queryLocalId() const override { return nullptr; }
Expand Down Expand Up @@ -1504,8 +1517,8 @@ void OwnedSpanScope::clear()
{
if (span)
{
setThreadedActiveSpan(prevSpan);
span->endSpan();
setThreadedActiveSpan(prevSpan);
span.clear();
}
}
Expand Down
2 changes: 2 additions & 0 deletions system/jlib/jtrace.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,8 @@ interface ISpan : extends IInterface
virtual void recordException(IException * e, bool spanFailed = true, bool escapedScope = true) = 0;
virtual void recordError(const SpanError & error = SpanError()) = 0;
virtual void setSpanStatusSuccess(bool spanSucceeded, const char * statusMessage = NO_STATUS_MESSAGE) = 0;
virtual const char * queryTraceId() const = 0;
virtual const char * querySpanId() const = 0;

virtual ISpan * createClientSpan(const char * name) = 0;
virtual ISpan * createInternalSpan(const char * name) = 0;
Expand Down
Loading

0 comments on commit 4a181eb

Please sign in to comment.