add many log messages for log-level DEBUG. simplify stdout logger

examples/client.c

@@ -20,9 +20,9 @@ void handler_TheAnswerChanged(UA_UInt32 handle, UA_DataValue *value) {
 }
 
 int main(int argc, char *argv[]) {
-    UA_Client *client = UA_Client_new(UA_ClientConfig_standard, Logger_Stdout_new());
+    UA_Client *client = UA_Client_new(UA_ClientConfig_standard, Logger_Stdout);
     UA_StatusCode retval = UA_Client_connect(client, ClientNetworkLayerTCP_connect,
-                                             "opc.tcp://localhost:16664");
+                                             "opc.tcp://virtualbox:16663");
 
     if(retval != UA_STATUSCODE_GOOD) {
         UA_Client_delete(client);

examples/client_firstSteps.c

@@ -13,7 +13,7 @@
 #endif
 
 int main(void) {
-    UA_Client *client = UA_Client_new(UA_ClientConfig_standard, Logger_Stdout_new());
+    UA_Client *client = UA_Client_new(UA_ClientConfig_standard, Logger_Stdout);
     UA_StatusCode retval = UA_Client_connect(client, ClientNetworkLayerTCP_connect, "opc.tcp://localhost:16664");
     if(retval != UA_STATUSCODE_GOOD) {
         UA_Client_delete(client);

examples/logger_stdout.c

@@ -7,35 +7,26 @@
 #include <stdarg.h>
 #include "logger_stdout.h"
 
-static void print_time(void) {
-	UA_DateTime now = UA_DateTime_now();
-	UA_ByteString str;
-	UA_DateTime_toString(now, &str);
-	printf("%.27s", str.data); //a bit hacky way not to display nanoseconds
-	UA_ByteString_deleteMembers(&str);
-}
-
 const char *LogLevelNames[6] = {"trace", "debug", "info", "warning", "error", "fatal"};
-const char *LogCategoryNames[4] = {"communication", "server", "client", "userland"};
+const char *LogCategoryNames[6] = {"network", "channel", "session", "server", "client", "userland"};
 
 #if ((__GNUC__ == 4 && __GNUC_MINOR__ >= 6) || __GNUC__ > 4 || defined(__clang__))
 #pragma GCC diagnostic push
 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
 #endif
-static void Logger_Stdout(UA_LogLevel level, UA_LogCategory category, const char *msg, ...) {
-    printf("[");
-    print_time();
+
+void Logger_Stdout(UA_LogLevel level, UA_LogCategory category, const char *msg, ...) {
+	UA_String time;
+	UA_DateTime_toString(UA_DateTime_now(), &time);
+    printf("[%.23s] %s/%s\t", time.data, LogLevelNames[level], LogCategoryNames[category]);
+	UA_ByteString_deleteMembers(&time);
     va_list ap;
     va_start(ap, msg);
-    printf("] %s/%s\t", LogLevelNames[level], LogCategoryNames[category]);
     vprintf(msg, ap);
-    printf("\n");
     va_end(ap);
+    printf("\n");
 }
+
 #if ((__GNUC__ == 4 && __GNUC_MINOR__ >= 6) || __GNUC__ > 4 || defined(__clang__))
 #pragma GCC diagnostic pop
 #endif
-
-UA_Logger Logger_Stdout_new(void) {
-	return Logger_Stdout;
-}

examples/logger_stdout.h

@@ -13,8 +13,7 @@
 extern "C" {
 #endif
 
-/** Initialises the logger for the current thread. */
-UA_EXPORT UA_Logger Logger_Stdout_new(void);
+UA_EXPORT void Logger_Stdout(UA_LogLevel level, UA_LogCategory category, const char *msg, ...);
 
 #ifdef __cplusplus
 }

examples/networklayer_tcp.c

@@ -235,18 +235,11 @@ static void ServerNetworkLayerTCP_closeConnection(UA_Connection *connection) {
     connection->state = UA_CONNECTION_CLOSED;
 #endif
     ServerNetworkLayerTCP *layer = connection->handle;
-    struct sockaddr_in addr;
-    socklen_t addrlen = sizeof(struct sockaddr_in);
-    int gsn_result = getsockname(connection->sockfd, (struct sockaddr*)&addr, &addrlen);
-    if(gsn_result == 0)
-        UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Closing the connection from %s:%d",
-                    inet_ntoa(addr.sin_addr), ntohs(addr.sin_port));
-    else
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION,
-                       "Closing the connection on socket %d, but could not resolve the name",
-                       connection->sockfd);
-    shutdown(connection->sockfd, 2); /* only shut down here. this triggers the select, where the socket
-                                        is closed in the main thread */
+    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Closing the Connection %i",
+                connection->sockfd);
+    /* only "shutdown" here. this triggers the select, where the socket is
+       "closed" in the mainloop */
+    shutdown(connection->sockfd, 2);
 }
 
 /* call only from the single networking thread */
@@ -257,13 +250,9 @@ static UA_StatusCode ServerNetworkLayerTCP_add(ServerNetworkLayerTCP *layer, UA_
 
     struct sockaddr_in addr;
     socklen_t addrlen = sizeof(struct sockaddr_in);
-    int gsn_result = getsockname(newsockfd, (struct sockaddr*)&addr, &addrlen);
-    if(gsn_result == 0)
-        UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "New connection from %s:%d",
-                    inet_ntoa(addr.sin_addr), ntohs(addr.sin_port));
-    else
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION,
-                       "Could not get the connection name on the new socket %d", newsockfd);
+    getsockname(newsockfd, (struct sockaddr*)&addr, &addrlen);
+    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "New Connection %i over TCP from %s:%d",
+                newsockfd, inet_ntoa(addr.sin_addr), ntohs(addr.sin_port));
     UA_Connection_init(c);
     c->sockfd = newsockfd;
     c->handle = layer;
