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

@@ -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 */

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
  *

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)

server/core/session.c

@@ -43,7 +43,10 @@
 #include <skygw_utils.h>
 #include <log_manager.h>
 
+/** 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;
         

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
  */

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 */