Logging: Refine security manager log printouts

Some of log traces were redundant, some of them carried unhelpul data. This
commit reorganizes calls to log macros to make them more helpful.

Change-Id: I6b814610e32f4c568ce6c8acfae33da0d1878dd0
Signed-off-by: Marcin Lis <m.lis@samsung.com>

7 files changed, 54 insertions, 62 deletions

diff --git a/src/client/client-security-manager.cpp b/src/client/client-security-manager.cpp
index 1090dcc3..9de0fa96 100644
--- a/src/client/client-security-manager.cpp
+++ b/src/client/client-security-manager.cpp
@@ -113,8 +113,6 @@ int security_manager_app_install(const app_inst_req *p_req)
     using namespace SecurityManager;
     MessageBuffer send, recv;
 
-    LogDebug("app_install() called");
-
     return try_catch([&] {
         //checking parameters
         if (!p_req)
@@ -132,7 +130,7 @@ int security_manager_app_install(const app_inst_req *p_req)
         //send buffer to server
         int retval = sendToServer(SERVICE_SOCKET_INSTALLER, send.Pop(), recv);
         if (retval != SECURITY_MANAGER_API_SUCCESS) {
-            LogDebug("Error in sendToServer. Error code: " << retval);
+            LogError("Error in sendToServer. Error code: " << retval);
             return SECURITY_MANAGER_ERROR_UNKNOWN;
         }
 
@@ -151,8 +149,6 @@ int security_manager_app_uninstall(const app_inst_req *p_req)
     using namespace SecurityManager;
     MessageBuffer send, recv;
 
-    LogDebug("app_uninstall() called");
-
     return try_catch([&] {
         //checking parameters
         if (!p_req)
@@ -167,7 +163,7 @@ int security_manager_app_uninstall(const app_inst_req *p_req)
         //send buffer to server
         int retval = sendToServer(SERVICE_SOCKET_INSTALLER, send.Pop(), recv);
         if (retval != SECURITY_MANAGER_API_SUCCESS) {
-            LogDebug("Error in sendToServer. Error code: " << retval);
+            LogError("Error in sendToServer. Error code: " << retval);
             return SECURITY_MANAGER_ERROR_UNKNOWN;
         }
 
diff --git a/src/common/message-buffer.cpp b/src/common/message-buffer.cpp
index 59db4810..332dcc40 100644
--- a/src/common/message-buffer.cpp
+++ b/src/common/message-buffer.cpp
@@ -53,7 +53,7 @@ bool MessageBuffer::Ready() {
 void MessageBuffer::Read(size_t num, void *bytes) {
     CountBytesLeft();
     if (num > m_bytesLeft) {
-        LogDebug("Protocol broken. OutOfData. Asked for: " << num << " Ready: " << m_bytesLeft << " Buffer.size(): " << m_buffer.Size());
+        LogError("Protocol broken. OutOfData. Asked for: " << num << " Ready: " << m_bytesLeft << " Buffer.size(): " << m_buffer.Size());
         Throw(Exception::OutOfData);
     }
 
diff --git a/src/server/db/privilege_db.cpp b/src/server/db/privilege_db.cpp
index f407c6be..5eafde61 100644
--- a/src/server/db/privilege_db.cpp
+++ b/src/server/db/privilege_db.cpp
@@ -102,11 +102,12 @@ bool PrivilegeDb::PkgIdExists(const std::string &pkgId)
                         Queries.at(QueryType::EPkgIdExists));
         command->BindString(1, pkgId.c_str());
         if (command->Step()) {
-            LogPedantic("PkgId: " << pkgId << " found in database");
+            // pkgId found in the database
             command->Reset();
             return true;
         };
 
+        // pkgId not found in the database
         return false;
     });
 }
@@ -123,7 +124,9 @@ bool PrivilegeDb::GetAppPkgId(const std::string &appId, std::string &pkgId)
             return false;
         }
 
+        // application package found in the database, get it
         pkgId = command->GetColumnString(0);
+
         return true;
     });
 }