@@ -277,7 +266,7 @@ static UA_StatusCode ServerNetworkLayerTCP_add(ServerNetworkLayerTCP *layer, UA_
     struct ConnectionMapping *nm;
     nm = realloc(layer->mappings, sizeof(struct ConnectionMapping)*(layer->mappingsSize+1));
     if(!nm) {
-        UA_LOG_ERROR(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "No memory for a new connection");
+        UA_LOG_ERROR(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "No memory for a new Connection");
         free(c);
         return UA_STATUSCODE_BADINTERNALERROR;
     }
@@ -291,13 +280,13 @@ static UA_StatusCode ServerNetworkLayerTCP_start(ServerNetworkLayerTCP *layer, U
     layer->layer.logger = logger;
 #ifdef _WIN32
     if((layer->serversockfd = socket(PF_INET, SOCK_STREAM,0)) == (UA_Int32)INVALID_SOCKET) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Error opening socket, code: %d",
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Error opening socket, code: %d",
                        WSAGetLastError());
         return UA_STATUSCODE_BADINTERNALERROR;
     }
 #else
     if((layer->serversockfd = socket(PF_INET, SOCK_STREAM, 0)) < 0) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Error opening socket");
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Error opening socket");
         return UA_STATUSCODE_BADINTERNALERROR;
     }
 #endif
@@ -308,20 +297,20 @@ static UA_StatusCode ServerNetworkLayerTCP_start(ServerNetworkLayerTCP *layer, U
     if(setsockopt(layer->serversockfd, SOL_SOCKET,
                   SO_REUSEADDR, (const char *)&optval,
                   sizeof(optval)) == -1) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION,
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK,
                        "Error during setting of socket options");
         CLOSESOCKET(layer->serversockfd);
         return UA_STATUSCODE_BADINTERNALERROR;
     }
     if(bind(layer->serversockfd, (const struct sockaddr *)&serv_addr,
             sizeof(serv_addr)) < 0) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Error during socket binding");
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Error during socket binding");
         CLOSESOCKET(layer->serversockfd);
         return UA_STATUSCODE_BADINTERNALERROR;
     }
     socket_set_nonblocking(layer->serversockfd);
     listen(layer->serversockfd, MAXBACKLOG);
-    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "TCP network layer Listening on %.*s",
+    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "TCP network layer listening on %.*s",
                 layer->layer.discoveryUrl.length, layer->layer.discoveryUrl.data);
     return UA_STATUSCODE_GOOD;
 }
@@ -394,7 +383,7 @@ ServerNetworkLayerTCP_getJobs(ServerNetworkLayerTCP *layer, UA_Job **jobs, UA_UI
 
 static size_t
 ServerNetworkLayerTCP_stop(ServerNetworkLayerTCP *layer, UA_Job **jobs) {
-    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION,
+    UA_LOG_INFO(layer->layer.logger, UA_LOGCATEGORY_NETWORK,
                 "Shutting down the TCP network layer with %d open connection(s)", layer->mappingsSize);
     shutdown(layer->serversockfd,2);
     CLOSESOCKET(layer->serversockfd);
@@ -487,11 +476,11 @@ ClientNetworkLayerTCP_connect(UA_ConnectionConfig localConf, char *endpointUrl,
 
     size_t urlLength = strlen(endpointUrl);
     if(urlLength < 11 || urlLength >= 512) {
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Server url size invalid");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Server url size invalid");
         return connection;
     }
     if(strncmp(endpointUrl, "opc.tcp://", 10) != 0) {
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Server url does not begin with opc.tcp://");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Server url does not begin with opc.tcp://");
         return connection;
     }
 
@@ -504,7 +493,7 @@ ClientNetworkLayerTCP_connect(UA_ConnectionConfig localConf, char *endpointUrl,
         }
     }
     if(port == 0) {
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Port invalid");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Port invalid");
         return connection;
     }
 
@@ -521,12 +510,12 @@ ClientNetworkLayerTCP_connect(UA_ConnectionConfig localConf, char *endpointUrl,
 #else
     if((connection.sockfd = socket(AF_INET, SOCK_STREAM, 0)) == -1) {
 #endif
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Could not create socket");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Could not create socket");
         return connection;
     }
     struct hostent *server = gethostbyname(hostname);
     if(!server) {
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "DNS lookup of %s failed", hostname);
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "DNS lookup of %s failed", hostname);
         return connection;
     }
     struct sockaddr_in server_addr;
@@ -537,14 +526,14 @@ ClientNetworkLayerTCP_connect(UA_ConnectionConfig localConf, char *endpointUrl,
     connection.state = UA_CONNECTION_OPENING;
     if(connect(connection.sockfd, (struct sockaddr *) &server_addr, sizeof(server_addr)) < 0) {
         ClientNetworkLayerClose(&connection);
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Connection failed");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Connection failed");
         return connection;
     }
 
 #ifdef SO_NOSIGPIPE
     int val = 1;
     if(setsockopt(connection.sockfd, SOL_SOCKET, SO_NOSIGPIPE, (void*)&val, sizeof(val)) < 0) {
-        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_COMMUNICATION, "Couldn't set SO_NOSIGPIPE");
+        UA_LOG_WARNING((*logger), UA_LOGCATEGORY_NETWORK, "Couldn't set SO_NOSIGPIPE");
         return connection;
     }
 #endif

