Merge "Extended Android file store error logs." into sc-dev am: 93cfe22910

Original change: https://googleplex-android-review.googlesource.com/c/platform/vendor/widevine/+/13736812

Change-Id: I8c7cc8bd3347684e3953e275e98bbb6f2eb637a9

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;
           }
         }