Skip to content

Commit

Permalink
Log TLS and HTTP statistics on exit.
Browse files Browse the repository at this point in the history 
These stats measure how efficiently TLS and HTTP are reusing connections (i.e. pipelining).
  • Loading branch information
@dwsteele
dwsteele committed May 26, 2019
1 parent 819eda0 commit 38f28bd
Show file tree
Hide file tree
Showing 9 changed files with 136 additions and 6 deletions.
2 changes: 1 addition & 1 deletion src/Makefile.in
View file
Expand Up @@ -270,7 +270,7 @@ common/error.o: common/error.c build.auto.h common/error.auto.c common/error.aut
common/exec.o: common/exec.c build.auto.h common/assert.h common/debug.h common/error.auto.h common/error.h common/exec.h common/io/filter/filter.h common/io/filter/group.h common/io/handleRead.h common/io/handleWrite.h common/io/io.h common/io/read.h common/io/read.intern.h common/io/write.h common/io/write.intern.h common/log.h common/logLevel.h common/macro.h common/memContext.h common/object.h common/stackTrace.h common/time.h common/type/buffer.h common/type/convert.h common/type/keyValue.h common/type/string.h common/type/variant.h common/type/variantList.h common/wait.h common/exec.o: common/exec.c build.auto.h common/assert.h common/debug.h common/error.auto.h common/error.h common/exec.h common/io/filter/filter.h common/io/filter/group.h common/io/handleRead.h common/io/handleWrite.h common/io/io.h common/io/read.h common/io/read.intern.h common/io/write.h common/io/write.intern.h common/log.h common/logLevel.h common/macro.h common/memContext.h common/object.h common/stackTrace.h common/time.h common/type/buffer.h common/type/convert.h common/type/keyValue.h common/type/string.h common/type/variant.h common/type/variantList.h common/wait.h
$(CC) $(CFLAGS) $(CMAKE) -c common/exec.c -o common/exec.o $(CC) $(CFLAGS) $(CMAKE) -c common/exec.c -o common/exec.o


common/exit.o: common/exit.c build.auto.h command/command.h common/assert.h common/debug.h common/error.auto.h common/error.h common/exit.h common/io/filter/filter.h common/io/filter/group.h common/io/read.h common/io/write.h common/lock.h common/log.h common/logLevel.h common/memContext.h common/stackTrace.h common/time.h common/type/buffer.h common/type/convert.h common/type/keyValue.h common/type/string.h common/type/stringList.h common/type/variant.h common/type/variantList.h config/config.auto.h config/config.h config/define.auto.h config/define.h perl/exec.h protocol/client.h protocol/command.h protocol/helper.h common/exit.o: common/exit.c build.auto.h command/command.h common/assert.h common/debug.h common/error.auto.h common/error.h common/exit.h common/io/filter/filter.h common/io/filter/group.h common/io/http/client.h common/io/http/header.h common/io/http/query.h common/io/read.h common/io/tls/client.h common/io/write.h common/lock.h common/log.h common/logLevel.h common/memContext.h common/stackTrace.h common/time.h common/type/buffer.h common/type/convert.h common/type/keyValue.h common/type/string.h common/type/stringList.h common/type/variant.h common/type/variantList.h config/config.auto.h config/config.h config/define.auto.h config/define.h perl/exec.h protocol/client.h protocol/command.h protocol/helper.h
$(CC) $(CFLAGS) $(CMAKE) -c common/exit.c -o common/exit.o $(CC) $(CFLAGS) $(CMAKE) -c common/exit.c -o common/exit.o


