From a30fc0c7879adf21012ae1dd66ca2b7118cefa26 Mon Sep 17 00:00:00 2001 From: VilhoRaatikka Date: Mon, 17 Nov 2014 23:27:14 +0200 Subject: [PATCH] MAX-328, Add session identifier to trace log entries. Session id is given to session in session_alloc and stored to thread's local storage variable when thread picks a new event from epoll_wait. --- log_manager/log_manager.cc | 42 +++++++++++++++++++++++++++++++------- server/core/dcb.c | 15 ++++++++++++++ server/core/poll.c | 9 ++++++++ server/core/session.c | 29 ++++++++++++++++++++++++++ server/include/dcb.h | 11 +++------- server/include/session.h | 1 + 6 files changed, 92 insertions(+), 15 deletions(-) diff --git a/log_manager/log_manager.cc b/log_manager/log_manager.cc index a875bd2ad..04c96b353 100644 --- a/log_manager/log_manager.cc +++ b/log_manager/log_manager.cc @@ -57,6 +57,10 @@ static simple_mutex_t msg_mutex; * actual library calls such as skygw_log_write. */ int lm_enabled_logfiles_bitmask = 0; +/** + * Thread-specific variable for session id which is used in trace logging. + */ +__thread size_t tls_sesid = 0; /** * BUFSIZ comes from the system. It equals with block size or @@ -720,17 +724,29 @@ static int logmanager_write_log( { /** Length of string that will be written, limited by bufsize */ int safe_str_len; + /** Length of session id */ + int sesid_str_len; + + /** 2 braces and 2 spaces */ + if (id == LOGFILE_TRACE && tls_sesid > 0) + { + sesid_str_len = 2+2+get_decimal_len(tls_sesid); + } + else + { + sesid_str_len = 0; + } timestamp_len = get_timestamp_len(); /** Findout how much can be safely written with current block size */ - if (timestamp_len-1+str_len > lf->lf_buf_size) + if (timestamp_len-1+sesid_str_len-1+str_len > lf->lf_buf_size) { safe_str_len = lf->lf_buf_size; } else { - safe_str_len = timestamp_len-1+str_len; + safe_str_len = timestamp_len-1+sesid_str_len-1+str_len; } /** * Seek write position and register to block buffer. @@ -761,7 +777,7 @@ static int logmanager_write_log( simple_mutex_unlock(&msg_mutex); } #endif - + /** Book space for log string from buffer */ wp = blockbuf_get_writepos(&bb, id, safe_str_len, @@ -783,16 +799,28 @@ static int logmanager_write_log( */ timestamp_len = snprint_timestamp(wp, timestamp_len); - - + if (id == LOGFILE_TRACE) + { + /** + * Write session id + */ + snprintf(wp+timestamp_len, sesid_str_len, "[%lu] ", tls_sesid); + sesid_str_len -= 1; /*< remove terminating char */ + } /** * Write next string to overwrite terminating null character * of the timestamp string. */ if (use_valist) { - vsnprintf(wp+timestamp_len, safe_str_len-timestamp_len, str, valist); + vsnprintf(wp+timestamp_len+sesid_str_len, + safe_str_len-timestamp_len-sesid_str_len, + str, + valist); } else { - snprintf(wp+timestamp_len, safe_str_len-timestamp_len, "%s", str); + snprintf(wp+timestamp_len+sesid_str_len, + safe_str_len-timestamp_len-sesid_str_len, + "%s", + str); } /** write to syslog */ diff --git a/server/core/dcb.c b/server/core/dcb.c index 244b50c06..641691e72 100644 --- a/server/core/dcb.c +++ b/server/core/dcb.c @@ -90,6 +90,21 @@ static int dcb_null_close(DCB *dcb); static int dcb_null_auth(DCB *dcb, SERVER *server, SESSION *session, GWBUF *buf); static int dcb_isvalid_nolock(DCB *dcb); +size_t dcb_get_session_id( + DCB* dcb) +{ + size_t rval; + + if (dcb != NULL && dcb->session != NULL) + { + rval = dcb->session->ses_id; + } + else + { + rval = 0; + } + return rval; +} /** * Return the pointer to the lsit of zombie DCB's * diff --git a/server/core/poll.c b/server/core/poll.c index 36e118b72..378147ac4 100644 --- a/server/core/poll.c +++ b/server/core/poll.c @@ -41,6 +41,8 @@ extern int lm_enabled_logfiles_bitmask; +extern __thread size_t tls_sesid; + /** * @file poll.c - Abstraction of the epoll functionality * @@ -677,6 +679,7 @@ uint32_t ev; #else atomic_add(&pollStats.n_write, 1); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.write_ready(dcb); #endif } else { @@ -712,6 +715,7 @@ uint32_t ev; dcb->fd))); atomic_add( &pollStats.n_accept, 1); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.accept(dcb); } else @@ -724,6 +728,7 @@ uint32_t ev; dcb, dcb->fd))); atomic_add(&pollStats.n_read, 1); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.read(dcb); } #if MUTEX_BLOCK @@ -759,6 +764,7 @@ uint32_t ev; strerror(eno)))); } atomic_add(&pollStats.n_error, 1); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.error(dcb); } @@ -783,6 +789,7 @@ uint32_t ev; { dcb->flags |= DCBF_HUNG; spinlock_release(&dcb->dcb_initlock); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.hangup(dcb); } else @@ -811,12 +818,14 @@ uint32_t ev; { dcb->flags |= DCBF_HUNG; spinlock_release(&dcb->dcb_initlock); + LOGIF(LT, (tls_sesid = dcb_get_session_id(dcb))); dcb->func.hangup(dcb); } else spinlock_release(&dcb->dcb_initlock); } #endif + LOGIF(LT, tls_sesid = 0); spinlock_acquire(&pollqlock); if (dcb->evq.pending_events == 0) diff --git a/server/core/session.c b/server/core/session.c index 7170c6bcc..9283fffa8 100644 --- a/server/core/session.c +++ b/server/core/session.c @@ -43,7 +43,10 @@ #include #include +/** Defined in log_manager.cc */ extern int lm_enabled_logfiles_bitmask; +/** Global session id; updated safely by holding session_spin */ +static size_t session_id; static SPINLOCK session_spin = SPINLOCK_INIT; static SESSION *allSessions = NULL; @@ -216,10 +219,29 @@ session_alloc(SERVICE *service, DCB *client_dcb) session->state = SESSION_STATE_ROUTER_READY; spinlock_release(&session->ses_lock); spinlock_acquire(&session_spin); + session->ses_id = ++session_id; /*< assign an id and increase */ session->next = allSessions; allSessions = session; spinlock_release(&session_spin); + if (session->client->user == NULL) + { + LOGIF(LT, (skygw_log_write( + LOGFILE_TRACE, + "Started session [%lu] for %s service ", + session->ses_id, + service->name))); + } + else + { + LOGIF(LT, (skygw_log_write( + LOGFILE_TRACE, + "Started %s client session [%lu] for '%s' from %s", + service->name, + session->ses_id, + session->client->user, + session->client->remote))); + } atomic_add(&service->stats.n_sessions, 1); atomic_add(&service->stats.n_current, 1); CHK_SESSION(session); @@ -352,6 +374,13 @@ bool session_free( } free(session->filters); } + + LOGIF(LT, (skygw_log_write( + LOGFILE_TRACE, + "Stopped %s client session [%lu]", + session->service->name, + session->ses_id))); + free(session); succp = true; diff --git a/server/include/dcb.h b/server/include/dcb.h index 86aef5920..0695a6e57 100644 --- a/server/include/dcb.h +++ b/server/include/dcb.h @@ -307,16 +307,11 @@ int dcb_remove_callback(DCB *, DCB_REASON, int (*)(struct dcb *, DCB_REASON, vo void *); int dcb_isvalid(DCB *); /* Check the DCB is in the linked list */ -bool dcb_set_state( - DCB* dcb, - dcb_state_t new_state, - dcb_state_t* old_state); -void dcb_call_foreach (DCB_REASON reason); +bool dcb_set_state(DCB* dcb, dcb_state_t new_state, dcb_state_t* old_state); +void dcb_call_foreach (DCB_REASON reason); +size_t dcb_get_session_id(DCB* dcb);; -void dcb_call_foreach ( - DCB_REASON reason); - /** * DCB flags values */ diff --git a/server/include/session.h b/server/include/session.h index 86de23782..a1733c873 100644 --- a/server/include/session.h +++ b/server/include/session.h @@ -110,6 +110,7 @@ typedef struct session { #endif SPINLOCK ses_lock; session_state_t state; /**< Current descriptor state */ + size_t ses_id; /**< unique session identifier */ struct dcb *client; /**< The client connection */ void *data; /**< The session data */ void *router_session;/**< The router instance data */