improve logging with new convenience macros

include/ua_log.h

@@ -51,7 +51,7 @@ typedef enum {
     UA_LOGCATEGORY_CLIENT,
     UA_LOGCATEGORY_USERLAND
 } UA_LogCategory;
-    
+
 /**
  * The signature of the logger. The msg string and following varargs are
  * formatted according to the rules of the printf command.

plugins/networklayer_tcp.c

@@ -291,7 +291,7 @@ ServerNetworkLayerTCP_closeConnection(UA_Connection *connection) {
 #endif
     //cppcheck-suppress unreadVariable
     ServerNetworkLayerTCP *layer = connection->handle;
-    UA_LOG_INFO(layer->logger, UA_LOGCATEGORY_NETWORK, "Closing the Connection %i",
+    UA_LOG_INFO(layer->logger, UA_LOGCATEGORY_NETWORK, "Connection %i | Closing the connection",
                 connection->sockfd);
     /* only "shutdown" here. this triggers the select, where the socket is
        "closed" in the mainloop */
@@ -308,7 +308,7 @@ ServerNetworkLayerTCP_add(ServerNetworkLayerTCP *layer, UA_Int32 newsockfd) {
     struct sockaddr_in addr;
     socklen_t addrlen = sizeof(struct sockaddr_in);
     getpeername(newsockfd, (struct sockaddr*)&addr, &addrlen);
-    UA_LOG_INFO(layer->logger, UA_LOGCATEGORY_NETWORK, "New Connection %i over TCP from %s:%d",
+    UA_LOG_INFO(layer->logger, UA_LOGCATEGORY_NETWORK, "Connection %i | New connection over TCP from %s:%d",
                 newsockfd, inet_ntoa(addr.sin_addr), ntohs(addr.sin_port));
     UA_Connection_init(c);
     c->sockfd = newsockfd;

src/server/ua_securechannel_manager.c

@@ -32,8 +32,7 @@ void UA_SecureChannelManager_cleanupTimedOut(UA_SecureChannelManager *cm, UA_Dat
             entry->channel.securityToken.createdAt +
             (UA_DateTime)(entry->channel.securityToken.revisedLifetime * UA_MSEC_TO_DATETIME);
         if(timeout < now || !entry->channel.connection) {
-            UA_LOG_DEBUG(cm->server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                         "SecureChannel %i has timed out", entry->channel.securityToken.channelId);
+            UA_LOG_DEBUG_CHANNEL(cm->server->config.logger, (&entry->channel), "SecureChannel has timed out");
             LIST_REMOVE(entry, pointers);
             UA_SecureChannel_deleteMembersCleanup(&entry->channel);
 #ifndef UA_ENABLE_MULTITHREADING

src/server/ua_server_binary.c

@@ -41,19 +41,19 @@ static UA_ByteString processChunk(UA_SecureChannel *channel, UA_Server *server,
     UA_ByteString bytes = UA_BYTESTRING_NULL;
     switch(messageHeader->messageTypeAndChunkType & 0xff000000) {
     case UA_CHUNKTYPE_INTERMEDIATE:
-        UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL, "Chunk message");
+        UA_LOG_TRACE_CHANNEL(server->config.logger, channel, "Chunk message");
         UA_SecureChannel_appendChunk(channel, requestId, msg, pos, chunksize);
         break;
     case UA_CHUNKTYPE_FINAL:
-        UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL, "Final chunk message");
+        UA_LOG_TRACE_CHANNEL(server->config.logger, channel, "Final chunk message");
         bytes = UA_SecureChannel_finalizeChunk(channel, requestId, msg, pos, chunksize, deleteRequest);
         break;
     case UA_CHUNKTYPE_ABORT:
-        UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL, "Chunk aborted");
+        UA_LOG_INFO_CHANNEL(server->config.logger, channel, "Chunk aborted");
         UA_SecureChannel_removeChunk(channel, requestId);
         break;
     default:
-        UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL, "Unknown chunk type");
+        UA_LOG_INFO_CHANNEL(server->config.logger, channel, "Unknown chunk type");
     }
     return bytes;
 }
@@ -378,14 +378,15 @@ processRequest(UA_SecureChannel *channel, UA_Server *server, UA_UInt32 requestId
     getServicePointers(requestTypeId.identifier.numeric, &requestType, &responseType, &service);
     if(!requestType) {
         /* The service is not supported */
-        if(requestTypeId.identifier.numeric==787)
-            UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
+        if(requestTypeId.identifier.numeric==787) {
+            UA_LOG_INFO_CHANNEL(server->config.logger, channel,
                         "Client requested a subscription, but those are not enabled "
                         "in the build. The message will be skipped");
-        else
-            UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                        "Unknown request: NodeId(ns=%d, i=%d)",
-                        requestTypeId.namespaceIndex, requestTypeId.identifier.numeric);
+        } else {
+            UA_LOG_INFO_CHANNEL(server->config.logger, channel,
+                                "Unknown request: NodeId(ns=%d, i=%d)",
+                                requestTypeId.namespaceIndex, requestTypeId.identifier.numeric);
+        }
         sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSERVICEUNSUPPORTED);
         return;
     }
@@ -428,24 +429,10 @@ processRequest(UA_SecureChannel *channel, UA_Server *server, UA_UInt32 requestId
        requestType->typeIndex != UA_TYPES_FINDSERVERSREQUEST &&
        requestType->typeIndex != UA_TYPES_GETENDPOINTSREQUEST &&
        requestType->typeIndex != UA_TYPES_OPENSECURECHANNELREQUEST) {
-        UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                    "Client tries to call a service with a non-activated session");
+        UA_LOG_INFO_SESSION(server->config.logger, session, "Service request on a non-activated session");
         sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSESSIONNOTACTIVATED);
         return;
     }
-#ifndef UA_ENABLE_NONSTANDARD_STATELESS
-    if(session == &anonymousSession &&
-       requestType->typeIndex != UA_TYPES_CREATESESSIONREQUEST &&
-       requestType->typeIndex != UA_TYPES_ACTIVATESESSIONREQUEST &&
-       requestType->typeIndex != UA_TYPES_FINDSERVERSREQUEST &&
-       requestType->typeIndex != UA_TYPES_GETENDPOINTSREQUEST &&
-       requestType->typeIndex != UA_TYPES_OPENSECURECHANNELREQUEST) {
-        UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                    "Client tries to call a service without a session");
-        sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSECURITYCHECKSFAILED);
-        return;
-    }
-#endif
 
     /* Update the session lifetime */
     UA_Session_updateLifetime(session);
@@ -460,9 +447,6 @@ processRequest(UA_SecureChannel *channel, UA_Server *server, UA_UInt32 requestId
 #endif
 
     /* Call the service */
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                 "Processing a service with type id %u on Session %u",
-                 requestType->typeId.identifier.numeric, session->authenticationToken.identifier.numeric);
     UA_assert(service);
     UA_assert(requestType);
     UA_assert(responseType);