@@ -142,12 +145,12 @@ void PrivilegeDb::AddApplication(const std::string &appId,
         command->BindString(2, pkgId.c_str());
 
         if (command->Step()) {
-            LogPedantic("Unexpected SQLITE_ROW answer to query: " <<
+            LogDebug("Unexpected SQLITE_ROW answer to query: " <<
                     Queries.at(QueryType::EAddApplication));
         };
 
         command->Reset();
-        LogPedantic( "Added appId: " << appId << ", pkgId: " << pkgId);
+        LogDebug("Added appId: " << appId << ", pkgId: " << pkgId);
     });
 }
 
@@ -168,12 +171,12 @@ void PrivilegeDb::RemoveApplication(const std::string &appId,
         command->BindString(1, appId.c_str());
 
         if (command->Step()) {
-            LogPedantic("Unexpected SQLITE_ROW answer to query: " <<
+            LogDebug("Unexpected SQLITE_ROW answer to query: " <<
                     Queries.at(QueryType::ERemoveApplication));
         };
 
         command->Reset();
-        LogPedantic( "Removed appId: " << appId);
+        LogDebug("Removed appId: " << appId);
 
         pkgIdIsNoMore = !(this->PkgIdExists(pkgId));
     });
@@ -190,7 +193,7 @@ void PrivilegeDb::GetPkgPrivileges(const std::string &pkgId,
 
         while (command->Step()) {
             std::string privilege = command->GetColumnString(0);
-            LogPedantic ("Got privilege: "<< privilege);
+            LogDebug("Got privilege: " << privilege);
             currentPrivileges.push_back(privilege);
         };
     });
@@ -203,7 +206,12 @@ void PrivilegeDb::RemoveAppPrivileges(const std::string &appId)
             mSqlConnection->PrepareDataCommand(Queries.at(QueryType::ERemoveAppPrivileges));
 
         command->BindString(1, appId.c_str());
-        command->Step();
+        if (command->Step()) {
+            LogDebug("Unexpected SQLITE_ROW answer to query: " <<
+                    Queries.at(QueryType::ERemoveAppPrivileges));
+        }
+
+        LogDebug("Removed all privileges for appId: " << appId);
     });
 }
 
@@ -221,6 +229,7 @@ void PrivilegeDb::UpdateAppPrivileges(const std::string &appId,
             command->BindString(2, privilege.c_str());
             command->Step();
             command->Reset();
+            LogDebug("Added privilege: " << privilege << " to appId: " << appId);
         }
     });
 }
diff --git a/src/server/main/socket-manager.cpp b/src/server/main/socket-manager.cpp
index b4db0db2..cdbb1910 100644
--- a/src/server/main/socket-manager.cpp
+++ b/src/server/main/socket-manager.cpp
@@ -199,7 +199,7 @@ void SocketManager::ReadyForAccept(int sock) {
 //    LogInfo("Accept on sock: " << sock << " Socket opended: " << client);
     if (-1 == client) {
         int err = errno;
-        LogDebug("Error in accept: " << strerror(err));
+        LogError("Error in accept: " << strerror(err));
         return;
     }
 
@@ -243,7 +243,7 @@ void SocketManager::ReadyForRead(int sock) {
             case EINTR:
                 break;
             default:
-                LogDebug("Reading sock error: " << strerror(err));
+                LogError("Reading sock error: " << strerror(err));
                 CloseSocket(sock);
         }
     }
@@ -268,7 +268,7 @@ void SocketManager::ReadyForSendMsg(int sock) {
             break;
         case EPIPE:
         default:
-            LogDebug("Error during send: " << strerror(err));
+            LogError("Error during send: " << strerror(err));
             CloseSocket(sock);
             break;
         }
