Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ZSS Logging Improvements #444

Open
wants to merge 17 commits into
base: v2.x/staging
Choose a base branch
from
Open

ZSS Logging Improvements #444

Show file tree
Hide file tree
Changes from 11 commits
Commits
Show all changes
17 commits
Select commit Hold shift + click to select a range
da3da93
first iteration at logging improvements for zss data services due to …
jordanfilteau1995 Apr 27, 2024
8c6b391
more metadata added; changed format.
jordanfilteau1995 Apr 28, 2024
ea41cee
making changes requested by Sean to conform to Zowe common logging fo…
jordanfilteau1995 Apr 29, 2024
7702b00
adding a second loghandler; more backwards compatibility.
jordanfilteau1995 Apr 29, 2024
c0fbdb5
removing magic numbers; adding comments.
jordanfilteau1995 Apr 29, 2024
701ce00
simplify code
jordanfilteau1995 Apr 29, 2024
18f74b4
updating based on Sean feedback, adding small test case.
jordanfilteau1995 Apr 30, 2024
8ccaac5
adding build script
jordanfilteau1995 Apr 30, 2024
f5f88d4
Merge branch 'v2.x/staging' into jordan-logging-improvements
jordanfilteau1995 Apr 30, 2024
8f926e3
moving new handler2 to end of LoggingDestination; using const char *;…
jordanfilteau1995 May 1, 2024
73511cc
Merge branch 'jordan-logging-improvements' of github.com:zowe/zowe-co…
jordanfilteau1995 May 1, 2024
890be90
addressing some of Irek's comments.
jordanfilteau1995 May 29, 2024
a8cc7cf
Merge branch 'v2.x/staging' into jordan-logging-improvements
jordanfilteau1995 May 29, 2024
7c64dda
Merge branch 'v2.x/staging' into jordan-logging-improvements
jordanfilteau1995 Jul 19, 2024
e0373ea
committing tests
jordanfilteau1995 Jul 19, 2024
ccbf89b
updating test and build
jordanfilteau1995 Aug 5, 2024
af3de61
adding declarations
jordanfilteau1995 Aug 5, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
284 changes: 248 additions & 36 deletions c/logging.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,9 @@
#include <string.h>
#include <stdarg.h>
#include <sys/stat.h>

#include <time.h>
#include <unistd.h>
#include <sys/time.h>
#endif

#include "zowetypes.h"
Expand All @@ -36,6 +38,7 @@
#include "utils.h"
#include "logging.h"
#include "printables_for_dump.h"
#include "zos.h"

#ifdef __ZOWE_OS_ZOS
#include "le.h"
Expand Down Expand Up @@ -402,11 +405,13 @@ int setLoggingContext(LoggingContext *context) {
#endif /* not LOGGING_CUSTOM_CONTEXT_GETTER */
}

