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

6 files changed, 44 insertions, 13 deletions

diff --git a/install.cpp b/install.cpp
index be97987..8f2f252 100644
--- a/install.cpp
+++ b/install.cpp
@@ -165,9 +165,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 ff95915..ddf85c1 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 ea05bf1..8e18864 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 4dcaa0f..ca72911 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 c6d0e1c..da31975 100644
--- a/updater/install.c
+++ b/updater/install.c
@@ -58,6 +58,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 82546ed..21633dc 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,