From b6918c7c433054ac4352d5f7746f7c2bf2971083 Mon Sep 17 00:00:00 2001
From: Tao Bao <tbao@google.com>
Date: Tue, 19 May 2015 17:02:16 -0700
Subject: [PATCH] Log update outputs in order

Although stdout and stderr are both redirected to log file with no
buffering, we are seeing some outputs are mixed in random order.
This is because ui_print commands from the updater are passed to the
recovery binary via a pipe, which may interleave with other outputs
that go to stderr directly.

In recovery, adding ui::PrintOnScreenOnly() function to handle
ui_print command, which skips printing to stdout. Meanwhile, updater
prints the contents to stderr in addition to piping them to recovery.

Change-Id: Idda93ea940d2e23a0276bb8ead4aa70a3cb97700
---
 install.cpp       |  4 ++--
 screen_ui.cpp     | 35 +++++++++++++++++++++++++----------
 screen_ui.h       |  2 ++
 ui.h              |  4 +++-
 updater/install.c |  6 ++++++
 verifier_test.cpp |  6 ++++++
 6 files changed, 44 insertions(+), 13 deletions(-)

diff --git a/install.cpp b/install.cpp
index c7d382f3..7d88ed72 100644
--- a/install.cpp
+++ b/install.cpp
@@ -164,9 +164,9 @@ try_update_binary(const char* path, ZipArchive* zip, bool* wipe_cache) {
         } else if (strcmp(command, "ui_print") == 0) {
             char* str = strtok(NULL, "\n");
             if (str) {
-                ui->Print("%s", str);
+                ui->PrintOnScreenOnly("%s", str);
             } else {
-                ui->Print("\n");
+                ui->PrintOnScreenOnly("\n");
             }
             fflush(stdout);
         } else if (strcmp(command, "wipe_cache") == 0) {
diff --git a/screen_ui.cpp b/screen_ui.cpp
index ff959151..ddf85c19 100644
--- a/screen_ui.cpp
+++ b/screen_ui.cpp
@@ -30,8 +30,10 @@
 
 #include <vector>
 
-#include "base/strings.h"
-#include "cutils/properties.h"
+#include <base/strings.h>
+#include <base/stringprintf.h>
+#include <cutils/properties.h>
+
 #include "common.h"
 #include "device.h"
 #include "minui/minui.h"
@@ -506,18 +508,17 @@ void ScreenRecoveryUI::SetStage(int current, int max) {
     pthread_mutex_unlock(&updateMutex);
 }
 
-void ScreenRecoveryUI::Print(const char *fmt, ...) {
-    char buf[256];
-    va_list ap;
-    va_start(ap, fmt);
-    vsnprintf(buf, 256, fmt, ap);
-    va_end(ap);
+void ScreenRecoveryUI::PrintV(const char* fmt, bool copy_to_stdout, va_list ap) {
+    std::string str;
+    android::base::StringAppendV(&str, fmt, ap);
 
-    fputs(buf, stdout);
+    if (copy_to_stdout) {
+        fputs(str.c_str(), stdout);
+    }
 
     pthread_mutex_lock(&updateMutex);
     if (text_rows_ > 0 && text_cols_ > 0) {
-        for (const char* ptr = buf; *ptr != '\0'; ++ptr) {
+        for (const char* ptr = str.c_str(); *ptr != '\0'; ++ptr) {
             if (*ptr == '\n' || text_col_ >= text_cols_) {
                 text_[text_row_][text_col_] = '\0';
                 text_col_ = 0;
@@ -532,6 +533,20 @@ void ScreenRecoveryUI::Print(const char *fmt, ...) {
     pthread_mutex_unlock(&updateMutex);
 }
 
+void ScreenRecoveryUI::Print(const char* fmt, ...) {
+    va_list ap;
+    va_start(ap, fmt);
+    PrintV(fmt, true, ap);
+    va_end(ap);
+}
+
+void ScreenRecoveryUI::PrintOnScreenOnly(const char *fmt, ...) {
+    va_list ap;
+    va_start(ap, fmt);
+    PrintV(fmt, false, ap);
+    va_end(ap);
+}
+
 void ScreenRecoveryUI::PutChar(char ch) {
     pthread_mutex_lock(&updateMutex);
     if (ch != '\n') text_[text_row_][text_col_++] = ch;
diff --git a/screen_ui.h b/screen_ui.h
index ea05bf15..8e18864d 100644
--- a/screen_ui.h
+++ b/screen_ui.h
@@ -49,6 +49,7 @@ class ScreenRecoveryUI : public RecoveryUI {
 
     // printing messages
     void Print(const char* fmt, ...) __printflike(2, 3);
+    void PrintOnScreenOnly(const char* fmt, ...) __printflike(2, 3);
     void ShowFile(const char* filename);
 
     // menu display
@@ -125,6 +126,7 @@ class ScreenRecoveryUI : public RecoveryUI {
     void ProgressThreadLoop();
 
     void ShowFile(FILE*);
+    void PrintV(const char*, bool, va_list);
     void PutChar(char);
     void ClearText();
 
diff --git a/ui.h b/ui.h
index 4dcaa0f8..ca72911d 100644
--- a/ui.h
+++ b/ui.h
@@ -62,8 +62,10 @@ class RecoveryUI {
     virtual bool WasTextEverVisible() = 0;
 
     // Write a message to the on-screen log (shown if the user has
-    // toggled on the text display).
+    // toggled on the text display). Print() will also dump the message
+    // to stdout / log file, while PrintOnScreenOnly() not.
     virtual void Print(const char* fmt, ...) __printflike(2, 3) = 0;
+    virtual void PrintOnScreenOnly(const char* fmt, ...) __printflike(2, 3) = 0;
 
     virtual void ShowFile(const char* filename) = 0;
 
diff --git a/updater/install.c b/updater/install.c
index 01a5dd24..da6b5778 100644
--- a/updater/install.c
+++ b/updater/install.c
@@ -61,6 +61,12 @@ void uiPrint(State* state, char* buffer) {
         line = strtok(NULL, "\n");
     }
     fprintf(ui->cmd_pipe, "ui_print\n");
+
+    // The recovery will only print the contents to screen for pipe command
+    // ui_print. We need to dump the contents to stderr (which has been
+    // redirected to the log file) directly.
+    fprintf(stderr, buffer);
+    fprintf(stderr, "\n");
 }
 
 __attribute__((__format__(printf, 2, 3))) __nonnull((2))
diff --git a/verifier_test.cpp b/verifier_test.cpp
index 82546edc..21633dc2 100644
--- a/verifier_test.cpp
+++ b/verifier_test.cpp
@@ -141,6 +141,12 @@ class FakeUI : public RecoveryUI {
         vfprintf(stderr, fmt, ap);
         va_end(ap);
     }
+    void PrintOnScreenOnly(const char* fmt, ...) {
+        va_list ap;
+        va_start(ap, fmt);
+        vfprintf(stderr, fmt, ap);
+        va_end(ap);
+    }
     void ShowFile(const char*) { }
 
     void StartMenu(const char* const * headers, const char* const * items,