LoggingDestination *logConfigureDestination(LoggingContext *context,
unsigned int id,
char *name,
void *data,
LogHandler handler){
LoggingDestination *logConfigureDestination3(LoggingContext *context,
unsigned int id,
char *name,
void *data,
LogHandler handler,
DataDumper dumper,
LogHandler2 handler2) {

if (context == NULL) {
context = getLoggingContext();
Expand Down Expand Up @@ -439,47 +444,219 @@ LoggingDestination *logConfigureDestination(LoggingContext *context,
destination->name = name;
destination->data = data;
destination->handler = handler;
destination->dumper = standardDumperFunction;
destination->handler2 = handler2;
destination->dumper = dumper != NULL ? dumper : standardDumperFunction;
destination->state = LOG_DESTINATION_STATE_INIT;
return destination;
}

LoggingDestination *logConfigureDestination(LoggingContext *context,
unsigned int id,
char *name,
void *data,
LogHandler handler){

return logConfigureDestination3(context, id, name, data, handler, NULL, NULL);
}

LoggingDestination *logConfigureDestination2(LoggingContext *context,
unsigned int id,
char *name,
void *data,
LogHandler handler,
DataDumper dumper){
LoggingDestination *destination = logConfigureDestination(context, id, name, data, handler);
if (destination != NULL) {
destination->dumper = dumper;

return logConfigureDestination3(context, id, name, data, handler, dumper, NULL);
}

static char *logLevelToString(int level) {
switch (level) {
case ZOWE_LOG_SEVERE: return "CRITICAL";
case ZOWE_LOG_WARNING: return "WARN";
case ZOWE_LOG_INFO: return "INFO";
case ZOWE_LOG_DEBUG: return "DEBUG";
case ZOWE_LOG_DEBUG2: return "FINER";
case ZOWE_LOG_DEBUG3: return "TRACE";
default: return "NA";
}
return destination;
}

void printStdout(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList){
typedef struct zl_time_t {
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
char value[32];
} zl_time_t;

static zl_time_t gettime(void) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With all the non-Metal stuff, the ZIS build fails now:

ERROR CCN3277 ../../deps/zowe-common-c/c/logging.c:490   Syntax error: possible missing ';' or ','?
ERROR CCN3045 ../../deps/zowe-common-c/c/logging.c:490   Undeclared identifier time_t.
ERROR CCN3007 ../../deps/zowe-common-c/c/logging.c:493   "struct tm" is undefined.
ERROR CCN3045 ../../deps/zowe-common-c/c/logging.c:496   Undeclared identifier t.
ERROR CCN3007 ../../deps/zowe-common-c/c/logging.c:500   "struct timeval" is undefined.
ERROR CCN3277 ../../deps/zowe-common-c/c/logging.c:513   Syntax error: possible missing ';' or ','?
ERROR CCN3045 ../../deps/zowe-common-c/c/logging.c:513   Undeclared identifier pthread_t.
ERROR CCN3045 ../../deps/zowe-common-c/c/logging.c:514   Undeclared identifier pThread.
ERROR CCN3277 ../../deps/zowe-common-c/c/logging.c:605   Syntax error: possible missing ')' or ','?
CCN0793(I) Compilation failed for file ../../deps/zowe-common-c/c/logging.c.  Object file not created.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you name this function according to the style of this file? E.g., getCurrentTime.


time_t t = time(NULL);
const char *format = "%Y-%m-%d %H:%M:%S";

struct tm lt;
zl_time_t result;

gmtime_r(&t, &lt);
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved

strftime(result.value, sizeof(result.value), format, &lt);
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved

struct timeval now;
gettimeofday(&now, NULL);
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
int milli = now.tv_usec / 1000;
snprintf(result.value+strlen(result.value), 5, ".%03d", milli);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why 5? I also suggest you check the return value for -1 and at least make sure the buffer is terminated if the call fails.


return result;
}

static const char *getServiceName() {
return "ZWESZ1";
}

static void getTaskInformation(char *taskInformation, unsigned int taskInformationSize) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's also fine to use size_t as the type for sizes because it's what the C library functions do (I know, you're probably not going to have a buffer larger than 4GB but that's not the only reason).

pthread_t pThread = pthread_self();
snprintf(taskInformation, taskInformationSize, "0x%p:0x%p:%d", getTCB(), &pThread, getpid());
}

static void getMessage(char *message, unsigned int messageSize, const char *formatString, va_list argList) {
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
vsnprintf(message, messageSize, formatString, argList);
}

/*
* 1. Try to get the name from the TCB.
* 2. Try to get the name from the login data base.
*/
static void getUserID(char *user, unsigned int userSize) {
TCB *tcb = getTCB();
ACEE *acee = (ACEE *) tcb->tcbsenv;
if (acee) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But no ACEE can also mean no impersonation and there should probably be a job-level ACEE and user in that case. Why have you chosen getlogin_r over that? And will getlogin_r return the proper value if zss is running as an STC?

snprintf(user, userSize, "%.*s", acee->aceeuser[0], acee->aceeuser[1]);
} else {
getlogin_r(user, userSize);
}
}

/*
* These seem very generous.
*
*/
#define LOG_USER_ID_MAX_LENGTH 8
#define LOG_MESSAGE_MAX_LENGTH 512
#define LOG_TASK_INFO_MAX_LENGTH 128

static void prependMetadata(int logLevel,
char *fullMessage,
unsigned int fullMessageSize,
char *formatString,
va_list argList,
char *fileName,
char *functionName,
unsigned int lineNumber) {
char user[LOG_USER_ID_MAX_LENGTH + 1] = {0};
getUserID((char *) &user, sizeof(user) - 1);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The function already null-terminates, so this may confuse people.

zl_time_t time = {0};
time = gettime();
char message[LOG_MESSAGE_MAX_LENGTH + 1] = {0};
getMessage((char *) &message, sizeof(message), formatString, argList);
char taskInformation[LOG_TASK_INFO_MAX_LENGTH + 1] = {0};
getTaskInformation((char *) &taskInformation, sizeof(taskInformation));
char *logLevelAsString = logLevelToString(logLevel);
/*
* The following fields were added in the second iteration of LogHandler.
*
* 1. fileName
* 2. functionName
* 3. lineNumber
* 4. logLevel
*
* (1,2,3) were never asked for, but (4) wasn't propogated down to the LogHandler and was just used to determine
* if the message should be printed. (4) is now passed to here so that it can be used to construct the common
* logging format.
*
* If one of these (1,2,3,4) isn't present, then they all aren't based on this implementation; therefore, we'll just format with what's
* available to us without relying on new arguments. The previous LogHandler will return null or empty values for (1,2), a 0 for (3), and
* ZOWE_LOG_NA for (4), which when going thorugh logLevelToString() will be NA.
*
* The existing logs in the server should contain the level, as long as logConfigureDestination3() is used. If not, it will have the placeholder.
*
*/
if (!fileName || strlen(fileName) == 0 || !functionName || strlen(functionName) == 0 || lineNumber == 0) {
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
snprintf(fullMessage,
fullMessageSize,
"%s <%s:%s> %s %s %s",
time.value,
getServiceName(),
taskInformation,
user,
logLevelAsString,
message);
} else {
snprintf(fullMessage,
fullMessageSize,
"%s <%s:%s> %s %s (%s:%s:%d) %s",
time.value,
getServiceName(),
taskInformation,
user,
logLevelAsString,
basename(fileName),
functionName,
lineNumber,
message);
}
}

void printToLog(FILE *destination,
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
char *formatString,
va_list argList,
int logLevel,
char *fileName,
char *functionName,
unsigned int lineNumber) {
#ifdef METTLE
printf("broken printf in logging.c\n");
#else
vfprintf(stdout,formatString,argList);
#else
char fullMessage[LOG_USER_ID_MAX_LENGTH + LOG_MESSAGE_MAX_LENGTH + LOG_TASK_INFO_MAX_LENGTH + 1] = {0};
prependMetadata(logLevel, (char *) &fullMessage, sizeof(fullMessage), formatString, argList, fileName, functionName, lineNumber);
fprintf(destination, "%s\n", fullMessage);
#endif
}

void printStdout2(LoggingContext *context,
LoggingComponent *component,
void *data,
char *formatString,
va_list argList,
int logLevel,
char *fileName,
char *functionName,
unsigned int lineNumber) {
printToLog(stdout, formatString, argList, logLevel, fileName, functionName, lineNumber);
}

void printStdout(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList){
printStdout2(context, component, data, formatString, argList, ZOWE_LOG_NA, "", "", 0);
}

void printStderr2(LoggingContext *context,
LoggingComponent *component,
void *data,
char *formatString,
va_list argList,
int logLevel,
char *fileName,
char *functionName,
unsigned int lineNumber) {
printToLog(stderr, formatString, argList, logLevel, fileName, functionName, lineNumber);
}

void printStderr(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList){
#ifdef METTLE
printf("broken printf in logging.c\n");
#else
vfprintf(stderr,formatString,argList);
#endif
printStderr2(context, component, data, formatString, argList, ZOWE_LOG_NA, "", "", 0);
}

void logConfigureStandardDestinations(LoggingContext *context){
if (context == NULL) {
context = getLoggingContext();
}
logConfigureDestination(context,LOG_DEST_DEV_NULL,"/dev/null",NULL,NULL);
logConfigureDestination(context,LOG_DEST_PRINTF_STDOUT,"printf(stdout)",NULL,printStdout);
logConfigureDestination(context,LOG_DEST_PRINTF_STDERR,"printf(stderr)",NULL,printStderr);
logConfigureDestination3(context,LOG_DEST_DEV_NULL,"/dev/null",NULL,NULL,NULL,NULL);
logConfigureDestination3(context,LOG_DEST_PRINTF_STDOUT,"printf(stdout)",NULL,printStdout,NULL,printStdout2);
logConfigureDestination3(context,LOG_DEST_PRINTF_STDERR,"printf(stderr)",NULL,printStderr,NULL,printStderr2);
}

void logConfigureComponent(LoggingContext *context, uint64 compID, char *compName, int destination, int level){
Expand Down Expand Up @@ -649,7 +826,14 @@ int logGetLevel(LoggingContext *context, uint64 compID){
return component ? component->currentDetailLevel : ZOWE_LOG_NA;
}

void zowelog(LoggingContext *context, uint64 compID, int level, char *formatString, ...){
void zowelogInner(LoggingContext *context,
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
uint64 compID,
int level,
char *fileName,
char *functionName,
unsigned int lineNumber,
char *formatString,
va_list argPointer) {

if (logShouldTrace(context, compID, level) == FALSE) {
return;
Expand All @@ -666,10 +850,7 @@ void zowelog(LoggingContext *context, uint64 compID, int level, char *formatStri
}

if (maxDetailLevel >= level){
va_list argPointer;

LoggingDestination *destination = &getDestinationTable(context, compID)[component->destination];
// printf("log.2 comp.dest=%d\n",component->destination);fflush(stdout);
if (component->destination >= MAX_LOGGING_DESTINATIONS){
char message[128];
sprintf(message,"Destination %d is out of range (log)\n",component->destination);
Expand All @@ -680,34 +861,58 @@ void zowelog(LoggingContext *context, uint64 compID, int level, char *formatStri
printf("dev/null case\n");
return;
}
// printf("log.3\n");fflush(stdout);
if (destination->state == LOG_DESTINATION_STATE_UNINITIALIZED){
char message[128];
sprintf(message,"Destination %d is not initialized for logging\n",component->destination);
lastResortLog(message);
return;
}
/* here, pass to a var-args handler */
va_start(argPointer, formatString);

destination->handler(context,component,destination->data,formatString,argPointer);

va_end(argPointer);
if (destination->handler2) {
destination->handler2(context,component,destination->data,formatString,argPointer,level,fileName,functionName,lineNumber);
} else {
destination->handler(context,component,destination->data,formatString,argPointer);
}
}
}

void zowelog2(LoggingContext *context, uint64 compID, int level, char *fileName, char *functionName, unsigned int lineNumber, char *formatString, ...) {
va_list argPointer;
va_start(argPointer, formatString);
zowelogInner(context, compID, level, fileName, functionName, lineNumber, formatString, argPointer);
va_end(argPointer);
}

void zowelog(LoggingContext *context, uint64 compID, int level, char *formatString, ...){
va_list argPointer;
va_start(argPointer, formatString);
zowelogInner(context, compID, level, "", "", 0, formatString, argPointer);
va_end(argPointer);
}

static void printToDestination(LoggingDestination *destination,
struct LoggingContext_tag *context,
LoggingComponent *component,
int level, char *fileName,
char *functionName, unsigned int lineNumber,
void *data, char *formatString, ...){
va_list argPointer;
va_start(argPointer, formatString);
destination->handler(context,component,destination->data,formatString,argPointer);
if (destination->handler2) {
destination->handler2(context,component,destination->data,formatString,argPointer,level,fileName,functionName,lineNumber);
} else {
destination->handler(context,component,destination->data,formatString,argPointer);
}
va_end(argPointer);
}

void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int dataSize){
void zowedumpInner(LoggingContext *context,
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
uint64 compID,
int level,
void *data,
int dataSize,
char *fileName,
char *functionName,
unsigned int lineNumber) {

if (logShouldTrace(context, compID, level) == FALSE) {
return;
Expand Down Expand Up @@ -748,15 +953,22 @@ void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int
for (int i = 0; ; i++){
char *result = destination->dumper(workBuffer, sizeof(workBuffer), data, dataSize, i);
if (result != NULL){
printToDestination(destination, context, component, destination->data, "%s\n", result);
printToDestination(destination, context, component, level, fileName, functionName, lineNumber, destination->data, "%s\n", result);
}
else {
break;
}
}

}
}

void zowedump2(LoggingContext *context, uint64 compID, int level, void *data, int dataSize, char *fileName, char *functionName, unsigned int lineNumber) {
jordanfilteau1995 marked this conversation as resolved.
Show resolved Hide resolved
zowedumpInner(context, compID, level, data, dataSize, fileName, functionName, lineNumber);
}

void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int dataSize){
zowedumpInner(context, compID, level, data, dataSize, "", "", 0);
}

bool logShouldTraceInternal(LoggingContext *context, uint64 componentID, int level) {
Expand Down
Loading
Loading