diag: targeted EINVAL tracing

src/context/context.rs

@@ -776,24 +776,33 @@ impl FdTbl {
 
         let tag = min & UPPER_FDTBL_TAG;
 
-        let (fdtbl, min) = self.select_fdtbl_mut(min);
+        let found_pos = {
-
+            let (fdtbl, min_val) = self.select_fdtbl_mut(min);
-        // Find the first empty slot in the posix_fdtbl starting from `min`.
+            fdtbl.iter().enumerate().skip(min_val).find(|(_, slot)| slot.is_none()).map(|(pos, _)| pos)
-        if let Some((pos, slot)) = fdtbl
-            .iter_mut()
-            .enumerate()
-            .skip(min)
-            .find(|(_, slot)| slot.is_none())
-        {
-            *slot = Some(file);
-            self.active_count += 1;
-            return Some(FileHandle::from(pos | tag));
         };
 
-        let len = fdtbl.len();
+        if let Some(pos) = found_pos {
+            if tag == 0 && pos <= 5 {
+                crate::info!("ADDFILE_MIN: pos={}", pos);
+            }
+            let (fdtbl, _) = self.select_fdtbl_mut(min | tag);
+            if let Some(slot) = fdtbl.get_mut(pos) {
+                *slot = Some(file);
+            }
+            self.active_count += 1;
+            return Some(FileHandle::from(pos | tag));
+        }
+
+        let len = {
+            let (fdtbl, _) = self.select_fdtbl_mut(min);
+            fdtbl.len()
+        };
 
-        // If no empty slot was found, we need to allocate a new slot.
         if len >= min {
+            if tag == 0 {
+                crate::info!("ADDFILE_APPEND: pos={}", len);
+            }
+            let (fdtbl, _) = self.select_fdtbl_mut(min | tag);
             fdtbl.push(Some(file));
             self.active_count += 1;
             Some(FileHandle::from(len | tag))
@@ -835,6 +844,18 @@ impl FdTbl {
             return None;
         }
         let index = i.get();
+        let is_posix = index & UPPER_FDTBL_TAG == 0;
+
+        if is_posix {
+            let real_index = Self::strip_tags(index);
+            if real_index >= super::CONTEXT_MAX_FILES {
+                return None;
+            }
+            if real_index <= 5 {
+                crate::info!("INSERT_FILE: posix_fd={}", real_index);
+            }
+        }
+
         let (fdtbl, real_index) = self.select_fdtbl_mut(index);
 
         if real_index >= super::CONTEXT_MAX_FILES {
@@ -960,8 +981,13 @@ impl FdTbl {
 
     fn remove_file(&mut self, i: FileHandle) -> Option<FileDescriptor> {
         let index = i.get();
+        let is_posix = index & UPPER_FDTBL_TAG == 0;
         let (fdtbl, real_index) = self.select_fdtbl_mut(index);
 
+        if is_posix && real_index <= 5 {
+            crate::info!("REMOVE_FILE: posix_fd={}", real_index);
+        }
+
         let removed_file_opt = fdtbl.get_mut(real_index).and_then(|opt| opt.take());
         if removed_file_opt.is_some() {
             self.active_count -= 1;

src/scheme/mod.rs

@@ -384,7 +384,10 @@ impl KernelScheme for SchemeList {
     ) -> Result<usize> {
         match self.get_user_inner(id, token) {
             Some(inner) => inner.write(buf, token),
-            None => Err(Error::new(EBADF)),
+            None => {
+                error!("KWRITE: scheme {} not found", id);
+                Err(Error::new(EBADF))
+            }
         }
     }
 

src/scheme/user.rs

@@ -167,7 +167,9 @@ impl UserInner {
     fn next_id(&self, token: &mut CleanLockToken) -> Result<u32> {
         let idx = {
             let mut states = self.states.lock(token.token());
-            states.insert(State::Placeholder)
+            let idx = states.insert(State::Placeholder);
+            info!("TAG_ALLOC: scheme={} tag={}", self.scheme_id.get(), idx);
+            idx
         };
 
         // TODO: implement blocking?
@@ -721,9 +723,12 @@ impl UserInner {
     }
 
     pub fn write(&self, buf: UserSliceRo, token: &mut CleanLockToken) -> Result<usize> {
+        info!("WRITE_ENTRY: scheme={} buf_len={}", self.scheme_id.get(), buf.len());
         let mut bytes_read = 0;
         for chunk in buf.in_exact_chunks(size_of::<Cqe>()) {
-            match ParsedCqe::parse_cqe(&unsafe { chunk.read_exact::<Cqe>()? })
+            let cqe = unsafe { chunk.read_exact::<Cqe>()? };
+            info!("CQE_RECV: scheme={} opcode={} tag={} result={}", self.scheme_id.get(), cqe.flags & 0b111, cqe.tag, cqe.result);
+            match ParsedCqe::parse_cqe(&cqe)
                 .and_then(|p| self.handle_parsed(&p, token))
             {
                 Ok(()) => bytes_read += size_of::<Cqe>(),
@@ -741,8 +746,6 @@ impl UserInner {
         flags: MapFlags,
         token: &mut CleanLockToken,
     ) -> Result<()> {
-        info!("REQUEST FMAP");
-
         let tag = self.next_id(token)?;
         {
             let mut states = self.states.lock(token.token());
@@ -779,20 +782,28 @@ impl UserInner {
             ParsedCqe::RespondAndNotifyOnDetach { tag, res, extra0 } => {
                 self.respond(tag, Response::Regular(res, extra0, true), token)?
             }
-            ParsedCqe::ResponseWithFd { tag, fd } => self.respond(
+            ParsedCqe::ResponseWithFd { tag, fd } => {
+                info!("RESPOND_WITH_FD: tag={} fd={}", tag, fd);
+                self.respond(
                 tag,
                 Response::Fd({
-                    {
+                    let removed = {
                         let current_lock = context::current();
                         let mut current = current_lock.read(token.token());
                         let (context, mut token) = current.token_split();
                         context.remove_file(FileHandle::from(fd), &mut token)
+                    };
+                    match removed {
+                        Some(desc) => desc.description,
+                        None => {
+                            error!("EINVAL ResponseWithFd: tag={} fd={} not in procmgr fd table", tag, fd);
+                            return Err(Error::new(EINVAL));
+                        }
                     }
-                    .ok_or(Error::new(EINVAL))?
-                    .description
                 }),
                 token,
-            )?,
+            )?;
+            },
             ParsedCqe::ResponseWithMultipleFds { tag, num_fds: _ } => {
                 self.respond(tag, Response::MultipleFds(None), token)?;
             }
@@ -931,6 +942,11 @@ impl UserInner {
                     State::Placeholder => return Err(Error::new(EBADFD)),
                     // invalid scheme to kernel call
                     old_state @ (State::Responded(_) | State::Fmap(_)) => {
+                        error!("EINVAL respond: tag={} state={:?}", tag, match &old_state {
+                            State::Responded(_) => "Responded",
+                            State::Fmap(_) => "Fmap",
+                            _ => unreachable!(),
+                        });
                         *o = old_state;
                         return Err(Error::new(EINVAL));
                     }

src/syscall/fs.rs

@@ -45,6 +45,12 @@ pub fn file_op_generic_ext<T>(
         (file, desc)
     };
 
+    // Debug: trace fd=3 to catch corruption
+    if fd.get() == 3 && fd.get() & syscall::UPPER_FDTBL_TAG == 0 {
+        let pid = context::current().read(token.token()).pid;
+        info!("FD3_TRACE: pid={} scheme={} number={}", pid, desc.scheme.get(), desc.number);
+    }
+
     let scheme = scheme::get_scheme(token.token(), desc.scheme)?;
 
     op(&*scheme, file.description, desc, token)
@@ -848,8 +854,13 @@ pub fn sys_write(fd: FileHandle, buf: UserSliceRo, token: &mut CleanLockToken) -
             } else {
                 0
             };
+            let res = scheme.kwriteoff(desc.number, buf, offset, desc.flags, desc.flags, token);
+            if res.is_err() {
+                let pid = context::current().read(token.token()).pid;
+                error!("SYS_WRITE_ERR: pid={} fd={} scheme={} number={} offset={} err={:?}", pid, fd.get(), desc.scheme.get(), desc.number, offset, res.as_ref().err());
+            }
             Ok((
-                scheme.kwriteoff(desc.number, buf, offset, desc.flags, desc.flags, token)?,
+                res?,
                 desc_arc,
                 desc,
             ))