feat: always write the guest pad log to pad.log in the session folder

app/src/main/cpp/fakeinput_steam.cpp

@@ -8,6 +8,7 @@
  * a game become more of these nodes instead of vanishing.
  */
 #include <algorithm>
+#include <atomic>
 #include <cerrno>
 #include <climits>
 #include <cstdint>
@@ -38,6 +39,9 @@
 #include <sys/inotify.h>
 #include <sys/ioctl.h>
 #include <sys/mman.h>
+#include <sys/prctl.h>
+#include <time.h>
+#include <unistd.h>
 #include <sys/select.h>
 #include <sys/socket.h>
 #include <sys/stat.h>
@@ -295,21 +299,52 @@ static void controller_fork_child() {
 
 namespace Logger {
 int log_enabled;
+// FAKE_EVDEV_LOG_FILE: the session's pad.log, shared by every process the library is loaded in
+// (the client, each game), so a pad report has the guest side in one file of the session folder.
+// Opened with the raw syscall: open() is this library's own hook.
+static int log_fd = -1;
+static char log_name[17];
 
 void init() {
   log_enabled = getenv("FAKE_EVDEV_LOG") && atoi(getenv("FAKE_EVDEV_LOG"));
+  const char *path = getenv("FAKE_EVDEV_LOG_FILE");
+  if (log_enabled && path && *path)
+    log_fd = static_cast<int>(syscall(SYS_openat, AT_FDCWD, path, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC, 0644));
+  if (prctl(PR_GET_NAME, log_name) != 0) strcpy(log_name, "?");
 }
 
 void log(const char *message, ...) {
   if (!log_enabled)
     return;
 
+  if (log_fd < 0) {
+    va_list args;
+    va_start(args, message);
+    vfprintf(stderr, message, args);
+    va_end(args);
+    std::cerr.flush();
+    return;
+  }
+  // One write per line: O_APPEND keeps lines from different processes whole.
+  char line[512];
+  struct timespec now;
+  clock_gettime(CLOCK_REALTIME, &now);
+  struct tm local;
+  localtime_r(&now.tv_sec, &local);
+  int n = snprintf(line, sizeof(line), "%02d:%02d:%02d.%03ld %d %s: ", local.tm_hour, local.tm_min,
+                   local.tm_sec, now.tv_nsec / 1000000, getpid(), log_name);
   va_list args;
   va_start(args, message);
-  vfprintf(stderr, message, args);
+  if (n > 0 && n < static_cast<int>(sizeof(line)))
+    n += vsnprintf(line + n, sizeof(line) - n, message, args);
   va_end(args);
-
-  std::cerr.flush();
+  if (n <= 0) return;
+  if (n >= static_cast<int>(sizeof(line))) {
+    n = sizeof(line) - 1;
+    line[n - 1] = '\n';
+  }
+  ssize_t ignored = write(log_fd, line, n);
+  (void)ignored;
 }
 } // namespace Logger
 
@@ -1268,6 +1303,14 @@ __attribute__((visibility("hidden"))) static bool process_is_steam_client() {
   return known == 1;
 }
 
+// What the client starts with, so a pad log says whether it was offered a Deck at all.
+__attribute__((constructor)) static void log_client_start() {
+  config();
+  if (process_is_steam_client())
+    Logger::log("loaded in the Steam client: deck %s, ring slot 0 %s\n", fake_deck_enabled() ? "on" : "off",
+                get_ring_path_for_slot(0).empty() ? "(none configured)" : get_ring_path_for_slot(0).c_str());
+}
+
 __attribute__((visibility("hidden"))) static bool is_deck_hidraw_path(const char *pathname) {
   return pathname && fake_deck_enabled() && !strcmp(pathname, DECK_HIDRAW_PATH);
 }
@@ -1376,12 +1419,16 @@ __attribute__((visibility("hidden"))) static void *deck_report_thread(void *arg)
 __attribute__((visibility("hidden"))) static int open_deck_hidraw(int flags) {
   static auto my_open = reinterpret_cast<int (*)(const char *, int, ...)>(dlsym(RTLD_NEXT, "open"));
   if (!process_is_steam_client()) {
+    // Only the client reads the Deck; a game sees Steam Input's virtual pad instead.
+    Logger::log("deck: %s refused: not the Steam client\n", DECK_HIDRAW_PATH);
     errno = ENOENT;
     return -1;
   }
   std::string ring_path = get_ring_path_for_slot(0);
   int ring_fd = ring_path.empty() ? -1 : my_open(ring_path.c_str(), O_RDONLY | O_CLOEXEC);
   if (ring_fd < 0) {
+    Logger::log("deck: %s refused: ring %s not openable (%s)\n", DECK_HIDRAW_PATH,
+                ring_path.empty() ? "(none configured)" : ring_path.c_str(), strerror(errno));
     errno = ENODEV;
     return -1;
   }
@@ -1394,12 +1441,15 @@ __attribute__((visibility("hidden"))) static int open_deck_hidraw(int flags) {
   void *mapping = mmap(nullptr, mapping_size, PROT_READ, MAP_SHARED, ring_fd, 0);
   syscall(SYS_close, ring_fd);
   if (mapping == MAP_FAILED || !ring_header_is_valid(static_cast<FakeInputRingHeader *>(mapping))) {
+    Logger::log("deck: %s refused: ring %s %s\n", DECK_HIDRAW_PATH, ring_path.c_str(),
+                mapping == MAP_FAILED ? "could not be mapped" : "has no valid header");
     if (mapping != MAP_FAILED) munmap(mapping, mapping_size);
     errno = ENODEV;
     return -1;
   }
   int pair[2];
   if (socketpair(AF_UNIX, SOCK_SEQPACKET | SOCK_CLOEXEC, 0, pair) < 0) {
+    Logger::log("deck: %s refused: socketpair failed (%s)\n", DECK_HIDRAW_PATH, strerror(errno));
     munmap(mapping, mapping_size);
     return -1;
   }
@@ -1451,17 +1501,32 @@ __attribute__((visibility("hidden"))) static bool is_deck_sysfs_fd(int fd) {
   return is_deck_sysfs_path(path);
 }
 
+// Once per process: proof the client's enumeration reached the Deck's sysfs at all. No line here
+// and no open of /dev/hidraw16 means the client never looked; a line here and no open means it
+// looked and turned the device down.
+__attribute__((visibility("hidden"))) static void note_deck_sysfs(const char *how, int result) {
+  static std::atomic<bool> noted{false};
+  if (!noted.exchange(true))
+    Logger::log("deck: sysfs checked (%s%s)\n", how, result == 0 ? "" : ", failed");
+}
+
 EXPORT int fstatfs(int fd, struct statfs *buf) {
   static auto real = reinterpret_cast<int (*)(int, struct statfs *)>(dlsym(RTLD_NEXT, "fstatfs"));
   int result = real(fd, buf);
-  if (result == 0 && fake_deck_enabled() && is_deck_sysfs_fd(fd)) buf->f_type = SYSFS_FS_MAGIC;
+  if (fake_deck_enabled() && is_deck_sysfs_fd(fd)) {
+    note_deck_sysfs("fstatfs", result);
+    if (result == 0) buf->f_type = SYSFS_FS_MAGIC;
+  }
   return result;
 }
 
 EXPORT int statfs(const char *path, struct statfs *buf) {
   static auto real = reinterpret_cast<int (*)(const char *, struct statfs *)>(dlsym(RTLD_NEXT, "statfs"));
   int result = real(path, buf);
-  if (result == 0 && fake_deck_enabled() && is_deck_sysfs_path(path)) buf->f_type = SYSFS_FS_MAGIC;
+  if (fake_deck_enabled() && is_deck_sysfs_path(path)) {
+    note_deck_sysfs(path, result);
+    if (result == 0) buf->f_type = SYSFS_FS_MAGIC;
+  }
   return result;
 }
 
@@ -1483,6 +1548,15 @@ __attribute__((visibility("hidden"))) static int copy_ioctl_string(ioctl_request
 }
 
 // Feature reports carry the report id (0) first, then the Valve message: type, length, payload.
+// The client repeats some feature reports (settings, rumble) for as long as it has the pad; each
+// is logged the first time and then at 2, 4, 8... so the log shows what it asked and how often
+// without a line per report.
+__attribute__((visibility("hidden"))) static void log_deck_feature(const char *what, uint8_t feature) {
+  static std::atomic<unsigned> counts[2][256];
+  unsigned n = ++counts[what[0] == 's'][feature];
+  if ((n & (n - 1)) == 0) Logger::log("deck: feature 0x%02x %s (x%u)\n", feature, what, n);
+}
+
 __attribute__((visibility("hidden"))) static int
 deck_feature(DeckHidraw &deck, ioctl_request_t op, uint8_t *buf, bool set) {
   size_t size = _IOC_SIZE(op);
@@ -1496,7 +1570,7 @@ deck_feature(DeckHidraw &deck, ioctl_request_t op, uint8_t *buf, bool set) {
       int left = buf[6] | buf[7] << 8, right = buf[8] | buf[9] << 8;
       send_vibration(left, right, left || right ? 1000 : 0, 0);
     }
-    Logger::log("deck: feature 0x%02x set\n", buf[1]);
+    log_deck_feature("set", buf[1]);
     return static_cast<int>(size);
   }
   uint8_t reply[DECK_REPORT_BYTES + 1] = {};
@@ -1526,7 +1600,7 @@ deck_feature(DeckHidraw &deck, ioctl_request_t op, uint8_t *buf, bool set) {
     reply[1] = deck.pending_feature;
     break;
   }
-  Logger::log("deck: feature 0x%02x read\n", deck.pending_feature);
+  log_deck_feature("read", deck.pending_feature);
   size_t length = std::min(size, sizeof(reply));
   memcpy(buf, reply, length);
   return static_cast<int>(length);

app/src/main/java/com/droiddeck/launcher/core/DeviceReport.kt

@@ -173,7 +173,7 @@ object DeviceReport {
 
         h("Device switch files in Download")
         for (name in listOf("droiddeck-env", "droiddeck-tu-debug", "droiddeck-driver",
-                            "droiddeck-osc", "droiddeck-no-pad", "droiddeck-pad-log",
+                            "droiddeck-osc", "droiddeck-no-pad",
                             "droiddeck-no-hud", "droiddeck-wlr-renderer")) {
             val f = File(Environment.getExternalStorageDirectory(), "Download/$name")
             if (f.isFile) k(name, FileUtils.readString(f)?.trim()?.replace('\n', ' ')?.ifEmpty { "(present, empty)" } ?: "(present)")

app/src/main/java/com/droiddeck/launcher/session/SessionService.kt

@@ -299,7 +299,7 @@ class SessionService : Service() {
         val controllersOn = !File(Environment.getExternalStorageDirectory(), NO_PAD_SWITCH).exists()
         SessionState.deckPad = false
         deckBinds = emptyList()
-        if (controllersOn) addControllerEnvironment(guest, fakeInputDir)
+        if (controllersOn) addControllerEnvironment(guest, fakeInputDir, sessionDir)
         // The desktop is wlroots (labwc). Stock wlroots allocates through gbm on a real DRM render
         // node, and ours is a KGSL stand-in - labwc died at "unable to create allocator" - so the
         // default is pixman (software, shm), where a Vulkan program cannot draw at all; those run
@@ -616,7 +616,7 @@ class SessionService : Service() {
     }
 
     /** The fake evdev pads: the ring files the app writes and the identity SDL and Steam see. */
-    private fun addControllerEnvironment(guest: MutableList<String>, fakeInputDir: File) {
+    private fun addControllerEnvironment(guest: MutableList<String>, fakeInputDir: File, sessionDir: File) {
         FakeInputWriter.prepareRingSlots(fakeInputDir, 4)
         // Virtual pads a client made last session (event16 and up, and their hidden rings) are
         // not there any more; a client that crashed never took its own down.
@@ -660,9 +660,11 @@ class SessionService : Service() {
         // The client reads a Deck controller through SDL's HIDAPI; a hint in the environment
         // outranks the client's own. Nothing else is shown the Deck (libfakeinput).
         if (!SessionState.deckPad) guest.add("SDL_JOYSTICK_HIDAPI=0")
-        if (File(Environment.getExternalStorageDirectory(), PAD_LOG_SWITCH).exists()) {
-            guest.add("FAKE_EVDEV_LOG=1")
-        }
+        // The guest side of the pads (libfakeinput: which pads were opened, the Deck's hidraw and why
+        // it was refused) in pad.log beside the session's other logs, so it is in every shared zip.
+        // Setup-time lines only, nothing per input event.
+        guest.add("FAKE_EVDEV_LOG=1")
+        guest.add("FAKE_EVDEV_LOG_FILE=" + File(sessionDir, "pad.log").path)
         SessionState.fakeInputDir = fakeInputDir
     }
 
@@ -1232,7 +1234,6 @@ class SessionService : Service() {
         private const val STEAM_PICKUP_MS = 1500L
         private const val STEAM_EXIT_MS = 10_000L
         private const val NO_PAD_SWITCH = "Download/droiddeck-no-pad"
-        private const val PAD_LOG_SWITCH = "Download/droiddeck-pad-log"
         private const val NO_UINPUT_SWITCH = "Download/droiddeck-no-uinput"
         private const val NO_DECK_PAD_SWITCH = "Download/droiddeck-no-deck-pad"
         /** libfakeinput numbers the pads made through its /dev/uinput stand-in from here. */