epics/epics-base
0
0
Fork 0
Code Issues Pull Requests Projects Wiki Activity
Files
5ae9cc6536a41337cc8272f3ea8a9bd6123a2742
epics-base/modules/libcom/test/epicsErrlogTest.c
Emilio Perez 8c08c57247 Allow adding error symbols after early initialization 
This was acomplished by making errSymbolAdd add the error symbol directly
into the global hash table and removing errnumlist which is not needed
anymore.

Unit tests were added for checking the following cases:
- Adding a valid symbol and checking that it exists (fixed by this change)
- Getting an existing error symbol
- Getting a non existing error symbol
- Adding an invalid error symbol (fixed by this change)
- Adding an error symbol with a code that already
  exists (fixed by this change)

Therefore, issue #268 was fixed

error: statically allocate error symbol hash table

This will allow calling errSymbolAdd before errSymBld, therefore, a
function adding error symbols can now be run before iocInit or errlogInit

error: add a constant for the minimum module number

Make adding an identical error symbol not fail

A test case was also added which test that adding an error symbol
with same error code and message as one added before will not fail

Add locking to error symbol table

This protects the cases of:
- simultaneously adding and requesting of an error symbol
- simultaneously adding many error symbols

Update release notes regarding adding error symbols
2023-09-22 08:20:19 -07:00

611 lines
17 KiB
C
Raw Blame History

