Merge pull request #619 from open62541/new_log

Improve logging

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

@@ -237,7 +237,7 @@ typedef struct {
     UA_ConnectionConfig conf;
     UA_UInt16 port;
     UA_Logger logger; // Set during start
-    
+
     /* open sockets and connections */
     UA_Int32 serversockfd;
     size_t mappingsSize;
@@ -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 | Force 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;
@@ -346,12 +346,13 @@ ServerNetworkLayerTCP_start(UA_ServerNetworkLayer *nl, UA_Logger logger) {
 #ifndef _MSC_VER
         du.length = (size_t)snprintf(discoveryUrl, 255, "opc.tcp://%s:%d", hostname, layer->port);
 #else
-        du.length = (size_t)_snprintf_s(discoveryUrl, 255, _TRUNCATE, "opc.tcp://%s:%d", hostname, layer->port);
+        du.length = (size_t)_snprintf_s(discoveryUrl, 255, _TRUNCATE,
+                                        "opc.tcp://%s:%d", hostname, layer->port);
 #endif
         du.data = (UA_Byte*)discoveryUrl;
     }
     UA_String_copy(&du, &nl->discoveryUrl);
-    
+
     /* open the server socket */
 #ifdef _WIN32
     if((layer->serversockfd = socket(PF_INET, SOCK_STREAM,0)) == (UA_Int32)INVALID_SOCKET) {
@@ -428,9 +429,10 @@ ServerNetworkLayerTCP_getJobs(UA_ServerNetworkLayer *nl, UA_Job **jobs, UA_UInt1
     size_t j = 0;
     UA_ByteString buf = UA_BYTESTRING_NULL;
     for(size_t i = 0; i < layer->mappingsSize && j < (size_t)resultsize; i++) {
-        if(!UA_fd_isset(layer->mappings[i].sockfd, &errset) && !UA_fd_isset(layer->mappings[i].sockfd, &fdset)) {
+        if(!UA_fd_isset(layer->mappings[i].sockfd, &errset) &&
+           !UA_fd_isset(layer->mappings[i].sockfd, &fdset))
           continue;
-        }
+
         UA_StatusCode retval = socket_recv(layer->mappings[i].connection, &buf, 0);
         if(retval == UA_STATUSCODE_GOOD) {
             js[j].job.binaryMessage.connection = layer->mappings[i].connection;
@@ -439,6 +441,8 @@ ServerNetworkLayerTCP_getJobs(UA_ServerNetworkLayer *nl, UA_Job **jobs, UA_UInt1
             j++;
         } else if (retval == UA_STATUSCODE_BADCONNECTIONCLOSED) {
             UA_Connection *c = layer->mappings[i].connection;
+            UA_LOG_INFO(layer->logger, UA_LOGCATEGORY_NETWORK,
+                        "Connection %i | Connection closed from remote", c->sockfd);
             /* the socket was closed from remote */
             js[j].type = UA_JOBTYPE_DETACHCONNECTION;
             js[j].job.closeConnection = layer->mappings[i].connection;
@@ -453,8 +457,8 @@ ServerNetworkLayerTCP_getJobs(UA_ServerNetworkLayer *nl, UA_Job **jobs, UA_UInt1
     }
 
     if(j == 0) {
-    	free(js);
-    	js = NULL;
+        free(js);
+        js = NULL;
     }
 
     *jobs = js;

src/client/ua_client.c

@@ -90,7 +90,7 @@ void UA_Client_delete(UA_Client* client){
 }
 
 UA_ClientState UA_EXPORT UA_Client_getState(UA_Client *client) {
-    if (client == NULL)
+    if(!client)
         return UA_CLIENTSTATE_ERRORED;
     return client->state;
 }
@@ -329,14 +329,14 @@ static UA_StatusCode ActivateSession(UA_Client *client) {
     request.requestHeader.timeoutHint = 600000;
 
     //manual ExtensionObject encoding of the identityToken
-    if(client->authenticationMethod == UA_CLIENTAUTHENTICATION_NONE){
+    if(client->authenticationMethod == UA_CLIENTAUTHENTICATION_NONE) {
         UA_AnonymousIdentityToken* identityToken = UA_malloc(sizeof(UA_AnonymousIdentityToken));
         UA_AnonymousIdentityToken_init(identityToken);
         UA_String_copy(&client->token.policyId, &identityToken->policyId);
         request.userIdentityToken.encoding = UA_EXTENSIONOBJECT_DECODED;
         request.userIdentityToken.content.decoded.type = &UA_TYPES[UA_TYPES_ANONYMOUSIDENTITYTOKEN];
         request.userIdentityToken.content.decoded.data = identityToken;
-    }else{
+    } else {
         UA_UserNameIdentityToken* identityToken = UA_malloc(sizeof(UA_UserNameIdentityToken));
         UA_UserNameIdentityToken_init(identityToken);
         UA_String_copy(&client->token.policyId, &identityToken->policyId);
@@ -522,19 +522,20 @@ static UA_StatusCode CloseSecureChannel(UA_Client *client) {
     retval |= UA_SymmetricAlgorithmSecurityHeader_encodeBinary(&symHeader, &message, &offset);
     retval |= UA_SequenceHeader_encodeBinary(&seqHeader, &message, &offset);
     retval |= UA_NodeId_encodeBinary(&typeId, &message, &offset);
-    retval |= UA_encodeBinary(&request, &UA_TYPES[UA_TYPES_CLOSESECURECHANNELREQUEST],NULL,NULL, &message, &offset);
+    retval |= UA_encodeBinary(&request, &UA_TYPES[UA_TYPES_CLOSESECURECHANNELREQUEST], NULL,
+                              NULL, &message, &offset);
 
     msgHeader.messageHeader.messageSize = (UA_UInt32)offset;
     offset = 0;
     retval |= UA_SecureConversationMessageHeader_encodeBinary(&msgHeader, &message, &offset);
 
-    if(retval != UA_STATUSCODE_GOOD) {
+    if(retval == UA_STATUSCODE_GOOD) {
+        message.length = msgHeader.messageHeader.messageSize;
+        retval = client->connection.send(&client->connection, &message);
+    } else {
         client->connection.releaseSendBuffer(&client->connection, &message);
-        return retval;
     }
-
-    message.length = msgHeader.messageHeader.messageSize;
-    retval = client->connection.send(&client->connection, &message);
+    client->connection.close(&client->connection);
     return retval;
 }
 
@@ -549,7 +550,8 @@ UA_Client_getEndpoints(UA_Client *client, const char *serverUrl,
 
 
     UA_StatusCode retval = UA_STATUSCODE_GOOD;
-    client->connection = client->config.connectionFunc(UA_ConnectionConfig_standard, serverUrl, client->config.logger);
+    client->connection = client->config.connectionFunc(UA_ConnectionConfig_standard, serverUrl,
+                                                       client->config.logger);
     if(client->connection.state != UA_CONNECTION_OPENING) {
         retval = UA_STATUSCODE_BADCONNECTIONCLOSED;
         goto cleanup;
@@ -570,6 +572,7 @@ UA_Client_getEndpoints(UA_Client *client, const char *serverUrl,
 
     /* always cleanup */
     cleanup:
+    UA_Client_disconnect(client);
     UA_Client_reset(client);
     return retval;
 }
@@ -629,13 +632,16 @@ UA_Client_connect(UA_Client *client, const char *endpointUrl) {
 }
 
 UA_StatusCode UA_Client_disconnect(UA_Client *client) {
+    if(client->state != UA_CLIENTSTATE_CONNECTED)
+        return UA_STATUSCODE_BADNOTCONNECTED;
     UA_StatusCode retval = UA_STATUSCODE_GOOD;
-    //is a session established?
-    if(client->state == UA_CLIENTSTATE_CONNECTED && client->channel.connection->state == UA_CONNECTION_ESTABLISHED)
+    /* Is a session established? */
+    if(client->channel.connection->state == UA_CONNECTION_ESTABLISHED &&
+       !UA_NodeId_equal(&client->authenticationToken, &UA_NODEID_NULL))
         retval = CloseSession(client);
-    //is a secure channel established?
-    if(retval == UA_STATUSCODE_GOOD && client->channel.connection->state == UA_CONNECTION_ESTABLISHED)
-        retval = CloseSecureChannel(client);
+    /* Is a secure channel established? */
+    if(client->channel.connection->state == UA_CONNECTION_ESTABLISHED)
+        retval |= CloseSecureChannel(client);
     return retval;
 }
 

src/client/ua_client_internal.h

@@ -68,7 +68,6 @@ struct UA_Client {
 
     /* Session */
     UA_UserTokenPolicy token;
-    UA_NodeId sessionId;
     UA_NodeId authenticationToken;
     UA_UInt32 requestHandle;
     

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
@@ -106,13 +105,11 @@ UA_SecureChannelManager_renew(UA_SecureChannelManager *cm, UA_Connection *conn,
     /* if no security token is already issued */
     if(channel->nextSecurityToken.tokenId == 0) {
         channel->nextSecurityToken.channelId = channel->securityToken.channelId;
-        //FIXME: UaExpert seems not to use the new tokenid
         channel->nextSecurityToken.tokenId = cm->lastTokenId++;
-        //channel->nextSecurityToken.tokenId = channel->securityToken.tokenId;
         channel->nextSecurityToken.createdAt = UA_DateTime_now();
         channel->nextSecurityToken.revisedLifetime =
-                (request->requestedLifetime > cm->server->config.maxSecurityTokenLifetime) ?
-                        cm->server->config.maxSecurityTokenLifetime : request->requestedLifetime;
+            (request->requestedLifetime > cm->server->config.maxSecurityTokenLifetime) ?
+            cm->server->config.maxSecurityTokenLifetime : request->requestedLifetime;
         /* lifetime 0 -> return the max lifetime */
         if(channel->nextSecurityToken.revisedLifetime == 0)
             channel->nextSecurityToken.revisedLifetime = cm->server->config.maxSecurityTokenLifetime;
@@ -139,18 +136,20 @@ UA_SecureChannel * UA_SecureChannelManager_get(UA_SecureChannelManager *cm, UA_U
 UA_StatusCode UA_SecureChannelManager_close(UA_SecureChannelManager *cm, UA_UInt32 channelId) {
     channel_list_entry *entry;
     LIST_FOREACH(entry, &cm->channels, pointers) {
-        if(entry->channel.securityToken.channelId == channelId) {
-            LIST_REMOVE(entry, pointers);
-            UA_SecureChannel_deleteMembersCleanup(&entry->channel);
+        if(entry->channel.securityToken.channelId == channelId)
+            break;
+    }
+    if(!entry)
+        return UA_STATUSCODE_BADINTERNALERROR;
+
+    LIST_REMOVE(entry, pointers);
+    UA_SecureChannel_deleteMembersCleanup(&entry->channel);
 #ifndef UA_ENABLE_MULTITHREADING
-            cm->currentChannelCount--;
-            UA_free(entry);
+    cm->currentChannelCount--;
+    UA_free(entry);
 #else
-            cm->currentChannelCount = uatomic_add_return(&cm->currentChannelCount, -1);
-            UA_Server_delayedFree(cm->server, entry);
+    cm->currentChannelCount = uatomic_add_return(&cm->currentChannelCount, -1);
+    UA_Server_delayedFree(cm->server, entry);
 #endif
-            return UA_STATUSCODE_GOOD;
-        }
-    }
-    return UA_STATUSCODE_BADINTERNALERROR;
+    return UA_STATUSCODE_GOOD;
 }

src/server/ua_server_binary.c

@@ -17,19 +17,20 @@ static void init_response_header(const UA_RequestHeader *p, UA_ResponseHeader *r
 }
 
 static void
-sendError(UA_SecureChannel *channel, const UA_ByteString *msg, size_t pos,
+sendError(UA_SecureChannel *channel, const UA_ByteString *msg, size_t pos, const UA_DataType *responseType,
           UA_UInt32 requestId, UA_StatusCode error) {
-    UA_RequestHeader p;
-    if(UA_RequestHeader_decodeBinary(msg, &pos, &p) != UA_STATUSCODE_GOOD)
+    UA_RequestHeader requestHeader;
+    UA_StatusCode retval = UA_RequestHeader_decodeBinary(msg, &pos, &requestHeader);
+    if(retval != UA_STATUSCODE_GOOD)
         return;
-    UA_ResponseHeader r;
-    UA_ResponseHeader_init(&r);
-    init_response_header(&p, &r);
-    r.serviceResult = error;
-    UA_SecureChannel_sendBinaryMessage(channel, requestId, &r,
-                                       &UA_TYPES[UA_TYPES_SERVICEFAULT]);
-    UA_RequestHeader_deleteMembers(&p);
-    UA_ResponseHeader_deleteMembers(&r);
+    void *response = UA_alloca(responseType->memSize);
+    UA_init(response, responseType);
+    UA_ResponseHeader *responseHeader = (UA_ResponseHeader*)response;
+    init_response_header(&requestHeader, responseHeader);
+    responseHeader->serviceResult = error;
+    UA_SecureChannel_sendBinaryMessage(channel, requestId, response, responseType);
+    UA_RequestHeader_deleteMembers(&requestHeader);
+    UA_ResponseHeader_deleteMembers(responseHeader);
 }
 
 /* Returns a complete decoded request (without securechannel headers + padding)
@@ -41,41 +42,45 @@ 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;
 }
 
 static void
 getServicePointers(UA_UInt32 requestTypeId, const UA_DataType **requestType,
-                   const UA_DataType **responseType, UA_Service *service) {
+                   const UA_DataType **responseType, UA_Service *service,
+                   UA_Boolean *requiresSession) {
     switch(requestTypeId - UA_ENCODINGOFFSET_BINARY) {
     case UA_NS0ID_GETENDPOINTSREQUEST:
         *service = (UA_Service)Service_GetEndpoints;
         *requestType = &UA_TYPES[UA_TYPES_GETENDPOINTSREQUEST];
         *responseType = &UA_TYPES[UA_TYPES_GETENDPOINTSRESPONSE];
+        *requiresSession = false;
         break;
     case UA_NS0ID_FINDSERVERSREQUEST:
         *service = (UA_Service)Service_FindServers;
         *requestType = &UA_TYPES[UA_TYPES_FINDSERVERSREQUEST];
         *responseType = &UA_TYPES[UA_TYPES_FINDSERVERSRESPONSE];
+        *requiresSession = false;
         break;
     case UA_NS0ID_CREATESESSIONREQUEST:
         *service = (UA_Service)Service_CreateSession;
         *requestType = &UA_TYPES[UA_TYPES_CREATESESSIONREQUEST];
         *responseType = &UA_TYPES[UA_TYPES_CREATESESSIONRESPONSE];
+        *requiresSession = false;
         break;
     case UA_NS0ID_ACTIVATESESSIONREQUEST:
         *service = (UA_Service)Service_ActivateSession;
@@ -244,8 +249,7 @@ static void processHEL(UA_Connection *connection, const UA_ByteString *msg, size
 
     UA_ByteString ack_msg;
     UA_ByteString_init(&ack_msg);
-    if(connection->getSendBuffer(connection, connection->localConf.sendBufferSize,
-                                 &ack_msg) != UA_STATUSCODE_GOOD)
+    if(connection->getSendBuffer(connection, connection->localConf.sendBufferSize, &ack_msg) != UA_STATUSCODE_GOOD)
         return;
 
     size_t tmpPos = 0;
@@ -318,8 +322,7 @@ static void processOPN(UA_Connection *connection, UA_Server *server, const UA_By
     respHeader.messageHeader.messageSize = 0;
     respHeader.secureChannelId = p.securityToken.channelId;
 
-    UA_NodeId responseType = UA_NODEID_NUMERIC(0, UA_NS0ID_OPENSECURECHANNELRESPONSE +
-                                               UA_ENCODINGOFFSET_BINARY);
+    UA_NodeId responseType = UA_NODEID_NUMERIC(0, UA_NS0ID_OPENSECURECHANNELRESPONSE + UA_ENCODINGOFFSET_BINARY);
 
     UA_ByteString resp_msg;
     UA_ByteString_init(&resp_msg);
@@ -356,103 +359,112 @@ processRequest(UA_SecureChannel *channel, UA_Server *server, UA_UInt32 requestId
     size_t ppos = 0;
     size_t *pos = &ppos;
 
+    /* Decode the nodeid */
     UA_NodeId requestTypeId;
     UA_StatusCode retval = UA_NodeId_decodeBinary(msg, pos, &requestTypeId);
-    if(retval != UA_STATUSCODE_GOOD) {
-        sendError(channel, msg, *pos, requestId, retval);
+    if(retval != UA_STATUSCODE_GOOD)
         return;
-    }
+
+    /* Store the start-position of the request */
+    size_t requestPos = *pos;
 
     /* Test if the service type nodeid has the right format */
     if(requestTypeId.identifierType != UA_NODEIDTYPE_NUMERIC ||
        requestTypeId.namespaceIndex != 0) {
         UA_NodeId_deleteMembers(&requestTypeId);
-        sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSERVICEUNSUPPORTED);
-        return;
+        sendError(channel, msg, requestPos, &UA_TYPES[UA_TYPES_SERVICEFAULT], requestId, UA_STATUSCODE_BADSERVICEUNSUPPORTED);
     }
 
     /* Get the service pointers */
     UA_Service service = NULL;
     const UA_DataType *requestType = NULL;
     const UA_DataType *responseType = NULL;
-    getServicePointers(requestTypeId.identifier.numeric, &requestType, &responseType, &service);
+    UA_Boolean sessionRequired = true;
+    getServicePointers(requestTypeId.identifier.numeric, &requestType, &responseType, &service, &sessionRequired);
     if(!requestType) {
-        /* The service is not supported */
-        if(requestTypeId.identifier.numeric==787)
-            UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_SERVER,
-                        "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);
-        sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSERVICEUNSUPPORTED);
+        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");
+        } else {
+            UA_LOG_INFO_CHANNEL(server->config.logger, channel, "Unknown request %i", requestTypeId.identifier.numeric - UA_ENCODINGOFFSET_BINARY);
+        }
+        sendError(channel, msg, requestPos, &UA_TYPES[UA_TYPES_SERVICEFAULT], requestId, UA_STATUSCODE_BADSERVICEUNSUPPORTED);
         return;
     }
+    UA_assert(responseType);
 
-    /* Most services can only be called with a valid securechannel */
-#ifndef UA_ENABLE_NONSTANDARD_STATELESS
-    if(channel->securityToken.channelId == 0 &&
-       requestType->typeIndex > UA_TYPES_OPENSECURECHANNELREQUEST) {
-        sendError(channel, msg, *pos, requestId, UA_STATUSCODE_BADSECURECHANNELIDINVALID);
-        return;
-    }
+#ifdef UA_ENABLE_NONSTANDARD_STATELESS
+    /* Stateless extension: Sessions are optional */
+    sessionRequired = false;
 #endif
 
     /* Decode the request */
     void *request = UA_alloca(requestType->memSize);
-    size_t oldpos = *pos;
+    UA_RequestHeader *requestHeader = (UA_RequestHeader*)request;
     retval = UA_decodeBinary(msg, pos, request, requestType);
     if(retval != UA_STATUSCODE_GOOD) {
-        sendError(channel, msg, oldpos, requestId, retval);
+        sendError(channel, msg, requestPos, &UA_TYPES[UA_TYPES_SERVICEFAULT], requestId, retval);
         return;
     }
 
+    /* Prepare the respone */
+    void *response = UA_alloca(responseType->memSize);
+    UA_init(response, responseType);
+
     /* Find the matching session */
-    UA_Session *session =
-        UA_SecureChannel_getSession(channel, &((UA_RequestHeader*)request)->authenticationToken);
+    UA_Session *session = UA_SecureChannel_getSession(channel, &requestHeader->authenticationToken);
+
+    /* CreateSession and ActivateSession don't need a session */
+    if(requestType == &UA_TYPES[UA_TYPES_CREATESESSIONREQUEST]) {
+        Service_CreateSession(server, channel, request, response);
+        goto send_response;
+    }
+    if(requestType == &UA_TYPES[UA_TYPES_ACTIVATESESSIONREQUEST]) {
+        /* Search in all sessions, not only those of the channel */
+        if(!session)
+            session = UA_SessionManager_getSession(&server->sessionManager, &requestHeader->authenticationToken);
+        if(!session) {
+            sendError(channel, msg, requestPos, responseType, requestId, UA_STATUSCODE_BADSESSIONIDINVALID);
+            UA_deleteMembers(request, requestType);
+            return;
+        }
+        Service_ActivateSession(server, channel, session, request, response);
+        goto send_response;
+    }
+
+    /* Test if the session is valid */
     UA_Session anonymousSession;
     if(!session) {
-        /* session id 0 -> anonymous session */
+        if(sessionRequired || !UA_NodeId_equal(&requestHeader->authenticationToken, &UA_NODEID_NULL)) {
+            UA_LOG_INFO_CHANNEL(server->config.logger, channel, "Service request %i without a valid session",
+                                requestTypeId.identifier.numeric - UA_ENCODINGOFFSET_BINARY);
+            sendError(channel, msg, requestPos, responseType, requestId, UA_STATUSCODE_BADSESSIONIDINVALID);
+            UA_deleteMembers(request, requestType);
+            return;
+        }
+
+        /* Set an anonymous, inactive session */
         UA_Session_init(&anonymousSession);
         anonymousSession.sessionId = UA_NODEID_NUMERIC(0,0);
         anonymousSession.channel = channel;
-        anonymousSession.activated = true;
         session = &anonymousSession;
     }
 
-    /* Test if the session is valid */
-    if(!session->activated &&
-       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 with 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);
+    /* Trying to use a non-activated session? */
+    if(!session->activated && sessionRequired) {
+        UA_LOG_INFO_SESSION(server->config.logger, session, "Calling service %i on a non-activated session",
+                            requestTypeId.identifier.numeric - UA_ENCODINGOFFSET_BINARY);
+        sendError(channel, msg, requestPos, responseType, requestId, UA_STATUSCODE_BADSESSIONNOTACTIVATED);
+        UA_SessionManager_removeSession(&server->sessionManager, &session->authenticationToken);
+        UA_deleteMembers(request, requestType);
         return;
     }
-#endif
 
     /* Update the session lifetime */
     UA_Session_updateLifetime(session);
 
 #ifdef UA_ENABLE_SUBSCRIPTIONS
     /* The publish request is not answered immediately */
-    if(requestTypeId.identifier.numeric - UA_ENCODINGOFFSET_BINARY == UA_NS0ID_PUBLISHREQUEST) {
+    if(requestType == &UA_TYPES[UA_TYPES_PUBLISHREQUEST]) {
         Service_Publish(server, session, request, requestId);
         UA_deleteMembers(request, requestType);
         return;
@@ -460,21 +472,14 @@ 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);
-    void *response = UA_alloca(responseType->memSize);
-    UA_init(response, responseType);
     service(server, session, request, response);
 
+ send_response:
     /* Send the response */
     init_response_header(request, response);
     retval = UA_SecureChannel_sendBinaryMessage(channel, requestId, response, responseType);
     if(retval != UA_STATUSCODE_GOOD)
-        sendError(channel, msg, oldpos, requestId, retval);
+        sendError(channel, msg, requestPos, &UA_TYPES[UA_TYPES_SERVICEFAULT], requestId, retval);
 
     /* Clean up */
     UA_deleteMembers(request, requestType);
@@ -486,32 +491,37 @@ static void
 processMSG(UA_Connection *connection, UA_Server *server, const UA_TcpMessageHeader *messageHeader,
            const UA_ByteString *msg, size_t *pos) {
     /* Decode the header */
-    UA_UInt32 secureChannelId = 0;
+    UA_UInt32 channelId = 0;
     UA_UInt32 tokenId = 0;
     UA_SequenceHeader sequenceHeader;
-    UA_StatusCode retval = UA_UInt32_decodeBinary(msg, pos, &secureChannelId);
+    UA_StatusCode retval = UA_UInt32_decodeBinary(msg, pos, &channelId);
     retval |= UA_UInt32_decodeBinary(msg, pos, &tokenId);
     retval |= UA_SequenceHeader_decodeBinary(msg, pos, &sequenceHeader);
     if(retval != UA_STATUSCODE_GOOD)
         return;
 
-    /* Set the SecureChannel, channelid = 0 -> anonymous channel */
+    /* Get the SecureChannel */
     UA_SecureChannel *channel = connection->channel;
-    UA_SecureChannel anonymousChannel;
+    UA_SecureChannel anonymousChannel; /* use if no channel specified */
     if(!channel) {
         UA_SecureChannel_init(&anonymousChannel);
         anonymousChannel.connection = connection;
         channel = &anonymousChannel;
     }
-    if(secureChannelId != channel->securityToken.channelId) /* Not the channel we expected */
-        return;
+
+    /* Is the channel attached to connection? */
+    if(channelId != channel->securityToken.channelId) {
+        UA_LOG_INFO(server->config.logger, UA_LOGCATEGORY_NETWORK,
+                    "Connection %i | Received MSG with the channel id not bound to the connection", connection->sockfd);
+        Service_CloseSecureChannel(server, channel);
+    }
+
+    /* Does the token match? */
     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);
@@ -522,13 +532,16 @@ processMSG(UA_Connection *connection, UA_Server *server, const UA_TcpMessageHead
     UA_ByteString request = processChunk(channel, server, messageHeader, sequenceHeader.requestId,
                                          msg, *pos, messageHeader->messageSize - 24, &deleteRequest);
     *pos += (messageHeader->messageSize - 24);
-    if(request.length == 0)
-        return;
+    if(request.length > 0) {
+        /* Process the request */
+        processRequest(channel, server, sequenceHeader.requestId, &request);
+        if(deleteRequest)
+            UA_ByteString_deleteMembers(&request);
+    }
 
-    /* Process the request */
-    processRequest(channel, server, sequenceHeader.requestId, &request);
-    if(deleteRequest)
-        UA_ByteString_deleteMembers(&request);
+    /* Clean up a possible anonymous channel */
+    if(channel == &anonymousChannel)
+        UA_SecureChannel_deleteMembersCleanup(channel);
 }
 
 /* CLO -> Close the secure channel */
@@ -539,7 +552,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
@@ -570,12 +583,12 @@ void UA_Server_processBinaryMessage(UA_Server *server, UA_Connection *connection
         /* Process the message */
         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);
+            UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_NETWORK, "Connection %i | Process a HEL", connection->sockfd);
             processHEL(connection, msg, &pos);
             break;
 
         case UA_MESSAGETYPE_OPN:
+            UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_NETWORK, "Connection %i | Process a OPN", connection->sockfd);
             processOPN(connection, server, msg, &pos);
             break;
 
@@ -583,33 +596,29 @@ 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->sockfd);
+                             "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);
+            UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_NETWORK, "Connection %i | Process a MSG", connection->sockfd);
             processMSG(connection, server, &tcpMessageHeader, msg, &pos);
             break;
 
         case UA_MESSAGETYPE_CLO:
+            UA_LOG_TRACE(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);
+            UA_LOG_TRACE(server->config.logger, UA_LOGCATEGORY_NETWORK, "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. "
-                        "Arrived at position %i, skip after the announced length to position %i",
-                        connection->sockfd, pos, targetpos);
+            UA_LOG_DEBUG(server->config.logger, UA_LOGCATEGORY_NETWORK, "Connection %i | Message was not entirely processed. "
+                         "Skip from position %i to position %i; message length is %i", connection->sockfd, pos, targetpos,
+                         msg->length);
             pos = targetpos;
         }
     } while(msg->length > pos);

src/server/ua_server_internal.h

@@ -16,9 +16,9 @@
 /** Mapping of namespace-id and url to an external nodestore. For namespaces
     that have no mapping defined, the internal nodestore is used by default. */
 typedef struct UA_ExternalNamespace {
-	UA_UInt16 index;
-	UA_String url;
-	UA_ExternalNodeStore externalNodeStore;
+    UA_UInt16 index;
+    UA_String url;
+    UA_ExternalNodeStore externalNodeStore;
 } UA_ExternalNamespace;
 #endif
 
@@ -59,13 +59,13 @@ struct UA_Server {
     
 #ifdef UA_ENABLE_MULTITHREADING
     /* Dispatch queue head for the worker threads (the tail should not be in the same cache line) */
-	struct cds_wfcq_head dispatchQueue_head;
+    struct cds_wfcq_head dispatchQueue_head;
     UA_Worker *workers; /* there are nThread workers in a running server */
     struct cds_lfs_stack mainLoopJobs; /* Work that shall be executed only in the main loop and not
                                           by worker threads */
     struct DelayedJobs *delayedJobs;
     pthread_cond_t dispatchQueue_condition; /* so the workers don't spin if the queue is empty */
-	struct cds_wfcq_tail dispatchQueue_tail; /* Dispatch queue tail for the worker threads */
+    struct cds_wfcq_tail dispatchQueue_tail; /* Dispatch queue tail for the worker threads */
 #endif
 
     /* Config is the last element so that MSVC allows the usernamePasswordLogins

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
@@ -67,7 +67,7 @@ void Service_CloseSecureChannel(UA_Server *server, UA_UInt32 channelId);
  * which is used to identify the Session in the audit logs and in the Server's
  * address space. The second is the authenticationToken which is used to
  * associate an incoming request with a Session. */
-void Service_CreateSession(UA_Server *server, UA_Session *session,
+void Service_CreateSession(UA_Server *server, UA_SecureChannel *channel,
                            const UA_CreateSessionRequest *request,
                            UA_CreateSessionResponse *response);
 
@@ -76,8 +76,8 @@ void Service_CreateSession(UA_Server *server, UA_Session *session,
  * Session. This Service request shall be issued by the Client before it issues
  * any other Service request after CreateSession. Failure to do so shall cause
  * the Server to close the Session. */
-void Service_ActivateSession(UA_Server *server, UA_Session *session,
-                             const UA_ActivateSessionRequest *request,
+void Service_ActivateSession(UA_Server *server, UA_SecureChannel *channel,
+                             UA_Session *session, const UA_ActivateSessionRequest *request,
                              UA_ActivateSessionResponse *response);
 
 /* Used to terminate a Session. */

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,11 +693,7 @@ 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_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);
-
+    UA_LOG_DEBUG_SESSION(server->config.logger, session, "Processing WriteRequest");
     if(request->nodesToWriteSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -738,6 +732,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

@@ -3,9 +3,8 @@
 #include "ua_session_manager.h"
 #include "ua_types_generated_encoding_binary.h"
 
-void Service_CreateSession(UA_Server *server, UA_Session *session, const UA_CreateSessionRequest *request,
-                           UA_CreateSessionResponse *response) {
-    UA_SecureChannel *channel = session->channel;
+void Service_CreateSession(UA_Server *server, UA_SecureChannel *channel,
+                           const UA_CreateSessionRequest *request, UA_CreateSessionResponse *response) {
     if(channel->securityToken.channelId == 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSECURECHANNELIDINVALID;
         return;
@@ -17,14 +16,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,57 +32,36 @@ 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_CHANNEL(server->config.logger, channel, "Session %i created",
+                         newSession->sessionId.identifier.numeric);
 }
 
 void
-Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_ActivateSessionRequest *request,
-                        UA_ActivateSessionResponse *response) {
-    UA_SecureChannel *channel = session->channel;
-    // make the channel know about the session
-	UA_Session *foundSession =
-        UA_SessionManager_getSession(&server->sessionManager, &request->requestHeader.authenticationToken);
-
-	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);
-        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);
+Service_ActivateSession(UA_Server *server, UA_SecureChannel *channel, UA_Session *session,
+                        const UA_ActivateSessionRequest *request, UA_ActivateSessionResponse *response) {
+    if(session->validTill < UA_DateTime_now()) {
+        UA_LOG_INFO_SESSION(server->config.logger, session, "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, session, "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 +81,17 @@ Service_ActivateSession(UA_Server *server, UA_Session *session, const UA_Activat
             response->responseHeader.serviceResult = UA_STATUSCODE_BADIDENTITYTOKENINVALID;
             return;
         }
-        if(foundSession->channel && foundSession->channel != channel)
-            UA_SecureChannel_detachSession(foundSession->channel, foundSession);
-        UA_SecureChannel_attachSession(channel, foundSession);
-        foundSession->activated = true;
-        UA_Session_updateLifetime(foundSession);
+        if(session->channel && session->channel != channel) {
+            /* Close the old SecureChannel (this also detaches it) */
+            UA_LOG_INFO_SESSION(server->config.logger, session,
+                                "ActivateSession: Detach from old channel");
+            UA_SecureChannelManager_close(&server->secureChannelManager,
+                                          session->channel->securityToken.channelId);
+        }
+        UA_SecureChannel_attachSession(channel, session);
+        session->activated = true;
+        UA_Session_updateLifetime(session);
+        UA_LOG_INFO_SESSION(server->config.logger, session, "ActivateSession: Session activated");
         return;
     }
 
@@ -133,14 +115,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)
-                UA_SecureChannel_detachSession(foundSession->channel, foundSession);
-            UA_SecureChannel_attachSession(channel, foundSession);
-            foundSession->activated = true;
-            UA_Session_updateLifetime(foundSession);
+            if(session->channel && session->channel != channel) {
+                UA_LOG_INFO_SESSION(server->config.logger, session,
+                                    "ActivateSession: Detach from old channel");
+                UA_SecureChannel_detachSession(session->channel, session);
+            }
+            UA_SecureChannel_attachSession(channel, session);
+            session->activated = true;
+            UA_Session_updateLifetime(session);
+            UA_LOG_INFO_SESSION(server->config.logger, session, "ActivateSession: Session activated");
             return;
         }
         /* no match */
+        UA_LOG_INFO_SESSION(server->config.logger, session,
+                            "ActivateSession: Did not find matching username/password");
         response->responseHeader.serviceResult = UA_STATUSCODE_BADUSERACCESSDENIED;
         return;
     }
@@ -150,9 +138,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.c

@@ -29,11 +29,9 @@ void UA_SecureChannel_deleteMembersCleanup(UA_SecureChannel *channel) {
     UA_ChannelSecurityToken_deleteMembers(&channel->securityToken);
     UA_ChannelSecurityToken_deleteMembers(&channel->nextSecurityToken);
     UA_Connection *c = channel->connection;
-    if(c) {
+    if(c)
         UA_Connection_detachSecureChannel(c);
-        if(c->close)
-            c->close(c);
-    }
+
     /* just remove the pointers and free the linked list (not the sessions) */
     struct SessionEntry *se, *temp;
     LIST_FOREACH_SAFE(se, &channel->sessions, pointers, temp) {

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