Enhance logs in case of socket problems, client hangs on waitForSocket()

Change-Id: I30c3add6e1e21c3c28ae7a7b3b8c6e66477ea9ae

diff --git a/src/common/connection.cpp b/src/common/connection.cpp
index f273258c5eb6d7d96e073e80cf427fcbf360d069..2a073438e511432014e495379fd5cfa2ec6a0fc6 100644 (file)
--- a/src/common/connection.cpp
+++ b/src/common/connection.cpp
@@ -51,6 +51,7 @@ int waitForSocket(int sock, int event, int timeout) {
     pollfd desc[1];
     desc[0].fd = sock;
     desc[0].events = event;
+    LogError("[DEBUG ONLY] waitForSocket " << sock);
 
     while((-1 == (retval = poll(desc, 1, timeout))) && (errno == EINTR)) {
         timeout >>= 1;
@@ -58,7 +59,7 @@ int waitForSocket(int sock, int event, int timeout) {
     }
 
     if (0 == retval) {
-        LogDebug("Poll timeout");
+        LogError("[DEBUG ONLY] Poll timeout");
     } else if (-1 == retval) {
         int err = errno;
         LogError("Error in poll: " << GetErrnoString(err));
@@ -91,6 +92,8 @@ public:
             return SECURITY_MANAGER_ERROR_SOCKET;
         }
 
+        LogError("[DEBUG ONLY] m_sock= " << m_sock);
+
         if ((flags = fcntl(m_sock, F_GETFL, 0)) < 0 ||
             fcntl(m_sock, F_SETFL, flags | O_NONBLOCK) < 0)
         {
@@ -112,6 +115,7 @@ public:
 
         LogDebug("ClientAddr.sun_path = " << interface);
 
+        LogError("[DEBUG ONLY] m_sock= " << m_sock);
         int retval = TEMP_FAILURE_RETRY(connect(m_sock, (struct sockaddr*)&clientAddr, SUN_LEN(&clientAddr)));
         if ((retval == -1) && (errno == EINPROGRESS)) {
             if (0 >= waitForSocket(m_sock, POLLIN, POLL_TIMEOUT)) {

diff --git a/src/server/main/socket-manager.cpp b/src/server/main/socket-manager.cpp
index 46b1822aa6709a028e95327ff1f299c8242f1939..07b5925816af56c92f55f7a25b8eddacb5d61f7e 100644 (file)
--- a/src/server/main/socket-manager.cpp
+++ b/src/server/main/socket-manager.cpp
@@ -209,7 +209,7 @@ void SocketManager::ReadyForAccept(int sock) {
     struct sockaddr_un clientAddr;
     unsigned int clientLen = sizeof(clientAddr);
     int client = accept4(sock, (struct sockaddr*) &clientAddr, &clientLen, SOCK_NONBLOCK);
-//    LogInfo("Accept on sock: " << sock << " Socket opended: " << client);
+    LogError("[DEBUG ONLY] Accept on sock: " << sock << " Socket opended: " << client);
     if (-1 == client) {
         int err = errno;
         LogError("Error in accept: " << GetErrnoString(err));
@@ -245,7 +245,7 @@ void SocketManager::ReadyForRead(int sock) {
     ssize_t size = read(sock, &event.rawBuffer[0], 4096);
 
     if (size == 0) {
-        LogDebug("Reading returned 0 bytes, closing socket: " << sock);
+        LogError("[DEBUG ONLY] Reading returned 0 bytes, closing socket: " << sock);
         CloseSocket(sock);
     } else if (size >= 0) {
         event.rawBuffer.resize(size);
@@ -426,7 +426,7 @@ void SocketManager::MainLoop() {
             // and connection is open. Time to close it!
             // Putting new timeout in queue here is pointless.
             desc.isTimeout = false;
-            LogWarning("Closing socket because of timeout: " << pqTimeout.sock);
+            LogError("[DEBUG ONLY] Closing socket because of timeout: " << pqTimeout.sock);
             CloseSocket(pqTimeout.sock);
 
             // All done. Now we should process next select ;-)
@@ -485,12 +485,12 @@ int SocketManager::GetSocketFromSystemD(
         if (0 < sd_is_socket_unix(fd, SOCK_STREAM, 1,
                                   desc.serviceHandlerPath.c_str(), 0))
         {
-            LogInfo("Useable socket " << desc.serviceHandlerPath <<
+            LogError("[DEBUG ONLY] Useable socket " << desc.serviceHandlerPath <<
                 " was passed by SystemD under descriptor " << fd);
             return fd;
         }
     }
-    LogInfo("No useable sockets were passed by systemd.");
+    LogError("[DEBUG ONLY] No useable sockets were passed by systemd.");
     return -1;
 }
 
@@ -583,7 +583,7 @@ void SocketManager::CreateDomainSocket(
     description.useSendMsg = desc.useSendMsg;
     description.service = service;
 
-    LogDebug("Listen on socket: " << sockfd <<
+    LogError("[DEBUG ONLY] Listen on socket: " << sockfd <<
         " Handler: " << desc.serviceHandlerPath.c_str());
 }
 
@@ -598,6 +598,7 @@ void SocketManager::RegisterSocketService(GenericSocketService *service) {
         {
             auto &desc = m_socketDescriptionVector[i];
             if (desc.service == service && desc.isOpen) {
+                LogError("[DEBUG ONLY] Closing socket: " << i);
                 close(i);
                 desc.isOpen = false;
             }
@@ -685,14 +686,14 @@ void SocketManager::ProcessQueue() {
             auto &desc = m_socketDescriptionVector[data.connectionID.sock];
 
             if (!desc.isOpen) {
-                LogDebug("Received packet for sendmsg but connection is closed. Packet ignored! Socket: "
+                LogError("Received packet for sendmsg but connection is closed. Packet ignored! Socket: "
                           << data.connectionID.sock);
                 continue;
             }
 
             if (desc.counter != data.connectionID.counter)
             {
-                LogDebug("Received packet for write but counter is broken. Packet ignored! Socket: "
+                LogError("Received packet for write but counter is broken. Packet ignored! Socket: "
                           << data.connectionID.sock);
                 continue;
             }