recovery: use __android_log_pmsg_file_write for log files

(cherry-pick from commit a4f701af93)

- Add call to __android_log_pmsg_file_write for recovery logging.
- Add call to refresh pmsg if we reboot back into recovery and then
  allow overwrite of those logs.
- Add a new one-time executable recovery-refresh that refreshes pmsg
  in post-fs phase of init. We rely on pmsg eventually scrolling off
  to age the content after recovery-persist has done its job.
- Add a new one-time executable recovery-persist that transfers from
  pmsg to /data/misc/recovery/ directory if /cache is not mounted
  in post-fs-data phase of init.
- Build and appropriately trigger the above two as required if
  BOARD_CACHEIMAGE_PARTITION_SIZE is undefined.
- Add some simple unit tests

NB: Test failure is expected on systems that do not deliver either
the recovery-persist or recovery-refresh executables, e.g. systems
with /cache. Tests also require a timely reboot sequence of test
to truly verify, tests provide guidance on stderr to direct.

Bug: 27176738
Change-Id: I17bb95980234984f6b2087fd5941b0a3126b706b

Android.mk

@@ -101,6 +101,30 @@ else
   LOCAL_STATIC_LIBRARIES += $(TARGET_RECOVERY_UI_LIB)
 endif
 
+ifeq ($(BOARD_CACHEIMAGE_PARTITION_SIZE),)
+LOCAL_REQUIRED_MODULES := recovery-persist recovery-refresh
+endif
+
+include $(BUILD_EXECUTABLE)
+
+# recovery-persist (system partition dynamic executable run after /data mounts)
+# ===============================
+include $(CLEAR_VARS)
+LOCAL_SRC_FILES := recovery-persist.cpp
+LOCAL_MODULE := recovery-persist
+LOCAL_SHARED_LIBRARIES := liblog libbase
+LOCAL_CFLAGS := -Werror
+LOCAL_INIT_RC := recovery-persist.rc
+include $(BUILD_EXECUTABLE)
+
+# recovery-refresh (system partition dynamic executable run at init)
+# ===============================
+include $(CLEAR_VARS)
+LOCAL_SRC_FILES := recovery-refresh.cpp
+LOCAL_MODULE := recovery-refresh
+LOCAL_SHARED_LIBRARIES := liblog
+LOCAL_CFLAGS := -Werror
+LOCAL_INIT_RC := recovery-refresh.rc
 include $(BUILD_EXECUTABLE)
 
 # All the APIs for testing

recovery-persist.cpp