common/fork.o: common/fork.c build.auto.h common/assert.h common/debug.h common/error.auto.h common/error.h common/log.h common/logLevel.h common/stackTrace.h common/type/convert.h common/fork.o: common/fork.c build.auto.h common/assert.h common/debug.h common/error.auto.h common/error.h common/log.h common/logLevel.h common/stackTrace.h common/type/convert.h
Expand Down
14 changes: 14 additions & 0 deletions src/common/exit.c
View file
Expand Up @@ -10,6 +10,8 @@ Exit Routines
#include "common/debug.h" #include "common/debug.h"
#include "common/error.h" #include "common/error.h"
#include "common/exit.h" #include "common/exit.h"
#include "common/io/http/client.h"
#include "common/io/tls/client.h"
#include "common/lock.h" #include "common/lock.h"
#include "common/log.h" #include "common/log.h"
#include "config/config.h" #include "config/config.h"
Expand Down Expand Up @@ -152,6 +154,18 @@ exitSafe(int result, bool error, SignalType signalType)
TRY_END(); TRY_END();
#endif #endif


// Log tls statistics
String *tlsClientStat = tlsClientStatStr();

if (tlsClientStat != NULL)
LOG_DETAIL(strPtr(tlsClientStat));

// Log http statistics
String *httpClientStat = httpClientStatStr();

if (httpClientStat != NULL)
LOG_INFO(strPtr(httpClientStat));

