Further SAL_INFO("sal.file",...) tweaks

Now it should be fairly close to the (IMHO) ideal: One
SAL_INFO("sal.file") per file system system call. (Not read() and
write().)

Sure, on Linux one could just use strace, but my interest at the
moment is debugging what goes on on iOS.

Change-Id: I19ec0404c0c15a957de96d98376b4338b48a8cbd
Reviewed-on: https://gerrit.libreoffice.org/61687
Tested-by: Jenkins
Reviewed-by: Tor Lillqvist <tml@collabora.com>

3 files changed, 83 insertions, 28 deletions

diff --git a/sal/osl/unx/file.cxx b/sal/osl/unx/file.cxx
index 62ed5ed734d0..71f53470dd0e 100644
--- a/sal/osl/unx/file.cxx
+++ b/sal/osl/unx/file.cxx
@@ -255,25 +255,40 @@ oslFileError FileHandle_Impl::setSize(sal_uInt64 uSize)
         /* Save current position */
         off_t const nCurPos = lseek(m_fd, off_t(0), SEEK_CUR);
         if (nCurPos == off_t(-1))
+        {
+            int e = errno;
+            SAL_INFO("sal.file", "lseek(" << m_fd << ",0,SEEK_CUR): errno " << e << ": " << strerror(e));
             return result;
+        }
+        else
+            SAL_INFO("sal.file", "lseek(" << m_fd << ",0,SEEK_CUR): OK");
 
         /* Try 'expand' via 'lseek()' and 'write()' */
         if (lseek(m_fd, static_cast<off_t>(nSize - 1), SEEK_SET) == -1)
+        {
+            int e = errno;
+            SAL_INFO("sal.file", "lseek(" << m_fd << "," << nSize - 1 << ",SEEK_SET): errno " << e << ": " << strerror(e));
             return result;
+        }
+        else
+            SAL_INFO("sal.file", "lseek(" << m_fd << "," << nSize - 1 << ",SEEK_SET): OK");
 
         if (write(m_fd, "", size_t(1)) == -1)
         {
             /* Failure. Restore saved position */
+            int e = errno;
+            SAL_INFO("sal.file", "write(" << m_fd << ",\"\",1): errno " << e << ": " << strerror(e));
             (void) lseek(m_fd, nCurPos, SEEK_SET);
             return result;
         }
+        else
+            SAL_INFO("sal.file", "write(" << m_fd << ",\"\",1): OK");
 
         /* Success. Restore saved position */
         if (lseek(m_fd, nCurPos, SEEK_SET) == -1)
             return result;
     }
 
-    SAL_INFO("sal.file", "osl_setFileSize(" << m_fd << ", " << getSize() << ") => " << nSize);
     m_size = sal::static_int_cast< sal_uInt64 >(nSize);
     return osl_File_E_None;
 }
@@ -886,9 +901,7 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
     int fd = open_c( cpFilePath, flags, mode );
     if (fd == -1)
     {
-        int saved_errno = errno;
-        SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << ") failed: " << strerror(saved_errno));
-        return oslTranslateFileError(saved_errno);
+        return oslTranslateFileError(errno);
     }
 
 #if !HAVE_FEATURE_MACOSX_SANDBOX
@@ -898,21 +911,27 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
         int f = fcntl(fd, F_GETFL, 0);
         if (f == -1)
         {
-            int saved_errno = errno;
-            SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << "): fcntl(" << fd << ", F_GETFL) failed: " << strerror(saved_errno));
-            eRet = oslTranslateFileError(saved_errno);
+            int e = errno;
+            SAL_INFO("sal.file", "fcntl(" << fd << ",F_GETFL,0): errno " << e << ": " << strerror(e));
+            eRet = oslTranslateFileError(e);
             (void) close(fd);
+            SAL_INFO("sal.file", "close(" << fd << ")");
             return eRet;
         }
+        else
+            SAL_INFO("sal.file", "fcntl(" << fd << ",F_GETFL,0): OK");
 
         if (fcntl(fd, F_SETFL, (f & ~O_NONBLOCK)) == -1)
         {
-            int saved_errno = errno;
-            SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << "): fcntl(" << fd << ", F_SETFL) failed: " << strerror(saved_errno));
-            eRet = oslTranslateFileError(saved_errno);
+            int e = errno;
+            SAL_INFO("sal.file", "fcntl(" << fd << ",F_SETFL,(f & ~O_NONBLOCK)): errno " << e << ": " << strerror(e));
+            eRet = oslTranslateFileError(e);
             (void) close(fd);
+            SAL_INFO("sal.file", "close(" << fd << ")");
             return eRet;
         }
+        else
+            SAL_INFO("sal.file", "fcntl(" << fd << ",F_SETFL,(f & ~O_NONBLOCK)): OK");
     }
 #endif
 