@@ -0,0 +1,200 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#define LOG_TAG "recovery-persist"
+
+//
+// Strictly to deal with reboot into system after OTA after /data
+// mounts to pull the last pmsg file data and place it
+// into /data/misc/recovery/ directory, rotating it in.
+//
+// Usage: recovery-persist [--force-persist]
+//
+//    On systems without /cache mount, all file content representing in the
+//    recovery/ directory stored in /sys/fs/pstore/pmsg-ramoops-0 in logger
+//    format that reside in the LOG_ID_SYSTEM buffer at ANDROID_LOG_INFO
+//    priority or higher is transfered to the /data/misc/recovery/ directory.
+//    The content is matched and rotated in as need be.
+//
+//    --force-persist  ignore /cache mount, always rotate in the contents.
+//
+
+#include <errno.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
+
+#include <string>
+
+#include <android/log.h> /* Android Log Priority Tags */
+#include <android-base/file.h>
+#include <log/log.h>
+#include <log/logger.h> /* Android Log packet format */
+#include <private/android_logger.h> /* private pmsg functions */
+
+static const char *LAST_LOG_FILE = "/data/misc/recovery/last_log";
+static const char *LAST_PMSG_FILE = "/sys/fs/pstore/pmsg-ramoops-0";
+static const char *LAST_KMSG_FILE = "/data/misc/recovery/last_kmsg";
+static const char *LAST_CONSOLE_FILE = "/sys/fs/pstore/console-ramoops-0";
+
+static const int KEEP_LOG_COUNT = 10;
+
+// close a file, log an error if the error indicator is set
+static void check_and_fclose(FILE *fp, const char *name) {
+    fflush(fp);
+    if (ferror(fp)) SLOGE("%s %s", name, strerror(errno));
+    fclose(fp);
+}
+
+static void copy_file(const char* source, const char* destination) {
+    FILE* dest_fp = fopen(destination, "w");
+    if (dest_fp == nullptr) {
+        SLOGE("%s %s", destination, strerror(errno));
+    } else {
+        FILE* source_fp = fopen(source, "r");
+        if (source_fp != nullptr) {
+            char buf[4096];
+            size_t bytes;
+            while ((bytes = fread(buf, 1, sizeof(buf), source_fp)) != 0) {
+                fwrite(buf, 1, bytes, dest_fp);
+            }
+            check_and_fclose(source_fp, source);
+        }
+        check_and_fclose(dest_fp, destination);
+    }
+}
+
+static bool rotated = false;
+
+// Rename last_log -> last_log.1 -> last_log.2 -> ... -> last_log.$max.
+// Similarly rename last_kmsg -> last_kmsg.1 -> ... -> last_kmsg.$max.
+// Overwrite any existing last_log.$max and last_kmsg.$max.
+static void rotate_logs(int max) {
+    // Logs should only be rotated once.
+
+    if (rotated) {
+        return;
+    }
+    rotated = true;
+
+    for (int i = max-1; i >= 0; --i) {
+        std::string old_log(LAST_LOG_FILE);
+        if (i > 0) {
+          old_log += "." + std::to_string(i);
+        }
+        std::string new_log(LAST_LOG_FILE);
+        new_log += "." + std::to_string(i+1);
+
+        // Ignore errors if old_log doesn't exist.
+        rename(old_log.c_str(), new_log.c_str());
+
+        std::string old_kmsg(LAST_KMSG_FILE);
+        if (i > 0) {
+          old_kmsg += "." + std::to_string(i);
+        }
+        std::string new_kmsg(LAST_KMSG_FILE);
+        new_kmsg += "." + std::to_string(i+1);
+
+        rename(old_kmsg.c_str(), new_kmsg.c_str());
+    }
+}
+
+ssize_t logsave(
+        log_id_t /* logId */,
+        char /* prio */,
+        const char *filename,
+        const char *buf, size_t len,
+        void * /* arg */) {
+
+    std::string destination("/data/misc/");
+    destination += filename;
+
+    std::string buffer(buf, len);
+
+    {
+        std::string content;
+        android::base::ReadFileToString(destination, &content);
+
+        if (buffer.compare(content) == 0) {
+            return len;
+        }
+    }
+
+    // ToDo: Any others that match? Are we pulling in multiple
+    // already-rotated files? Algorithm thus far is KISS: one file,
+    // one rotation allowed.
+
+    rotate_logs(KEEP_LOG_COUNT);
+
+    return android::base::WriteStringToFile(buffer, destination.c_str());
+}
+
+int main(int argc, char **argv) {
+
+    /* Is /cache a mount?, we have been delivered where we are not wanted */
+    /*
+     * Following code halves the size of the executable as compared to:
+     *
+     *    load_volume_table();
+     *    has_cache = volume_for_path(CACHE_ROOT) != nullptr;
+     */
+    bool has_cache = false;
+    static const char mounts_file[] = "/proc/mounts";
+    FILE *fp = fopen(mounts_file, "r");
+    if (!fp) {
+        SLOGV("%s %s", mounts_file, strerror(errno));
+    } else {
+        char *line = NULL;
+        size_t len = 0;
+        ssize_t read;
+        while ((read = getline(&line, &len, fp)) != -1) {
+            if (strstr(line, " /cache ")) {
+                has_cache = true;
+                break;
+            }
+        }
+        free(line);
+        fclose(fp);
+    }
+
+    if (has_cache) {
+        /*
+         * TBD: Future location to move content from
+         * /cache/recovery to /data/misc/recovery/
+         */
+        /* if --force-persist flag, then transfer pmsg data anyways */
+        if ((argc <= 1) || !argv[1] || strcmp(argv[1], "--force-persist")) {
+            return 0;
+        }
+    }
+
+    /* Is there something in pmsg? */
+    if (access(LAST_PMSG_FILE, R_OK)) {
+        return 0;
+    }
+
+    // Take last pmsg file contents and send it off to the logsave
+    __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, "recovery/", logsave, NULL);
+
+    /* Is there a last console log too? */
+    if (rotated && !access(LAST_CONSOLE_FILE, R_OK)) {
+        copy_file(LAST_CONSOLE_FILE, LAST_KMSG_FILE);
+    }
+
+    return 0;
+}

recovery-persist.rc

@@ -0,0 +1,3 @@
+on post-fs-data
+    mkdir /data/misc/recovery 0770 system log
+    exec - system log -- /system/bin/recovery-persist

recovery-refresh.cpp