// Log command end if a command is set // Log command end if a command is set
if (cfgCommand() != cfgCmdNone) if (cfgCommand() != cfgCmdNone)
{ {
Expand Down
39 changes: 38 additions & 1 deletion src/common/io/http/client.c
View file
Expand Up @@ -40,6 +40,11 @@ STRING_EXTERN(HTTP_HEADER_ETAG_STR, HTTP_HEADER_
// 5xx errors that should always be retried // 5xx errors that should always be retried
#define HTTP_RESPONSE_CODE_RETRY_CLASS 5 #define HTTP_RESPONSE_CODE_RETRY_CLASS 5


/***********************************************************************************************************************************
Statistics
***********************************************************************************************************************************/
static HttpClientStat httpClientStatLocal;

/*********************************************************************************************************************************** /***********************************************************************************************************************************
Object type Object type
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
Expand Down Expand Up @@ -192,6 +197,8 @@ httpClientNew(


this->timeout = timeout; this->timeout = timeout;
this->tls = tlsClientNew(host, port, timeout, verifyPeer, caFile, caPath); this->tls = tlsClientNew(host, port, timeout, verifyPeer, caFile, caPath);

httpClientStatLocal.object++;
} }
MEM_CONTEXT_NEW_END(); MEM_CONTEXT_NEW_END();


Expand Down Expand Up @@ -253,7 +260,8 @@ httpClientRequest(


TRY_BEGIN() TRY_BEGIN()
{ {
tlsClientOpen(this->tls); if (tlsClientOpen(this->tls))
httpClientStatLocal.session++;


// Write the request // Write the request
String *queryStr = httpQueryRender(query); String *queryStr = httpQueryRender(query);
Expand Down Expand Up @@ -361,7 +369,10 @@ httpClientRequest(
// If the server notified of a closed connection then close the client connection after reading content. This // If the server notified of a closed connection then close the client connection after reading content. This
// prevents doing a retry on the next request when using the closed connection. // prevents doing a retry on the next request when using the closed connection.
if (strEq(headerKey, HTTP_HEADER_CONNECTION_STR) && strEq(headerValue, HTTP_VALUE_CONNECTION_CLOSE_STR)) if (strEq(headerKey, HTTP_HEADER_CONNECTION_STR) && strEq(headerValue, HTTP_VALUE_CONNECTION_CLOSE_STR))
{
this->closeOnContentEof = true; this->closeOnContentEof = true;
httpClientStatLocal.close++;
}
} }
while (1); while (1);


Expand Down Expand Up @@ -425,6 +436,8 @@ httpClientRequest(
{ {
LOG_DEBUG("retry %s: %s", errorTypeName(errorType()), errorMessage()); LOG_DEBUG("retry %s: %s", errorTypeName(errorType()), errorMessage());
retry = true; retry = true;

httpClientStatLocal.retry++;
} }


tlsClientClose(this->tls); tlsClientClose(this->tls);
Expand All @@ -438,12 +451,36 @@ httpClientRequest(


// Move the result buffer (if any) to the parent context // Move the result buffer (if any) to the parent context
bufMove(result, MEM_CONTEXT_OLD()); bufMove(result, MEM_CONTEXT_OLD());

httpClientStatLocal.request++;
} }
MEM_CONTEXT_TEMP_END(); MEM_CONTEXT_TEMP_END();


FUNCTION_LOG_RETURN(BUFFER, result); FUNCTION_LOG_RETURN(BUFFER, result);
} }


/***********************************************************************************************************************************
Format statistics to a string
***********************************************************************************************************************************/
String *
httpClientStatStr(void)
{
FUNCTION_TEST_VOID();

String *result = NULL;

if (httpClientStatLocal.object > 0)
{
result = strNewFmt(
"http statistics: objects %" PRIu64 ", sessions %" PRIu64 ", requests %" PRIu64 ", retries %" PRIu64
", closes %" PRIu64,
httpClientStatLocal.object, httpClientStatLocal.session, httpClientStatLocal.request, httpClientStatLocal.retry,
httpClientStatLocal.close);
}

FUNCTION_TEST_RETURN(result);
}

/*********************************************************************************************************************************** /***********************************************************************************************************************************
Get read interface Get read interface
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
Expand Down
13 changes: 13 additions & 0 deletions src/common/io/http/client.h
View file
Expand Up @@ -47,6 +47,18 @@ HTTP Constants
#define HTTP_RESPONSE_CODE_FORBIDDEN 403 #define HTTP_RESPONSE_CODE_FORBIDDEN 403
#define HTTP_RESPONSE_CODE_NOT_FOUND 404 #define HTTP_RESPONSE_CODE_NOT_FOUND 404


/***********************************************************************************************************************************
Statistics
***********************************************************************************************************************************/
typedef struct HttpClientStat
{
uint64_t object; // Objects created
uint64_t session; // TLS sessions created
uint64_t request; // Requests (i.e. calls to httpClientRequest())
uint64_t retry; // Request retries
uint64_t close; // Closes forced by server
} HttpClientStat;

/*********************************************************************************************************************************** /***********************************************************************************************************************************
Constructor Constructor
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
Expand All @@ -59,6 +71,7 @@ Functions
Buffer *httpClientRequest( Buffer *httpClientRequest(
HttpClient *this, const String *verb, const String *uri, const HttpQuery *query, const HttpHeader *requestHeader, HttpClient *this, const String *verb, const String *uri, const HttpQuery *query, const HttpHeader *requestHeader,
const Buffer *body, bool returnContent); const Buffer *body, bool returnContent);
String *httpClientStatStr(void);


/*********************************************************************************************************************************** /***********************************************************************************************************************************
Getters Getters
Expand Down
40 changes: 38 additions & 2 deletions src/common/io/tls/client.c
View file
Expand Up @@ -29,6 +29,11 @@ TLS Client
#include "common/type/keyValue.h" #include "common/type/keyValue.h"
#include "common/wait.h" #include "common/wait.h"


/***********************************************************************************************************************************
Statistics
***********************************************************************************************************************************/
static TlsClientStat tlsClientStatLocal;

/*********************************************************************************************************************************** /***********************************************************************************************************************************
Object type Object type
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
Expand Down Expand Up @@ -126,6 +131,8 @@ tlsClientNew(
else else
cryptoError(SSL_CTX_set_default_verify_paths(this->context) != 1, "unable to set default CA certificate location"); cryptoError(SSL_CTX_set_default_verify_paths(this->context) != 1, "unable to set default CA certificate location");
} }

tlsClientStatLocal.object++;
} }
MEM_CONTEXT_NEW_END(); MEM_CONTEXT_NEW_END();


Expand Down Expand Up @@ -411,7 +418,7 @@ tlsClientEof(THIS_VOID)
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Open connection if this is a new client or if the connection was closed by the server Open connection if this is a new client or if the connection was closed by the server
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
void bool
tlsClientOpen(TlsClient *this) tlsClientOpen(TlsClient *this)
{ {
FUNCTION_LOG_BEGIN(logLevelTrace) FUNCTION_LOG_BEGIN(logLevelTrace)
Expand All @@ -420,6 +427,8 @@ tlsClientOpen(TlsClient *this)


ASSERT(this != NULL); ASSERT(this != NULL);


bool result = false;

if (this->session == NULL) if (this->session == NULL)
{ {
// Free the read/write interfaces // Free the read/write interfaces
Expand Down Expand Up @@ -522,6 +531,8 @@ tlsClientOpen(TlsClient *this)
{ {
LOG_DEBUG("retry %s: %s", errorTypeName(errorType()), errorMessage()); LOG_DEBUG("retry %s: %s", errorTypeName(errorType()), errorMessage());
retry = true; retry = true;

tlsClientStatLocal.retry++;
} }


tlsClientClose(this); tlsClientClose(this);
Expand Down Expand Up @@ -570,9 +581,34 @@ tlsClientOpen(TlsClient *this)
ioReadOpen(this->read); ioReadOpen(this->read);
} }
MEM_CONTEXT_END(); MEM_CONTEXT_END();

tlsClientStatLocal.session++;
result = true;
} }


FUNCTION_LOG_RETURN_VOID(); tlsClientStatLocal.request++;

FUNCTION_LOG_RETURN(BOOL, result);
}

/***********************************************************************************************************************************
Format statistics to a string
***********************************************************************************************************************************/
String *
tlsClientStatStr(void)
{
FUNCTION_TEST_VOID();

String *result = NULL;

if (tlsClientStatLocal.object > 0)
{
result = strNewFmt(
"tls statistics: objects %" PRIu64 ", sessions %" PRIu64 ", requests %" PRIu64 ", retries %" PRIu64,
tlsClientStatLocal.object, tlsClientStatLocal.session, tlsClientStatLocal.request, tlsClientStatLocal.retry);
}

FUNCTION_TEST_RETURN(result);
} }


/*********************************************************************************************************************************** /***********************************************************************************************************************************
Expand Down
14 changes: 13 additions & 1 deletion src/common/io/tls/client.h
View file
Expand Up @@ -29,6 +29,17 @@ typedef struct TlsClient TlsClient;
#include "common/time.h" #include "common/time.h"
#include "common/type/string.h" #include "common/type/string.h"


/***********************************************************************************************************************************
Statistics
***********************************************************************************************************************************/
typedef struct TlsClientStat
{
uint64_t object; // Objects created
uint64_t session; // Sessions created
uint64_t request; // Requests (i.e. calls to tlsClientOpen())
uint64_t retry; // Connection retries
} TlsClientStat;

/*********************************************************************************************************************************** /***********************************************************************************************************************************
Constructor Constructor
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
Expand All @@ -38,8 +49,9 @@ TlsClient *tlsClientNew(
/*********************************************************************************************************************************** /***********************************************************************************************************************************
Functions Functions
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
void tlsClientOpen(TlsClient *this); bool tlsClientOpen(TlsClient *this);
void tlsClientClose(TlsClient *this); void tlsClientClose(TlsClient *this);
String *tlsClientStatStr(void);


/*********************************************************************************************************************************** /***********************************************************************************************************************************
Getters Getters
Expand Down
8 changes: 7 additions & 1 deletion test/src/module/common/exitTest.c
View file
Expand Up @@ -2,6 +2,7 @@
Test Exit Routines Test Exit Routines
***********************************************************************************************************************************/ ***********************************************************************************************************************************/
#include "common/error.h" #include "common/error.h"
#include "common/io/tls/client.h"
#include "common/log.h" #include "common/log.h"
#include "config/config.h" #include "config/config.h"


Expand Down Expand Up @@ -126,9 +127,14 @@ testRun(void)
harnessLogResult("P00 INFO: archive-push command end: terminated on signal from child process"); harnessLogResult("P00 INFO: archive-push command end: terminated on signal from child process");


// ------------------------------------------------------------------------------------------------------------------------- // -------------------------------------------------------------------------------------------------------------------------
tlsClientNew(strNew("BOGUS"), 443, 1000, true, NULL, NULL);
httpClientNew(strNew("BOGUS"), 443, 1000, true, NULL, NULL);

TEST_RESULT_INT( TEST_RESULT_INT(
exitSafe(errorTypeCode(&TermError), false, signalTypeTerm), errorTypeCode(&TermError), "exit on term with SIGTERM"); exitSafe(errorTypeCode(&TermError), false, signalTypeTerm), errorTypeCode(&TermError), "exit on term with SIGTERM");
harnessLogResult("P00 INFO: archive-push command end: terminated on signal [SIGTERM]"); harnessLogResult(
"P00 INFO: http statistics: objects 1, sessions 0, requests 0, retries 0, closes 0\n"
"P00 INFO: archive-push command end: terminated on signal [SIGTERM]");
} }