examples/networklayer_udp.c

@@ -94,7 +94,7 @@ static UA_StatusCode sendUDP(UA_Connection *connection, UA_ByteString *buf) {
 		UA_Int32 n = sendto(layer->serversockfd, buf->data, buf->length, 0,
                             (struct sockaddr*)sin, sizeof(struct sockaddr_in));
         if(n == -1L) {
-            UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "UDP send error %i", errno);
+            UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "UDP send error %i", errno);
             UA_ByteString_deleteMembers(buf);
             return UA_STATUSCODE_BADINTERNALERROR;
         }
@@ -124,7 +124,7 @@ static UA_StatusCode ServerNetworkLayerUDP_start(ServerNetworkLayerUDP *layer, U
     layer->layer.logger = logger;
     layer->serversockfd = socket(PF_INET, SOCK_DGRAM, 0);
     if(layer->serversockfd < 0) {
-		UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Error opening socket");
+		UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Error opening socket");
 		return UA_STATUSCODE_BADINTERNALERROR;
 	} 
 	const struct sockaddr_in serv_addr =
@@ -133,18 +133,18 @@ static UA_StatusCode ServerNetworkLayerUDP_start(ServerNetworkLayerUDP *layer, U
 	int optval = 1;
 	if(setsockopt(layer->serversockfd, SOL_SOCKET,
                   SO_REUSEADDR, (const char *)&optval, sizeof(optval)) == -1) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Could not setsockopt");
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Could not setsockopt");
 		CLOSESOCKET(layer->serversockfd);
 		return UA_STATUSCODE_BADINTERNALERROR;
 	}
 	if(bind(layer->serversockfd, (const struct sockaddr *)&serv_addr,
             sizeof(serv_addr)) < 0) {
-        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Could not bind the socket");
+        UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Could not bind the socket");
 		CLOSESOCKET(layer->serversockfd);
 		return UA_STATUSCODE_BADINTERNALERROR;
 	}
 	socket_set_nonblocking(layer->serversockfd);
-    UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "Listening for UDP connections on %s:%d",
+    UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "Listening for UDP connections on %s:%d",
                    inet_ntoa(serv_addr.sin_addr), ntohs(serv_addr.sin_port));
     return UA_STATUSCODE_GOOD;
 }
@@ -165,7 +165,7 @@ static size_t ServerNetworkLayerUDP_getJobs(ServerNetworkLayerUDP *layer, UA_Job
     if(!buf.data) {
         buf.data = malloc(sizeof(UA_Byte) * layer->conf.recvBufferSize);
         if(!buf.data)
-            UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_COMMUNICATION, "malloc failed");
+            UA_LOG_WARNING(layer->layer.logger, UA_LOGCATEGORY_NETWORK, "malloc failed");
     }
     struct sockaddr sender;
     socklen_t sendsize = sizeof(sender);

examples/server.c

@@ -41,7 +41,7 @@
 /****************************/
 
 UA_Boolean running = 1;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 /*************************/
 /* Read-only data source */
@@ -219,12 +219,11 @@ int main(int argc, char** argv) {
 #endif
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_ByteString certificate = loadCertificate();
     UA_Server_setServerCertificate(server, certificate);
     UA_ByteString_deleteMembers(&certificate);
-    UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
+    UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16663));
 
     // add node with the datetime data source
     UA_DataSource dateDataSource = (UA_DataSource) {.handle = NULL, .read = readTimeData, .write = NULL};

examples/server.cpp

@@ -23,8 +23,8 @@
 
 using namespace std;
 