@@ -305,7 +305,7 @@ void SocketManager::ReadyForWriteBuffer(int sock) {
             break;
         case EPIPE:
         default:
-            LogDebug("Error during write: " << strerror(err));
+            LogError("Error during write: " << strerror(err));
             CloseSocket(sock);
             break;
         }
diff --git a/src/server/service/installer.cpp b/src/server/service/installer.cpp
index 743d4eae..8f7bb0c7 100644
--- a/src/server/service/installer.cpp
+++ b/src/server/service/installer.cpp
@@ -111,9 +111,11 @@ bool InstallerService::processOne(const ConnectionID &conn, MessageBuffer &buffe
 
             switch (call_type) {
                 case SecurityModuleCall::APP_INSTALL:
+                    LogDebug("call_type: SecurityModuleCall::APP_INSTALL");
                     processAppInstall(buffer, send);
                     break;
                 case SecurityModuleCall::APP_UNINSTALL:
+                    LogDebug("call_type: SecurityModuleCall::APP_UNINSTALL");
                     processAppUninstall(buffer, send);
                     break;
                 case SecurityModuleCall::APP_GET_PKGID:
@@ -163,46 +165,45 @@ bool InstallerService::processAppInstall(MessageBuffer &buffer, MessageBuffer &s
     Deserialization::Deserialize(buffer, req.privileges);
     Deserialization::Deserialize(buffer, req.appPaths);
 
-    LogDebug("appId: " << req.appId);
-    LogDebug("pkgId: " << req.pkgId);
-
     std::string smackLabel;
     if (!generateAppLabel(req.pkgId, smackLabel)) {
-        LogError("Cannot generate Smack label for package");
+        LogError("Cannot generate Smack label for package: " << req.pkgId);
         Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
         return false;
     }
-    LogDebug("Smack label: " << smackLabel);
 
-    // create null terminated array of strigns for permissions
+    LogDebug("Install parameters: appId: " << req.appId << ", pkgId: " << req.pkgId
+            << ", generated smack label: " << smackLabel);
+
+    // create null terminated array of strings for permissions
     std::unique_ptr<const char *[]> pp_permissions(new const char* [req.privileges.size() + 1]);
     for (size_t i = 0; i < req.privileges.size(); ++i) {
-        LogDebug("Permission = " << req.privileges[i]);
+        LogDebug("  Permission = " << req.privileges[i]);
         pp_permissions[i] = req.privileges[i].c_str();
     }
     pp_permissions[req.privileges.size()] = nullptr;
 
     // start database transaction
     int result = perm_begin();
-    LogDebug("perm_begin() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
         // libprivilege is locked
+        LogError("perm_begin() returned " << result);
         Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
         return false;
     }
 
     result = perm_app_install(smackLabel.c_str());
-    LogDebug("perm_app_install() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
         // libprivilege error
+        LogError("perm_app_install() returned " << result);
         goto error_label;
     }
 
     result = perm_app_enable_permissions(smackLabel.c_str(), APP_TYPE_WGT,
                                          pp_permissions.get(), true);
-    LogDebug("perm_app_enable_permissions() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
         // libprivilege error
+        LogError("perm_app_enable_permissions() returned " << result);
         goto error_label;
     }
 
@@ -230,7 +231,7 @@ bool InstallerService::processAppInstall(MessageBuffer &buffer, MessageBuffer &s
         result = setupPath(req.pkgId, path, pathType);
 
         if (!result) {
-            LogDebug("setupPath() failed ");
+            LogError("setupPath() failed");
             goto error_label;
         }
     }
@@ -245,8 +246,8 @@ bool InstallerService::processAppInstall(MessageBuffer &buffer, MessageBuffer &s
 
     // finish database transaction
     result = perm_end();
-    LogDebug("perm_end() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
+        LogError("perm_end() returned " << result);
         if (pkgIdIsNew)
             if (!SmackRules::uninstallPackageRules(req.pkgId))
                 LogWarning("Failed to rollback package-specific smack rules");
@@ -263,7 +264,8 @@ bool InstallerService::processAppInstall(MessageBuffer &buffer, MessageBuffer &s
 error_label:
     // rollback failed transaction before exiting
     result = perm_rollback();
-    LogDebug("perm_rollback() returned " << result);
+    if (PC_OPERATION_SUCCESS != result)
+        LogError("perm_rollback() returned " << result);
     Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
     return false;
 }
@@ -278,11 +280,11 @@ bool InstallerService::processAppUninstall(MessageBuffer &buffer, MessageBuffer
     bool removePkg = false;
 
     Deserialization::Deserialize(buffer, appId);
-    LogDebug("appId: " << appId);
 
     int result = perm_begin();
-    LogDebug("perm_begin() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
+        // libprivilege is locked
+        LogError("perm_begin() returned " << result);
         Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
         return false;
     }
@@ -297,13 +299,13 @@ bool InstallerService::processAppUninstall(MessageBuffer &buffer, MessageBuffer
             m_privilegeDb.RollbackTransaction();
             appExists = false;
         } else {
-            LogDebug("pkgId: " << pkgId);
-
             if (!generateAppLabel(pkgId, smackLabel)) {
-                LogError("Cannot generate Smack label for package");
+                LogError("Cannot generate Smack label for package: " << pkgId);
                 goto error_label;
             }
-            LogDebug("Smack label: " << smackLabel);
+
+            LogDebug("Unnstall parameters: appId: " << appId << ", pkgId: " << pkgId
+                    << ", generated smack label: " << smackLabel);
 
             m_privilegeDb.GetPkgPrivileges(pkgId, oldPkgPrivileges);
             m_privilegeDb.UpdateAppPrivileges(appId, std::vector<std::string>());
@@ -321,9 +323,9 @@ bool InstallerService::processAppUninstall(MessageBuffer &buffer, MessageBuffer
 
     if (appExists) {
         result = perm_app_uninstall(smackLabel.c_str());
-        LogDebug("perm_app_uninstall() returned " << result);
         if (PC_OPERATION_SUCCESS != result) {
             // error in libprivilege-control
+            LogError("perm_app_uninstall() returned " << result);
             goto error_label;
         }
 
@@ -338,9 +340,9 @@ bool InstallerService::processAppUninstall(MessageBuffer &buffer, MessageBuffer
 
     // finish database transaction
     result = perm_end();
-    LogDebug("perm_end() returned " << result);
     if (PC_OPERATION_SUCCESS != result) {
         // error in libprivilege-control
+        LogError("perm_end() returned " << result);
         Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
         return false;
     }
@@ -352,7 +354,8 @@ bool InstallerService::processAppUninstall(MessageBuffer &buffer, MessageBuffer
 error_label:
     // rollback failed transaction before exiting
     result = perm_rollback();
-    LogDebug("perm_rollback() returned " << result);
+    if (PC_OPERATION_SUCCESS != result)
+        LogError("perm_rollback() returned " << result);
     Serialization::Serialize(send, SECURITY_MANAGER_API_ERROR_SERVER_ERROR);
     return false;
 }
diff --git a/src/server/service/smack-labels.cpp b/src/server/service/smack-labels.cpp
index 0dba6048..040cf708 100644
--- a/src/server/service/smack-labels.cpp
+++ b/src/server/service/smack-labels.cpp
@@ -54,15 +54,11 @@ typedef std::function<FileDecision(const FTSENT*)> LabelDecisionFn;
 
 static FileDecision labelAll(const FTSENT *ftsent __attribute__((unused)))
 {
-    LogDebug("Entering function: " << __func__);
-
     return FileDecision::LABEL;
 }
 
 static FileDecision labelDirs(const FTSENT *ftsent)
 {
-    LogDebug("Entering function: " << __func__);
-
     // label only directories
     if (S_ISDIR(ftsent->fts_statp->st_mode))
         return FileDecision::LABEL;
@@ -71,9 +67,7 @@ static FileDecision labelDirs(const FTSENT *ftsent)
 
 static FileDecision labelExecs(const FTSENT *ftsent)
 {
-    LogDebug("Entering function: " << __func__);
-
-    LogDebug("Mode = " << ftsent->fts_statp->st_mode);
+    // LogDebug("Mode = " << ftsent->fts_statp->st_mode); // this could be helpfull in debugging
     // label only regular executable files
     if (S_ISREG(ftsent->fts_statp->st_mode) && (ftsent->fts_statp->st_mode & S_IXUSR))
         return FileDecision::LABEL;
@@ -82,8 +76,6 @@ static FileDecision labelExecs(const FTSENT *ftsent)
 
 static FileDecision labelLinksToExecs(const FTSENT *ftsent)
 {
-    LogDebug("Entering function: " << __func__);
-
     struct stat buf;
 
     // check if it's a link
@@ -103,7 +95,7 @@ static FileDecision labelLinksToExecs(const FTSENT *ftsent)
     }
     // skip if link target is not a regular executable file
     if (buf.st_mode != (buf.st_mode | S_IXUSR | S_IFREG)) {
-        LogDebug(target.get() << "is not a regular executable file. Skipping.");
+        // LogDebug(target.get() << "is not a regular executable file. Skipping.");
         return FileDecision::SKIP;
     }
 
@@ -113,10 +105,6 @@ static FileDecision labelLinksToExecs(const FTSENT *ftsent)
 static bool dirSetSmack(const std::string &path, const std::string &label,
         const char *xattr_name, LabelDecisionFn fn)
 {
-    LogDebug("Entering function: "<< __func__ <<". Params:"
-            " path=" << path << ", label=" << label << ", xattr=" << xattr_name);
-
-
     char *const path_argv[] = {const_cast<char *>(path.c_str()), NULL};
     FTSENT *ftsent;
     FileDecision ret;
@@ -164,10 +152,6 @@ static bool dirSetSmack(const std::string &path, const std::string &label,
 static bool labelDir(const std::string &path, const std::string &label,
         bool set_transmutable, bool set_executables)
 {
-    LogDebug("Entering function: "<< __func__ <<". Params:"
-            " path=" << path << " label= " << label
-            << " set_transmutable= " << set_transmutable
-            << " set_executables= " << set_executables);
     bool ret = true;
 
     // setting access label on everything in given directory and below
diff --git a/src/server/service/smack-rules.cpp b/src/server/service/smack-rules.cpp
index 6281dc27..fd530e3f 100644
--- a/src/server/service/smack-rules.cpp
+++ b/src/server/service/smack-rules.cpp
@@ -79,12 +79,12 @@ bool SmackRules::loadFromFile(const std::string &path)
 
     fd = TEMP_FAILURE_RETRY(open(path.c_str(), O_RDONLY));
     if (fd == -1) {
-        LogError("Failed to open file: %s" << path);
+        LogError("Failed to open file: " << path);
         return false;
     }
 
     if (smack_accesses_add_from_file(m_handle, fd)) {
-        LogError("Failed to load smack rules from file: %s" << path);
+        LogError("Failed to load smack rules from file: " << path);
         ret = false;
     }
 
@@ -103,12 +103,12 @@ bool SmackRules::saveToFile(const std::string &path) const
 
     fd = TEMP_FAILURE_RETRY(open(path.c_str(), O_CREAT | O_WRONLY | O_TRUNC, 0644));
     if (fd == -1) {
-        LogError("Failed to create file: %s" << path);
+        LogError("Failed to create file: " << path);
         return false;
     }
 
     if (smack_accesses_save(m_handle, fd)) {
-        LogError("Failed to save rules to file: %s" << path);
+        LogError("Failed to save rules to file: " << path);
         unlink(path.c_str());
         ret = false;
     }