Extended Android file store error logs.

[ Merge of http://go/wvgerrit/120763 ]

This change introduces additional logging information for files and
file system operations on Android.

File reading and writing will attempt to make sense of |errno| and
log useful information.   In the event that the file must be closed,
the file stat will be printed.

Failures in determining the file size will print potential reasons for
the encountered error.

This partly restructures the File interface implementation to use file
descriptors instead of the C standard libraries FILE handle.  This is
done to ensure that |errno| is set to an expected value.

This change also introduces the utility functions SafeWrite() and
SafeRead() to handle common, retriable errors.

Bug: 178232354
Test: Android MediaDrm GTS and Android file-based unittests
Change-Id: I15a3c47a271098c9edb4bd9f619ed1a12dca6143

libwvdrmengine/cdm/util/include/file_utils.h

@@ -13,7 +13,7 @@ const char kCurrentDirectory[] = ".";
 const char kParentDirectory[] = "..";
 const char kDirectoryDelimiter = '/';
 const char kWildcard[] = "*";
-bool IsCurrentOrParentDirectory(char* dir);
+bool IsCurrentOrParentDirectory(const char* dir);
 
 class FileUtils {
  public:

libwvdrmengine/cdm/util/src/file_store.cpp

@@ -6,17 +6,16 @@
 
 #include "file_store.h"
 
-#include <dirent.h>
 #include <errno.h>
 #include <fcntl.h>
-#include <stdio.h>
-#include <sys/sendfile.h>
+#include <string.h>
 #include <sys/stat.h>
 #include <sys/types.h>
+#include <threads.h>
+#include <time.h>
 #include <unistd.h>
 
-#include <cstring>
-#include <memory>
+#include <algorithm>
 
 #include "file_utils.h"
 #include "log.h"
@@ -24,17 +23,265 @@
 #include "wv_cdm_constants.h"
 
 #include <openssl/md5.h>
-#include <openssl/sha.h>
+
+// Size of the thread-local error string buffer.  Used for calls
+// to strerror_r(3).
+#define ERRORSTR_BUF_SIZE 1024
 
 namespace wvcdm {
-
 namespace {
+// Maximum number of attempts to read or write on a file.
+constexpr size_t kMaxIoAttempts = 5;
+
+// Stand in constant for a closed file descriptor.
+constexpr int kClosedFd = -1;
+
+// A reset value of |errno|.  Although unlikely, it is possible that a
+// system call could fail and not set |errno| to a new value.  This
+// would technically be a bug with glibc, but it could cause our error
+// handling code to enter a bad state.
+constexpr int kNoError = 0;
+
+// Reads from file specified by |fd| into the provided |buffer| up to
+// the number of bytes specified by |count|.
+// This is an internal function and assumes that all parameters are
+// valid.
+//
+// Returns:
+//    0 to |count| - Number of bytes successfully read from file.
+//    -1           - Error occurred, check |errno| for read(2).
+ssize_t SafeRead(int fd, char* buffer, size_t count) {
+  size_t attempts = 0;
+  size_t total_bytes_read = 0;
+  while (total_bytes_read < count && attempts < kMaxIoAttempts) {
+    const size_t to_read = count - total_bytes_read;
+    errno = kNoError;
+    const ssize_t res = read(fd, buffer, to_read);
+    if (res > 0) {
+      attempts = 0;  // Clearing |attempts| on success.
+      // It is possible that fewer bytes than |to_read| were read.
+      // In this case, try reading again.  Non-critical errors will
+      // likely result in success or |errno| being set to EAGAIN on
+      // the second call.  Critical errors will result in a different
+      // error that the caller will need to handle.
+      total_bytes_read += static_cast<size_t>(res);
+      continue;
+    }
+    if (res == 0) return total_bytes_read;  // EOF.
+    attempts++;
+    if ((errno != EINTR && errno != EAGAIN) || attempts >= kMaxIoAttempts) {
+      // Caller must handle all other errors, or if max attempts
+      // have been reached.
+      return -1;
+    }
+    // read() was interrupted by signal, safe to try again.
+  }
+  return total_bytes_read;
+}
+
+// Writes to the file specified by |fd| from the provided |buffer|.
+// Function will attempt to write all bytes specified by |count|.
+// This is an internal function and assumes that all parameters are
+// valid.
+//
+// Returns:
+//    |count| - Successfully wrote all bytes to file.
+//    -1      - Error occurred, check |errno| for write(2).
+ssize_t SafeWrite(int fd, const char* buffer, size_t count) {
+  size_t attempts = 0;
+  size_t total_bytes_written = 0;
+  while (total_bytes_written < count && attempts < kMaxIoAttempts) {
+    const size_t to_write = count - total_bytes_written;
+    errno = kNoError;
+    const ssize_t res = write(fd, &buffer[total_bytes_written], to_write);
+    if (res > 0) {
+      attempts = 0;  // Clearing |attempts| on success.
+      // It is possible that fewer bytes than |to_write| were written.
+      // In this case, try writing again.  Non-critical errors will
+      // likely result in success or |errno| being set to EAGAIN on
+      // the second call.  Critical errors will result in a different
+      // error that the caller will need to handle.
+      total_bytes_written += static_cast<size_t>(res);
+      continue;
+    }
+    if (res == 0) return total_bytes_written;  // Possible EOF.
+    attempts++;
+    if ((errno != EINTR && errno != EAGAIN) || attempts >= kMaxIoAttempts) {
+      // Caller must handle all other errors, or if max attempts
+      // have been reached.
+      return -1;
+    }
+    // write() was interrupted by signal, safe to try again.
+  }
+  return total_bytes_written;
+}
+
+// Converts the provided error number to its string representation.
+// Supports a subset of error numbers expected from the system calls
+// used in this module.
+// TODO(b/183653374): Replace this with strerrorname_np().
+const char* ErrnoToString(int num) {
+  switch (num) {
+    case kNoError:
+      return "ZERO";
+    case EACCES:
+      return "EACCES";
+    case EAGAIN:
+      return "EAGAIN";
+    case EBADF:
+      return "EBADF";
+    case EBUSY:
+      return "EBUSY";
+    case EDESTADDRREQ:
+      return "EDESTADDRREQ";
+    case EDQUOT:
+      return "EDQUOT";
+    case EEXIST:
+      return "EEXIST";
+    case EFAULT:
+      return "EFAULT";
+    case EFBIG:
+      return "EFBIG";
+    case EINTR:
+      return "EINTR";
+    case EINVAL:
+      return "EINVAL";
+    case EIO:
+      return "EIO";
+    case EISDIR:
+      return "EISDIR";
+    case ELOOP:
+      return "ELOOP";
+    case EMFILE:
+      return "EMFILE";
+    case ENAMETOOLONG:
+      return "ENAMETOOLONG";
+    case ENFILE:
+      return "ENFILE";
+    case ENODEV:
+      return "ENODEV";
+    case ENOENT:
+      return "ENOENT";
+    case ENOMEM:
+      return "ENOMEM";
+    case ENOSPC:
+      return "ENOSPC";
+    case ENOTDIR:
+      return "ENOTDIR";
+    case ENXIO:
+      return "ENXIO";
+    case EOPNOTSUPP:
+      return "EOPNOTSUPP";
+    case EOVERFLOW:
+      return "EOVERFLOW";
+    case EPERM:
+      return "EPERM";
+    case EPIPE:
+      return "EPIPE";
+    case EROFS:
+      return "EROFS";
+    case ETXTBSY:
+      return "ETXTBSY";
+#if EWOULDBLOCK != EAGAIN
+    case EWOULDBLOCK:
+      return "EWOULDBLOCK";
+#endif
+  }
+  return "UNKNOWN";
+}
+
+// Safely converts the provided error number to its standard
+// description string as provided by strerror_r().
+// This function is guaranteed to return null-terminated string,
+// and is thread safe.
+const char* ErrnoToDescription(int num) {
+  static thread_local char error_buf[ERRORSTR_BUF_SIZE];
+  if (num == kNoError) {
+    return "Unspecified error";
+  }
+  // Always ensure there is a null term.
+  error_buf[sizeof(error_buf) - 1] = 0;
+  // See strerror_l(3) manual page for details.
+#if (_POSIX_C_SOURCE >= 200112L || _XOPEN_SOURCE >= 600) && !_GNU_SOURCE
+  // Portable version:
+  //    int strerror_r(int num, char* buf, size_t buflen)
+  // Returns:
+  //    0 on success
+  //    -1 or a positive value on error (depends on glibc version)
+  const int res = strerror_r(num, error_buf, sizeof(error_buf));
+  return res != 0 ? "Unknown" : error_buf;
+#else
+  // GNU specific version:
+  //    char* strerror_r(int num, char* buf, size_t buflen)
+  // Returns:
+  //    Pointer to |buf| or internal string on success
+  //    Null on error
+  const char* res = strerror_r(num, error_buf, sizeof(error_buf));
+  return res == nullptr ? "Unknown" : res;
+#endif
+}
+
+// Converts the provided file |mode| to a "ls" style file mode.
+std::string StatModeToString(unsigned int mode) {
+  std::string mode_rep;
+  mode_rep.reserve(11);  // 1 file type + 9 permissions + 1 term.
+  // File type.
+  if (S_ISREG(mode)) {
+    mode_rep.append("-");
+  } else if (S_ISDIR(mode)) {
+    mode_rep.append("d");
+  } else if (S_ISLNK(mode)) {
+    mode_rep.append("l");
+  } else if (S_ISCHR(mode)) {
+    mode_rep.append("c");
+  } else if (S_ISBLK(mode)) {
+    mode_rep.append("b");
+  } else if (S_ISSOCK(mode)) {
+    mode_rep.append("s");
+  } else {
+    mode_rep.append("?");
+  }
+  // User owner permission.
+  mode_rep.append((mode & S_IRUSR) ? "r" : "-");
+  mode_rep.append((mode & S_IWUSR) ? "w" : "-");
+  mode_rep.append((mode & S_IXUSR) ? "x" : "-");
+  // Group owner permission.
+  mode_rep.append((mode & S_IRGRP) ? "r" : "-");
+  mode_rep.append((mode & S_IWGRP) ? "w" : "-");
+  mode_rep.append((mode & S_IXGRP) ? "x" : "-");
+  // Others permission.
+  mode_rep.append((mode & S_IROTH) ? "r" : "-");
+  mode_rep.append((mode & S_IWOTH) ? "w" : "-");
+  mode_rep.append((mode & S_IXOTH) ? "x" : "-");
+  return mode_rep;
+}
+
+// Coverts the provided system time in seconds to a string representation
+// in the system's local time.
+// Time format is a modified ISO8601.
+//    Example: 2021-03-01 12:32:53
+// If the time cannot be converted into this format, then the decimal
+// representation of seconds are returned.
+std::string PosixTimeToString(time_t seconds) {
+  struct tm timestamp;
+  if (localtime_r(&seconds, &timestamp) == nullptr) {
+    // Only possible failure is an overflow.
+    return std::to_string(seconds);
+  }
+  char buffer[32];
+  memset(buffer, 0, sizeof(buffer));
+  const size_t length = strftime(buffer, sizeof(buffer), "%F %T", &timestamp);
+  if (length == 0) {
+    // Unexpected error.  Just return seconds.
+    return std::to_string(seconds);
+  }
+  return std::string(buffer, length);
+}
 
 std::string GetFileNameSafeHash(const std::string& input) {
   std::vector<uint8_t> hash(MD5_DIGEST_LENGTH);
-  const unsigned char* input_ptr =
-      reinterpret_cast<const unsigned char*>(input.data());
-  MD5(input_ptr, input.size(), &hash[0]);
+  MD5(reinterpret_cast<const uint8_t*>(input.data()), input.size(),
+      hash.data());
   return wvcdm::Base64SafeEncode(hash);
 }
 
@@ -59,63 +306,120 @@ std::string GetFileNameForIdentifier(const std::string path,
 
   if (dir_path.empty())
     return file_name;
-  else
-    return dir_path + kDirectoryDelimiter + file_name;
+  return dir_path + kDirectoryDelimiter + file_name;
 }
 }  // namespace
 
-class FileImpl : public File {
+class AndroidFile : public File {
  public:
-  FileImpl(FILE* file, const std::string& file_path)
-      : file_(file), file_path_(file_path) {}
+  // Parameters:
+  //   |fd|        - Open file descriptor for a regular file.
+  //   |flags|     - Bit field of flags originally passed to FileSystem::Open()
+  //   |file_path| - Path used to open file.
+  AndroidFile(int fd, int flags, const std::string& file_path)
+      : fd_(fd), flags_(flags), file_path_(file_path) {}
 
-  void FlushFile() {
-    fflush(file_);
-    fsync(fileno(file_));
-  }
+  ~AndroidFile() { Close(); }
 
-  ~FileImpl() {
-    if (file_) {
-      FlushFile();
-      fclose(file_);
-      file_ = nullptr;
-    }
-  }
+  bool IsOpen() const { return fd_ != kClosedFd; }
+
+  bool CanWrite() const { return !(flags_ & FileSystem::kReadOnly); }
+
+  // Used for logging.
+  const char* file_path() const { return file_path_.c_str(); }
 
   ssize_t Read(char* buffer, size_t bytes) override {
     if (!buffer) {
-      LOGW("File::Read: buffer is empty");
+      LOGE("Output |buffer| is null");
       return -1;
     }
-    if (!file_) {
-      LOGW("File::Read: file not open");
+    if (!IsOpen()) {
+      LOGE("File not open: path = %s", file_path());
       return -1;
     }
-    size_t len = fread(buffer, sizeof(char), bytes, file_);
-    if (len != bytes) {
-      LOGW("File::Read: fread failed: %d, %s", errno, strerror(errno));
+    const ssize_t res = SafeRead(fd_, buffer, bytes);
+    if (res < 0) {
+      const int saved_errno = errno;
+      LOGE("Read failed: errno = %s (%d), desc = %s",
+           ErrnoToString(saved_errno), saved_errno,
+           ErrnoToDescription(saved_errno));
+      return -1;
+    } else if (res < bytes) {
+      LOGD("Read output truncated: expected = %zu, actual = %zd", bytes, res);
     }
-    return len;
+    return res;
   }
 
   ssize_t Write(const char* buffer, size_t bytes) override {
     if (!buffer) {
-      LOGW("File::Write: buffer is empty");
+      LOGE("Input |buffer| is null");
       return -1;
     }
-    if (!file_) {
-      LOGW("File::Write: file not open");
+    if (!IsOpen()) {
+      LOGE("File not open: path = %s", file_path());
       return -1;
     }
-    size_t len = fwrite(buffer, sizeof(char), bytes, file_);
-    if (len != bytes) {
-      LOGW("File::Write: fwrite failed: %d, %s", errno, strerror(errno));
+    if (!CanWrite()) {
+      LOGE("File is read only: path = %s", file_path());
+      return -1;
+    }
+    const ssize_t res = SafeWrite(fd_, buffer, bytes);
+    if (res < 0) {
+      const int saved_errno = errno;
+      LOGE("Write failed: errno = %s (%d), desc = %s",
+           ErrnoToString(saved_errno), saved_errno,
+           ErrnoToDescription(saved_errno));
+      return -1;
     }
     FlushFile();
-    return len;
+    return res;
   }
 
-  FILE* file_;
+ private:
+  void FlushFile() { fsync(fd_); }
+
+  void Close() {
+    if (IsOpen()) {
+      FlushFile();
+      close(fd_);
+      fd_ = kClosedFd;
+    }
+  }
+
+  // Logs the contents of the file's stat info.
+  void LogStat() const {
+    if (!IsOpen()) {
+      LOGD("No stat info available");
+      return;
+    }
+    struct stat st;
+    errno = kNoError;
+    if (fstat(fd_, &st) != 0) {
+      const int saved_errno = errno;
+      if (errno != EBADF) {
+        // No logs if an issue with FD, caller would have indicated the problem.
+        LOGE("Stat failed: errno = %s (%d), desc = %s",
+             ErrnoToString(saved_errno), saved_errno,
+             ErrnoToDescription(saved_errno));
+      }
+      return;
+    }
+    LOGD(
+        "Stat: path = %s, st_dev = %lu, st_ino = %lu, st_mode = 0%o (%s), "
+        "st_uid = %u, st_gid = %u, st_size = %ld, st_atime = %s, "
+        "st_mtime = %s, st_ctime = %s",
+        file_path(), st.st_dev, st.st_ino, st.st_mode,
+        StatModeToString(st.st_mode).c_str(), st.st_uid, st.st_gid, st.st_size,
+        PosixTimeToString(st.st_atime).c_str(),
+        PosixTimeToString(st.st_mtime).c_str(),
+        PosixTimeToString(st.st_ctime).c_str());
+  }
+
+  // File descriptor of the opened file.  Set to -1 when closed.
+  int fd_ = kClosedFd;
+  // Bit field of OpenFlags.
+  int flags_ = 0;
+  // Path used to open the file descriptor.
   std::string file_path_;
 };
 
@@ -127,39 +431,65 @@ FileSystem::FileSystem(const std::string& origin, void* /* extra_data */)
 
 FileSystem::~FileSystem() {}
 
-std::unique_ptr<File> FileSystem::Open(const std::string& in_name, int flags) {
-  std::string open_flags;
+std::unique_ptr<File> FileSystem::Open(const std::string& file_name,
+                                       int flags) {
+  const std::string file_path =
+      GetFileNameForIdentifier(file_name, identifier_);
+  // Verify flags.
+  if ((flags & kReadOnly) && (flags & kTruncate)) {
+    LOGE(
+        "Cannot be both truncated and be read-only: "
+        "file = %s, identifier = %s",
+        file_name.c_str(), identifier_.c_str());
+    return nullptr;
+  }
 
-  std::string name = GetFileNameForIdentifier(in_name, identifier_);
-
-  // create the enclosing directory if it does not exist
-  size_t delimiter_pos = name.rfind(kDirectoryDelimiter);
+  // Create the enclosing directory if it does not exist.
+  const size_t delimiter_pos = file_path.rfind(kDirectoryDelimiter);
   if (delimiter_pos != std::string::npos) {
-    std::string dir_path = name.substr(0, delimiter_pos);
+    const std::string dir_path = file_path.substr(0, delimiter_pos);
     if ((flags & FileSystem::kCreate) && !Exists(dir_path))
       FileUtils::CreateDirectory(dir_path);
   }
 
-  // ensure only owners has access
-  mode_t old_mask = umask(077);
-  if (((flags & FileSystem::kTruncate) && Exists(name)) ||
-      ((flags & FileSystem::kCreate) && !Exists(name))) {
-    FILE* fp = fopen(name.c_str(), "w+");
-    if (fp) {
-      fclose(fp);
-    }
-  }
-
-  open_flags = (flags & FileSystem::kReadOnly) ? "rb" : "rb+";
-
-  FILE* file = fopen(name.c_str(), open_flags.c_str());
-  umask(old_mask);
-  if (!file) {
-    LOGW("File::Open: fopen failed: %d, %s", errno, strerror(errno));
+  const bool exists = Exists(file_path);
+  if (!(flags & kCreate) && !exists) {
+    LOGD("File does not exist: file = %s, identifier = %s", file_name.c_str(),
+         identifier_.c_str());
     return nullptr;
   }
 
-  return std::unique_ptr<File>(new FileImpl(file, name));
+  const int open_flags = ((flags & kCreate) ? O_CREAT : 0) |
+                         ((flags & kReadOnly) ? O_RDONLY : O_RDWR) |
+                         ((flags & kTruncate) ? O_TRUNC : 0) |
+                         O_CLOEXEC;  // Never share on calls to exec().
+  constexpr mode_t kDefaultMode = S_IRUSR | S_IWUSR;
+  errno = kNoError;
+  const int fd = open(file_path.c_str(), open_flags, kDefaultMode);
+  if (fd < 0) {
+    const int saved_errno = errno;
+    LOGE("%s failed: errno = %s (%d), desc = %s, path = %s",
+         exists ? "Open" : "Create", ErrnoToString(saved_errno), saved_errno,
+         ErrnoToDescription(saved_errno), file_path.c_str());
+    return nullptr;
+  }
+  // Check that the opened file is a regular file.
+  struct stat st;
+  errno = kNoError;
+  if (fstat(fd, &st) != 0) {
+    const int saved_errno = errno;
+    LOGE("Stat failed: errno = %s (%d), desc = %s", ErrnoToString(saved_errno),
+         saved_errno, ErrnoToDescription(saved_errno));
+    close(fd);
+    return nullptr;
+  }
+  if (!S_ISREG(st.st_mode)) {
+    LOGE("Not a file: path = %s, st_mode = 0%o (%s)", file_path.c_str(),
+         st.st_mode, StatModeToString(st.st_mode).c_str());
+    close(fd);
+    return nullptr;
+  }
+  return std::unique_ptr<File>(new AndroidFile(fd, flags, file_path));
 }
 
 bool FileSystem::Exists(const std::string& path) {
@@ -170,13 +500,22 @@ bool FileSystem::Remove(const std::string& path) {
   return FileUtils::Remove(GetFileNameForIdentifier(path, identifier_));
 }
 
-ssize_t FileSystem::FileSize(const std::string& in_path) {
-  std::string path = GetFileNameForIdentifier(in_path, identifier_);
-  struct stat buf;
-  if (stat(path.c_str(), &buf) == 0)
-    return buf.st_size;
-  else
-    return -1;
+ssize_t FileSystem::FileSize(const std::string& file_name) {
+  const std::string file_path =
+      GetFileNameForIdentifier(file_name, identifier_);
+  struct stat st;
+  errno = kNoError;
+  if (stat(file_path.c_str(), &st) == 0) {
+    if (st.st_size == 0) {
+      LOGW("File is empty: name = %s", file_name.c_str());
+    }
+    return st.st_size;
+  }
+  // Else, error occurred.
+  const int saved_errno = errno;
+  LOGE("Stat failed: errno = %s (%d), desc = %s", ErrnoToString(saved_errno),
+       saved_errno, ErrnoToDescription(saved_errno));
+  return -1;
 }
 
 bool FileSystem::List(const std::string& path,
@@ -189,5 +528,4 @@ void FileSystem::set_origin(const std::string& origin) { origin_ = origin; }
 void FileSystem::set_identifier(const std::string& identifier) {
   identifier_ = identifier;
 }
-
 }  // namespace wvcdm

libwvdrmengine/cdm/util/src/file_utils.cpp

@@ -21,7 +21,7 @@
 
 namespace wvcdm {
 
-bool IsCurrentOrParentDirectory(char* dir) {
+bool IsCurrentOrParentDirectory(const char* dir) {
   return strcmp(dir, kCurrentDirectory) == 0 ||
          strcmp(dir, kParentDirectory) == 0;
 }
@@ -48,6 +48,8 @@ bool FileUtils::Remove(const std::string& path) {
           path_to_remove += entry->d_name;
           if (!Remove(path_to_remove)) {
             closedir(dir);
+            LOGW("Failed to remove directory entry: dir_path = %s, entry = %s",
+                 path.c_str(), entry->d_name);
             return false;
           }
         }