improve logging for timed out sessions and securechannels

src/server/ua_securechannel_manager.c

@@ -37,9 +37,6 @@ removeSecureChannelCallback(UA_Server *server, void *entry) {
 
 static UA_StatusCode
 removeSecureChannel(UA_SecureChannelManager *cm, channel_list_entry *entry){
-    UA_LOG_INFO_CHANNEL(cm->server->config.logger, &entry->channel,
-                         "SecureChannel has timed out");
-
     /* Add a delayed callback to remove the channel when the currently
      * scheduled jobs have completed */
     UA_StatusCode retval = UA_Server_delayedCallback(cm->server, removeSecureChannelCallback, entry);
@@ -64,6 +61,8 @@ UA_SecureChannelManager_cleanupTimedOut(UA_SecureChannelManager *cm, UA_DateTime
         UA_DateTime timeout = entry->channel.securityToken.createdAt +
             (UA_DateTime)(entry->channel.securityToken.revisedLifetime * UA_MSEC_TO_DATETIME);
         if(timeout < nowMonotonic || !entry->channel.connection) {
+            UA_LOG_INFO_CHANNEL(cm->server->config.logger, &entry->channel,
+                                "SecureChannel has timed out");
             removeSecureChannel(cm, entry);
         } else if(entry->channel.nextSecurityToken.tokenId > 0) {
             UA_SecureChannel_revolveTokens(&entry->channel);

src/server/ua_session_manager.c

@@ -33,9 +33,6 @@ removeSessionCallback(UA_Server *server, void *entry) {
 static UA_StatusCode
 removeSession(UA_SessionManager *sm, session_list_entry *sentry) {
     /* Deactivate the session */
-    UA_LOG_INFO(sm->server->config.logger, UA_LOGCATEGORY_SESSION,
-                "Session with token %i has timed out and is removed",
-                sentry->session.sessionId.identifier.numeric);
     sentry->session.activated = false;
 
     /* Add a delayed callback to remove the session when the currently
@@ -62,6 +59,8 @@ UA_SessionManager_cleanupTimedOut(UA_SessionManager *sm,
         /* Session has timed out? */
         if(sentry->session.validTill >= nowMonotonic)
             continue;
+        UA_LOG_INFO_SESSION(sm->server->config.logger, &sentry->session,
+                            "Session has timed out");
         removeSession(sm, sentry);
     }
 }

src/ua_session.h

@@ -81,44 +81,44 @@ UA_Session_getUniqueSubscriptionID(UA_Session *session);
 
 #define UA_LOG_TRACE_SESSION(LOGGER, SESSION, MSG, ...)                 \
     UA_LOG_TRACE(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                 (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                 (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                 UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                 ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                 ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                 UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                  ##__VA_ARGS__);
 
 #define UA_LOG_DEBUG_SESSION(LOGGER, SESSION, MSG, ...)                 \
     UA_LOG_DEBUG(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                 (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                 (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                 UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                 ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                 ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                 UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                  ##__VA_ARGS__);
 
 #define UA_LOG_INFO_SESSION(LOGGER, SESSION, MSG, ...)                  \
     UA_LOG_INFO(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                 (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                 (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                 UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                 ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                 ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                 UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                  ##__VA_ARGS__);
 
 #define UA_LOG_WARNING_SESSION(LOGGER, SESSION, MSG, ...)               \
     UA_LOG_WARNING(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                   (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                   (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                   UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                   ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                   ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                   UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                    ##__VA_ARGS__);
 
 #define UA_LOG_ERROR_SESSION(LOGGER, SESSION, MSG, ...)                 \
     UA_LOG_ERROR(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                 (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                 (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                 UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                 ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                 ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                 UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                  ##__VA_ARGS__);
 
 #define UA_LOG_FATAL_SESSION(LOGGER, SESSION, MSG, ...)                 \
     UA_LOG_FATAL(LOGGER, UA_LOGCATEGORY_SESSION, "Connection %i | SecureChannel %i | Session " UA_PRINTF_GUID_FORMAT " | " MSG, \
-                 (SESSION->channel ? (SESSION->channel->connection ? SESSION->channel->connection->sockfd : 0) : 0), \
-                 (SESSION->channel ? SESSION->channel->securityToken.channelId : 0), \
-                 UA_PRINTF_GUID_DATA(SESSION->sessionId.identifier.guid), \
+                 ((SESSION)->channel ? ((SESSION)->channel->connection ? (SESSION)->channel->connection->sockfd : 0) : 0), \
+                 ((SESSION)->channel ? (SESSION)->channel->securityToken.channelId : 0), \
+                 UA_PRINTF_GUID_DATA((SESSION)->sessionId.identifier.guid), \
                  ##__VA_ARGS__);
 
 #endif /* UA_SESSION_H_ */