FUNCTION_HARNESS_RESULT_VOID(); FUNCTION_HARNESS_RESULT_VOID();
Expand Down
6 changes: 6 additions & 0 deletions test/src/module/common/ioHttpTest.c
View file
Expand Up @@ -380,6 +380,10 @@ testRun(void)
HttpClient *client = NULL; HttpClient *client = NULL;
ioBufferSizeSet(35); ioBufferSizeSet(35);


// Reset statistics
httpClientStatLocal = (HttpClientStat){0};
TEST_RESULT_STR(httpClientStatStr(), NULL, "no stats yet");

TEST_ASSIGN(client, httpClientNew(strNew("localhost"), TLS_TEST_PORT, 500, true, NULL, NULL), "new client"); TEST_ASSIGN(client, httpClientNew(strNew("localhost"), TLS_TEST_PORT, 500, true, NULL, NULL), "new client");


TEST_ERROR( TEST_ERROR(
Expand Down Expand Up @@ -510,6 +514,8 @@ testRun(void)
TEST_RESULT_VOID(ioRead(httpClientIoRead(client), buffer), " read response"); TEST_RESULT_VOID(ioRead(httpClientIoRead(client), buffer), " read response");
TEST_RESULT_STR(strPtr(strNewBuf(buffer)), "01234567890123456789012345678901012", " check response"); TEST_RESULT_STR(strPtr(strNewBuf(buffer)), "01234567890123456789012345678901012", " check response");


TEST_RESULT_BOOL(httpClientStatStr() != NULL, true, "check statistics exist");

TEST_RESULT_VOID(httpClientFree(client), "free client"); TEST_RESULT_VOID(httpClientFree(client), "free client");
} }