@@ -920,18 +939,22 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
     struct stat aFileStat;
     if (fstat(fd, &aFileStat) == -1)
     {
-        int saved_errno = errno;
-        SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << "): fstat(" << fd << ") failed: " << strerror(saved_errno));
-        eRet = oslTranslateFileError(saved_errno);
+        int e = errno;
+        SAL_INFO("sal.file", "fstat(" << fd << "): errno " << e << ": " << strerror(e));
+        eRet = oslTranslateFileError(e);
         (void) close(fd);
+        SAL_INFO("sal.file", "close(" << fd << ")");
         return eRet;
     }
+    else
+        SAL_INFO("sal.file", "fstat(" << fd << "): OK");
 
     if (!S_ISREG(aFileStat.st_mode))
     {
         /* we only open regular files here */
         SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << "): not a regular file");
         (void) close(fd);
+        SAL_INFO("sal.file", "close(" << fd << ")");
         return osl_File_E_INVAL;
     }
 
@@ -940,14 +963,19 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
 #ifdef MACOSX
         if (flock(fd, LOCK_EX | LOCK_NB) == -1)
         {
+            int e = errno;
+            SAL_INFO("sal.file", "flock(" << fd << ",LOCK_EX|LOCK_NB): errno " << e << ": " << strerror(e));
             /* Mac OSX returns ENOTSUP for webdav drives. We should try read lock */
-            if ((errno != ENOTSUP) || ((flock(fd, LOCK_SH | LOCK_NB) == 1) && (errno != ENOTSUP)))
+            if ((e != ENOTSUP) || ((flock(fd, LOCK_SH | LOCK_NB) == 1) && (errno != ENOTSUP)))
             {
                 eRet = oslTranslateFileError(errno);
                 (void) close(fd);
+                SAL_INFO("sal.file", "close(" << fd << ")");
                 return eRet;
             }
         }
+        else
+            SAL_INFO("sal.file", "flock(" << fd << ",LOCK_EX|LOCK_NB): OK");
 #else   /* F_SETLK */
         struct flock aflock;
 
@@ -958,10 +986,11 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
 
         if (fcntl(fd, F_SETLK, &aflock) == -1)
         {
-            int saved_errno = errno;
-            SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << "): fcntl(" << fd << ", F_SETLK) failed: " << strerror(saved_errno));
-            eRet = oslTranslateFileError(saved_errno);
+            int e = errno;
+            SAL_INFO("sal.file", "fcntl(" << fd << ",F_SETLK): errno " << e << ": " << strerror(e));
+            eRet = oslTranslateFileError(e);
             (void) close(fd);
+            SAL_INFO("sal.file", "close(" << fd << ")");
             return eRet;
         }
 #endif  /* F_SETLK */