@@ -0,0 +1,128 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#define LOG_TAG "recovery-refresh"
+
+//
+// Strictly to deal with reboot into system after OTA, then
+// reboot while in system before boot complete landing us back
+// into recovery to continue with any mitigations with retained
+// log history. This simply refreshes the pmsg files from
+// the last pmsg file contents.
+//
+// Usage:
+//    recovery-refresh [--force-rotate|--rotate]
+//
+//    All file content representing in the recovery/ directory stored in
+//    /sys/fs/pstore/pmsg-ramoops-0 in logger format that reside in the
+//    LOG_ID_SYSTEM buffer at ANDROID_LOG_INFO priority or higher is
+//    refreshed into /dev/pmsg0. This ensures that an unexpected reboot
+//    before recovery-persist is run will still contain the associated
+//    pmsg Android Logger content.
+//
+//    --force-rotate  recovery/last_kmsg and recovery.last_log files are
+//                    rotated with .<number> suffixes upwards.
+//    --rotate        rotated only if rocovery/last_msg or recovery/last_log
+//                    exist, otherwise perform 1:1 refresh.
+//
+
+#include <string.h>
+
+#include <string>
+
+#include <android/log.h> /* Android Log Priority Tags */
+#include <log/logger.h> /* Android Log packet format */
+#include <private/android_logger.h> /* private pmsg functions */
+
+static const char LAST_KMSG_FILE[] = "recovery/last_kmsg";
+static const char LAST_LOG_FILE[] = "recovery/last_log";
+
+static ssize_t logbasename(
+        log_id_t /* logId */,
+        char /* prio */,
+        const char *filename,
+        const char * /* buf */, size_t len,
+        void *arg) {
+    if (strstr(LAST_KMSG_FILE, filename) ||
+            strstr(LAST_LOG_FILE, filename)) {
+        bool *doRotate = reinterpret_cast<bool *>(arg);
+        *doRotate = true;
+    }
+    return len;
+}
+
+static ssize_t logrotate(
+        log_id_t logId,
+        char prio,
+        const char *filename,
+        const char *buf, size_t len,
+        void *arg) {
+    bool *doRotate = reinterpret_cast<bool *>(arg);
+    if (!*doRotate) {
+        return __android_log_pmsg_file_write(logId, prio, filename, buf, len);
+    }
+
+    std::string name(filename);
+    size_t dot = name.find_last_of(".");
+    std::string sub = name.substr(0, dot);
+
+    if (!strstr(LAST_KMSG_FILE, sub.c_str()) &&
+                !strstr(LAST_LOG_FILE, sub.c_str())) {
+        return __android_log_pmsg_file_write(logId, prio, filename, buf, len);
+    }
+
+    // filename rotation
+    if (dot == std::string::npos) {
+        name += ".1";
+    } else {
+        std::string number = name.substr(dot + 1);
+        if (!isdigit(number.data()[0])) {
+            name += ".1";
+        } else {
+            unsigned long long i = std::stoull(number);
+            name = sub + "." + std::to_string(i + 1);
+        }
+    }
+
+    return __android_log_pmsg_file_write(logId, prio, name.c_str(), buf, len);
+}
+
+int main(int argc, char **argv) {
+    static const char filter[] = "recovery/";
+    static const char force_rotate_flag[] = "--force-rotate";
+    static const char rotate_flag[] = "--rotate";
+    ssize_t ret;
+    bool doRotate = false;
+
+    // Take last pmsg contents and rewrite it to the current pmsg session.
+    if ((argc <= 1) || !argv[1] ||
+            (((doRotate = strcmp(argv[1], rotate_flag))) &&
+                strcmp(argv[1], force_rotate_flag))) {
+        doRotate = false;
+    } else if (!doRotate) {
+        // Do we need to rotate?
+        __android_log_pmsg_file_read(
+            LOG_ID_SYSTEM, ANDROID_LOG_INFO, filter,
+            logbasename, &doRotate);
+    }
+
+    // Take action to refresh pmsg contents
+    ret = __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, filter,
+        logrotate, &doRotate);
+
+    return (ret < 0) ? ret : 0;
+}

recovery-refresh.rc

@@ -0,0 +1,2 @@
+on post-fs
+    exec - system log -- /system/bin/recovery-refresh

recovery.cpp

@@ -35,11 +35,14 @@
 #include <chrono>
 
 #include <adb.h>
+#include <android/log.h> /* Android Log Priority Tags */
 #include <android-base/file.h>
 #include <android-base/parseint.h>
 #include <android-base/stringprintf.h>
 #include <cutils/android_reboot.h>
 #include <cutils/properties.h>
+#include <log/logger.h> /* Android Log packet format */
+#include <private/android_logger.h> /* private pmsg functions */
 
 #include <healthd/BatteryMonitor.h>
 
