diff --git a/c/logging.c b/c/logging.c index b43f50367..701214bbe 100644 --- a/c/logging.c +++ b/c/logging.c @@ -26,7 +26,9 @@ #include #include #include - +#include +#include +#include #endif #include "zowetypes.h" @@ -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" @@ -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(); @@ -439,47 +444,231 @@ 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){ -#ifdef METTLE +typedef struct ZLTime_t { + char value[32]; +} ZLTime; + +static int getTime(ZLTime *result) { + + time_t t = time(NULL); + const char *format = "%Y-%m-%d %H:%M:%S"; + + struct tm lt; + gmtime_r(&t, <); + + if (strftime(result->value, sizeof(result->value), format, <) == 0) { + return 1; + } + + struct timeval now; + if (gettimeofday(&now, NULL) != 0) { + return 1; + } + + int milli = now.tv_usec / 1000; + snprintf(result->value+strlen(result->value), 5, ".%03d", milli); + + return 0; +} + +static const char *getDefaultServiceName() { + return "ZWESZ1"; +} + +static void getTaskInformation(char *taskInformation, unsigned int taskInformationSize) { + 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) { + 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) { + 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, + const char *serviceName) { + char user[LOG_USER_ID_MAX_LENGTH + 1] = {0}; + getUserID((char *) &user, sizeof(user) - 1); + ZLTime time = {0}; + if (getTime(&time) != 0) { + strcpy(time.value, "0000-00-00 00:00:00.000"); + } + 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. + * + * Service name is configurable. + * + */ + bool useFileMetadata = fileName && strlen(fileName) != 0 && functionName && strlen(functionName) != 0 && lineNumber != 0; + if (!useFileMetadata) { + snprintf(fullMessage, + fullMessageSize, + "%s <%s:%s> %s %s %s", + time.value, + serviceName != NULL && strlen(serviceName) != 0 ? serviceName : getDefaultServiceName(), + taskInformation, + user, + logLevelAsString, + message); + } else { + snprintf(fullMessage, + fullMessageSize, + "%s <%s:%s> %s %s (%s:%s:%d) %s", + time.value, + serviceName != NULL && strlen(serviceName) != 0 ? serviceName : getDefaultServiceName(), + taskInformation, + user, + logLevelAsString, + basename(fileName), + functionName, + lineNumber, + message); + } +} + +static void printToLog(FILE *destination, + char *formatString, + va_list argList, + int logLevel, + char *fileName, + char *functionName, + unsigned int lineNumber, + const char *serviceName) { +#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, serviceName); + 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, + const char *serviceName) { + printToLog(stdout, formatString, argList, logLevel, fileName, functionName, lineNumber, serviceName); +} + +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, + const char *serviceName) { + printToLog(stderr, formatString, argList, logLevel, fileName, functionName, lineNumber, serviceName); +} + 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){ @@ -649,7 +838,15 @@ int logGetLevel(LoggingContext *context, uint64 compID){ return component ? component->currentDetailLevel : ZOWE_LOG_NA; } -void zowelog(LoggingContext *context, uint64 compID, int level, char *formatString, ...){ +static void zowelogInner(LoggingContext *context, + uint64 compID, + int level, + char *fileName, + char *functionName, + unsigned int lineNumber, + const char *serviceName, + char *formatString, + va_list argPointer) { if (logShouldTrace(context, compID, level) == FALSE) { return; @@ -666,10 +863,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); @@ -680,34 +874,60 @@ 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,serviceName); + } else { + destination->handler(context,component,destination->data,formatString,argPointer); + } } +} +void zowelog2(LoggingContext *context, uint64 compID, int level, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName, char *formatString, ...) { + va_list argPointer; + va_start(argPointer, formatString); + zowelogInner(context, compID, level, fileName, functionName, lineNumber, serviceName, 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, + const char *serviceName, 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,serviceName); + } else { + destination->handler(context,component,destination->data,formatString,argPointer); + } va_end(argPointer); } -void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int dataSize){ +static void zowedumpInner(LoggingContext *context, + uint64 compID, + int level, + void *data, + int dataSize, + char *fileName, + char *functionName, + unsigned int lineNumber, + const char *serviceName) { if (logShouldTrace(context, compID, level) == FALSE) { return; @@ -748,7 +968,7 @@ 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, serviceName, destination->data, "%s\n", result); } else { break; @@ -756,7 +976,14 @@ void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int } } +} +void zowedump2(LoggingContext *context, uint64 compID, int level, void *data, int dataSize, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName) { + zowedumpInner(context, compID, level, data, dataSize, fileName, functionName, lineNumber, serviceName); +} + +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) { diff --git a/h/logging.h b/h/logging.h index 1d7654f71..cbad510ca 100644 --- a/h/logging.h +++ b/h/logging.h @@ -22,6 +22,30 @@ #include "collections.h" #include "le.h" +#define ZOWELOG_SEVERE($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_SEVERE, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + +#define ZOWELOG_WARNING($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_WARNING, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + +#define ZOWELOG_INFO($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_INFO, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + +#define ZOWELOG_DEBUG($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_DEBUG, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + +#define ZOWELOG_DEBUG2($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_DEBUG2, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + +#define ZOWELOG_DEBUG3($id, $fmt, ...) \ + zowelog2(NULL, $id, ZOWE_LOG_DEBUG3, \ + __FILE__, __FUNCTION__, __LINE__, NULL, $fmt, ##__VA_ARGS__) + /** \file * \brief logging.h defines a platform-independent logging facility that echoes some of Java logging. * @@ -46,6 +70,7 @@ ZOWE_PRAGMA_PACK_RESET #define RC_LOG_ERROR 8 #define ZOWE_LOG_NA -1 + #define ZOWE_LOG_SEVERE 0 #define ZOWE_LOG_ALWAYS 0 #define ZOWE_LOG_WARNING 1 @@ -131,11 +156,23 @@ typedef struct LogComponentsMap_tag { struct LoggingContext_tag; -typedef void (*LogHandler)(struct LoggingContext_tag *context, +typedef void (*LogHandler2)(struct LoggingContext_tag *context, LoggingComponent *component, void *data, char *formatString, - va_list argList); + va_list argList, + int logLevel, + char *fileName, + char *functionName, + unsigned int lineNumber, + const char *serviceName); + +typedef void (*LogHandler)(struct LoggingContext_tag *context, + LoggingComponent *component, + void *data, + char *formatString, + va_list argList); + typedef char *(*DataDumper)(char *workBuffer, int workBufferSize, void *data, int dataSize, int lineNumber); ZOWE_PRAGMA_PACK @@ -148,6 +185,7 @@ typedef struct LoggingDestination_tag{ void *data; /* used by destination to hold internal state */ LogHandler handler; DataDumper dumper; + LogHandler2 handler2; } LoggingDestination; #define MAX_LOGGING_COMPONENTS 256 @@ -255,9 +293,12 @@ extern LoggingContext *theLoggingContext; #define getLoggingContext GTLOGCTX #define setLoggingContext STLOGCTX #define zowelog ZOWELOG +#define zowelog2 ZOWELOG2 #define zowedump ZOWEDUMP +#define zowedump2 ZOWEDUM2 #define logConfigureDestination LGCFGDST #define logConfigureDestination2 LGCFGDS2 +#define logConfigureDestination3 LGCFGDS3 #define logConfigureStandardDestinations LGCFGSTD #define logConfigureComponent LGCFGCMP #define logSetLevel LGSETLVL @@ -267,6 +308,8 @@ extern LoggingContext *theLoggingContext; #define logSetExternalContext LGSLOGCX #define printStdout LGPRSOUT #define printStderr LGPRSERR +#define printStdout2 LGPROUT2 +#define printStderr2 LGPRERR2 #endif @@ -335,7 +378,9 @@ bool logShouldTraceInternal(LoggingContext *context, uint64 componentID, int lev */ void zowelog(LoggingContext *context, uint64 compID, int level, char *formatString, ...); +void zowelog2(LoggingContext *context, uint64 compID, int level, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName, char *formatString, ...); void zowedump(LoggingContext *context, uint64 compID, int level, void *data, int dataSize); +void zowedump2(LoggingContext *context, uint64 compID, int level, void *data, int dataSize, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName); #define LOGCHECK(context,component,level) \ ((component > MAX_LOGGING_COMPONENTS) ? \ @@ -355,6 +400,14 @@ LoggingDestination *logConfigureDestination2(LoggingContext *context, LogHandler handler, DataDumper dumper); +LoggingDestination *logConfigureDestination3(LoggingContext *context, + unsigned int id, + char *name, + void *data, + LogHandler handler, + DataDumper dumper, + LogHandler2 handler2); + void logConfigureStandardDestinations(LoggingContext *context); void logConfigureComponent(LoggingContext *context, uint64 compID, @@ -369,7 +422,9 @@ extern int logSetExternalContext(LoggingContext *context); extern LoggingContext *logGetExternalContext(); void printStdout(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList); +void printStdout2(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList, int logLevel, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName); void printStderr(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList); +void printStderr2(LoggingContext *context, LoggingComponent *component, void *data, char *formatString, va_list argList, int logLevel, char *fileName, char *functionName, unsigned int lineNumber, const char *serviceName); #endif diff --git a/tests/buildloggingtest.sh b/tests/buildloggingtest.sh new file mode 100755 index 000000000..d5b02b1f7 --- /dev/null +++ b/tests/buildloggingtest.sh @@ -0,0 +1,16 @@ +c89 -D_OPEN_THREADS -D_XOPEN_SOURCE=600 -DAPF_AUTHORIZED=0 -DNOIBMHTTP \ +"-Wa,goff" "-Wc,langlvl(EXTC99),float(HEX),agg,list(),so(),search(),\ +goff,xref,gonum,roconst,gonum,asm,asmlib('SYS1.MACLIB'),asmlib('CEE.SCEEMAC'),LP64" "-Wl,lp64,xplink" \ +-I ../h \ +-o loggingtest \ +./loggingtest.c \ +../c/utils.c \ +../c/logging.c \ +../c/alloc.c \ +../c/collections.c \ +../c/zos.c \ +../c/timeutls.c \ +../c/le.c \ +../c/scheduling.c \ +../c/recovery.c + diff --git a/tests/loggingtest.c b/tests/loggingtest.c new file mode 100644 index 000000000..00beeb008 --- /dev/null +++ b/tests/loggingtest.c @@ -0,0 +1,50 @@ +#include "logging.h" + +#include +#include +#include +#include +#include +#include +#include + +/* + BUILD + c89 -D_OPEN_THREADS -D_XOPEN_SOURCE=600 -DAPF_AUTHORIZED=0 -DNOIBMHTTP \ + "-Wa,goff" "-Wc,langlvl(EXTC99),float(HEX),agg,list(),so(),search(),\ + goff,xref,gonum,roconst,gonum,asm,asmlib('SYS1.MACLIB'),asmlib('CEE.SCEEMAC')" \ + -I ../h \ + -o loggingtest \ + ./loggingtest.c \ + ../c/utils.c \ + ../c/logging.c \ + ../c/alloc.c \ + ../c/collections.c \ + ../c/zos.c \ + ../c/timeutls.c \ + ../c/le.c \ + ../c/scheduling.c \ + ../c/recovery.c + + */ + +/* + * Test that logging is functional with and without new helper macros. Prove backwards compatibility. + */ +void main() { + LoggingContext *context = makeLoggingContext(); + + logConfigureStandardDestinations(context); + logConfigureComponent(context, LOG_COMP_DATASERVICE, "DATASERVICE", LOG_DEST_PRINTF_STDOUT, ZOWE_LOG_INFO); + + ZOWELOG_SEVERE(LOG_COMP_DATASERVICE, "Hello from zowelog2(). This log should have every field."); + zowelog(context, LOG_COMP_DATASERVICE, ZOWE_LOG_INFO, "Hello from zowelog(). This log should lack fileLocation information."); + + LoggingContext *context2 = makeLoggingContext(); + /* Using outdated logConfigureDestination. */ + logConfigureDestination(context2, LOG_DEST_PRINTF_STDOUT,"printf(stdout)", NULL, printStdout); + logConfigureComponent(context2, LOG_COMP_DATASERVICE, "DATASERVICE", LOG_DEST_PRINTF_STDOUT, ZOWE_LOG_INFO); + zowelog(context2, LOG_COMP_DATASERVICE, ZOWE_LOG_INFO, "Hello from zowelog(). This log should lack level and fileLocation information."); +} + +