Merge "libbinder : Use logging from liblog" am: 58864fd37f am: 424b87710b am: 57ae1ca8d4 am: 4fc9273332 am: 250b142b91

Original change: https://android-review.googlesource.com/c/platform/frameworks/native/+/2235623

Change-Id: Id7e29a305e1f6dfe7082675ccf3338a2a42ff181
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>

5 files changed, 110 insertions, 95 deletions

diff --git a/libs/binder/IPCThreadState.cpp b/libs/binder/IPCThreadState.cpp
index bfcf39ad30..11c8e5dcea 100644
--- a/libs/binder/IPCThreadState.cpp
+++ b/libs/binder/IPCThreadState.cpp
@@ -39,7 +39,6 @@
 #include <sys/resource.h>
 #include <unistd.h>
 
-#include "Static.h"
 #include "binder_module.h"
 
 #if LOG_NDEBUG
@@ -124,46 +123,43 @@ static const char* getReturnString(uint32_t cmd)
         return "unknown";
 }
 
-static const void* printBinderTransactionData(TextOutput& out, const void* data)
-{
+static const void* printBinderTransactionData(std::ostream& out, const void* data) {
     const binder_transaction_data* btd =
         (const binder_transaction_data*)data;
     if (btd->target.handle < 1024) {
         /* want to print descriptors in decimal; guess based on value */
-        out << "target.desc=" << btd->target.handle;
+        out << "\ttarget.desc=" << btd->target.handle;
     } else {
-        out << "target.ptr=" << btd->target.ptr;
+        out << "\ttarget.ptr=" << btd->target.ptr;
     }
-    out << " (cookie " << btd->cookie << ")" << endl
-        << "code=" << TypeCode(btd->code) << ", flags=" << (void*)(uint64_t)btd->flags << endl
-        << "data=" << btd->data.ptr.buffer << " (" << (void*)btd->data_size
-        << " bytes)" << endl
-        << "offsets=" << btd->data.ptr.offsets << " (" << (void*)btd->offsets_size
-        << " bytes)";
+    out << "\t (cookie " << btd->cookie << ")"
+        << "\n"
+        << "\tcode=" << TypeCode(btd->code) << ", flags=" << (void*)(uint64_t)btd->flags << "\n"
+        << "\tdata=" << btd->data.ptr.buffer << " (" << (void*)btd->data_size << " bytes)"
+        << "\n"
+        << "\toffsets=" << btd->data.ptr.offsets << " (" << (void*)btd->offsets_size << " bytes)";
     return btd+1;
 }
 
-static const void* printReturnCommand(TextOutput& out, const void* _cmd)
-{
+static const void* printReturnCommand(std::ostream& out, const void* _cmd) {
     static const size_t N = sizeof(kReturnStrings)/sizeof(kReturnStrings[0]);
     const int32_t* cmd = (const int32_t*)_cmd;
     uint32_t code = (uint32_t)*cmd++;
     size_t cmdIndex = code & 0xff;
     if (code == BR_ERROR) {
-        out << "BR_ERROR: " << (void*)(uint64_t)(*cmd++) << endl;
+        out << "\tBR_ERROR: " << (void*)(uint64_t)(*cmd++) << "\n";
         return cmd;
     } else if (cmdIndex >= N) {
-        out << "Unknown reply: " << code << endl;
+        out << "\tUnknown reply: " << code << "\n";
         return cmd;
     }
-    out << kReturnStrings[cmdIndex];
+    out << "\t" << kReturnStrings[cmdIndex];
 
     switch (code) {
         case BR_TRANSACTION:
         case BR_REPLY: {
-            out << ": " << indent;
-            cmd = (const int32_t *)printBinderTransactionData(out, cmd);
-            out << dedent;
+            out << ": ";
+            cmd = (const int32_t*)printBinderTransactionData(out, cmd);
         } break;
 
         case BR_ACQUIRE_RESULT: {
@@ -200,19 +196,18 @@ static const void* printReturnCommand(TextOutput& out, const void* _cmd)
             break;
     }
 
-    out << endl;
+    out << "\n";
     return cmd;
 }
 
-static const void* printCommand(TextOutput& out, const void* _cmd)
-{
+static const void* printCommand(std::ostream& out, const void* _cmd) {
     static const size_t N = sizeof(kCommandStrings)/sizeof(kCommandStrings[0]);
     const int32_t* cmd = (const int32_t*)_cmd;
     uint32_t code = (uint32_t)*cmd++;
     size_t cmdIndex = code & 0xff;
 
     if (cmdIndex >= N) {
-        out << "Unknown command: " << code << endl;
+        out << "Unknown command: " << code << "\n";
         return cmd;
     }
     out << kCommandStrings[cmdIndex];
@@ -220,9 +215,8 @@ static const void* printCommand(TextOutput& out, const void* _cmd)
     switch (code) {
         case BC_TRANSACTION:
         case BC_REPLY: {
-            out << ": " << indent;
-            cmd = (const int32_t *)printBinderTransactionData(out, cmd);
-            out << dedent;
+            out << ": ";
+            cmd = (const int32_t*)printBinderTransactionData(out, cmd);
         } break;
 
         case BC_ACQUIRE_RESULT: {
@@ -274,7 +268,7 @@ static const void* printCommand(TextOutput& out, const void* _cmd)
             break;
     }
 
-    out << endl;
+    out << "\n";
     return cmd;
 }
 
@@ -548,8 +542,10 @@ status_t IPCThreadState::getAndExecuteCommand()
         if (IN < sizeof(int32_t)) return result;
         cmd = mIn.readInt32();
         IF_LOG_COMMANDS() {
-            alog << "Processing top-level Command: "
-                 << getReturnString(cmd) << endl;
+            std::ostringstream logStream;
+            logStream << "Processing top-level Command: " << getReturnString(cmd) << "\n";
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
 
         pthread_mutex_lock(&mProcess->mThreadCountLock);
@@ -726,10 +722,11 @@ status_t IPCThreadState::transact(int32_t handle,
     flags |= TF_ACCEPT_FDS;
 
     IF_LOG_TRANSACTIONS() {
-        TextOutput::Bundle _b(alog);
-        alog << "BC_TRANSACTION thr " << (void*)pthread_self() << " / hand "
-            << handle << " / code " << TypeCode(code) << ": "
-            << indent << data << dedent << endl;
+        std::ostringstream logStream;
+        logStream << "BC_TRANSACTION thr " << (void*)pthread_self() << " / hand " << handle
+                  << " / code " << TypeCode(code) << ": \t" << data << "\n";
+        std::string message = logStream.str();
+        ALOGI("%s", message.c_str());
     }
 
     LOG_ONEWAY(">>>> SEND from pid %d uid %d %s", getpid(), getuid(),
@@ -774,11 +771,15 @@ status_t IPCThreadState::transact(int32_t handle,
         #endif
 
         IF_LOG_TRANSACTIONS() {
-            TextOutput::Bundle _b(alog);
-            alog << "BR_REPLY thr " << (void*)pthread_self() << " / hand "
-                << handle << ": ";
-            if (reply) alog << indent << *reply << dedent << endl;
-            else alog << "(none requested)" << endl;
+            std::ostringstream logStream;
+            logStream << "BR_REPLY thr " << (void*)pthread_self() << " / hand " << handle << ": ";
+            if (reply)
+                logStream << "\t" << *reply << "\n";
+            else
+                logStream << "(none requested)"
+                          << "\n";
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
     } else {
         err = waitForResponse(nullptr, nullptr);
@@ -920,8 +921,10 @@ status_t IPCThreadState::waitForResponse(Parcel *reply, status_t *acquireResult)
         cmd = (uint32_t)mIn.readInt32();
 
         IF_LOG_COMMANDS() {
-            alog << "Processing waitForResponse Command: "
-                << getReturnString(cmd) << endl;
+            std::ostringstream logStream;
+            logStream << "Processing waitForResponse Command: " << getReturnString(cmd) << "\n";
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
 
         switch (cmd) {
@@ -1033,17 +1036,19 @@ status_t IPCThreadState::talkWithDriver(bool doReceive)
     }
 
     IF_LOG_COMMANDS() {
-        TextOutput::Bundle _b(alog);
+        std::ostringstream logStream;
         if (outAvail != 0) {
-            alog << "Sending commands to driver: " << indent;
+            logStream << "Sending commands to driver: ";
             const void* cmds = (const void*)bwr.write_buffer;
-            const void* end = ((const uint8_t*)cmds)+bwr.write_size;
-            alog << HexDump(cmds, bwr.write_size) << endl;
-            while (cmds < end) cmds = printCommand(alog, cmds);
-            alog << dedent;
+            const void* end = ((const uint8_t*)cmds) + bwr.write_size;
+            logStream << "\t" << HexDump(cmds, bwr.write_size) << "\n";
+            while (cmds < end) cmds = printCommand(logStream, cmds);
         }
-        alog << "Size of receive buffer: " << bwr.read_size
-            << ", needRead: " << needRead << ", doReceive: " << doReceive << endl;
+        logStream << "Size of receive buffer: " << bwr.read_size << ", needRead: " << needRead
+                  << ", doReceive: " << doReceive << "\n";
+
+        std::string message = logStream.str();
+        ALOGI("%s", message.c_str());
     }
 
     // Return immediately if there is nothing to do.
@@ -1054,7 +1059,10 @@ status_t IPCThreadState::talkWithDriver(bool doReceive)
     status_t err;
     do {
         IF_LOG_COMMANDS() {
-            alog << "About to read/write, write size = " << mOut.dataSize() << endl;
+            std::ostringstream logStream;
+            logStream << "About to read/write, write size = " << mOut.dataSize() << "\n";
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
 #if defined(__ANDROID__)
         if (ioctl(mProcess->mDriverFD, BINDER_WRITE_READ, &bwr) >= 0)
@@ -1068,14 +1076,20 @@ status_t IPCThreadState::talkWithDriver(bool doReceive)
             err = -EBADF;
         }
         IF_LOG_COMMANDS() {
-            alog << "Finished read/write, write size = " << mOut.dataSize() << endl;
+            std::ostringstream logStream;
+            logStream << "Finished read/write, write size = " << mOut.dataSize() << "\n";
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
     } while (err == -EINTR);
 
     IF_LOG_COMMANDS() {
-        alog << "Our err: " << (void*)(intptr_t)err << ", write consumed: "
-            << bwr.write_consumed << " (of " << mOut.dataSize()
-                        << "), read consumed: " << bwr.read_consumed << endl;
+        std::ostringstream logStream;
+        logStream << "Our err: " << (void*)(intptr_t)err
+                  << ", write consumed: " << bwr.write_consumed << " (of " << mOut.dataSize()
+                  << "), read consumed: " << bwr.read_consumed << "\n";
+        std::string message = logStream.str();
+        ALOGI("%s", message.c_str());
     }
 
     if (err >= NO_ERROR) {
@@ -1096,14 +1110,15 @@ status_t IPCThreadState::talkWithDriver(bool doReceive)
             mIn.setDataPosition(0);
         }
         IF_LOG_COMMANDS() {
-            TextOutput::Bundle _b(alog);
-            alog << "Remaining data size: " << mOut.dataSize() << endl;
-            alog << "Received commands from driver: " << indent;
+            std::ostringstream logStream;
+            logStream << "Remaining data size: " << mOut.dataSize() << "\n";
+            logStream << "Received commands from driver: ";
             const void* cmds = mIn.data();
             const void* end = mIn.data() + mIn.dataSize();
-            alog << HexDump(cmds, mIn.dataSize()) << endl;
-            while (cmds < end) cmds = printReturnCommand(alog, cmds);
-            alog << dedent;
+            logStream << "\t" << HexDump(cmds, mIn.dataSize()) << "\n";
+            while (cmds < end) cmds = printReturnCommand(logStream, cmds);
+            std::string message = logStream.str();
+            ALOGI("%s", message.c_str());
         }
         return NO_ERROR;
     }
@@ -1285,15 +1300,15 @@ status_t IPCThreadState::executeCommand(int32_t cmd)
             Parcel reply;
             status_t error;
             IF_LOG_TRANSACTIONS() {
-                TextOutput::Bundle _b(alog);
-                alog << "BR_TRANSACTION thr " << (void*)pthread_self()
-                    << " / obj " << tr.target.ptr << " / code "
-                    << TypeCode(tr.code) << ": " << indent << buffer
-                    << dedent << endl
-                    << "Data addr = "
-                    << reinterpret_cast<const uint8_t*>(tr.data.ptr.buffer)
-                    << ", offsets addr="
-                    << reinterpret_cast<const size_t*>(tr.data.ptr.offsets) << endl;
+                std::ostringstream logStream;
+                logStream << "BR_TRANSACTION thr " << (void*)pthread_self() << " / obj "
+                          << tr.target.ptr << " / code " << TypeCode(tr.code) << ": \t" << buffer
+                          << "\n"
+                          << "Data addr = " << reinterpret_cast<const uint8_t*>(tr.data.ptr.buffer)
+                          << ", offsets addr="
+                          << reinterpret_cast<const size_t*>(tr.data.ptr.offsets) << "\n";
+                std::string message = logStream.str();
+                ALOGI("%s", message.c_str());
             }
             if (tr.target.ptr) {
                 // We only have a weak reference on the target object, so we must first try to
@@ -1329,21 +1344,21 @@ status_t IPCThreadState::executeCommand(int32_t cmd)
                 sendReply(reply, (tr.flags & kForwardReplyFlags));
             } else {
                 if (error != OK) {
-                    alog << "oneway function results for code " << tr.code
-                         << " on binder at "
-                         << reinterpret_cast<void*>(tr.target.ptr)
-                         << " will be dropped but finished with status "
-                         << statusToString(error);
+                    std::ostringstream logStream;
+                    logStream << "oneway function results for code " << tr.code << " on binder at "
+                              << reinterpret_cast<void*>(tr.target.ptr)
+                              << " will be dropped but finished with status "
+                              << statusToString(error);
 
                     // ideally we could log this even when error == OK, but it
                     // causes too much logspam because some manually-written
                     // interfaces have clients that call methods which always
                     // write results, sometimes as oneway methods.
                     if (reply.dataSize() != 0) {
-                         alog << " and reply parcel size " << reply.dataSize();
+                        logStream << " and reply parcel size " << reply.dataSize();
                     }
-
-                    alog << endl;
+                    std::string message = logStream.str();
+                    ALOGI("%s", message.c_str());
                 }
                 LOG_ONEWAY("NOT sending reply to %d!", mCallingPid);
             }
@@ -1358,9 +1373,11 @@ status_t IPCThreadState::executeCommand(int32_t cmd)
             mPropagateWorkSource = origPropagateWorkSet;
 
             IF_LOG_TRANSACTIONS() {
-                TextOutput::Bundle _b(alog);
-                alog << "BC_REPLY thr " << (void*)pthread_self() << " / obj "
-                    << tr.target.ptr << ": " << indent << reply << dedent << endl;
+                std::ostringstream logStream;
+                logStream << "BC_REPLY thr " << (void*)pthread_self() << " / obj " << tr.target.ptr
+                          << ": \t" << reply << "\n";
+                std::string message = logStream.str();
+                ALOGI("%s", message.c_str());
             }
 
         }
@@ -1481,7 +1498,10 @@ void IPCThreadState::freeBuffer(const uint8_t* data, size_t /*dataSize*/,
                                 const binder_size_t* /*objects*/, size_t /*objectsSize*/) {
     //ALOGI("Freeing parcel %p", &parcel);
     IF_LOG_COMMANDS() {
-        alog << "Writing BC_FREE_BUFFER for " << data << endl;
+        std::ostringstream logStream;
+        logStream << "Writing BC_FREE_BUFFER for " << data << "\n";
+        std::string message = logStream.str();
+        ALOGI("%s", message.c_str());
     }
     ALOG_ASSERT(data != NULL, "Called with NULL data");
     IPCThreadState* state = self();
diff --git a/libs/binder/Parcel.cpp b/libs/binder/Parcel.cpp
index 888757214d..83332980b2 100644
--- a/libs/binder/Parcel.cpp
+++ b/libs/binder/Parcel.cpp
@@ -2639,8 +2639,7 @@ status_t Parcel::rpcSetDataReference(
     return OK;
 }
 
-void Parcel::print(TextOutput& to, uint32_t /*flags*/) const
-{
+void Parcel::print(std::ostream& to, uint32_t /*flags*/) const {
     to << "Parcel(";
 
     if (errorCheck() != NO_ERROR) {
@@ -2648,7 +2647,7 @@ void Parcel::print(TextOutput& to, uint32_t /*flags*/) const
         to << "Error: " << (void*)(intptr_t)err << " \"" << strerror(-err) << "\"";
     } else if (dataSize() > 0) {
         const uint8_t* DATA = data();
-        to << indent << HexDump(DATA, dataSize()) << dedent;
+        to << "\t" << HexDump(DATA, dataSize());
 #ifdef BINDER_WITH_KERNEL_IPC
         if (const auto* kernelFields = maybeKernelFields()) {
             const binder_size_t* OBJS = kernelFields->mObjects;
@@ -2656,8 +2655,7 @@ void Parcel::print(TextOutput& to, uint32_t /*flags*/) const
             for (size_t i = 0; i < N; i++) {
                 const flat_binder_object* flat =
                         reinterpret_cast<const flat_binder_object*>(DATA + OBJS[i]);
-                to << endl
-                   << "Object #" << i << " @ " << (void*)OBJS[i] << ": "
+                to << "Object #" << i << " @ " << (void*)OBJS[i] << ": "
                    << TypeCode(flat->hdr.type & 0x7f7f7f00) << " = " << flat->binder;
             }
         }
diff --git a/libs/binder/TextOutput.cpp b/libs/binder/TextOutput.cpp
index a0ade50efb..5dd1f902f8 100644
--- a/libs/binder/TextOutput.cpp
+++ b/libs/binder/TextOutput.cpp
@@ -39,11 +39,10 @@ TextOutput::~TextOutput() {
 
 static void textOutputPrinter(void* cookie, const char* txt)
 {
-    ((TextOutput*)cookie)->print(txt, strlen(txt));
+    ((std::ostream*)cookie)->write(txt, strlen(txt));
 }
 
-TextOutput& operator<<(TextOutput& to, const TypeCode& val)
-{
+std::ostream& operator<<(std::ostream& to, const TypeCode& val) {
     printTypeCode(val.typeCode(), textOutputPrinter, (void*)&to);
     return to;
 }
@@ -61,8 +60,7 @@ HexDump::HexDump(const void *buf, size_t size, size_t bytesPerLine)
     else mAlignment = 1;
 }
 
-TextOutput& operator<<(TextOutput& to, const HexDump& val)
-{
+std::ostream& operator<<(std::ostream& to, const HexDump& val) {
     printHexData(0, val.buffer(), val.size(), val.bytesPerLine(),
         val.singleLineCutoff(), val.alignment(), val.carrayStyle(),
         textOutputPrinter, (void*)&to);
diff --git a/libs/binder/include/binder/Parcel.h b/libs/binder/include/binder/Parcel.h
index 54692398c6..6de6ce8025 100644
--- a/libs/binder/include/binder/Parcel.h
+++ b/libs/binder/include/binder/Parcel.h
@@ -595,7 +595,7 @@ public:
     // uid.
     uid_t               readCallingWorkSourceUid() const;
 
-    void                print(TextOutput& to, uint32_t flags = 0) const;
+    void print(std::ostream& to, uint32_t flags = 0) const;
 
 private:
     // `objects` and `objectsSize` always 0 for RPC Parcels.
@@ -1594,8 +1594,7 @@ status_t Parcel::readNullableStrongBinder(sp<T>* val) const {
 
 // ---------------------------------------------------------------------------
 
-inline TextOutput& operator<<(TextOutput& to, const Parcel& parcel)
-{
+inline std::ostream& operator<<(std::ostream& to, const Parcel& parcel) {
     parcel.print(to);
     return to;
 }
diff --git a/libs/binder/include/binder/TextOutput.h b/libs/binder/include/binder/TextOutput.h
index bf9c92bfc5..eb98042c42 100644
--- a/libs/binder/include/binder/TextOutput.h
+++ b/libs/binder/include/binder/TextOutput.h
@@ -94,7 +94,7 @@ private:
     uint32_t mCode;
 };
 
-TextOutput& operator<<(TextOutput& to, const TypeCode& val);
+std::ostream& operator<<(std::ostream& to, const TypeCode& val);
 
 class HexDump
 {
@@ -123,7 +123,7 @@ private:
     bool mCArrayStyle;
 };
 
-TextOutput& operator<<(TextOutput& to, const HexDump& val);
+std::ostream& operator<<(std::ostream& to, const HexDump& val);
 inline TextOutput& operator<<(TextOutput& to,
                               decltype(std::endl<char,
                                        std::char_traits<char>>)