@@ -974,8 +1003,6 @@ oslFileError openFilePath(const char *cpFilePath, oslFileHandle* pHandle, sal_uI
 
     pImpl->m_size = sal::static_int_cast< sal_uInt64 >(aFileStat.st_size);
 
-    SAL_INFO("sal.file", "osl_openFile(" << cpFilePath << ", " << ((flags & O_RDWR) ? "writeable":"readonly") << ") => " << pImpl->m_fd);
-
     *pHandle = static_cast<oslFileHandle>(pImpl);
 
     return osl_File_E_None;
@@ -1014,8 +1041,6 @@ oslFileError SAL_CALL osl_closeFile(oslFileHandle Handle)
     if (!pImpl)
         return osl_File_E_INVAL;
 
-    SAL_INFO("sal.file", "osl_closeFile(" << rtl::OString(pImpl->m_strFilePath) << ":" << pImpl->m_fd << ")");
-
     if (pImpl->m_kind == FileHandle_Impl::KIND_MEM)
     {
 #ifdef ANDROID
@@ -1037,12 +1062,17 @@ oslFileError SAL_CALL osl_closeFile(oslFileHandle Handle)
     {
         /* close, ignoring double failure */
         (void) close(pImpl->m_fd);
+        SAL_INFO("sal.file", "close(" << pImpl->m_fd << ")");
     }
     else if (close(pImpl->m_fd) == -1)
     {
+        int e = errno;
+        SAL_INFO("sal.file", "close(" << pImpl->m_fd << "): errno " << e << ": " << strerror(e));
         /* translate error code */
-        result = oslTranslateFileError(errno);
+        result = oslTranslateFileError(e);
     }
+    else
+        SAL_INFO("sal.file", "close(" << pImpl->m_fd << "): OK");
 
     (void) pthread_mutex_unlock(&(pImpl->m_mutex));
     delete pImpl;
diff --git a/sal/osl/unx/file_misc.cxx b/sal/osl/unx/file_misc.cxx
index 307a0f81afc7..8bc4303dce42 100644
--- a/sal/osl/unx/file_misc.cxx
+++ b/sal/osl/unx/file_misc.cxx
@@ -883,10 +883,10 @@ void attemptChangeMetadata( const sal_Char* pszFileName, mode_t nMode, time_t nA
 #endif
     {
         int e = errno;
-        SAL_INFO("sal.file", "chmod(" << pszFileName << std::oct << nMode << std::dec <<"): errno " << e << ": " << strerror(e));
+        SAL_INFO("sal.file", "chmod(" << pszFileName << ",0" << std::oct << nMode << std::dec <<"): errno " << e << ": " << strerror(e));
     }
     else
-        SAL_INFO("sal.file", "chmod(" << pszFileName << std::oct << nMode << std::dec <<"): OK");
+        SAL_INFO("sal.file", "chmod(" << pszFileName << ",0" << std::oct << nMode << std::dec <<"): OK");
 
     // No way to change utime of a symlink itself:
     if (!S_ISLNK(nMode))
@@ -964,12 +964,12 @@ static int oslDoCopyFile(const sal_Char* pszSourceFileName, const sal_Char* pszD
     if ( DestFileFD < 0 )
     {
         nRet=errno;
-        SAL_INFO("sal.file", "open(" << pszDestFileName << ",O_WRONLY|O_CREAT," << std::oct << mode << std::dec << "): errno " << nRet << ": " << strerror(nRet));
+        SAL_INFO("sal.file", "open(" << pszDestFileName << ",O_WRONLY|O_CREAT,0" << std::oct << mode << std::dec << "): errno " << nRet << ": " << strerror(nRet));
         osl_closeFile(SourceFileFH);
         return nRet;
     }
     else
-        SAL_INFO("sal.file", "open(" << pszDestFileName << ",O_WRONLY|O_CREAT," << std::oct << mode << std::dec << "): OK");
+        SAL_INFO("sal.file", "open(" << pszDestFileName << ",O_WRONLY|O_CREAT,0" << std::oct << mode << std::dec << "): OK");
 
     size_t nRemains = nSourceSize;
 
@@ -1005,8 +1005,15 @@ static int oslDoCopyFile(const sal_Char* pszSourceFileName, const sal_Char* pszD
     }
 
     osl_closeFile( SourceFileFH );
-    if ( close( DestFileFD ) == -1 && nRet == 0 )
-        nRet = errno;
+    if ( close( DestFileFD ) == -1 )
+    {
+        int e = errno;
+        SAL_INFO("sal.file", "close(" << DestFileFD << "): errno " << e << ": " << strerror(e));
+        if ( nRet == 0 )
+            nRet = e;
+    }
+    else
+        SAL_INFO("sal.file", "close(" << DestFileFD << "): OK");
 
     return nRet;
 }
diff --git a/sal/osl/unx/uunxapi.cxx b/sal/osl/unx/uunxapi.cxx
index a6dd0954bf41..3d8fb144a255 100644
--- a/sal/osl/unx/uunxapi.cxx
+++ b/sal/osl/unx/uunxapi.cxx
@@ -24,6 +24,7 @@
 #include <limits.h>
 #include <rtl/ustring.hxx>
 #include <osl/thread.h>
+#include <sal/log.hxx>
 
 #ifdef ANDROID
 #include <osl/detail/android-bootstrap.h>
@@ -288,6 +289,13 @@ int open_c(const char *cpPath, int oflag, int mode)
     accessFilePathState *state = prepare_to_access_file_path(cpPath);
 
     int result = open(cpPath, oflag, mode);
+    int saved_errno = errno;
+    if (result == -1)
+    {
+        SAL_INFO("sal.file", "open(" << cpPath << ",0" << std::oct << oflag << ",0" << mode << std::dec << "): errno " << saved_errno << ": " << strerror(saved_errno));
+    }
+    else
+        SAL_INFO("sal.file", "open(" << cpPath << ",0" << std::oct << oflag << ",0" << mode << std::dec << ") => " << result);
 
 #if HAVE_FEATURE_MACOSX_SANDBOX
     if (isSandboxed && result != -1 && (oflag & O_CREAT) && (oflag & O_EXCL))
@@ -318,6 +326,8 @@ int open_c(const char *cpPath, int oflag, int mode)
 
     done_accessing_file_path(cpPath, state);
 
+    errno = saved_errno;
+
     return result;
 }
 
@@ -353,6 +363,14 @@ int ftruncate_with_name(int fd, sal_uInt64 uSize, rtl_String* path)
 
     int result = ftruncate(fd, uSize);
 
+    if (result < 0)
+    {
+        int e = errno;
+        SAL_INFO("sal.file", "ftruncate(" << fd << "," << uSize << "): errno " << e << ": " << strerror(e));
+    }
+    else
+        SAL_INFO("sal.file", "ftruncate(" << fd << "," << uSize << "): OK");
+
     done_accessing_file_path(fn.getStr(), state);
 
     return result;