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
diff --git a/install.cpp b/install.cpp
index c7d382f..7d88ed7 100644
--- a/install.cpp
+++ b/install.cpp
@@ -164,9 +164,9 @@
         } 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 @@
     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 @@
     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 @@
 
     // 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 @@
     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 @@
     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 01a5dd2..da6b577 100644
--- a/updater/install.c
+++ b/updater/install.c
@@ -61,6 +61,12 @@
         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 @@
         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,