@@ -381,6 +384,18 @@ static void save_kernel_log(const char* destination) {
     android::base::WriteStringToFile(buffer, destination);
 }
 
+// write content to the current pmsg session.
+static ssize_t __pmsg_write(const char *filename, const char *buf, size_t len) {
+    return __android_log_pmsg_file_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
+                                         filename, buf, len);
+}
+
+static void copy_log_file_to_pmsg(const char* source, const char* destination) {
+    std::string content;
+    android::base::ReadFileToString(source, &content);
+    __pmsg_write(destination, content.c_str(), content.length());
+}
+
 // How much of the temp log we have copied to the copy in cache.
 static long tmplog_offset = 0;
 
@@ -440,11 +455,6 @@ static void rotate_logs(int max) {
 }
 
 static void copy_logs() {
-    // We can do nothing for now if there's no /cache partition.
-    if (!has_cache) {
-        return;
-    }
-
     // We only rotate and record the log of the current session if there are
     // actual attempts to modify the flash, such as wipes, installs from BCB
     // or menu selections. This is to avoid unnecessary rotation (and
@@ -453,6 +463,15 @@ static void copy_logs() {
         return;
     }
 
+    // Always write to pmsg, this allows the OTA logs to be caught in logcat -L
+    copy_log_file_to_pmsg(TEMPORARY_LOG_FILE, LAST_LOG_FILE);
+    copy_log_file_to_pmsg(TEMPORARY_INSTALL_FILE, LAST_INSTALL_FILE);
+
+    // We can do nothing for now if there's no /cache partition.
+    if (!has_cache) {
+        return;
+    }
+
     rotate_logs(KEEP_LOG_COUNT);
 
     // Copy logs to cache so the system can find out what happened.
@@ -489,13 +508,17 @@ finish_recovery(const char *send_intent) {
     // Save the locale to cache, so if recovery is next started up
     // without a --locale argument (eg, directly from the bootloader)
     // it will use the last-known locale.
-    if (locale != NULL && has_cache) {
-        LOGI("Saving locale \"%s\"\n", locale);
-        FILE* fp = fopen_path(LOCALE_FILE, "w");
-        fwrite(locale, 1, strlen(locale), fp);
-        fflush(fp);
-        fsync(fileno(fp));
-        check_and_fclose(fp, LOCALE_FILE);
+    if (locale != NULL) {
+        size_t len = strlen(locale);
+        __pmsg_write(LOCALE_FILE, locale, len);
+        if (has_cache) {
+            LOGI("Saving locale \"%s\"\n", locale);
+            FILE* fp = fopen_path(LOCALE_FILE, "w");
+            fwrite(locale, 1, len, fp);
+            fflush(fp);
+            fsync(fileno(fp));
+            check_and_fclose(fp, LOCALE_FILE);
+        }
     }
 
     copy_logs();
@@ -1188,7 +1211,69 @@ static void set_retry_bootloader_message(int retry_count, int argc, char** argv)
     set_bootloader_message(&boot);
 }
 
+static ssize_t logbasename(
+        log_id_t /* logId */,
+        char /* prio */,
+        const char *filename,
+        const char * /* buf */, size_t len,
+        void *arg) {
+    if (strstr(LAST_KMSG_FILE, filename) ||
+            strstr(LAST_LOG_FILE, filename)) {
+        bool *doRotate = reinterpret_cast<bool *>(arg);
+        *doRotate = true;
+    }
+    return len;
+}
+
+static ssize_t logrotate(
+        log_id_t logId,
+        char prio,
+        const char *filename,
+        const char *buf, size_t len,
+        void *arg) {
+    bool *doRotate = reinterpret_cast<bool *>(arg);
+    if (!*doRotate) {
+        return __android_log_pmsg_file_write(logId, prio, filename, buf, len);
+    }
+
+    std::string name(filename);
+    size_t dot = name.find_last_of(".");
+    std::string sub = name.substr(0, dot);
+
+    if (!strstr(LAST_KMSG_FILE, sub.c_str()) &&
+                !strstr(LAST_LOG_FILE, sub.c_str())) {
+        return __android_log_pmsg_file_write(logId, prio, filename, buf, len);
+    }
+
+    // filename rotation
+    if (dot == std::string::npos) {
+        name += ".1";
+    } else {
+        std::string number = name.substr(dot + 1);
+        if (!isdigit(number.data()[0])) {
+            name += ".1";
+        } else {
+            unsigned long long i = std::stoull(number);
+            name = sub + "." + std::to_string(i + 1);
+        }
+    }
+
+    return __android_log_pmsg_file_write(logId, prio, name.c_str(), buf, len);
+}
+
 int main(int argc, char **argv) {
+    // Take last pmsg contents and rewrite it to the current pmsg session.
+    static const char filter[] = "recovery/";
+    // Do we need to rotate?
+    bool doRotate = false;
+    __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, filter,
+        logbasename, &doRotate);
+    // Take action to refresh pmsg contents
+    __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, filter,
+        logrotate, &doRotate);
+
     // If this binary is started with the single argument "--adbd",
     // instead of being the normal recovery binary, it turns into kind
     // of a stripped-down version of adbd that only supports the

tests/Android.mk

@@ -23,7 +23,9 @@ LOCAL_MODULE := recovery_unit_test
 LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk
 LOCAL_STATIC_LIBRARIES := libverifier
 LOCAL_SRC_FILES := unit/asn1_decoder_test.cpp
+LOCAL_SRC_FILES += unit/recovery_test.cpp
 LOCAL_C_INCLUDES := bootable/recovery
+LOCAL_SHARED_LIBRARIES := liblog
 include $(BUILD_NATIVE_TEST)
 
 # Component tests

tests/unit/recovery_test.cpp

@@ -0,0 +1,92 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <fcntl.h>
+#include <string.h>
+#include <sys/types.h>
+#include <unistd.h>
+
+#include <android/log.h>
+#include <gtest/gtest.h>
+#include <log/logger.h>
+#include <private/android_logger.h>
+
+static const char myFilename[] = "/data/misc/recovery/inject.txt";
+static const char myContent[] = "Hello World\nWelcome to my recovery\n";
+
+// Failure is expected on systems that do not deliver either the
+// recovery-persist or recovery-refresh executables. Tests also require
+// a reboot sequence of test to truly verify.
+
+static ssize_t __pmsg_fn(log_id_t logId, char prio, const char *filename,
+                         const char *buf, size_t len, void *arg) {
+    EXPECT_EQ(LOG_ID_SYSTEM, logId);
+    EXPECT_EQ(ANDROID_LOG_INFO, prio);
+    EXPECT_EQ(0, NULL == strstr(myFilename,filename));
+    EXPECT_EQ(0, strcmp(myContent, buf));
+    EXPECT_EQ(sizeof(myContent), len);
+    EXPECT_EQ(0, NULL != arg);
+    return len;
+}
+
+// recovery.refresh - May fail. Requires recovery.inject, two reboots,
+//                    then expect success after second reboot.
+TEST(recovery, refresh) {
+    EXPECT_EQ(0, access("/system/bin/recovery-refresh", F_OK));
+
+    ssize_t ret = __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, "recovery/", __pmsg_fn, NULL);
+    if (ret == -ENOENT) {
+        EXPECT_LT(0, __android_log_pmsg_file_write(
+            LOG_ID_SYSTEM, ANDROID_LOG_INFO,
+            myFilename, myContent, sizeof(myContent)));
+        fprintf(stderr, "injected test data, "
+                        "requires two intervening reboots "
+                        "to check for replication\n");
+    }
+    EXPECT_EQ((ssize_t)sizeof(myContent), ret);
+}
+
+// recovery.persist - Requires recovery.inject, then a reboot, then
+//                    expect success after for this test on that boot.
+TEST(recovery, persist) {
+    EXPECT_EQ(0, access("/system/bin/recovery-persist", F_OK));
+
+    ssize_t ret = __android_log_pmsg_file_read(
+        LOG_ID_SYSTEM, ANDROID_LOG_INFO, "recovery/", __pmsg_fn, NULL);
+    if (ret == -ENOENT) {
+        EXPECT_LT(0, __android_log_pmsg_file_write(
+            LOG_ID_SYSTEM, ANDROID_LOG_INFO,
+            myFilename, myContent, sizeof(myContent)));
+        fprintf(stderr, "injected test data, "
+                        "requires intervening reboot "
+                        "to check for storage\n");
+    }
+
+    int fd = open(myFilename, O_RDONLY);
+    EXPECT_LE(0, fd);
+
+    char buf[sizeof(myContent) + 32];
+    ret = read(fd, buf, sizeof(buf));
+    close(fd);
+    EXPECT_EQ(ret, (ssize_t)sizeof(myContent));
+    EXPECT_EQ(0, strcmp(myContent, buf));
+    if (fd >= 0) {
+        fprintf(stderr, "Removing persistent test data, "
+                        "check if reconstructed on reboot\n");
+    }
+    EXPECT_EQ(0, unlink(myFilename));
+}