Expand Down
6 changes: 6 additions & 0 deletions test/src/module/common/ioTlsTest.c
View file
Expand Up @@ -177,6 +177,10 @@ testRun(void)
{ {
TlsClient *client = NULL; TlsClient *client = NULL;


// Reset statistics
tlsClientStatLocal = (TlsClientStat){0};
TEST_RESULT_STR(tlsClientStatStr(), NULL, "no stats yet");

testTlsServer(); testTlsServer();
ioBufferSizeSet(12); ioBufferSizeSet(12);


Expand Down Expand Up @@ -220,6 +224,8 @@ testRun(void)
TEST_RESULT_INT(ioRead(tlsClientIoRead(client), output), 0, "read no output after eof"); TEST_RESULT_INT(ioRead(tlsClientIoRead(client), output), 0, "read no output after eof");
TEST_RESULT_BOOL(ioReadEof(tlsClientIoRead(client)), true, " check eof = true"); TEST_RESULT_BOOL(ioReadEof(tlsClientIoRead(client)), true, " check eof = true");


TEST_RESULT_BOOL(tlsClientStatStr() != NULL, true, "check statistics exist");

TEST_RESULT_VOID(tlsClientFree(client), "free client"); TEST_RESULT_VOID(tlsClientFree(client), "free client");
} }


Expand Down

0 comments on commit 38f28bd

Please sign in to comment.