Add logging features to improve observability

.replit

@@ -15,3 +15,7 @@ channel = "stable-23_11"
 
 [rules.formatter.fileExtensions.".ts"]
 id = "module:nodejs-20:v24-20240117-0bd73cd/formatter:prettier"
+
+[[ports]]
+localPort = 24678
+externalPort = 80

Cargo.toml

@@ -13,6 +13,8 @@ libc = "0.2.152"
 napi = { version = "2.12.2", default-features = false, features = ["napi4"] }
 napi-derive = "2.12.2"
 nix = { version = "0.29.0", features = ["fs", "term", "poll"] }
+log = "0.4"
+env_logger = "0.10"
 
 [build-dependencies]
 napi-build = "2.0.1"

README.md

@@ -32,6 +32,7 @@ The biggest difference from existing PTY libraries is that this one works with B
 - `npm install`
 - `npm run build`
 - `npm run test`
+- `RUST_LOG=debug npm run test` (Run tests with visible log statements)
 
 ## Publishing
 

index.d.ts

@@ -3,6 +3,7 @@
 
 /* auto-generated by NAPI-RS */
 
+export declare function initLogging(): void
 /** The options that can be passed to the constructor of Pty. */
 export interface PtyOptions {
   command: string
@@ -19,17 +20,17 @@ export interface Size {
   rows: number
 }
 /** Resize the terminal. */
-export function ptyResize(fd: number, size: Size): void
+export declare function ptyResize(fd: number, size: Size): void
 /**
  * Set the close-on-exec flag on a file descriptor. This is `fcntl(fd, F_SETFD, FD_CLOEXEC)` under
  * the covers.
  */
-export function setCloseOnExec(fd: number, closeOnExec: boolean): void
+export declare function setCloseOnExec(fd: number, closeOnExec: boolean): void
 /**
  * Get the close-on-exec flag on a file descriptor. This is `fcntl(fd, F_GETFD) & FD_CLOEXEC ==
  *_CLOEXEC` under the covers.
  */
-export function getCloseOnExec(fd: number): boolean
+export declare function getCloseOnExec(fd: number): boolean
 export class Pty {
   /** The pid of the forked process. */
   pid: number
@@ -40,4 +41,6 @@ export class Pty {
    * descriptor.
    */
   takeFd(): c_int
+  /** useful method for checking the PTY state from the JavaScript side. */
+  isActive(): boolean
 }

index.js

@@ -310,8 +310,9 @@ if (!nativeBinding) {
   throw new Error(`Failed to load native binding`)
 }
 
-const { Pty, ptyResize, setCloseOnExec, getCloseOnExec } = nativeBinding
+const { initLogging, Pty, ptyResize, setCloseOnExec, getCloseOnExec } = nativeBinding
 
+module.exports.initLogging = initLogging
 module.exports.Pty = Pty
 module.exports.ptyResize = ptyResize
 module.exports.setCloseOnExec = setCloseOnExec

src/lib.rs

@@ -21,9 +21,20 @@ use nix::poll::{poll, PollFd, PollFlags, PollTimeout};
 use nix::pty::{openpty, Winsize};
 use nix::sys::termios::{self, SetArg};
 
+use log::{info, warn, error};
+
+use env_logger;
+
+
 #[macro_use]
 extern crate napi_derive;
 
+#[napi]
+pub fn init_logging() {
+    env_logger::init();
+}
+
+
 #[napi]
 #[allow(dead_code)]
 struct Pty {
@@ -105,6 +116,7 @@ impl Pty {
   #[napi(constructor)]
   #[allow(dead_code)]
   pub fn new(_env: Env, opts: PtyOptions) -> Result<Self, napi::Error> {
+    info!("Creating new PTY with command: {}", opts.command);
     let size = opts.size.unwrap_or(Size { cols: 80, rows: 24 });
     let window_size = Winsize {
       ws_col: size.cols,
@@ -122,6 +134,7 @@ impl Pty {
     // way into subprocesses. Also set the nonblocking flag to avoid Node from consuming a full I/O
     // thread for this.
     let pty_res = openpty(&window_size, None).map_err(cast_to_napi_error)?;
+    info!("PTY pair opened successfully");
     let controller_fd = pty_res.master;
     let user_fd = pty_res.slave;
     set_close_on_exec(controller_fd.as_raw_fd(), true)?;
@@ -202,6 +215,7 @@ impl Pty {
     // actually spawn the child
     let mut child = cmd.spawn()?;
     let pid = child.id();
+    info!("Spawned child process with PID: {}", pid);
 
     // We're creating a new thread for every child, this uses a bit more system resources compared
     // to alternatives (below), trading off simplicity of implementation.
@@ -268,44 +282,56 @@ impl Pty {
   #[napi]
   #[allow(dead_code)]
   pub fn take_fd(&mut self) -> Result<c_int, napi::Error> {
-    if let Some(fd) = self.controller_fd.take() {
-      Ok(fd.into_raw_fd())
-    } else {
-      Err(napi::Error::new(
-        napi::Status::GenericFailure,
-        "fd failed: bad file descriptor (os error 9)",
-      ))
-    }
+      self.controller_fd.take().map(|fd| {
+          let raw_fd = fd.into_raw_fd();
+          info!("File descriptor {} taken from PTY", raw_fd);
+          raw_fd
+      }).ok_or_else(|| {
+          warn!("Attempt to take fd failed: fd already taken or never initialized");
+          napi::Error::new(
+              napi::Status::GenericFailure,
+              "File descriptor has already been taken or was never initialized",
+          )
+      })
+  }
+
+  /// useful method for checking the PTY state from the JavaScript side.
+  #[napi]
+  pub fn is_active(&self) -> bool {
+      self.controller_fd.is_some()
   }
 }
 
 /// Resize the terminal.
 #[napi]
 #[allow(dead_code)]
 fn pty_resize(fd: i32, size: Size) -> Result<(), napi::Error> {
-  let window_size = Winsize {
-    ws_col: size.cols,
-    ws_row: size.rows,
-    ws_xpixel: 0,
-    ws_ypixel: 0,
-  };
-
-  let res = unsafe { libc::ioctl(fd, libc::TIOCSWINSZ, &window_size as *const _) };
-  if res == -1 {
-    return Err(napi::Error::new(
-      napi::Status::GenericFailure,
-      format!("ioctl TIOCSWINSZ failed: {}", Error::last_os_error()),
-    ));
-  }
-
-  Ok(())
+    info!("Attempting to resize PTY (fd: {}) to {}x{}", fd, size.cols, size.rows);
+    let window_size = Winsize {
+        ws_col: size.cols,
+        ws_row: size.rows,
+        ws_xpixel: 0,
+        ws_ypixel: 0,
+    };
+    let res = unsafe { libc::ioctl(fd, libc::TIOCSWINSZ, &window_size as *const _) };
+    if res == -1 {
+        let err = Error::last_os_error();
+        error!("Failed to resize PTY: {} (errno: {})", err, err.raw_os_error().unwrap_or(-1));
+        return Err(napi::Error::new(
+            napi::Status::GenericFailure,
+            format!("ioctl TIOCSWINSZ failed: {}", err),
+        ));
+    }
+    info!("Successfully resized PTY to {}x{}", size.cols, size.rows);
+    Ok(())
 }
 
 /// Set the close-on-exec flag on a file descriptor. This is `fcntl(fd, F_SETFD, FD_CLOEXEC)` under
 /// the covers.
 #[napi]
 #[allow(dead_code)]
 fn set_close_on_exec(fd: i32, close_on_exec: bool) -> Result<(), napi::Error> {
+  info!("Setting close-on-exec flag to {} for fd {}", close_on_exec, fd);
   let old_flags = match fcntl(fd as RawFd, FcntlArg::F_GETFD) {
     Ok(flags) => FdFlag::from_bits_truncate(flags),
     Err(err) => {
@@ -318,17 +344,19 @@ fn set_close_on_exec(fd: i32, close_on_exec: bool) -> Result<(), napi::Error> {
   let mut new_flags = old_flags;
   new_flags.set(FdFlag::FD_CLOEXEC, close_on_exec);
   if old_flags == new_flags {
-    // It's already in the correct state!
+    info!("Close-on-exec flag already in correct state for fd {}", fd);
     return Ok(());
   }
 
   if let Err(err) = fcntl(fd as RawFd, FcntlArg::F_SETFD(new_flags)) {
+    error!("Failed to set close-on-exec flag for fd {}: {}", fd, err);
     return Err(napi::Error::new(
       GenericFailure,
       format!("fcntl F_SETFD: {}", err,),
     ));
   };
 
+  info!("Successfully set close-on-exec flag for fd {}", fd);
   Ok(())
 }
 
@@ -349,6 +377,7 @@ fn get_close_on_exec(fd: i32) -> Result<bool, napi::Error> {
 /// Set the file descriptor to be non-blocking.
 #[allow(dead_code)]
 fn set_nonblocking(fd: i32) -> Result<(), napi::Error> {
+  info!("Setting fd {} to non-blocking mode", fd);
   let old_flags = match fcntl(fd, FcntlArg::F_GETFL) {
     Ok(flags) => OFlag::from_bits_truncate(flags),
     Err(err) => {
@@ -363,11 +392,13 @@ fn set_nonblocking(fd: i32) -> Result<(), napi::Error> {
   new_flags.set(OFlag::O_NONBLOCK, true);
   if old_flags != new_flags {
     if let Err(err) = fcntl(fd, FcntlArg::F_SETFL(new_flags)) {
+      error!("Failed to set fd {} to non-blocking mode: {}", fd, err);
       return Err(napi::Error::new(
         GenericFailure,
         format!("fcntl F_SETFL: {}", err),
       ));
     }
+    info!("Successfully set fd {} to non-blocking mode", fd);
   }
   Ok(())
 }

tests/index.test.ts

@@ -1,14 +1,23 @@
-import { Pty, getCloseOnExec, setCloseOnExec } from '../wrapper';
+import { Pty, getCloseOnExec, setCloseOnExec, initLogging} from '../wrapper';
 import { type Writable } from 'stream';
 import { readdirSync, readlinkSync } from 'fs';
-import { describe, test, expect } from 'vitest';
+import { describe, test, expect, beforeAll} from 'vitest';
 
 const EOT = '\x04';
 const procSelfFd = '/proc/self/fd/';
 const IS_DARWIN = process.platform === 'darwin';
 
 const testSkipOnDarwin = IS_DARWIN ? test.skip : test;
 
+
+beforeAll(() => {
+  // Initialize logging
+  initLogging();
+  // Set the log level to 'debug' to see all log messages
+  process.env.RUST_LOG = 'debug';
+});
+
+
 type FdRecord = Record<string, string>;
 function getOpenFds(): FdRecord {
   const fds: FdRecord = {};

wrapper.ts

@@ -8,8 +8,10 @@ import {
   ptyResize,
 } from './index.js';
 import { type PtyOptions as RawOptions } from './index.js';
+import { initLogging as rawInitLogging } from './index.js';
 
 export type PtyOptions = RawOptions;
+export const initLogging = rawInitLogging;
 
 type ExitResult = {
   error: NodeJS.ErrnoException | null;