@@ -508,10 +492,9 @@ processMSG(UA_Connection *connection, UA_Server *server, const UA_TcpMessageHead
     if(tokenId != channel->securityToken.tokenId) {
         if(tokenId != channel->nextSecurityToken.tokenId) {
             /* close the securechannel but keep the connection open */
-            UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                        "Request with a wrong security token. Closing the SecureChannel %i.",
-                        channel->securityToken.channelId);
-            Service_CloseSecureChannel(server, channel->securityToken.channelId);
+            UA_LOG_INFO_CHANNEL(server->config.logger, channel,
+                                "Request with a wrong security token. Closing the SecureChannel.");
+            Service_CloseSecureChannel(server, channel);
             return;
         }
         UA_SecureChannel_revolveTokens(channel);
@@ -539,7 +522,7 @@ processCLO(UA_Connection *connection, UA_Server *server, const UA_ByteString *ms
     if(retval != UA_STATUSCODE_GOOD || !connection->channel ||
        connection->channel->securityToken.channelId != channelId)
         return;
-    Service_CloseSecureChannel(server, channelId);
+    Service_CloseSecureChannel(server, connection->channel);
 }
 
 /* Process binary message received from Connection dose not modify UA_ByteString
@@ -571,11 +554,13 @@ void UA_Server_processBinaryMessage(UA_Server *server, UA_Connection *connection
         switch(tcpMessageHeader.messageTypeAndChunkType & 0x00ffffff) {
         case UA_MESSAGETYPE_HEL:
             UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK,
-                         "Process a HEL on Connection %i", connection->sockfd);
+                         "Connection %i | Process a HEL", connection->sockfd);
             processHEL(connection, msg, &pos);
             break;
 
         case UA_MESSAGETYPE_OPN:
+            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK,
+                         "Connection %i | Process a OPN", connection->sockfd);
             processOPN(connection, server, msg, &pos);
             break;
 
@@ -583,31 +568,33 @@ void UA_Server_processBinaryMessage(UA_Server *server, UA_Connection *connection
 #ifndef UA_ENABLE_NONSTANDARD_STATELESS
             if(connection->state != UA_CONNECTION_ESTABLISHED) {
                 UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK,
-                             "Received a MSG where the connection is not established on Connection %i",
+                             "Connection %i | Received a MSG, but the connection is not established",
                              connection->sockfd);
                 connection->close(connection);
                 return;
             }
 #endif
             UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK,
-                         "Process a MSG on Connection %i", connection->sockfd);
+                         "Connection %i | Process a MSG", connection->sockfd);
             processMSG(connection, server, &tcpMessageHeader, msg, &pos);
             break;
 
         case UA_MESSAGETYPE_CLO:
+            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK,
+                         "Connection %i | Process a CLO", connection->sockfd);
             processCLO(connection, server, msg, &pos);
             connection->close(connection);
             return;
 
         default:
             UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_NETWORK,
-                        "Unknown request type on Connection %i", connection->sockfd);
+                        "Connection %i | Unknown request type", connection->sockfd);
         }
 
         /* Loop to process the next message in the stream */
         if(pos != targetpos) {
             UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_NETWORK,
-                        "Message on Connection %i was not entirely processed. "
+                        "Connection %i | Message was not entirely processed. "
                         "Arrived at position %i, skip after the announced length to position %i",
                         connection->sockfd, pos, targetpos);
             pos = targetpos;

src/server/ua_services.h

@@ -54,7 +54,7 @@ void Service_OpenSecureChannel(UA_Server *server, UA_Connection *connection,
                                UA_OpenSecureChannelResponse *response);
 
 /** Used to terminate a SecureChannel. */
-void Service_CloseSecureChannel(UA_Server *server, UA_UInt32 channelId);
+void Service_CloseSecureChannel(UA_Server *server, UA_SecureChannel *channel);
 
 /**
  * Session Service Set

src/server/ua_services_attribute.c

@@ -335,17 +335,15 @@ void Service_Read_single(UA_Server *server, UA_Session *session, const UA_Timest
 
 void Service_Read(UA_Server *server, UA_Session *session, const UA_ReadRequest *request,
                   UA_ReadResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing ReadRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing ReadRequest");
     if(request->nodesToReadSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
     }
 
     if(request->timestampsToReturn > 3){
-    	response->responseHeader.serviceResult = UA_STATUSCODE_BADTIMESTAMPSTORETURNINVALID;
-    	return;
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADTIMESTAMPSTORETURNINVALID;
+        return;
     }
 
     size_t size = request->nodesToReadSize;
@@ -357,7 +355,7 @@ void Service_Read(UA_Server *server, UA_Session *session, const UA_ReadRequest *
 
     response->resultsSize = size;
     if(request->maxAge < 0) {
-    	response->responseHeader.serviceResult = UA_STATUSCODE_BADMAXAGEINVALID;
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADMAXAGEINVALID;
         return;
     }
 
@@ -560,7 +558,7 @@ CopyValueIntoNode(UA_VariableNode *node, const UA_WriteValue *wvalue) {
           }
       }
     }
-    
+
     if(!rangeptr) {
         UA_Variant_deleteMembers(&node->value.variant.value);
         UA_Variant_copy(newV, &node->value.variant.value);
@@ -585,103 +583,103 @@ CopyAttributeIntoNode(UA_Server *server, UA_Session *session,
     const UA_DataType *attr_type = NULL;
 
     UA_StatusCode retval = UA_STATUSCODE_GOOD;
-	switch(wvalue->attributeId) {
+    switch(wvalue->attributeId) {
     case UA_ATTRIBUTEID_NODEID:
     case UA_ATTRIBUTEID_NODECLASS:
     case UA_ATTRIBUTEID_DATATYPE:
-		retval = UA_STATUSCODE_BADWRITENOTSUPPORTED;
-		break;
-	case UA_ATTRIBUTEID_BROWSENAME:
-		CHECK_DATATYPE(QUALIFIEDNAME);
+        retval = UA_STATUSCODE_BADWRITENOTSUPPORTED;
+        break;
+    case UA_ATTRIBUTEID_BROWSENAME:
+        CHECK_DATATYPE(QUALIFIEDNAME);
         target = &node->browseName;
         attr_type = &UA_TYPES[UA_TYPES_QUALIFIEDNAME];
-		break;
-	case UA_ATTRIBUTEID_DISPLAYNAME:
-		CHECK_DATATYPE(LOCALIZEDTEXT);
+        break;
+    case UA_ATTRIBUTEID_DISPLAYNAME:
+        CHECK_DATATYPE(LOCALIZEDTEXT);
         target = &node->displayName;
         attr_type = &UA_TYPES[UA_TYPES_LOCALIZEDTEXT];
-		break;
-	case UA_ATTRIBUTEID_DESCRIPTION:
-		CHECK_DATATYPE(LOCALIZEDTEXT);
+        break;
+    case UA_ATTRIBUTEID_DESCRIPTION:
+        CHECK_DATATYPE(LOCALIZEDTEXT);
         target = &node->description;
         attr_type = &UA_TYPES[UA_TYPES_LOCALIZEDTEXT];
-		break;
-	case UA_ATTRIBUTEID_WRITEMASK:
-		CHECK_DATATYPE(UINT32);
-		node->writeMask = *(UA_UInt32*)value;
-		break;
-	case UA_ATTRIBUTEID_USERWRITEMASK:
-		CHECK_DATATYPE(UINT32);
-		node->userWriteMask = *(UA_UInt32*)value;
-		break;    
-	case UA_ATTRIBUTEID_ISABSTRACT:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_OBJECTTYPE | UA_NODECLASS_REFERENCETYPE |
+        break;
+    case UA_ATTRIBUTEID_WRITEMASK:
+        CHECK_DATATYPE(UINT32);
+        node->writeMask = *(UA_UInt32*)value;
+        break;
+    case UA_ATTRIBUTEID_USERWRITEMASK:
+        CHECK_DATATYPE(UINT32);
+        node->userWriteMask = *(UA_UInt32*)value;
+        break;
+    case UA_ATTRIBUTEID_ISABSTRACT:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_OBJECTTYPE | UA_NODECLASS_REFERENCETYPE |
                               UA_NODECLASS_VARIABLETYPE | UA_NODECLASS_DATATYPE);
-		CHECK_DATATYPE(BOOLEAN);
-		((UA_ObjectTypeNode*)node)->isAbstract = *(UA_Boolean*)value;
-		break;
-	case UA_ATTRIBUTEID_SYMMETRIC:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_REFERENCETYPE);
-		CHECK_DATATYPE(BOOLEAN);
-		((UA_ReferenceTypeNode*)node)->symmetric = *(UA_Boolean*)value;
-		break;
-	case UA_ATTRIBUTEID_INVERSENAME:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_REFERENCETYPE);
-		CHECK_DATATYPE(LOCALIZEDTEXT);
+        CHECK_DATATYPE(BOOLEAN);
+        ((UA_ObjectTypeNode*)node)->isAbstract = *(UA_Boolean*)value;
+        break;
+    case UA_ATTRIBUTEID_SYMMETRIC:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_REFERENCETYPE);
+        CHECK_DATATYPE(BOOLEAN);
+        ((UA_ReferenceTypeNode*)node)->symmetric = *(UA_Boolean*)value;
+        break;
+    case UA_ATTRIBUTEID_INVERSENAME:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_REFERENCETYPE);
+        CHECK_DATATYPE(LOCALIZEDTEXT);
         target = &((UA_ReferenceTypeNode*)node)->inverseName;
         attr_type = &UA_TYPES[UA_TYPES_LOCALIZEDTEXT];
-		break;
-	case UA_ATTRIBUTEID_CONTAINSNOLOOPS:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VIEW);
-		CHECK_DATATYPE(BOOLEAN);
+        break;
+    case UA_ATTRIBUTEID_CONTAINSNOLOOPS:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VIEW);
+        CHECK_DATATYPE(BOOLEAN);
         ((UA_ViewNode*)node)->containsNoLoops = *(UA_Boolean*)value;
-		break;
-	case UA_ATTRIBUTEID_EVENTNOTIFIER:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VIEW | UA_NODECLASS_OBJECT);
-		CHECK_DATATYPE(BYTE);
+        break;
+    case UA_ATTRIBUTEID_EVENTNOTIFIER:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VIEW | UA_NODECLASS_OBJECT);
+        CHECK_DATATYPE(BYTE);
         ((UA_ViewNode*)node)->eventNotifier = *(UA_Byte*)value;
-		break;
-	case UA_ATTRIBUTEID_VALUE:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE | UA_NODECLASS_VARIABLETYPE);
+        break;
+    case UA_ATTRIBUTEID_VALUE:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE | UA_NODECLASS_VARIABLETYPE);
         if(((const UA_VariableNode*)node)->valueSource == UA_VALUESOURCE_VARIANT)
             retval = CopyValueIntoNode((UA_VariableNode*)node, wvalue);
         else
             retval = Service_Write_single_ValueDataSource(server, session, (const UA_VariableNode*)node, wvalue);
-		break;
-	case UA_ATTRIBUTEID_ACCESSLEVEL:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
-		CHECK_DATATYPE(BYTE);
-		((UA_VariableNode*)node)->accessLevel = *(UA_Byte*)value;
-		break;
-	case UA_ATTRIBUTEID_USERACCESSLEVEL:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
-		CHECK_DATATYPE(BYTE);
-		((UA_VariableNode*)node)->userAccessLevel = *(UA_Byte*)value;
-		break;
-	case UA_ATTRIBUTEID_MINIMUMSAMPLINGINTERVAL:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
-		CHECK_DATATYPE(DOUBLE);
-		((UA_VariableNode*)node)->minimumSamplingInterval = *(UA_Double*)value;
-		break;
-	case UA_ATTRIBUTEID_HISTORIZING:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
-		CHECK_DATATYPE(BOOLEAN);
-		((UA_VariableNode*)node)->historizing = *(UA_Boolean*)value;
-		break;
-	case UA_ATTRIBUTEID_EXECUTABLE:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_METHOD);
-		CHECK_DATATYPE(BOOLEAN);
-		((UA_MethodNode*)node)->executable = *(UA_Boolean*)value;
-		break;
-	case UA_ATTRIBUTEID_USEREXECUTABLE:
-		CHECK_NODECLASS_WRITE(UA_NODECLASS_METHOD);
-		CHECK_DATATYPE(BOOLEAN);
-		((UA_MethodNode*)node)->userExecutable = *(UA_Boolean*)value;
-		break;
-	default:
-		retval = UA_STATUSCODE_BADATTRIBUTEIDINVALID;
-		break;
-	}
+        break;
+    case UA_ATTRIBUTEID_ACCESSLEVEL:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
+        CHECK_DATATYPE(BYTE);
+        ((UA_VariableNode*)node)->accessLevel = *(UA_Byte*)value;
+        break;
+    case UA_ATTRIBUTEID_USERACCESSLEVEL:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
+        CHECK_DATATYPE(BYTE);
+        ((UA_VariableNode*)node)->userAccessLevel = *(UA_Byte*)value;
+        break;
+    case UA_ATTRIBUTEID_MINIMUMSAMPLINGINTERVAL:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
+        CHECK_DATATYPE(DOUBLE);
+        ((UA_VariableNode*)node)->minimumSamplingInterval = *(UA_Double*)value;
+        break;
+    case UA_ATTRIBUTEID_HISTORIZING:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_VARIABLE);
+        CHECK_DATATYPE(BOOLEAN);
+        ((UA_VariableNode*)node)->historizing = *(UA_Boolean*)value;
+        break;
+    case UA_ATTRIBUTEID_EXECUTABLE:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_METHOD);
+        CHECK_DATATYPE(BOOLEAN);
+        ((UA_MethodNode*)node)->executable = *(UA_Boolean*)value;
+        break;
+    case UA_ATTRIBUTEID_USEREXECUTABLE:
+        CHECK_NODECLASS_WRITE(UA_NODECLASS_METHOD);
+        CHECK_DATATYPE(BOOLEAN);
+        ((UA_MethodNode*)node)->userExecutable = *(UA_Boolean*)value;
+        break;
+    default:
+        retval = UA_STATUSCODE_BADATTRIBUTEIDINVALID;
+        break;
+    }
     if(attr_type) {
         UA_deleteMembers(target, attr_type);
         retval = UA_copy(value, target, attr_type);
@@ -695,10 +693,8 @@ UA_StatusCode Service_Write_single(UA_Server *server, UA_Session *session, const
 
 void Service_Write(UA_Server *server, UA_Session *session, const UA_WriteRequest *request,
                    UA_WriteResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing WriteRequest");
     UA_assert(server != NULL && session != NULL && request != NULL && response != NULL);
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing WriteRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
 
     if(request->nodesToWriteSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
@@ -738,6 +734,6 @@ void Service_Write(UA_Server *server, UA_Session *session, const UA_WriteRequest
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
         if(!isExternal[i])
 #endif
-		  response->results[i] = Service_Write_single(server, session, &request->nodesToWrite[i]);
+            response->results[i] = Service_Write_single(server, session, &request->nodesToWrite[i]);
     }
 }

src/server/ua_services_call.c

@@ -28,13 +28,13 @@ static UA_StatusCode
 satisfySignature(const UA_Variant *var, const UA_Argument *arg) {
     if(!UA_NodeId_equal(&var->type->typeId, &arg->dataType) )
         return UA_STATUSCODE_BADINVALIDARGUMENT;
-    
+
     // Note: The namespace compiler will compile nodes with their actual array dimensions
     // Todo: Check if this is standard conform for scalars
     if(arg->arrayDimensionsSize > 0 && var->arrayDimensionsSize > 0)
         if(var->arrayDimensionsSize != arg->arrayDimensionsSize)
             return UA_STATUSCODE_BADINVALIDARGUMENT;
-        
+
     UA_Int32 *varDims = var->arrayDimensions;
     size_t varDimsSize = var->arrayDimensionsSize;
     UA_Boolean scalar = UA_Variant_isScalar(var);
@@ -112,24 +112,24 @@ Service_Call_single(UA_Server *server, UA_Session *session, const UA_CallMethodR
         result->statusCode = UA_STATUSCODE_BADMETHODINVALID;
         return;
     }
-    
+
     const UA_ObjectNode *withObject =
         (const UA_ObjectNode*)UA_NodeStore_get(server->nodestore, &request->objectId);
     if(!withObject) {
         result->statusCode = UA_STATUSCODE_BADNODEIDINVALID;
         return;
     }
-    
+
     if(methodCalled->nodeClass != UA_NODECLASS_METHOD) {
         result->statusCode = UA_STATUSCODE_BADNODECLASSINVALID;
         return;
     }
-    
+
     if(withObject->nodeClass != UA_NODECLASS_OBJECT && withObject->nodeClass != UA_NODECLASS_OBJECTTYPE) {
         result->statusCode = UA_STATUSCODE_BADNODECLASSINVALID;
         return;
     }
-    
+
     /* Verify method/object relations */
     // Object must have a hasComponent reference (or any inherited referenceType from sayd reference)
     // to be valid for a methodCall...
@@ -145,7 +145,7 @@ Service_Call_single(UA_Server *server, UA_Session *session, const UA_CallMethodR
     }
     if(result->statusCode != UA_STATUSCODE_GOOD)
         return;
-        
+
     /* Verify method executable */
     if(!methodCalled->executable || !methodCalled->userExecutable) {
         result->statusCode = UA_STATUSCODE_BADNOTWRITABLE; // There is no NOTEXECUTABLE?
@@ -172,7 +172,7 @@ Service_Call_single(UA_Server *server, UA_Session *session, const UA_CallMethodR
         result->statusCode = UA_STATUSCODE_BADINTERNALERROR;
         return;
     }
-    
+
     /* Call method if available */
     if(methodCalled->attachedMethod) {
         result->outputArguments = UA_Array_new(outputArguments->value.variant.value.arrayLength,
@@ -184,12 +184,12 @@ Service_Call_single(UA_Server *server, UA_Session *session, const UA_CallMethodR
     }
     else
         result->statusCode = UA_STATUSCODE_BADNOTWRITABLE; // There is no NOTEXECUTABLE?
-    
     /* TODO: Verify Output Argument count, types and sizes */
 }
 
 void Service_Call(UA_Server *server, UA_Session *session, const UA_CallRequest *request,
                   UA_CallResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing CallRequest");
     if(request->methodsToCallSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -202,7 +202,7 @@ void Service_Call(UA_Server *server, UA_Session *session, const UA_CallRequest *
         return;
     }
     response->resultsSize = request->methodsToCallSize;
-    
+
     for(size_t i = 0; i < request->methodsToCallSize;i++)
         Service_Call_single(server, session, &request->methodsToCall[i], &response->results[i]);
 }

src/server/ua_services_discovery.c

@@ -4,6 +4,7 @@
 
 void Service_FindServers(UA_Server *server, UA_Session *session,
                          const UA_FindServersRequest *request, UA_FindServersResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing FindServersRequest");
     /* copy ApplicationDescription from the config */
     UA_ApplicationDescription *descr = UA_malloc(sizeof(UA_ApplicationDescription));
     if(!descr) {
@@ -28,7 +29,7 @@ void Service_FindServers(UA_Server *server, UA_Session *session,
     size_t existing = descr->discoveryUrlsSize;
     descr->discoveryUrls = disc;
     descr->discoveryUrlsSize += server->config.networkLayersSize;
-        
+
     // TODO: Add nl only if discoveryUrl not already present
     for(size_t i = 0; i < server->config.networkLayersSize; i++) {
         UA_ServerNetworkLayer *nl = &server->config.networkLayers[i];
@@ -41,6 +42,7 @@ void Service_FindServers(UA_Server *server, UA_Session *session,
 
 void Service_GetEndpoints(UA_Server *server, UA_Session *session, const UA_GetEndpointsRequest *request,
                           UA_GetEndpointsResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing GetEndpointsRequest");
     /* Test if one of the networklayers exposes the discoveryUrl of the requested endpoint */
     /* Disabled, servers in a virtualbox don't know their external hostname */
     /* UA_Boolean foundUri = false; */
@@ -57,9 +59,9 @@ void Service_GetEndpoints(UA_Server *server, UA_Session *session, const UA_GetEn
     
     /* test if the supported binary profile shall be returned */
 #ifdef NO_ALLOCA
-	UA_Boolean relevant_endpoints[server->endpointDescriptionsSize];
+    UA_Boolean relevant_endpoints[server->endpointDescriptionsSize];
 #else
-	UA_Boolean *relevant_endpoints = UA_alloca(sizeof(UA_Byte) * server->endpointDescriptionsSize);
+    UA_Boolean *relevant_endpoints = UA_alloca(sizeof(UA_Byte) * server->endpointDescriptionsSize);
 #endif
     size_t relevant_count = 0;
     for(size_t j = 0; j < server->endpointDescriptionsSize; j++) {

src/server/ua_services_nodemanagement.c

@@ -511,7 +511,7 @@ void Service_AddNodes_single(UA_Server *server, UA_Session *session, const UA_Ad
     if(!UA_NodeId_isNull(&item->typeDefinition.nodeId)) {
         if (instantiationCallback != NULL)
           instantiationCallback->method(result->addedNodeId, item->typeDefinition.nodeId,
-                                        instantiationCallback->handle); 
+                                        instantiationCallback->handle);
         
         if(item->nodeClass == UA_NODECLASS_OBJECT)
             result->statusCode = instantiateObjectNode(server, session, &result->addedNodeId,
@@ -528,6 +528,7 @@ void Service_AddNodes_single(UA_Server *server, UA_Session *session, const UA_Ad
 
 void Service_AddNodes(UA_Server *server, UA_Session *session, const UA_AddNodesRequest *request,
                       UA_AddNodesResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing AddNodesRequest");
     if(request->nodesToAddSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -741,17 +742,17 @@ UA_Server_addMethodNode(UA_Server *server, const UA_NodeId requestedNewNodeId,
 /* Adds a one-way reference to the local nodestore */
 static UA_StatusCode
 addOneWayReference(UA_Server *server, UA_Session *session, UA_Node *node, const UA_AddReferencesItem *item) {
-	size_t i = node->referencesSize;
+    size_t i = node->referencesSize;
     size_t refssize = (i+1) | 3; // so the realloc is not necessary every time
-	UA_ReferenceNode *new_refs = UA_realloc(node->references, sizeof(UA_ReferenceNode) * refssize);
-	if(!new_refs)
-		return UA_STATUSCODE_BADOUTOFMEMORY;
+    UA_ReferenceNode *new_refs = UA_realloc(node->references, sizeof(UA_ReferenceNode) * refssize);
+    if(!new_refs)
+        return UA_STATUSCODE_BADOUTOFMEMORY;
     node->references = new_refs;
     UA_ReferenceNode_init(&new_refs[i]);
     UA_StatusCode retval = UA_NodeId_copy(&item->referenceTypeId, &new_refs[i].referenceTypeId);
     retval |= UA_ExpandedNodeId_copy(&item->targetNodeId, &new_refs[i].targetId);
     new_refs[i].isInverse = !item->isForward;
-    if(retval == UA_STATUSCODE_GOOD) 
+    if(retval == UA_STATUSCODE_GOOD)
         node->referencesSize = i+1;
     else
         UA_ReferenceNode_deleteMembers(&new_refs[i]);
@@ -779,22 +780,22 @@ Service_AddReferences_single(UA_Server *server, UA_Session *session, const UA_Ad
 
     // todo: remove reference if the second direction failed
     return retval;
-} 
+}
 
-void Service_AddReferences(UA_Server *server, UA_Session *session,
-                           const UA_AddReferencesRequest *request,
+void Service_AddReferences(UA_Server *server, UA_Session *session, const UA_AddReferencesRequest *request,
                            UA_AddReferencesResponse *response) {
-	if(request->referencesToAddSize <= 0) {
-		response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
-		return;
-	}
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing AddReferencesRequest");
+    if(request->referencesToAddSize <= 0) {
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
+        return;
+    }
     size_t size = request->referencesToAddSize;
-	
+
     if(!(response->results = UA_malloc(sizeof(UA_StatusCode) * size))) {
-		response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
-		return;
-	}
-	response->resultsSize = size;
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
+        return;
+    }
+    response->resultsSize = size;
 
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
 #ifdef NO_ALLOCA
@@ -805,30 +806,30 @@ void Service_AddReferences(UA_Server *server, UA_Session *session,
     UA_UInt32 *indices = UA_alloca(sizeof(UA_UInt32) * size);
 #endif /*NO_ALLOCA */
     memset(isExternal, false, sizeof(UA_Boolean) * size);
-	for(size_t j = 0; j < server->externalNamespacesSize; j++) {
-		size_t indicesSize = 0;
-		for(size_t i = 0;i < size;i++) {
-			if(request->referencesToAdd[i].sourceNodeId.namespaceIndex
+    for(size_t j = 0; j < server->externalNamespacesSize; j++) {
+        size_t indicesSize = 0;
+        for(size_t i = 0;i < size;i++) {
+            if(request->referencesToAdd[i].sourceNodeId.namespaceIndex
                != server->externalNamespaces[j].index)
-				continue;
-			isExternal[i] = true;
-			indices[indicesSize] = i;
-			indicesSize++;
-		}
-		if (indicesSize == 0)
-			continue;
-		UA_ExternalNodeStore *ens = &server->externalNamespaces[j].externalNodeStore;
-		ens->addReferences(ens->ensHandle, &request->requestHeader, request->referencesToAdd,
+                continue;
+            isExternal[i] = true;
+            indices[indicesSize] = i;
+            indicesSize++;
+        }
+        if (indicesSize == 0)
+            continue;
+        UA_ExternalNodeStore *ens = &server->externalNamespaces[j].externalNodeStore;
+        ens->addReferences(ens->ensHandle, &request->requestHeader, request->referencesToAdd,
                            indices, indicesSize, response->results, response->diagnosticInfos);
-	}
+    }
 #endif
 
-	for(size_t i = 0; i < response->resultsSize; i++) {
+    for(size_t i = 0; i < response->resultsSize; i++) {
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
-		if(!isExternal[i])
+        if(!isExternal[i])
 #endif
             Service_AddReferences_single(server, session, &request->referencesToAdd[i]);
-	}
+    }
 }
 
 /****************/
@@ -865,7 +866,7 @@ Service_DeleteNodes_single(UA_Server *server, UA_Session *session, const UA_Node
         bd.referenceTypeId = UA_NODEID_NUMERIC(0, UA_NS0ID_HASSUBTYPE);
         bd.includeSubtypes = true;
         bd.nodeClassMask = UA_NODECLASS_OBJECTTYPE;
-        
+
         /* browse type definitions with admin rights */
         UA_BrowseResult result;
         UA_BrowseResult_init(&result);
@@ -885,12 +886,13 @@ Service_DeleteNodes_single(UA_Server *server, UA_Session *session, const UA_Node
         }
         UA_BrowseResult_deleteMembers(&result);
     }
-    
+
     return UA_NodeStore_remove(server->nodestore, nodeId);
 }
 
 void Service_DeleteNodes(UA_Server *server, UA_Session *session, const UA_DeleteNodesRequest *request,
                          UA_DeleteNodesResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing DeleteNodesRequest");
     if(request->nodesToDeleteSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -901,7 +903,7 @@ void Service_DeleteNodes(UA_Server *server, UA_Session *session, const UA_Delete
         return;
     }
     response->resultsSize = request->nodesToDeleteSize;
-    for(size_t i=0; i<request->nodesToDeleteSize; i++) {
+    for(size_t i = 0; i < request->nodesToDeleteSize; i++) {
         UA_DeleteNodesItem *item = &request->nodesToDelete[i];
         response->results[i] = Service_DeleteNodes_single(server, session, &item->nodeId,
                                                           item->deleteTargetReferences);
@@ -916,7 +918,7 @@ static UA_StatusCode
 deleteOneWayReference(UA_Server *server, UA_Session *session, UA_Node *node,
                       const UA_DeleteReferencesItem *item) {
     UA_Boolean edited = false;
-    for(size_t i = node->referencesSize - 1; ; i--) {
+    for(size_t i = node->referencesSize-1; ; i--) {
         if(i > node->referencesSize)
             break; /* underflow after i == 0 */
         if(!UA_NodeId_equal(&item->targetNodeId.nodeId, &node->references[i].targetId.nodeId))
@@ -957,8 +959,10 @@ Service_DeleteReferences_single(UA_Server *server, UA_Session *session,
 }
 
 void
-Service_DeleteReferences(UA_Server *server, UA_Session *session, const UA_DeleteReferencesRequest *request,
+Service_DeleteReferences(UA_Server *server, UA_Session *session,
+                         const UA_DeleteReferencesRequest *request,
                          UA_DeleteReferencesResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing DeleteReferencesRequest");
     if(request->referencesToDeleteSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;

src/server/ua_services_securechannel.c

@@ -11,29 +11,30 @@ void Service_OpenSecureChannel(UA_Server *server, UA_Connection *connection,
             UA_SecureChannelManager_open(&server->secureChannelManager, connection, request, response);
 
         if(response->responseHeader.serviceResult == UA_STATUSCODE_GOOD)
-            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                         "Opened SecureChannel %i on Connection %i",
-                         response->securityToken.channelId, connection->sockfd);
+            UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
+                         "Connection %i | SecureChannel %i | OpenSecureChannel: Opened SecureChannel",
+                         connection->sockfd, response->securityToken.channelId);
         else
             UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                         "Opening SecureChannel on Connection %i failed", connection->sockfd);
+                         "Connection %i | OpenSecureChannel: Opening a SecureChannel failed",
+                         connection->sockfd);
     } else {
         response->responseHeader.serviceResult =
             UA_SecureChannelManager_renew(&server->secureChannelManager, connection, request, response);
 
         if(response->responseHeader.serviceResult == UA_STATUSCODE_GOOD)
             UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                         "Renewed SecureChannel %i on Connection %i",
-                         response->securityToken.channelId, connection->sockfd);
+                         "Connection %i | SecureChannel %i | OpenSecureChannel: SecureChannel renewed",
+                         connection->sockfd, response->securityToken.channelId);
         else
             UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                         "Renewing SecureChannel on Connection %i failed", connection->sockfd);
+                         "Connection %i | OpenSecureChannel: Renewing SecureChannel failed",
+                         connection->sockfd);
     }
 }
 
 /* The server does not send a CloseSecureChannel response */
-void Service_CloseSecureChannel(UA_Server *server, UA_UInt32 channelId) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SECURECHANNEL,
-                 "Closing SecureChannel %i", channelId);
-    UA_SecureChannelManager_close(&server->secureChannelManager, channelId);
+void Service_CloseSecureChannel(UA_Server *server, UA_SecureChannel *channel) {
+    UA_LOG_INFO_CHANNEL(server->config.logger, channel, "CloseSecureChannel");
+    UA_SecureChannelManager_close(&server->secureChannelManager, channel->securityToken.channelId);
 }

src/server/ua_services_session.c

@@ -17,14 +17,12 @@ void Service_CreateSession(UA_Server *server, UA_Session *session, const UA_Crea
         return;
     response->serverEndpointsSize = server->endpointDescriptionsSize;
 
-	UA_Session *newSession;
+    UA_Session *newSession;
     response->responseHeader.serviceResult =
         UA_SessionManager_createSession(&server->sessionManager, channel, request, &newSession);
-	if(response->responseHeader.serviceResult != UA_STATUSCODE_GOOD) {
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                     "Processing CreateSessionRequest on SecureChannel %i failed",
-                     channel->securityToken.channelId);
-		return;
+    if(response->responseHeader.serviceResult != UA_STATUSCODE_GOOD) {
+        UA_LOG_DEBUG_CHANNEL(server->config.logger, channel, "Processing CreateSessionRequest failed");
+        return;
     }
 
     //TODO get maxResponseMessageSize internally
@@ -35,15 +33,13 @@ void Service_CreateSession(UA_Server *server, UA_Session *session, const UA_Crea
     response->responseHeader.serviceResult = UA_String_copy(&request->sessionName, &newSession->sessionName);
     if(server->endpointDescriptions)
         response->responseHeader.serviceResult |=
-            UA_ByteString_copy(&server->endpointDescriptions->serverCertificate, &response->serverCertificate);
+            UA_ByteString_copy(&server->endpointDescriptions->serverCertificate,
+                               &response->serverCertificate);
     if(response->responseHeader.serviceResult != UA_STATUSCODE_GOOD) {
         UA_SessionManager_removeSession(&server->sessionManager, &newSession->authenticationToken);
          return;
     }
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing CreateSessionRequest on SecureChannel %i succeeded, created Session (ns=%i,i=%i)",
-                 channel->securityToken.channelId, response->sessionId.namespaceIndex,
-                 response->sessionId.identifier.numeric);
+    UA_LOG_DEBUG_SESSION(server->config.logger, newSession, "Session created");
 }
 
 void
@@ -51,41 +47,33 @@ Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_Activat
                         UA_ActivateSessionResponse *response) {
     UA_SecureChannel *channel = session->channel;
     // make the channel know about the session
-	UA_Session *foundSession =
+    UA_Session *foundSession =
         UA_SessionManager_getSession(&server->sessionManager, &request->requestHeader.authenticationToken);
 
-	if(!foundSession) {
+    if(!foundSession) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSESSIONIDINVALID;
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                     "Processing ActivateSessionRequest on SecureChannel %i, "
-                     "but no session found for the authentication token",
-                     channel->securityToken.channelId);
+        UA_LOG_INFO_CHANNEL(server->config.logger, channel, "ActivateSession: No "
+                            "session found for the authentication token");
         return;
-	}
+    }
 
     if(foundSession->validTill < UA_DateTime_now()) {
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                     "Processing ActivateSessionRequest on SecureChannel %i, but the session has timed out",
-                     channel->securityToken.channelId);
+        UA_LOG_INFO_SESSION(server->config.logger, foundSession, "ActivateSession: SecureChannel %i wants "
+                            "to activate, but the session has timed out", channel->securityToken.channelId);
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSESSIONIDINVALID;
         return;
-	}
+    }
 
     if(request->userIdentityToken.encoding < UA_EXTENSIONOBJECT_DECODED ||
        (request->userIdentityToken.content.decoded.type != &UA_TYPES[UA_TYPES_ANONYMOUSIDENTITYTOKEN] &&
         request->userIdentityToken.content.decoded.type != &UA_TYPES[UA_TYPES_USERNAMEIDENTITYTOKEN])) {
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                     "Invalided UserIdentityToken on SecureChannel %i for Session (ns=%i,i=%i)",
-                     channel->securityToken.channelId, foundSession->sessionId.namespaceIndex,
-                     foundSession->sessionId.identifier.numeric);
+        UA_LOG_INFO_SESSION(server->config.logger, foundSession, "ActivateSession: SecureChannel %i wants "
+                            "to activate, but the UserIdentify token is invalid",
+                            channel->securityToken.channelId);
         response->responseHeader.serviceResult = UA_STATUSCODE_BADINTERNALERROR;
         return;
     }
 
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing ActivateSessionRequest on SecureChannel %i for Session (ns=%i,i=%i)",
-                 channel->securityToken.channelId, foundSession->sessionId.namespaceIndex,
-                 foundSession->sessionId.identifier.numeric);
 
     UA_String ap = UA_STRING(ANONYMOUS_POLICY);
     UA_String up = UA_STRING(USERNAME_POLICY);
@@ -105,11 +93,15 @@ Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_Activat
             response->responseHeader.serviceResult = UA_STATUSCODE_BADIDENTITYTOKENINVALID;
             return;
         }
-        if(foundSession->channel && foundSession->channel != channel)
+        if(foundSession->channel && foundSession->channel != channel) {
+            UA_LOG_INFO_SESSION(server->config.logger, foundSession,
+                                "ActivateSession: Detach from old channel");
             UA_SecureChannel_detachSession(foundSession->channel, foundSession);
+        }
         UA_SecureChannel_attachSession(channel, foundSession);
         foundSession->activated = true;
         UA_Session_updateLifetime(foundSession);
+        UA_LOG_INFO_SESSION(server->config.logger, foundSession, "ActivateSession: Session activated");
         return;
     }
 
@@ -133,14 +125,20 @@ Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_Activat
             if(!UA_String_equal(&token->userName, user) || !UA_String_equal(&token->password, pw))
                 continue;
             /* success - activate */
-            if(foundSession->channel && foundSession->channel != channel)
+            if(foundSession->channel && foundSession->channel != channel) {
+                UA_LOG_INFO_SESSION(server->config.logger, foundSession,
+                                    "ActivateSession: Detach from old channel");
                 UA_SecureChannel_detachSession(foundSession->channel, foundSession);
+            }
             UA_SecureChannel_attachSession(channel, foundSession);
             foundSession->activated = true;
             UA_Session_updateLifetime(foundSession);
+            UA_LOG_INFO_SESSION(server->config.logger, foundSession, "ActivateSession: Session activated");
             return;
         }
         /* no match */
+        UA_LOG_INFO_SESSION(server->config.logger, foundSession,
+                            "ActivateSession: Did not find matching username/password");
         response->responseHeader.serviceResult = UA_STATUSCODE_BADUSERACCESSDENIED;
         return;
     }
@@ -150,9 +148,7 @@ Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_Activat
 void
 Service_CloseSession(UA_Server *server, UA_Session *session, const UA_CloseSessionRequest *request,
                      UA_CloseSessionResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing CloseSessionRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
+    UA_LOG_INFO_SESSION(server->config.logger, session, "CloseSession");
     response->responseHeader.serviceResult =
         UA_SessionManager_removeSession(&server->sessionManager, &session->authenticationToken);
 }

src/server/ua_services_subscription.c

@@ -40,6 +40,7 @@ setSubscriptionSettings(UA_Server *server, UA_Subscription *subscription,
 void Service_CreateSubscription(UA_Server *server, UA_Session *session,
                                 const UA_CreateSubscriptionRequest *request,
                                 UA_CreateSubscriptionResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing CreateSubscriptionRequest");
     response->subscriptionId = UA_Session_getUniqueSubscriptionID(session);
     UA_Subscription *newSubscription = UA_Subscription_new(session, response->subscriptionId);
     if(!newSubscription) {
@@ -62,6 +63,7 @@ void Service_CreateSubscription(UA_Server *server, UA_Session *session,
 void Service_ModifySubscription(UA_Server *server, UA_Session *session,
                                 const UA_ModifySubscriptionRequest *request,
                                 UA_ModifySubscriptionResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing ModifySubscriptionRequest");
     UA_Subscription *sub = UA_Session_getSubscriptionByID(session, request->subscriptionId);
     if(!sub) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
@@ -81,7 +83,7 @@ void Service_ModifySubscription(UA_Server *server, UA_Session *session,
 void Service_SetPublishingMode(UA_Server *server, UA_Session *session,
                                const UA_SetPublishingModeRequest *request,
                                UA_SetPublishingModeResponse *response) {
-
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing SetPublishingModeRequest");
     if(request->subscriptionIdsSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -161,7 +163,7 @@ Service_CreateMonitoredItems_single(UA_Server *server, UA_Session *session, UA_S
     }
     newMon->subscription = sub;
     newMon->attributeID = request->itemToMonitor.attributeId;
-    newMon->itemId = UA_Session_getUniqueSubscriptionID(session);
+    newMon->itemId = ++(sub->lastMonitoredItemId);
     newMon->timestampsToReturn = timestampsToReturn;
     setMonitoredItemSettings(server, newMon, request->monitoringMode,
                              request->requestedParameters.clientHandle,
@@ -181,6 +183,7 @@ void
 Service_CreateMonitoredItems(UA_Server *server, UA_Session *session,
                              const UA_CreateMonitoredItemsRequest *request,
                              UA_CreateMonitoredItemsResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing CreateMonitoredItemsRequest");
     UA_Subscription *sub = UA_Session_getSubscriptionByID(session, request->subscriptionId);
     if(!sub) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
@@ -229,6 +232,7 @@ Service_ModifyMonitoredItems_single(UA_Server *server, UA_Session *session, UA_S
 void Service_ModifyMonitoredItems(UA_Server *server, UA_Session *session,
                                   const UA_ModifyMonitoredItemsRequest *request,
                                   UA_ModifyMonitoredItemsResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing ModifyMonitoredItemsRequest");
     UA_Subscription *sub = UA_Session_getSubscriptionByID(session, request->subscriptionId);
     if(!sub) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
@@ -259,6 +263,7 @@ void Service_ModifyMonitoredItems(UA_Server *server, UA_Session *session,
 void
 Service_Publish(UA_Server *server, UA_Session *session,
                 const UA_PublishRequest *request, UA_UInt32 requestId) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing PublishRequest");
     /* Return an error if the session has no subscription */
     if(LIST_EMPTY(&session->serverSubscriptions)) {
         UA_PublishResponse response;
@@ -289,7 +294,7 @@ Service_Publish(UA_Server *server, UA_Session *session,
         UA_Subscription *sub = UA_Session_getSubscriptionByID(session, ack->subscriptionId);
         if(!sub) {
             response->results[i] = UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
-            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
+            UA_LOG_DEBUG_SESSION(server->config.logger, session,
                          "Cannot process acknowledgements subscription %u", ack->subscriptionId);
             continue;
         }
@@ -309,17 +314,15 @@ Service_Publish(UA_Server *server, UA_Session *session,
 
     /* Queue the publish response */
     SIMPLEQ_INSERT_TAIL(&session->responseQueue, entry, listEntry);
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                 "Queued a publication message on session %u",
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Queued a publication message",
                  session->authenticationToken.identifier.numeric);
 
     /* Answer immediately to a late subscription */
     UA_Subscription *immediate;
     LIST_FOREACH(immediate, &session->serverSubscriptions, listEntry) {
         if(immediate->state == UA_SUBSCRIPTIONSTATE_LATE) {
-            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                         "Response on a late subscription on session %u",
-                         session->authenticationToken.identifier.numeric);
+            UA_LOG_DEBUG_SESSION(server->config.logger, session, "Response on a late subscription",
+                                 session->authenticationToken.identifier.numeric);
             UA_Subscription_publishCallback(server, immediate);
             return;
         }
@@ -329,6 +332,7 @@ Service_Publish(UA_Server *server, UA_Session *session,
 void Service_DeleteSubscriptions(UA_Server *server, UA_Session *session,
                                  const UA_DeleteSubscriptionsRequest *request,
                                  UA_DeleteSubscriptionsResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing DeleteSubscriptionsRequest");
     response->results = UA_malloc(sizeof(UA_StatusCode) * request->subscriptionIdsSize);
     if(!response->results) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
@@ -343,6 +347,7 @@ void Service_DeleteSubscriptions(UA_Server *server, UA_Session *session,
 void Service_DeleteMonitoredItems(UA_Server *server, UA_Session *session,
                                   const UA_DeleteMonitoredItemsRequest *request,
                                   UA_DeleteMonitoredItemsResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing DeleteMonitoredItemsRequest");
     UA_Subscription *sub = UA_Session_getSubscriptionByID(session, request->subscriptionId);
     if(!sub) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
@@ -364,6 +369,7 @@ void Service_DeleteMonitoredItems(UA_Server *server, UA_Session *session,
 
 void Service_Republish(UA_Server *server, UA_Session *session, const UA_RepublishRequest *request,
                        UA_RepublishResponse *response) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing RepublishRequest");
     /* get the subscription */
     UA_Subscription *sub = UA_Session_getSubscriptionByID(session, request->subscriptionId);
     if (!sub) {

src/server/ua_services_view.c

@@ -34,7 +34,7 @@ fillReferenceDescription(UA_NodeStore *ns, const UA_Node *curr, UA_ReferenceNode
 static const UA_Node *
 returnRelevantNodeExternal(UA_ExternalNodeStore *ens, const UA_BrowseDescription *descr,
                            const UA_ReferenceNode *reference) {
-    /*	prepare a read request in the external nodestore	*/
+    /* prepare a read request in the external nodestore */
     UA_ReadValueId *readValueIds = UA_Array_new(6,&UA_TYPES[UA_TYPES_READVALUEID]);
     UA_UInt32 *indices = UA_Array_new(6,&UA_TYPES[UA_TYPES_UINT32]);
     UA_UInt32 indicesSize = 6;
@@ -108,9 +108,9 @@ returnRelevantNode(UA_Server *server, const UA_BrowseDescription *descr, UA_Bool
 
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
     /* return the node from an external namespace*/
-	for(size_t nsIndex = 0; nsIndex < server->externalNamespacesSize; nsIndex++) {
-		if(reference->targetId.nodeId.namespaceIndex != server->externalNamespaces[nsIndex].index)
-			continue;
+    for(size_t nsIndex = 0; nsIndex < server->externalNamespacesSize; nsIndex++) {
+        if(reference->targetId.nodeId.namespaceIndex != server->externalNamespaces[nsIndex].index)
+            continue;
         *isExternal = true;
         return returnRelevantNodeExternal(&server->externalNamespaces[nsIndex].externalNodeStore,
                                           descr, reference);
@@ -361,14 +361,12 @@ Service_Browse_single(UA_Server *server, UA_Session *session, struct Continuatio
 
 void Service_Browse(UA_Server *server, UA_Session *session, const UA_BrowseRequest *request,
                     UA_BrowseResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing BrowseRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing BrowseRequest");
     if(!UA_NodeId_isNull(&request->view.viewId)) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADVIEWIDUNKNOWN;
         return;
     }
-    
+
     if(request->nodesToBrowseSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -381,7 +379,7 @@ void Service_Browse(UA_Server *server, UA_Session *session, const UA_BrowseReque
         return;
     }
     response->resultsSize = size;
-    
+
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
 #ifdef NO_ALLOCA
     UA_Boolean isExternal[size];
@@ -436,24 +434,22 @@ UA_Server_browseNext_single(UA_Server *server, UA_Session *session, UA_Boolean r
 
 void Service_BrowseNext(UA_Server *server, UA_Session *session, const UA_BrowseNextRequest *request,
                         UA_BrowseNextResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing BrowseNextRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
-   if(request->continuationPointsSize <= 0) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing BrowseNextRequest");
+    if(request->continuationPointsSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
-   }
-   size_t size = request->continuationPointsSize;
-   response->results = UA_Array_new(size, &UA_TYPES[UA_TYPES_BROWSERESULT]);
-   if(!response->results) {
-       response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
-       return;
-   }
-
-   response->resultsSize = size;
-   for(size_t i = 0; i < size; i++)
-       UA_Server_browseNext_single(server, session, request->releaseContinuationPoints,
-                                   &request->continuationPoints[i], &response->results[i]);
+    }
+    size_t size = request->continuationPointsSize;
+    response->results = UA_Array_new(size, &UA_TYPES[UA_TYPES_BROWSERESULT]);
+    if(!response->results) {
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
+        return;
+    }
+
+    response->resultsSize = size;
+    for(size_t i = 0; i < size; i++)
+        UA_Server_browseNext_single(server, session, request->releaseContinuationPoints,
+                                    &request->continuationPoints[i], &response->results[i]);
 }
 
 /***********************/
@@ -567,10 +563,8 @@ void Service_TranslateBrowsePathsToNodeIds_single(UA_Server *server, UA_Session
 void Service_TranslateBrowsePathsToNodeIds(UA_Server *server, UA_Session *session,
                                            const UA_TranslateBrowsePathsToNodeIdsRequest *request,
                                            UA_TranslateBrowsePathsToNodeIdsResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing TranslateBrowsePathsToNodeIdsRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
-	if(request->browsePathsSize <= 0) {
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing TranslateBrowsePathsToNodeIdsRequest");
+    if(request->browsePathsSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
     }
@@ -592,40 +586,37 @@ void Service_TranslateBrowsePathsToNodeIds(UA_Server *server, UA_Session *sessio
 #endif /*NO_ALLOCA */
     memset(isExternal, false, sizeof(UA_Boolean) * size);
     for(size_t j = 0; j < server->externalNamespacesSize; j++) {
-    	size_t indexSize = 0;
-    	for(size_t i = 0;i < size;i++) {
-    		if(request->browsePaths[i].startingNode.namespaceIndex != server->externalNamespaces[j].index)
-    			continue;
-    		isExternal[i] = true;
-    		indices[indexSize] = i;
-    		indexSize++;
-    	}
-    	if(indexSize == 0)
-    		continue;
-    	UA_ExternalNodeStore *ens = &server->externalNamespaces[j].externalNodeStore;
-    	ens->translateBrowsePathsToNodeIds(ens->ensHandle, &request->requestHeader, request->browsePaths,
-    			indices, indexSize, response->results, response->diagnosticInfos);
+        size_t indexSize = 0;
+        for(size_t i = 0;i < size;i++) {
+            if(request->browsePaths[i].startingNode.namespaceIndex != server->externalNamespaces[j].index)
+                continue;
+            isExternal[i] = true;
+            indices[indexSize] = i;
+            indexSize++;
+        }
+        if(indexSize == 0)
+            continue;
+        UA_ExternalNodeStore *ens = &server->externalNamespaces[j].externalNodeStore;
+        ens->translateBrowsePathsToNodeIds(ens->ensHandle, &request->requestHeader, request->browsePaths,
+                indices, indexSize, response->results, response->diagnosticInfos);
     }
 #endif
 
     response->resultsSize = size;
     for(size_t i = 0; i < size; i++) {
 #ifdef UA_ENABLE_EXTERNAL_NAMESPACES
-    	if(!isExternal[i])
+        if(!isExternal[i])
 #endif
-    		Service_TranslateBrowsePathsToNodeIds_single(server, session, &request->browsePaths[i],
+            Service_TranslateBrowsePathsToNodeIds_single(server, session, &request->browsePaths[i],
                                                          &response->results[i]);
     }
 }
 
 void Service_RegisterNodes(UA_Server *server, UA_Session *session, const UA_RegisterNodesRequest *request,
                            UA_RegisterNodesResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing RegisterNodesRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
-
-	//TODO: hang the nodeids to the session if really needed
-	response->responseHeader.timestamp = UA_DateTime_now();
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing RegisterNodesRequest");
+    //TODO: hang the nodeids to the session if really needed
+    response->responseHeader.timestamp = UA_DateTime_now();
     if(request->nodesToRegisterSize <= 0)
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
     else {
@@ -639,12 +630,9 @@ void Service_RegisterNodes(UA_Server *server, UA_Session *session, const UA_Regi
 
 void Service_UnregisterNodes(UA_Server *server, UA_Session *session, const UA_UnregisterNodesRequest *request,
                              UA_UnregisterNodesResponse *response) {
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SESSION,
-                 "Processing UnRegisterNodesRequest for Session (ns=%i,i=%i)",
-                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
-
-	//TODO: remove the nodeids from the session if really needed
-	response->responseHeader.timestamp = UA_DateTime_now();
-	if(request->nodesToUnregisterSize==0)
-		response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing UnRegisterNodesRequest");
+    //TODO: remove the nodeids from the session if really needed
+    response->responseHeader.timestamp = UA_DateTime_now();
+    if(request->nodesToUnregisterSize==0)
+        response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
 }

src/server/ua_subscription.c

@@ -22,6 +22,7 @@ UA_MonitoredItem * UA_MonitoredItem_new() {
     new->lastSampledValue = UA_BYTESTRING_NULL;
     memset(&new->sampleJobGuid, 0, sizeof(UA_Guid));
     new->sampleJobIsRegistered = false;
+    new->itemId = 0;
     return new;
 }
 
@@ -44,21 +45,21 @@ void MonitoredItem_delete(UA_Server *server, UA_MonitoredItem *monitoredItem) {
 
 static void SampleCallback(UA_Server *server, UA_MonitoredItem *monitoredItem) {
     if(monitoredItem->monitoredItemType != UA_MONITOREDITEMTYPE_CHANGENOTIFY) {
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                     "Cannot process a monitoreditem that is not a data change notification");
+        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER, "Session %i | MonitoredItem %i | "
+                     "Cannot process a monitoreditem that is not a data change notification",
+                     monitoredItem->subscription->session->sessionId, monitoredItem->itemId);
         return;
     }
 
     MonitoredItem_queuedValue *newvalue = UA_malloc(sizeof(MonitoredItem_queuedValue));
     if(!newvalue) {
         UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                    "Skipped a sample due to lack of memory on monitoreditem %u", monitoredItem->itemId);
+                    "Session %i | MonitoredItem %i | Skipped a sample due to lack of memory",
+                    monitoredItem->subscription->session->sessionId, monitoredItem->itemId);
         return;
     }
     UA_DataValue_init(&newvalue->value);
     newvalue->clientHandle = monitoredItem->clientHandle;
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                 "Sampling the value on monitoreditem %u", monitoredItem->itemId);
 
     /* Read the value */
     UA_ReadValueId rvid;
@@ -89,11 +90,18 @@ static void SampleCallback(UA_Server *server, UA_MonitoredItem *monitoredItem) {
         UA_ByteString_deleteMembers(&newValueAsByteString);
         UA_DataValue_deleteMembers(&newvalue->value);
         UA_free(newvalue);
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                     "Do not sample since the data value has not changed");
+        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER, "Session %u | Subscription %u | "
+                     "MonitoredItem %u | Do not sample an unchanged value",
+                     monitoredItem->subscription->session->sessionId.identifier.numeric,
+                     monitoredItem->subscription->subscriptionID, monitoredItem->itemId);
         return;
     }
 
+    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER, "Session %u | Subscription %u | "
+                 "MonitoredItem %u | Sampling the value",
+                 monitoredItem->subscription->session->sessionId.identifier.numeric,
+                 monitoredItem->subscription->subscriptionID, monitoredItem->itemId);
+
     /* do we have space in the queue? */
     if(monitoredItem->currentQueueSize >= monitoredItem->maxQueueSize) {
         if(!monitoredItem->discardOldest) {
@@ -118,7 +126,6 @@ static void SampleCallback(UA_Server *server, UA_MonitoredItem *monitoredItem) {
 }
 
 UA_StatusCode MonitoredItem_registerSampleJob(UA_Server *server, UA_MonitoredItem *mon) {
-    //SampleCallback(server, mon);
     UA_Job job = {.type = UA_JOBTYPE_METHODCALL,
                   .job.methodCall = {.method = (UA_ServerCallback)SampleCallback, .data = mon} };
     UA_StatusCode retval = UA_Server_addRepeatedJob(server, job, (UA_UInt32)mon->samplingInterval,
@@ -152,6 +159,7 @@ UA_Subscription * UA_Subscription_new(UA_Session *session, UA_UInt32 subscriptio
     new->publishJobIsRegistered = false;
     new->currentKeepAliveCount = 0;
     new->currentLifetimeCount = 0;
+    new->lastMonitoredItemId = 0;
     new->state = UA_SUBSCRIPTIONSTATE_LATE; /* The first publish response is sent immediately */
     LIST_INIT(&new->retransmissionQueue);
     LIST_INIT(&new->MonitoredItems);
@@ -234,18 +242,17 @@ void UA_Subscription_publishCallback(UA_Server *server, UA_Subscription *sub) {
     /* Dequeue a response */
     UA_PublishResponseEntry *pre = SIMPLEQ_FIRST(&sub->session->responseQueue);
     if(!pre) {
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-            "Cannot send a publish response on subscription %u " \
-            "since the publish queue is empty on session %u",
-            sub->subscriptionID, sub->session->authenticationToken.identifier.numeric);
+        UA_LOG_DEBUG_SESSION(server->config.logger, sub->session,
+                             "Cannot send a publish response on subscription %u, "
+                             "since the publish queue is empty", sub->subscriptionID)
         if(sub->state != UA_SUBSCRIPTIONSTATE_LATE) {
             sub->state = UA_SUBSCRIPTIONSTATE_LATE;
         } else {
             sub->currentLifetimeCount++;
             if(sub->currentLifetimeCount >= sub->lifeTimeCount) {
                 UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                    "End of lifetime for subscription %u on session %u",
-                    sub->subscriptionID, sub->session->authenticationToken.identifier.numeric);
+                    "Session %u | Subscription %u | End of lifetime for subscription",
+                            sub->session->authenticationToken.identifier.numeric, sub->subscriptionID);
                 UA_Session_deleteSubscription(server, sub->session, sub->subscriptionID);
             }
         }
@@ -322,10 +329,8 @@ void UA_Subscription_publishCallback(UA_Server *server, UA_Subscription *sub) {
     }
 
     /* Send the response */
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                 "Sending out a publish response on subscription %u on securechannel %u " \
-                 "with %u notifications", sub->subscriptionID,
-                 sub->session->authenticationToken.identifier.numeric, (UA_UInt32)notifications);
+    UA_LOG_DEBUG_SESSION(server->config.logger, sub->session,
+                   "Sending out a publish response with %u notifications", (UA_UInt32)notifications);
     UA_SecureChannel_sendBinaryMessage(sub->session->channel, requestId, response,
                                        &UA_TYPES[UA_TYPES_PUBLISHRESPONSE]);
 
@@ -345,17 +350,10 @@ UA_StatusCode Subscription_registerPublishJob(UA_Server *server, UA_Subscription
     UA_Job job = (UA_Job) {.type = UA_JOBTYPE_METHODCALL,
                            .job.methodCall = {.method = (UA_ServerCallback)UA_Subscription_publishCallback,
                                               .data = sub} };
-    UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                 "Adding a subscription with %i millisec interval", (int)sub->publishingInterval);
-    UA_StatusCode retval = UA_Server_addRepeatedJob(server, job,
-                                                    (UA_UInt32)sub->publishingInterval,
+    UA_StatusCode retval = UA_Server_addRepeatedJob(server, job, (UA_UInt32)sub->publishingInterval,
                                                     &sub->publishJobGuid);
     if(retval == UA_STATUSCODE_GOOD)
         sub->publishJobIsRegistered = true;
-    else
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                     "Could not register a subscription publication job " \
-                     "with status code 0x%08x\n", retval);
     return retval;
 }
 
@@ -363,12 +361,7 @@ UA_StatusCode Subscription_unregisterPublishJob(UA_Server *server, UA_Subscripti
     if(!sub->publishJobIsRegistered)
         return UA_STATUSCODE_GOOD;
     sub->publishJobIsRegistered = false;
-    UA_StatusCode retval = UA_Server_removeRepeatedJob(server, sub->publishJobGuid);
-    if(retval != UA_STATUSCODE_GOOD)
-        UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_SERVER,
-                     "Could not remove a subscription publication job " \
-                     "with status code 0x%08x\n", retval);
-    return retval;
+    return UA_Server_removeRepeatedJob(server, sub->publishJobGuid);
 }
 
 #endif /* UA_ENABLE_SUBSCRIPTIONS */

src/server/ua_subscription.h

@@ -67,10 +67,10 @@ typedef struct UA_NotificationMessageEntry {
 
 /* We use only a subset of the states defined in the standard */
 typedef enum {
-	/* UA_SUBSCRIPTIONSTATE_CLOSED */
-	/* UA_SUBSCRIPTIONSTATE_CREATING */
-	UA_SUBSCRIPTIONSTATE_NORMAL,
-	UA_SUBSCRIPTIONSTATE_LATE,
+    /* UA_SUBSCRIPTIONSTATE_CLOSED */
+    /* UA_SUBSCRIPTIONSTATE_CREATING */
+    UA_SUBSCRIPTIONSTATE_NORMAL,
+    UA_SUBSCRIPTIONSTATE_LATE,
     UA_SUBSCRIPTIONSTATE_KEEPALIVE
 } UA_SubscriptionState;
 
@@ -81,17 +81,18 @@ struct UA_Subscription {
     UA_Session *session;
     UA_UInt32 lifeTimeCount;
     UA_UInt32 maxKeepAliveCount;
-    UA_Double publishingInterval;     // [ms] 
+    UA_Double publishingInterval;     // [ms]
     UA_UInt32 subscriptionID;
     UA_UInt32 notificationsPerPublish;
     UA_Boolean publishingEnabled;
     UA_UInt32 priority;
-    UA_UInt32 sequenceNumber;
 
     /* Runtime information */
-	UA_SubscriptionState state;
+    UA_SubscriptionState state;
+    UA_UInt32 sequenceNumber;
     UA_UInt32 currentKeepAliveCount;
-	UA_UInt32 currentLifetimeCount;
+    UA_UInt32 currentLifetimeCount;
+    UA_UInt32 lastMonitoredItemId;
 
     /* Publish Job */
     UA_Guid publishJobGuid;

src/ua_securechannel.h

@@ -76,4 +76,37 @@ UA_ByteString UA_SecureChannel_finalizeChunk(UA_SecureChannel *channel, UA_UInt3
 
 void UA_SecureChannel_removeChunk(UA_SecureChannel *channel, UA_UInt32 requestId);
 
+/**
+ * Log Helper
+ * ---------- */
+#define UA_LOG_TRACE_CHANNEL(LOGGER, CHANNEL, MSG, ...)                 \
+    UA_LOG_TRACE(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                 (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                 CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
+#define UA_LOG_DEBUG_CHANNEL(LOGGER, CHANNEL, MSG, ...)                 \
+    UA_LOG_DEBUG(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                 (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                 CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
+#define UA_LOG_INFO_CHANNEL(LOGGER, CHANNEL, MSG, ...)                   \
+    UA_LOG_INFO(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
+#define UA_LOG_WARNING_CHANNEL(LOGGER, CHANNEL, MSG, ...)               \
+    UA_LOG_WARNING(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                   (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                   CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
+#define UA_LOG_ERROR_CHANNEL(LOGGER, CHANNEL, MSG, ...)                 \
+    UA_LOG_ERROR(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                 (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                 CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
+#define UA_LOG_FATAL_CHANNEL(LOGGER, CHANNEL, MSG, ...)                 \
+    UA_LOG_FATAL(LOGGER, UA_LOGCATEGORY_SECURECHANNEL, "Connection %i | SecureChannel %i | " MSG, \
+                 (CHANNEL->connection ? CHANNEL->connection->sockfd : 0), \
+                 CHANNEL->securityToken.channelId, ##__VA_ARGS__);
+
 #endif /* UA_SECURECHANNEL_H_ */

src/ua_session.c

@@ -33,7 +33,7 @@ void UA_Session_init(UA_Session *session) {
     LIST_INIT(&session->continuationPoints);
 #ifdef UA_ENABLE_SUBSCRIPTIONS
     LIST_INIT(&session->serverSubscriptions);
-    session->lastSubscriptionID = UA_UInt32_random();
+    session->lastSubscriptionID = 0;
     SIMPLEQ_INIT(&session->responseQueue);
 #endif
 }
@@ -80,14 +80,14 @@ void UA_Session_addSubscription(UA_Session *session, UA_Subscription *newSubscri
 
 UA_StatusCode
 UA_Session_deleteSubscription(UA_Server *server, UA_Session *session, UA_UInt32 subscriptionID) {
-    UA_Subscription *sub = UA_Session_getSubscriptionByID(session, subscriptionID);    
+    UA_Subscription *sub = UA_Session_getSubscriptionByID(session, subscriptionID);
     if(!sub)
         return UA_STATUSCODE_BADSUBSCRIPTIONIDINVALID;
     LIST_REMOVE(sub, listEntry);
     UA_Subscription_deleteMembers(sub, server);
     UA_free(sub);
     return UA_STATUSCODE_GOOD;
-} 
+}
 
 UA_Subscription *
 UA_Session_getSubscriptionByID(UA_Session *session, UA_UInt32 subscriptionID) {

src/ua_session.h

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