-UA_Logger logger;
 UA_Boolean running = 1;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -36,7 +36,6 @@ int main() {
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
 
     // add a variable node to the adresspace

examples/server_datasource.c

@@ -16,7 +16,7 @@
 #endif
 
 UA_Boolean running = 1;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -47,7 +47,6 @@ int main(int argc, char** argv) {
     signal(SIGINT, stopHandler); /* catches ctrl-c */
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
 

examples/server_firstSteps.c

@@ -14,7 +14,7 @@
 #endif
 
 UA_Boolean running;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int signal) {
     running = UA_FALSE;
@@ -25,7 +25,6 @@ int main(void) {
     signal(SIGTERM, stopHandler);
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
     running = UA_TRUE;

examples/server_method.c

@@ -16,7 +16,7 @@
 #endif
 
 UA_Boolean running = UA_TRUE;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static UA_StatusCode
 helloWorldMethod(const UA_NodeId objectId, const UA_Variant *input,
@@ -53,7 +53,6 @@ int main(int argc, char** argv) {
 
     /* initialize the server */
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
 

examples/server_nodeset.c

@@ -19,7 +19,7 @@
 #include "nodeset.h"
 
 UA_Boolean running = UA_TRUE;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -31,7 +31,6 @@ int main(int argc, char** argv) {
 
     /* initialize the server */
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
 

examples/server_readspeed.c

@@ -20,7 +20,7 @@
 #include "ua_types_encoding_binary.h"
 
 UA_Boolean running = 1;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -31,7 +31,6 @@ int main(int argc, char** argv) {
     signal(SIGINT, stopHandler); /* catches ctrl-c */
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
 

examples/server_repeated_job.c

@@ -15,7 +15,7 @@
 #endif
 
 UA_Boolean running = 1;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -30,7 +30,6 @@ int main(int argc, char** argv) {
     signal(SIGINT, stopHandler); /* catches ctrl-c */
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_Server_addNetworkLayer(server, ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664));
 

examples/server_variable.c

@@ -15,7 +15,7 @@
 #endif
 
 UA_Boolean running = 1;
-UA_Logger logger;
+UA_Logger logger = Logger_Stdout;
 
 static void stopHandler(int sign) {
     UA_LOG_INFO(logger, UA_LOGCATEGORY_SERVER, "received ctrl-c");
@@ -37,7 +37,6 @@ int main(int argc, char** argv) {
     signal(SIGINT, stopHandler); /* catches ctrl-c */
 
     UA_Server *server = UA_Server_new(UA_ServerConfig_standard);
-    logger = Logger_Stdout_new();
     UA_Server_setLogger(server, logger);
     UA_ServerNetworkLayer *nl;
     nl = ServerNetworkLayerTCP_new(UA_ConnectionConfig_standard, 16664);

include/ua_log.h

@@ -40,7 +40,9 @@ typedef enum {
 } UA_LogLevel;
 
 typedef enum {
-    UA_LOGCATEGORY_COMMUNICATION,
+    UA_LOGCATEGORY_NETWORK,
+    UA_LOGCATEGORY_SECURECHANNEL,
+    UA_LOGCATEGORY_SESSION,
     UA_LOGCATEGORY_SERVER,
     UA_LOGCATEGORY_CLIENT,
     UA_LOGCATEGORY_USERLAND

src/client/ua_client.c

@@ -132,15 +132,20 @@ static UA_StatusCode HelAckHandshake(UA_Client *c) {
 
     message.length = messageHeader.messageSize;
     retval = c->connection.send(&c->connection, &message);
-    if(retval != UA_STATUSCODE_GOOD)
+    if(retval != UA_STATUSCODE_GOOD) {
+        UA_LOG_DEBUG(c->logger, UA_LOGCATEGORY_NETWORK, "Sending HEL failed");
         return retval;
+    }
+    UA_LOG_DEBUG(c->logger, UA_LOGCATEGORY_NETWORK, "Sent HEL message");
 
     UA_ByteString reply;
     UA_ByteString_init(&reply);
     do {
         retval = c->connection.recv(&c->connection, &reply, c->config.timeout);
-        if(retval != UA_STATUSCODE_GOOD)
+        if(retval != UA_STATUSCODE_GOOD) {
+            UA_LOG_DEBUG(c->logger, UA_LOGCATEGORY_NETWORK, "Receiving ACK message failed");
             return retval;
+        }
     } while(!reply.data);
 
     offset = 0;
@@ -148,8 +153,12 @@ static UA_StatusCode HelAckHandshake(UA_Client *c) {
     UA_TcpAcknowledgeMessage ackMessage;
     retval = UA_TcpAcknowledgeMessage_decodeBinary(&reply, &offset, &ackMessage);
     UA_ByteString_deleteMembers(&reply);
-    if(retval != UA_STATUSCODE_GOOD)
+    if(retval != UA_STATUSCODE_GOOD) {
+        UA_LOG_DEBUG(c->logger, UA_LOGCATEGORY_NETWORK, "Decoding ACK message failed");
         return retval;
+    }
+
+    UA_LOG_DEBUG(c->logger, UA_LOGCATEGORY_NETWORK, "Received ACK message");
     conn->remoteConf.maxChunkCount = ackMessage.maxChunkCount;
     conn->remoteConf.maxMessageSize = ackMessage.maxMessageSize;
     conn->remoteConf.protocolVersion = ackMessage.protocolVersion;
@@ -187,11 +196,13 @@ static UA_StatusCode SecureChannelHandshake(UA_Client *client, UA_Boolean renew)
     opnSecRq.requestedLifetime = client->config.secureChannelLifeTime;
     if(renew) {
         opnSecRq.requestType = UA_SECURITYTOKENREQUESTTYPE_RENEW;
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "Requesting to renew the SecureChannel");
     } else {
         opnSecRq.requestType = UA_SECURITYTOKENREQUESTTYPE_ISSUE;
         UA_ByteString_init(&client->channel.clientNonce);
         UA_ByteString_copy(&client->channel.clientNonce, &opnSecRq.clientNonce);
         opnSecRq.securityMode = UA_MESSAGESECURITYMODE_NONE;
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "Requesting to open a SecureChannel");
     }
 
     UA_ByteString message;
@@ -228,8 +239,10 @@ static UA_StatusCode SecureChannelHandshake(UA_Client *client, UA_Boolean renew)
     UA_ByteString_init(&reply);
     do {
         retval = client->connection.recv(&client->connection, &reply, client->config.timeout);
-        if(retval != UA_STATUSCODE_GOOD)
+        if(retval != UA_STATUSCODE_GOOD) {
+            UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "Receiving OpenSecureChannelResponse failed");
             return retval;
+        }
     } while(!reply.data);
 
     offset = 0;
@@ -243,22 +256,35 @@ static UA_StatusCode SecureChannelHandshake(UA_Client *client, UA_Boolean renew)
         UA_ByteString_deleteMembers(&reply);
         UA_AsymmetricAlgorithmSecurityHeader_deleteMembers(&asymHeader);
         UA_NodeId_deleteMembers(&requestType);
-        UA_LOG_ERROR(client->logger, UA_LOGCATEGORY_CLIENT,
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_CLIENT,
                      "Reply answers the wrong request. Expected OpenSecureChannelResponse.");
         return UA_STATUSCODE_BADINTERNALERROR;
     }
 
     UA_OpenSecureChannelResponse response;
-    UA_OpenSecureChannelResponse_decodeBinary(&reply, &offset, &response);
+    retval = UA_OpenSecureChannelResponse_decodeBinary(&reply, &offset, &response);
+    if(!retval) {
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "Decoding OpenSecureChannelResponse failed");
+        UA_ByteString_deleteMembers(&reply);
+        UA_AsymmetricAlgorithmSecurityHeader_deleteMembers(&asymHeader);
+        UA_OpenSecureChannelResponse_init(&response);
+        response.responseHeader.serviceResult = retval;
+        return retval;
+    }
     client->scExpiresAt = UA_DateTime_now() + response.securityToken.revisedLifetime * 10000;
     UA_ByteString_deleteMembers(&reply);
     retval = response.responseHeader.serviceResult;
 
-    if(!renew && retval == UA_STATUSCODE_GOOD) {
+    if(retval != UA_STATUSCODE_GOOD)
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "SecureChannel could not be opened / renewed");
+    else if(!renew) {
         UA_ChannelSecurityToken_copy(&response.securityToken, &client->channel.securityToken);
-        UA_ByteString_deleteMembers(&client->channel.serverNonce); // if the handshake is repeated
+        /* if the handshake is repeated, replace the old nonce */
+        UA_ByteString_deleteMembers(&client->channel.serverNonce);
         UA_ByteString_copy(&response.serverNonce, &client->channel.serverNonce);
-    }
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "SecureChannel opened");
+    } else
+        UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_SECURECHANNEL, "SecureChannel renewed");
 
     UA_OpenSecureChannelResponse_deleteMembers(&response);
     UA_AsymmetricAlgorithmSecurityHeader_deleteMembers(&asymHeader);
@@ -266,9 +292,12 @@ static UA_StatusCode SecureChannelHandshake(UA_Client *client, UA_Boolean renew)
 }
 
 /** If the request fails, then the response is cast to UA_ResponseHeader (at the beginning of every
-    response) and filled with the appropriate error code */
-static void synchronousRequest(UA_Client *client, void *request, const UA_DataType *requestType,
+    response) and filled with theaappropriate error code */
+static void synchronousRequest(UA_Client *client, void *r, const UA_DataType *requestType,
                                void *response, const UA_DataType *responseType) {
+    /* Requests always begin witih a RequestHeader, therefore we can cast. */
+    UA_RequestHeader *request = r;
+
     UA_StatusCode retval = UA_STATUSCODE_GOOD;
     if(!response)
         return;
@@ -282,25 +311,15 @@ static void synchronousRequest(UA_Client *client, void *request, const UA_DataTy
         return;
     }
 
-    /* HANDLING REQUEST HEADER PARAMETERS */
-    typedef struct {
-        UA_RequestHeader requestHeader;
-    } headerOnlyRequest;
-    /* The cast is valid, since all requests start with a requestHeader */
-
-    /* Copy authenticationToken token to request header */
-    UA_NodeId_copy(&client->authenticationToken, &((headerOnlyRequest*)request)->requestHeader.authenticationToken);
-
-    ((headerOnlyRequest*)request)->requestHeader.timestamp = UA_DateTime_now();
-
-    ((headerOnlyRequest*)request)->requestHeader.requestHandle = ++client->requestHandle;
-
-    /*/HANDLING REQUEST HEADER PARAMETERS */
+    /* handling request parameters */
+    UA_NodeId_copy(&client->authenticationToken, &request->authenticationToken);
+    request->timestamp = UA_DateTime_now();
+    request->requestHandle = ++client->requestHandle;
 
     /* Send the request */
     UA_UInt32 requestId = ++client->requestId;
-    retval = UA_SecureChannel_sendBinaryMessage(&client->channel, requestId,
-                                                              request, requestType);
+    UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_CLIENT, "Sending a request of type %i", requestType->typeId.identifier.numeric);
+    retval = UA_SecureChannel_sendBinaryMessage(&client->channel, requestId, request, requestType);
     if(retval) {
         if(retval == UA_STATUSCODE_BADENCODINGLIMITSEXCEEDED)
             respHeader->serviceResult = UA_STATUSCODE_BADREQUESTTOOLARGE;
@@ -335,8 +354,9 @@ static void synchronousRequest(UA_Client *client, void *request, const UA_DataTy
     UA_NodeId expectedNodeId = UA_NODEID_NUMERIC(0, responseType->typeId.identifier.numeric +
                                                  UA_ENCODINGOFFSET_BINARY);
 
-    if(retval != UA_STATUSCODE_GOOD)
+    if(retval != UA_STATUSCODE_GOOD) {
         goto finish;
+    }
 
     /* Todo: we need to demux responses since a publish responses may come at any time */
     if(!UA_NodeId_equal(&responseId, &expectedNodeId) || seqHeader.requestId != requestId) {
@@ -359,9 +379,11 @@ static void synchronousRequest(UA_Client *client, void *request, const UA_DataTy
     UA_SymmetricAlgorithmSecurityHeader_deleteMembers(&symHeader);
     UA_ByteString_deleteMembers(&reply);
     if(retval != UA_STATUSCODE_GOOD){
+        UA_LOG_INFO(client->logger, UA_LOGCATEGORY_CLIENT, "Error receiving the response");
         client->state = UA_CLIENTSTATE_ERRORED;
         respHeader->serviceResult = retval;
     }
+    UA_LOG_DEBUG(client->logger, UA_LOGCATEGORY_CLIENT, "Received a response of type %i", responseId.identifier.numeric);
 }
 
 static UA_StatusCode ActivateSession(UA_Client *client) {
@@ -1040,7 +1062,7 @@ void UA_Client_doPublish(UA_Client *client) {
 #ifdef ENABLE_METHODCALLS
 UA_CallResponse UA_Client_call(UA_Client *client, UA_CallRequest *request) {
     UA_CallResponse response;
-    synchronousRequest(client, request, &UA_TYPES[UA_TYPES_CALLREQUEST],
+    synchronousRequest(client, (UA_RequestHeader*)request, &UA_TYPES[UA_TYPES_CALLREQUEST],
                        &response, &UA_TYPES[UA_TYPES_CALLRESPONSE]);
     return response;
 }

src/server/ua_securechannel_manager.c

@@ -37,8 +37,7 @@ void UA_SecureChannelManager_cleanupTimedOut(UA_SecureChannelManager *cm, UA_Dat
                 entry->channel.connection){
             UA_SecureChannel_revolveTokens(&entry->channel);
             entry = LIST_NEXT(entry, pointers);
-        }
-        else {
+        } else {
             channel_list_entry *next = LIST_NEXT(entry, pointers);
             LIST_REMOVE(entry, pointers);
             UA_SecureChannel_deleteMembersCleanup(&entry->channel);
@@ -99,8 +98,7 @@ UA_StatusCode UA_SecureChannelManager_open(UA_SecureChannelManager *cm, UA_Conne
 
 UA_StatusCode UA_SecureChannelManager_renew(UA_SecureChannelManager *cm, UA_Connection *conn,
                                             const UA_OpenSecureChannelRequest *request,
-                                            UA_OpenSecureChannelResponse *response)
-{
+                                            UA_OpenSecureChannelResponse *response) {
     UA_SecureChannel *channel = conn->channel;
     if(channel == UA_NULL)
         return UA_STATUSCODE_BADINTERNALERROR;

src/server/ua_server_binary.c

@@ -233,6 +233,9 @@ static void processMSG(UA_Connection *connection, UA_Server *server, const UA_By
     if(clientChannel != &anonymousChannel && tokenId != clientChannel->securityToken.tokenId) {
         if(tokenId != clientChannel->nextSecurityToken.tokenId) {
             /* close the securechannel but keep the connection open */
+            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                        "Request with a wrong security token. Closing the SecureChannel %i.",
+                        clientChannel->securityToken.channelId);
             Service_CloseSecureChannel(server, clientChannel->securityToken.channelId);
             return;
         }
@@ -250,6 +253,12 @@ static void processMSG(UA_Connection *connection, UA_Server *server, const UA_By
 
     switch(requestType.identifier.numeric - UA_ENCODINGOFFSET_BINARY) {
     case UA_NS0ID_GETENDPOINTSREQUEST: {
+        if(clientChannel == &anonymousChannel)
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_NETWORK, "Processing GetEndpointsRequest on Connection %i",
+                         connection->sockfd);
+        else
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL, "Processing GetEndpointsRequest on SecureChannel %i",
+                         clientChannel->securityToken.channelId);
         UA_GetEndpointsRequest p;
         UA_GetEndpointsResponse r;
         if(UA_GetEndpointsRequest_decodeBinary(msg, pos, &p))
@@ -265,6 +274,12 @@ static void processMSG(UA_Connection *connection, UA_Server *server, const UA_By
     }
 
     case UA_NS0ID_FINDSERVERSREQUEST: {
+        if(clientChannel == &anonymousChannel)
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_NETWORK, "Processing FindServerRequest on Connection %i",
+                         connection->sockfd);
+        else
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL, "Processing FindServerRequest on SecureChannel %i",
+                         clientChannel->securityToken.channelId);
         UA_FindServersRequest  p;
         UA_FindServersResponse r;
         if(UA_FindServersRequest_decodeBinary(msg, pos, &p))
@@ -333,7 +348,7 @@ static void processMSG(UA_Connection *connection, UA_Server *server, const UA_By
     case UA_NS0ID_TRANSLATEBROWSEPATHSTONODEIDSREQUEST:
         INVOKE_SERVICE(TranslateBrowsePathsToNodeIds, UA_TYPES_TRANSLATEBROWSEPATHSTONODEIDSRESPONSE);
         break;
-#ifdef ENABLE_SUBSCRIPTIONS    
+#ifdef ENABLE_SUBSCRIPTIONS
     case UA_NS0ID_CREATESUBSCRIPTIONREQUEST:
         INVOKE_SERVICE(CreateSubscription, UA_TYPES_CREATESUBSCRIPTIONRESPONSE);
         break;
@@ -366,18 +381,18 @@ static void processMSG(UA_Connection *connection, UA_Server *server, const UA_By
         INVOKE_SERVICE(AddReferences, UA_TYPES_ADDREFERENCESRESPONSE);
         break;
     case UA_NS0ID_DELETENODESREQUEST:
-      INVOKE_SERVICE(DeleteNodes, UA_TYPES_DELETENODESRESPONSE);
-      break;
+        INVOKE_SERVICE(DeleteNodes, UA_TYPES_DELETENODESRESPONSE);
+        break;
     case UA_NS0ID_DELETEREFERENCESREQUEST:
-      INVOKE_SERVICE(DeleteReferences, UA_TYPES_DELETEREFERENCESRESPONSE);
-      break;
+        INVOKE_SERVICE(DeleteReferences, UA_TYPES_DELETEREFERENCESRESPONSE);
+        break;
 #endif
     default: {
         if(requestType.namespaceIndex == 0 && requestType.identifier.numeric==787)
-            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_COMMUNICATION,
+            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_NETWORK,
                         "Client requested a subscription that are not supported, the message will be skipped");
         else
-            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_COMMUNICATION, "Unknown request: NodeId(ns=%d, i=%d)",
+            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_NETWORK, "Unknown request: NodeId(ns=%d, i=%d)",
                         requestType.namespaceIndex, requestType.identifier.numeric);
         UA_RequestHeader p;
         UA_ServiceFault r;
@@ -405,7 +420,7 @@ static void processCLO(UA_Connection *connection, UA_Server *server, const UA_By
 }
 
 /**
- * process binary message received from socket
+ * process binary message received from Connection
  * dose not modify UA_ByteString you have to free it youself.
  * use of connection->getSendBuffer() and connection->sent() to answer Message
  */
@@ -414,7 +429,7 @@ void UA_Server_processBinaryMessage(UA_Server *server, UA_Connection *connection
     UA_TcpMessageHeader tcpMessageHeader;
     do {
         if(UA_TcpMessageHeader_decodeBinary(msg, &pos, &tcpMessageHeader)) {
-            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_COMMUNICATION, "Decoding of message header failed");
+            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_NETWORK, "Decoding of message header failed");
             connection->close(connection);
             break;
         }
@@ -432,20 +447,23 @@ void UA_Server_processBinaryMessage(UA_Server *server, UA_Connection *connection
             if(connection->state != UA_CONNECTION_ESTABLISHED) {
                 connection->close(connection);
                 return;
-            } else
+            }
 #endif
-                processMSG(connection, server, msg, &pos);
+            processMSG(connection, server, msg, &pos);
             break;
         case UA_MESSAGETYPEANDFINAL_CLOF & 0xffffff:
             processCLO(connection, server, msg, &pos);
             connection->close(connection);
             return;
+        default:
+            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_NETWORK, "Unknown request type on Connection %i", connection->sockfd);
         }
 
         UA_TcpMessageHeader_deleteMembers(&tcpMessageHeader);
         if(pos != targetpos) {
-            UA_LOG_INFO(server->logger, UA_LOGCATEGORY_COMMUNICATION,
-                        "The message was not entirely processed, skipping to the end");
+            UA_LOG_INFO(server->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);
             pos = targetpos;
         }
     } while(msg->length > (UA_Int32)pos);

src/server/ua_services_attribute.c

@@ -312,6 +312,9 @@ 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->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing ReadRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
     if(request->nodesToReadSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -323,7 +326,6 @@ void Service_Read(UA_Server *server, UA_Session *session, const UA_ReadRequest *
     }
 
     size_t size = request->nodesToReadSize;
-
     response->results = UA_Array_new(&UA_TYPES[UA_TYPES_DATAVALUE], size);
     if(!response->results) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
@@ -331,7 +333,6 @@ 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;
         return;
@@ -661,6 +662,9 @@ UA_StatusCode Service_Write_single(UA_Server *server, UA_Session *session, UA_Wr
 void Service_Write(UA_Server *server, UA_Session *session, const UA_WriteRequest *request,
                    UA_WriteResponse *response) {
     UA_assert(server != UA_NULL && session != UA_NULL && request != UA_NULL && response != UA_NULL);
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing WriteRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
 
     if(request->nodesToWriteSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;

src/server/ua_services_securechannel.c

@@ -6,14 +6,30 @@ void Service_OpenSecureChannel(UA_Server *server, UA_Connection *connection,
                                const UA_OpenSecureChannelRequest *request,
                                UA_OpenSecureChannelResponse *response) {
     // todo: if(request->clientProtocolVersion != protocolVersion)
-    if(request->requestType == UA_SECURITYTOKENREQUESTTYPE_ISSUE)
+    if(request->requestType == UA_SECURITYTOKENREQUESTTYPE_ISSUE) {
         UA_SecureChannelManager_open(&server->secureChannelManager, connection, request, response);
-    else
+        if(response->responseHeader.serviceResult == UA_STATUSCODE_GOOD)
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                         "Opened SecureChannel %i on Connection %i",
+                         response->securityToken.channelId, connection->sockfd);
+        else
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                         "Opening SecureChannel on Connection %i failed", connection->sockfd);
+    } else {
         UA_SecureChannelManager_renew(&server->secureChannelManager, connection, request, response);
+        if(response->responseHeader.serviceResult == UA_STATUSCODE_GOOD)
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                         "Renewed SecureChannel %i on Connection %i",
+                         response->securityToken.channelId, connection->sockfd);
+        else
+            UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                         "Renewing SecureChannel on Connection %i failed", connection->sockfd);
+    }
 }
 
 void Service_CloseSecureChannel(UA_Server *server, UA_Int32 channelId) {
-	//Sten: this service is a bit assymmetric to OpenSecureChannel since CloseSecureChannelRequest does not contain any indormation
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SECURECHANNEL,
+                 "Closing SecureChannel %i", channelId);
     UA_SecureChannelManager_close(&server->secureChannelManager, channelId);
     // 62451 Part 6 Chapter 7.1.4 - The server does not send a CloseSecureChannel response
 }

src/server/ua_services_session.c

@@ -16,8 +16,12 @@ void Service_CreateSession(UA_Server *server, UA_SecureChannel *channel,
 	UA_Session *newSession;
     response->responseHeader.serviceResult = UA_SessionManager_createSession(&server->sessionManager,
                                                                              channel, request, &newSession);
-	if(response->responseHeader.serviceResult != UA_STATUSCODE_GOOD)
+	if(response->responseHeader.serviceResult != UA_STATUSCODE_GOOD) {
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing CreateSessionRequest on SecureChannel %i failed",
+                 channel->securityToken.channelId);
 		return;
+    }
 
     //TODO get maxResponseMessageSize internally
     newSession->maxResponseMessageSize = request->maxResponseMessageSize;
@@ -32,6 +36,10 @@ void Service_CreateSession(UA_Server *server, UA_SecureChannel *channel,
         UA_SessionManager_removeSession(&server->sessionManager, server, &newSession->authenticationToken);
          return;
     }
+    UA_LOG_DEBUG(server->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);
 }
 
 void Service_ActivateSession(UA_Server *server, UA_SecureChannel *channel,
@@ -44,11 +52,21 @@ void Service_ActivateSession(UA_Server *server, UA_SecureChannel *channel,
 
 	if(foundSession == UA_NULL) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSESSIONIDINVALID;
+        UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                     "Processing ActivateSessionRequest on SecureChannel %i, but no session found for the authentication token",
+                     channel->securityToken.channelId);
         return;
 	} else if(foundSession->validTill < UA_DateTime_now()) {
+        UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                     "Processing ActivateSessionRequest on SecureChannel %i, but the session has timed out",
+                     channel->securityToken.channelId);
         response->responseHeader.serviceResult = UA_STATUSCODE_BADSESSIONIDINVALID;
         return;
 	}
+    UA_LOG_DEBUG(server->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_UserIdentityToken token;
     UA_UserIdentityToken_init(&token);
@@ -116,12 +134,9 @@ void Service_ActivateSession(UA_Server *server, UA_SecureChannel *channel,
 
 void Service_CloseSession(UA_Server *server, UA_Session *session, const UA_CloseSessionRequest *request,
                           UA_CloseSessionResponse *response) {
-	UA_Session *foundSession =
-        UA_SessionManager_getSession(&server->sessionManager,
-		                             (const UA_NodeId*)&request->requestHeader.authenticationToken);
-	if(foundSession == UA_NULL)
-		response->responseHeader.serviceResult = UA_STATUSCODE_BADSESSIONIDINVALID;
-	else 
-        response->responseHeader.serviceResult =
-            UA_SessionManager_removeSession(&server->sessionManager, server, &session->authenticationToken);
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing CloseSessionRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
+    response->responseHeader.serviceResult =
+        UA_SessionManager_removeSession(&server->sessionManager, server, &session->authenticationToken);
 }

src/server/ua_services_view.c

@@ -385,6 +385,9 @@ 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->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing BrowseRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
     if(!UA_NodeId_isNull(&request->view.viewId)) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADVIEWIDUNKNOWN;
         return;
@@ -440,6 +443,9 @@ void Service_Browse(UA_Server *server, UA_Session *session, const UA_BrowseReque
 
 void Service_BrowseNext(UA_Server *server, UA_Session *session, const UA_BrowseNextRequest *request,
                         UA_BrowseNextResponse *response) {
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing BrowseNextRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
    if(request->continuationPointsSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
@@ -606,13 +612,15 @@ translateBrowsePath(UA_Server *server, UA_Session *session, const UA_BrowsePath
 void Service_TranslateBrowsePathsToNodeIds(UA_Server *server, UA_Session *session,
                                            const UA_TranslateBrowsePathsToNodeIdsRequest *request,
                                            UA_TranslateBrowsePathsToNodeIdsResponse *response) {
+    UA_LOG_DEBUG(server->logger, UA_LOGCATEGORY_SESSION,
+                 "Processing TranslateBrowsePathsToNodeIdsRequest for Session (ns=%i,i=%i)",
+                 session->sessionId.namespaceIndex, session->sessionId.identifier.numeric);
 	if(request->browsePathsSize <= 0) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADNOTHINGTODO;
         return;
     }
 
     size_t size = request->browsePathsSize;
-
     response->results = UA_Array_new(&UA_TYPES[UA_TYPES_BROWSEPATHRESULT], size);
     if(!response->results) {
         response->responseHeader.serviceResult = UA_STATUSCODE_BADOUTOFMEMORY;
@@ -656,6 +664,9 @@ void Service_TranslateBrowsePathsToNodeIds(UA_Server *server, UA_Session *sessio
 
 void Service_RegisterNodes(UA_Server *server, UA_Session *session, const UA_RegisterNodesRequest *request,
                            UA_RegisterNodesResponse *response) {
+    UA_LOG_DEBUG(server->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();
     if(request->nodesToRegisterSize <= 0)
@@ -671,6 +682,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->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)