/*************************************************************************\
* Copyright (c) 2010 Brookhaven Science Associates, as Operator of
* Brookhaven National Laboratory.
* Copyright (c) 2010 UChicago Argonne LLC, as Operator of Argonne
* National Laboratory.
* SPDX-License-Identifier: EPICS
* EPICS BASE is distributed subject to a Software License Agreement found
* in file LICENSE that is included with this distribution.
\*************************************************************************/
/*
* Author: Michael Davidsaver
* Date: 2010-09-24
*/
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include "epicsAssert.h"
#include "epicsThread.h"
#include "epicsEvent.h"
#include "dbDefs.h"
#include "errlog.h"
#include "epicsUnitTest.h"
#include "testMain.h"
#include "iocLog.h"
#include "logClient.h"
#include "envDefs.h"
#include "osiSock.h"
#include "fdmgr.h"
#include "epicsString.h"
#include "errSymTbl.h"
/* private between errlog.c and this test */
LIBCOM_API
void errlogStripANSI(char *msg);
#define LOGBUFSIZE 2048
static
const char longmsg[]="A0123456789abcdef"
"B0123456789abcdef"
"C0123456789abcdef"
"D0123456789abcdef"
"E0123456789abcdef"
"F0123456789abcdef"
"G0123456789abcdef"
"H0123456789abcdef"
"I0123456789abcdef"
"J0123456789abcdef"
"K0123456789abcdef"
"L0123456789abcdef"
"M0123456789abcdef"
"N0123456789abcdef"
"O0123456789abcdef"
"P0123456789abcdef"
"Q0123456789abcdef"
"R0123456789abcdef"
"S0123456789abcdef"
;
STATIC_ASSERT(NELEMENTS(longmsg)==324);
static
const char truncmsg[]="A0123456789abcdef"
"B0123456789abcdef"
"C0123456789abcdef"
"D0123456789abcdef"
"E0123456789abcdef"
"F0123456789abcdef"
"G0123456789abcdef"
"H0123456789abcdef"
"I0123456789abcdef"
"J0123456789abcdef"
"K0123456789abcdef"
"L0123456789abcdef"
"M0123456789abcdef"
"N0123456789abcdef"
"O01<<TRUNCATED>>\n"
;
STATIC_ASSERT(NELEMENTS(truncmsg)==256);
typedef struct {
unsigned int count;
const char* expect;
size_t checkLen;
epicsEventId jammer;
int jam;
epicsEventId done;
} clientPvt;
static void testLogPrefix(void);
static void acceptNewClient( void *pParam );
static void readFromClient( void *pParam );
static void testPrefixLogandCompare( const char* logmessage);
static void *pfdctx;
static SOCKET sock;
static SOCKET insock;
static const char* prefixactualmsg[]= {
"A message without prefix",
"A message with prefix",
"DONE"
};
static const char *prefixstring = "fac=LI21 ";
static const char prefixexpectedmsg[] = "A message without prefix"
"fac=LI21 A message with prefix"
"fac=LI21 DONE"
;
static char prefixmsgbuffer[1024];
static void
testEqInt_(int line, int lhs, int rhs, const char *LHS, const char *RHS)
{
testOk(lhs==rhs, "%d: %s (%d) == %s (%d)", line, LHS, lhs, RHS, rhs);
}
#define testEqInt(L, R) testEqInt_(__LINE__, L, R, #L, #R);
static
void logClient(void* raw, const char* msg)
{
clientPvt *pvt = raw;
size_t len;
char show[46];
/* Simulate thread priority on non-realtime
* OSs like Linux. This will cause the logging
* thread to sleep with the buffer lock held.
*/
if (pvt->jam > 0) {
pvt->jam = 0;
epicsEventMustWait(pvt->jammer);
} else if (pvt->jam < 0) {
pvt->jam++;
if (pvt->jam == 0)
epicsEventMustWait(pvt->jammer);
}
len = strlen(msg);
if (len > 45) {
/* Only show start and end of long messages */
strncpy(show, msg, 20);
show[20] = 0;
strcat(show + 20, " ... ");
strcat(show + 25, msg + len - 20);
}
else {
strcpy(show, msg);
}
if (pvt->checkLen)
if (!testOk(pvt->checkLen == len, "Received %d chars", (int) len)) {
testDiag("Expected %d", (int) pvt->checkLen);
if (!pvt->expect)
testDiag("Message is \"%s\"", show);
}
if (pvt->expect) {
if (!testOk(strcmp(pvt->expect, msg) == 0, "Message is \"%s\"", show)) {
len = strlen(pvt->expect);
if (len > 45) {
testDiag("Expected \"%.20s ... %s\"",
pvt->expect, pvt->expect + len - 20);
}
else {
testDiag("Expected \"%s\"", pvt->expect);
}
}
}
pvt->count++;
epicsEventSignal(pvt->done);
}
static
void testANSIStrip(void)
{
char scratch[64];
char actual[128];
char input[128];
#define testEscape(INP, EXPECT) \
strcpy(scratch, INP); \
epicsStrnEscapedFromRaw(input, sizeof(input), INP, sizeof(INP)); \
errlogStripANSI(scratch); \
epicsStrnEscapedFromRaw(actual, sizeof(actual), scratch, epicsStrnLen(scratch, sizeof(scratch))); \
testOk(strcmp(scratch, EXPECT)==0, "input \"%s\" expect \"%s\" actual \"%s\"", input, EXPECT, actual)
testEscape("", "");
testEscape("hello", "hello");
testEscape("he\033[31;1mllo", "hello");
testEscape("\033[31;1mhello", "hello");
testEscape("hello\033[31;1m", "hello");
testEscape("hello\033[31;1", "hello");
testEscape("hello\033[", "hello");
testEscape("hello\033", "hello");
#undef testEscape
}
static void testErrorMessageMatches(long status, const char *expected)
{
const char *msg = errSymMsg(status);
testOk(strcmp(msg, expected) == 0,
"Error code %ld returns \"%s\", expected message \"%s\"", status,
msg, expected
);
}
static void testGettingExistingErrorSymbol()
{
testErrorMessageMatches(S_err_invCode, "Invalid error symbol code");
}
static void testGettingNonExistingErrorSymbol()
{
long invented_code = (0x7999 << 16) | 0x9998;
testErrorMessageMatches(invented_code, "<Unknown code>");
}
static void testAddingErrorSymbol()
{
long invented_code = (0x7999 << 16) | 0x9999;
errSymbolAdd(invented_code, "Invented Error Message");
testErrorMessageMatches(invented_code, "Invented Error Message");
}
static void testAddingInvalidErrorSymbol()
{
long invented_code = (500 << 16) | 0x1;
testOk(errSymbolAdd(invented_code, "No matter"),
"Adding error symbol with module code < 501 should fail");
}
static void testAddingExistingErrorSymbol()
{
testOk(errSymbolAdd(S_err_invCode, "Duplicate"),
"Adding an error symbol with an existing error code should fail");
}
static void testAddingExistingErrorSymbolWithSameMessage()
{
long invented_code = (0x7999 << 16) | 0x9997;
errSymbolAdd(invented_code, "Invented Error Message");
testOk(!errSymbolAdd(invented_code, "Invented Error Message"),
"Adding identical error symbol shouldn't fail");
}
MAIN(epicsErrlogTest)
{
size_t mlen, i, N;
char msg[256];
clientPvt pvt, pvt2;
testPlan(54);
testANSIStrip();
strcpy(msg, truncmsg);
errlogInit2(LOGBUFSIZE, 256);
pvt.count = 0;
pvt2.count = 0;
pvt.expect = NULL;
pvt2.expect = NULL;
pvt.checkLen = 0;
pvt2.checkLen = 0;
pvt.jam = 0;
pvt2.jam = 0;
pvt.jammer = epicsEventMustCreate(epicsEventEmpty);
pvt.done = epicsEventMustCreate(epicsEventEmpty);
pvt2.jammer = epicsEventMustCreate(epicsEventEmpty);
pvt2.done = epicsEventMustCreate(epicsEventEmpty);
testDiag("Check listener registration");
errlogAddListener(&logClient, &pvt);
pvt.expect = "Testing";
pvt.checkLen = strlen(pvt.expect);
errlogPrintfNoConsole("%s", pvt.expect);
errlogFlush();
epicsEventMustWait(pvt.done);
testEqInt(pvt.count, 1);
errlogAddListener(&logClient, &pvt2);
/* logClient will not see ANSI escape sequences */
pvt2.expect = pvt.expect = "Testing2";
pvt2.checkLen = pvt.checkLen = strlen(pvt.expect);
errlogPrintfNoConsole("%s", ANSI_RED("Testing2"));
errlogFlush();
epicsEventMustWait(pvt.done);
testEqInt(pvt.count, 2);
epicsEventMustWait(pvt2.done);
testEqInt(pvt2.count, 1);
/* Removes the first listener */
testOk(1 == errlogRemoveListeners(&logClient, &pvt),
"Removed 1 listener");
pvt2.expect = "Testing3";
pvt2.checkLen = strlen(pvt2.expect);
errlogPrintfNoConsole("%s", pvt2.expect);
errlogFlush();
testOk(epicsEventWaitWithTimeout(pvt.done, 0.5) == epicsEventWaitTimeout,
"%d: Listener 1 didn't run", __LINE__);
testOk(epicsEventTryWait(pvt2.done) == epicsEventOK,
"%d: Listener 2 ran", __LINE__);
testEqInt(pvt.count, 2);
testEqInt(pvt2.count, 2);
/* Add the second listener again, then remove both instances */
errlogAddListener(&logClient, &pvt2);
testOk(2 == errlogRemoveListeners(&logClient, &pvt2),
"Removed 2 listeners");
errlogPrintfNoConsole("Something different");
errlogFlush();
testOk(epicsEventWaitWithTimeout(pvt.done, 0.5) == epicsEventWaitTimeout,
"%d: Listener 1 didn't run", __LINE__);
testOk(epicsEventTryWait(pvt2.done) == epicsEventWaitTimeout,
"%d: Listener 2 didn't run", __LINE__);
testEqInt(pvt.count, 2);
testEqInt(pvt2.count, 2);
/* Re-add one listener */
errlogAddListener(&logClient, &pvt);
testDiag("Check truncation");
pvt.expect = truncmsg;
pvt.checkLen = 255;
errlogPrintfNoConsole("%s", longmsg);
errlogFlush();
epicsEventMustWait(pvt.done);
testEqInt(pvt.count, 3);
pvt.expect = NULL;
testDiag("Check priority");
/* For the following tests it is important that
* the buffer should not flush until we request it
*/
pvt.jam = 1;
errlogPrintfNoConsole("%s", longmsg);
testOk(epicsEventWaitWithTimeout(pvt.done, 0.5) == epicsEventWaitTimeout,
"%d: Listener 1 didn't run", __LINE__);
testEqInt(pvt.count, 3);
epicsEventSignal(pvt.jammer);
errlogFlush();
epicsEventMustWait(pvt.done);
testEqInt(pvt.count, 4);
testDiag("Find buffer capacity (%u theoretical)",LOGBUFSIZE);
pvt.checkLen = 0;
for (mlen = 8; mlen <= 255; mlen *= 2) {
double eff;
char save = msg[mlen - 1];
N = LOGBUFSIZE / mlen; /* # of of messages to send */
msg[mlen - 1] = '\0';
pvt.count = 0;
/* pvt.checkLen = mlen - 1; */
pvt.jam = 1;
for (i = 0; i < N; i++) {
errlogPrintfNoConsole("%s", msg);
}
epicsEventSignal(pvt.jammer);
errlogFlush();
eff = (double) (pvt.count * mlen) / LOGBUFSIZE * 100.0;
testDiag(" For %d messages of length %d got %u (%.1f%% efficient)",
(int) N, (int) mlen, pvt.count, eff);
msg[mlen - 1] = save;
N = pvt.count; /* Save final count for the test below */
/* Clear "errlog: <n> messages were discarded" status */
pvt.checkLen = 0;
errlogPrintfNoConsole(".");
errlogFlush();
}
testOk(epicsEventTryWait(pvt.done) == epicsEventOK,
"%d: Listener 1 ran", __LINE__);
testDiag("Checking buffer use after partial flush");
/* Use the numbers from the largest block size above */
mlen /= 2;
msg[mlen - 1] = '\0';
pvt.jam = 1;
pvt.count = 0;
testDiag("Filling with %d messages of size %d", (int) N, (int) mlen);
for (i = 0; i < N; i++) {
errlogPrintfNoConsole("%s", msg);
}
testOk(epicsEventWaitWithTimeout(pvt.done, 0.5) == epicsEventWaitTimeout,
"%d: Listener 1 didn't run", __LINE__);
testEqInt(pvt.count, 0);
/* Extract the first 2 messages, 2*(sizeof(msgNode) + 128) bytes */
pvt.jam = -2;
epicsEventSignal(pvt.jammer);
epicsThreadSleep(0.5);
testDiag("Drained %u messages", pvt.count);
epicsEventMustWait(pvt.done);
testEqInt(pvt.count, 2);
/* The buffer has space for 1 more message: sizeof(msgNode) + 256 bytes */
errlogPrintfNoConsole("%s", msg); /* Use up that space */
testDiag("Overflow the buffer");
errlogPrintfNoConsole("%s", msg);
testOk(epicsEventWaitWithTimeout(pvt.done, 0.5) == epicsEventWaitTimeout,
"%d: Listener 1 didn't run", __LINE__);
testEqInt(pvt.count, 2);
epicsEventSignal(pvt.jammer); /* Empty */
errlogFlush();
testDiag("Logged %u messages", pvt.count);
epicsEventMustWait(pvt.done);
/* Expect N+1 messages +- 1 depending on impl */
testOk(pvt.count >= N && pvt.count<=N+2, "Logged %u messages, expected %zu", pvt.count, N+1);
/* Clean up */
testOk(1 == errlogRemoveListeners(&logClient, &pvt),
"Removed 1 listener");
osiSockAttach();
testLogPrefix();
osiSockRelease();
testGettingExistingErrorSymbol();
testGettingNonExistingErrorSymbol();
testAddingErrorSymbol();
testAddingInvalidErrorSymbol();
testAddingExistingErrorSymbol();
testAddingExistingErrorSymbolWithSameMessage();
return testDone();
}
/*
* Tests the log prefix code
* The prefix is only applied to log messages as they go out to the socket,
* so we need to create a server listening on a port, accept connections etc.
* This code is a reduced version of the code in iocLogServer.
*/
static void testLogPrefix(void) {
struct sockaddr_in serverAddr;
int status;
struct timeval timeout;
struct sockaddr_in actualServerAddr;
osiSocklen_t actualServerAddrSize;
char portstring[16];
testDiag("Testing iocLogPrefix");
timeout.tv_sec = 5; /* in seconds */
timeout.tv_usec = 0;
memset((void*)prefixmsgbuffer, 0, sizeof prefixmsgbuffer);
/* Clear "errlog: <n> messages were discarded" status */
errlogPrintfNoConsole(".");
errlogFlush();
sock = epicsSocketCreate(AF_INET, SOCK_STREAM, 0);
if (sock == INVALID_SOCKET) {
testAbort("epicsSocketCreate failed.");
}
/* We listen on a an available port. */
memset((void *)&serverAddr, 0, sizeof serverAddr);
serverAddr.sin_family = AF_INET;
serverAddr.sin_port = htons(0);
status = bind (sock, (struct sockaddr *)&serverAddr,
sizeof (serverAddr) );
if (status < 0) {
testAbort("bind failed; all ports in use?");
}
status = listen(sock, 10);
if (status < 0) {
testAbort("listen failed!");
}
/* Determine the port that the OS chose */
actualServerAddrSize = sizeof actualServerAddr;
memset((void *)&actualServerAddr, 0, sizeof serverAddr);
status = getsockname(sock, (struct sockaddr *) &actualServerAddr,
&actualServerAddrSize);
if (status < 0) {
testAbort("Can't find port number!");
}
sprintf(portstring, "%d", ntohs(actualServerAddr.sin_port));
testDiag("Listening on port %s", portstring);
/* Set the EPICS environment variables for logging. */
epicsEnvSet ( "EPICS_IOC_LOG_INET", "localhost" );
epicsEnvSet ( "EPICS_IOC_LOG_PORT", portstring );
pfdctx = (void *) fdmgr_init();
if (status < 0) {
testAbort("fdmgr_init failed!");
}
status = fdmgr_add_callback(pfdctx, sock, fdi_read,
acceptNewClient, &serverAddr);
if (status < 0) {
testAbort("fdmgr_add_callback failed!");
}
testOk1(iocLogInit() == 0);
fdmgr_pend_event(pfdctx, &timeout);
testPrefixLogandCompare(prefixactualmsg[0]);
iocLogPrefix(prefixstring);
testPrefixLogandCompare(prefixactualmsg[1]);
testPrefixLogandCompare(prefixactualmsg[2]);
epicsSocketDestroy(sock);
}
static void testPrefixLogandCompare( const char* logmessage ) {
struct timeval timeout;
timeout.tv_sec = 5; /* in seconds */
timeout.tv_usec = 0;
errlogPrintfNoConsole("%s", logmessage);
errlogFlush();
iocLogFlush();
fdmgr_pend_event(pfdctx, &timeout);
}
static void acceptNewClient ( void *pParam )
{
osiSocklen_t addrSize;
struct sockaddr_in addr;
int status;
addrSize = sizeof ( addr );
insock = epicsSocketAccept ( sock, (struct sockaddr *)&addr, &addrSize );
testOk(insock != INVALID_SOCKET && addrSize >= sizeof (addr),
"Accepted new client");
status = fdmgr_add_callback(pfdctx, insock, fdi_read,
readFromClient, NULL);
testOk(status >= 0, "Client read configured");
}
static void readFromClient(void *pParam)
{
char recvbuf[1024];
int recvLength;
memset(recvbuf, 0, 1024);
recvLength = recv(insock, recvbuf, 1024, 0);
if (recvLength > 0) {
strcat(prefixmsgbuffer, recvbuf);
/* If we have received all of the messages. */
if (strstr(prefixmsgbuffer, "DONE") != NULL) {
size_t msglen = strlen(prefixexpectedmsg);
int prefixcmp = strncmp(prefixexpectedmsg, prefixmsgbuffer, msglen);
if (!testOk(prefixcmp == 0, "prefix matches")) {
testDiag("Expected '%s'\n", prefixexpectedmsg);
testDiag("Obtained '%s'\n", prefixmsgbuffer);
}
}
}
}
Reference in New Issue View Git Blame Copy Permalink