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

@@ -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) {

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;

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();
 

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;
 

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))

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,