Common: adds more FF_DEBUG

src/common/android/binder.c

@@ -1,5 +1,7 @@
 #include "common/android/binder.h"
+#include "common/debug.h"
 
+#include <errno.h>
 #include <fcntl.h>
 #include <sys/mman.h>
 #include <unistd.h>
@@ -9,11 +11,16 @@ const char* ffBinderOpen(FFBinder* binder) {
 
     const int fd = open(FF_BINDER_DEVICE, O_RDWR | O_CLOEXEC);
     if (fd < 0) {
+        FF_DEBUG("open(" FF_BINDER_DEVICE ") failed: %s", strerror(errno));
         return "Failed to open " FF_BINDER_DEVICE;
     }
 
     struct binder_version version = { .protocol_version = 0 };
-    if (ioctl(fd, BINDER_VERSION, &version) != 0 || version.protocol_version != BINDER_CURRENT_PROTOCOL_VERSION) {
+    const int versionIoctl = ioctl(fd, BINDER_VERSION, &version);
+    if (versionIoctl != 0 || version.protocol_version != BINDER_CURRENT_PROTOCOL_VERSION) {
+        FF_DEBUG("BINDER_VERSION reported protocol %u, expected %u (%s)",
+            version.protocol_version, BINDER_CURRENT_PROTOCOL_VERSION,
+            versionIoctl != 0 ? strerror(errno) : "version mismatch");
         close(fd);
         return "Unsupported binder protocol version";
     }
@@ -22,6 +29,7 @@ const char* ffBinderOpen(FFBinder* binder) {
     // addresses in BR_REPLY, so it has to stay mapped for as long as the handle is used.
     void* shared = mmap(nullptr, FF_BINDER_SHARED_SIZE, PROT_READ, MAP_PRIVATE | MAP_NORESERVE, fd, 0);
     if (shared == MAP_FAILED) {
+        FF_DEBUG("mmap(" FF_BINDER_DEVICE ") failed: %s", strerror(errno));
         close(fd);
         return "Failed to mmap " FF_BINDER_DEVICE;
     }
@@ -55,6 +63,8 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
     reply->fdCount = 0;
 
     if (parcel->truncated) {
+        FF_DEBUG("The parcel was truncated at %zu bytes, the caller buffer holds %zu",
+            parcel->size, parcel->capacity);
         return "Binder parcel does not fit the caller buffer";
     }
 
@@ -86,6 +96,7 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
         .read_buffer = (binder_uintptr_t) (uintptr_t) readBuffer,
     };
     if (ioctl(binder->fd, BINDER_WRITE_READ, &exchange) != 0) {
+        FF_DEBUG("BINDER_WRITE_READ(handle=%u, code=%u) failed: %s", handle, code, strerror(errno));
         return "BINDER_WRITE_READ failed";
     }
 
@@ -103,8 +114,10 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
                 break;
 
             case BR_FAILED_REPLY:
+                FF_DEBUG("BR_FAILED_REPLY for handle=%u, code=%u", handle, code);
                 return "Binder transaction failed";
             case BR_DEAD_REPLY:
+                FF_DEBUG("BR_DEAD_REPLY: handle=%u is dead", handle);
                 return "Binder service is not running";
 
             case BR_INCREFS:
@@ -123,6 +136,8 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
 
             case BR_REPLY: {
                 if ((size_t) (end - cursor) < sizeof(struct binder_transaction_data)) {
+                    FF_DEBUG("BR_REPLY is truncated: %zu of %zu bytes left",
+                        (size_t) (end - cursor), sizeof(struct binder_transaction_data));
                     return "Truncated binder reply";
                 }
                 struct binder_transaction_data data;
@@ -140,6 +155,8 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
                 const char* error = nullptr;
                 if (payloadSize > 0) {
                     if (payloadSize > reply->capacity) {
+                        FF_DEBUG("The reply carries %zu payload bytes, the caller buffer holds %zu",
+                            payloadSize, reply->capacity);
                         error = "Binder reply does not fit the caller buffer";
                     } else {
                         memcpy(reply->data, payload, payloadSize);
@@ -211,6 +228,7 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
                 // later transaction on them fails with BR_FAILED_REPLY, which says nothing about the
                 // real cause. Reported, but only when nothing more specific is already at hand.
                 if (ioctl(binder->fd, BINDER_WRITE_READ, &release) != 0 && error == nullptr) {
+                    FF_DEBUG("BC_ACQUIRE/BC_FREE_BUFFER failed: %s", strerror(errno));
                     error = "Releasing the binder reply failed";
                 }
 
@@ -218,10 +236,13 @@ const char* ffBinderTransact(FFBinder* binder, uint32_t handle, uint32_t code, u
             }
 
             default:
+                FF_DEBUG("Unexpected binder command 0x%08x for handle=%u, code=%u", command, handle, code);
                 return "Unexpected binder command";
         }
     }
 
+    FF_DEBUG("The binder reply for handle=%u, code=%u held no BR_REPLY (%zu bytes read)",
+        handle, code, (size_t) exchange.read_consumed);
     return "No reply from binder";
 }
 
@@ -238,12 +259,16 @@ const char* ffBinderLookupService(FFBinder* binder, const char* name, uint32_t t
         return error;
     }
     if (ffBinderReplyIsStatus(&reply)) {
+        FF_DEBUG("The service manager returned a status parcel for %s, code=%u", name, transactionCode);
         return "Service manager rejected the request";
     }
-    if (ffBinderReadI32(reply.data, reply.size, 0) != 0) {
+    const int32_t exception = ffBinderReadI32(reply.data, reply.size, 0);
+    if (exception != 0) {
+        FF_DEBUG("The service manager raised exception %d for %s", exception, name);
         return "Service manager raised an exception";
     }
     if (reply.handleCount == 0) {
+        FF_DEBUG("The service manager returned no handle for %s", name);
         return "Service is not registered";
     }
 

src/common/android/dex.c

@@ -2,8 +2,10 @@
 #include "common/debug.h"
 #include "common/mallocHelper.h"
 
+#include <errno.h>
 #include <fcntl.h>
 #include <stdio.h>
+#include <string.h>
 #include <sys/mman.h>
 #include <sys/stat.h>
 #include <unistd.h>
@@ -460,6 +462,8 @@ static const char* findDexEntry(const uint8_t* jar, size_t jarSize, const char*
         }
     }
     if (eocd == SIZE_MAX) {
+        FF_DEBUG("No end-of-central-directory record in the last %zu bytes of a %zu byte jar",
+            newest - oldest + FF_ZIP_EOCD_SIZE, jarSize);
         return "The jar has no zip directory";
     }
 
@@ -479,6 +483,8 @@ static const char* findDexEntry(const uint8_t* jar, size_t jarSize, const char*
         const uint16_t commentLength = dexU16(jar + offset + FF_ZIP_OFF_CENTRAL_COMMENT_LENGTH);
         const size_t entrySize = FF_ZIP_CENTRAL_SIZE + (size_t) nameLength + (size_t) extraLength + (size_t) commentLength;
         if (entrySize > directoryEnd - offset) {
+            FF_DEBUG("A zip entry claims %zu bytes but only %zu remain in the directory",
+                entrySize, (size_t) (directoryEnd - offset));
             return "A zip directory entry runs past the directory";
         }
 
@@ -487,6 +493,8 @@ static const char* findDexEntry(const uint8_t* jar, size_t jarSize, const char*
             const uint32_t uncompressed = dexU32(jar + offset + FF_ZIP_OFF_CENTRAL_UNCOMPRESSED_SIZE);
             const uint32_t localOffset = dexU32(jar + offset + FF_ZIP_OFF_CENTRAL_LOCAL_OFFSET);
             if (compressedSize == FF_ZIP_ZIP64_SENTINEL || uncompressed == FF_ZIP_ZIP64_SENTINEL || localOffset == FF_ZIP_ZIP64_SENTINEL) {
+                FF_DEBUG("The dex entry is zip64: compressed=%u, uncompressed=%u, localOffset=%u",
+                    compressedSize, uncompressed, localOffset);
                 return "A dex entry is stored as zip64, which is not supported";
             }
             if (localOffset > jarSize || FF_ZIP_LOCAL_HEADER_SIZE > jarSize - localOffset) {
@@ -509,6 +517,7 @@ static const char* findDexEntry(const uint8_t* jar, size_t jarSize, const char*
 
         offset += entrySize;
     }
+    FF_DEBUG("No entry in the %zu byte jar is named %s", jarSize, entry);
     return "The jar has no usable dex entry";
 }
 
@@ -545,6 +554,7 @@ static const char* inflateDex(const uint8_t* data, size_t dataSize, uint32_t unc
     // the pointer, which is also why no failure path has to free it by hand.
     FF_AUTO_FREE uint8_t* buffer = malloc(uncompressedSize);
     if (buffer == nullptr) {
+        FF_DEBUG("malloc(%u) for the inflated dex failed", uncompressedSize);
         return "malloc failed";
     }
 
@@ -557,12 +567,16 @@ static const char* inflateDex(const uint8_t* data, size_t dataSize, uint32_t unc
     stream.next_out = buffer;
     stream.avail_out = (uInt) uncompressedSize;
 
-    if (ffinflateInit2_(&stream, -MAX_WBITS, ZLIB_VERSION, (int) sizeof(z_stream)) != Z_OK) {
+    const int initStatus = ffinflateInit2_(&stream, -MAX_WBITS, ZLIB_VERSION, (int) sizeof(z_stream));
+    if (initStatus != Z_OK) {
+        FF_DEBUG("inflateInit2() failed: zlib status %d", initStatus);
         return "inflateInit2 failed";
     }
     const int status = ffinflate(&stream, Z_FINISH);
     ffinflateEnd(&stream);
     if (status != Z_STREAM_END || stream.total_out != (uLong) uncompressedSize) {
+        FF_DEBUG("inflate() returned %d, produced %lu of %u bytes",
+            status, stream.total_out, uncompressedSize);
         return "Inflating the dex failed";
     }
 
@@ -587,19 +601,25 @@ const char* ffDexStaticInts(const char* jarPath, const FFDexStaticIntRequest* re
 
     const int fd = open(jarPath, O_RDONLY | O_CLOEXEC);
     if (fd < 0) {
+        FF_DEBUG("open(%s) failed: %s", jarPath, strerror(errno));
         return "open(jar) failed";
     }
 
     struct stat st = {};
-    if (fstat(fd, &st) != 0 || st.st_size <= 0) {
+    const int statStatus = fstat(fd, &st);
+    if (statStatus != 0 || st.st_size <= 0) {
+        FF_DEBUG("fstat(%s) reported %s (%lld bytes)", jarPath,
+            statStatus != 0 ? strerror(errno) : "an empty file", (long long) st.st_size);
         close(fd);
         return "fstat(jar) failed";
     }
     mapping.mappedSize = (size_t) st.st_size;
     mapping.mapped = mmap(nullptr, mapping.mappedSize, PROT_READ, MAP_PRIVATE, fd, 0);
     // The mapping outlives the descriptor, so the descriptor can go either way from here.
+    const int mmapErrno = mapping.mapped == MAP_FAILED ? errno : 0;
     close(fd);
     if (mapping.mapped == MAP_FAILED) {
+        FF_DEBUG("mmap(%s, %zu bytes) failed: %s", jarPath, mapping.mappedSize, strerror(mmapErrno));
         mapping.mapped = nullptr;
         return "mmap(jar) failed";
     }
@@ -610,6 +630,8 @@ const char* ffDexStaticInts(const char* jarPath, const FFDexStaticIntRequest* re
     FF_AUTO_FREE uint8_t* settled = calloc(count, 1);
     FF_AUTO_FREE uint32_t* typeIndexes = malloc((size_t) count * sizeof(uint32_t));
     if (settled == nullptr || typeIndexes == nullptr) {
+        FF_DEBUG("Allocating %zu bytes for %u static int requests failed",
+            (size_t) count * (1 + sizeof(uint32_t)), count);
         return "malloc failed";
     }
 
@@ -650,6 +672,7 @@ const char* ffDexStaticInts(const char* jarPath, const FFDexStaticIntRequest* re
             }
             data = findDexMagic(mapping.mapped, mapping.mappedSize, &dataSize);
             if (data == nullptr) {
+                FF_DEBUG("Neither %s nor a dex magic signature is in the %zu byte jar", entry, mapping.mappedSize);
                 return "No dex in the jar";
             }
         } else if (method == FF_ZIP_METHOD_DEFLATED) {
@@ -664,6 +687,8 @@ const char* ffDexStaticInts(const char* jarPath, const FFDexStaticIntRequest* re
             return "The jar deflates its dex entries and fastfetch was built without zlib";
             #endif
         } else if (method != FF_ZIP_METHOD_STORED) {
+            FF_DEBUG("%s uses compression method %u, only %u (stored) and %u (deflated) are handled",
+                entry, method, FF_ZIP_METHOD_STORED, FF_ZIP_METHOD_DEFLATED);
             return "A dex entry uses an unsupported compression method";
         }
         // A STORED entry needs no further work: `dataSize` already holds the `compressedSize` that