nfs4: Improve debug output

* Make more info available from Dump functions.
* Allow locking to fail in Dump functions to avoid deadlocks caused by
  debug output.
* Make corrections to the nfs4_unlink() changes in hrev59023.

Change-Id: I8e5431baacb3cfa0baaedd2695c597549e746d2c
Reviewed-on: https://review.haiku-os.org/c/haiku/+/9628
Tested-by: Commit checker robot <[email protected]>
Reviewed-by: waddlesplash <[email protected]>
This commit is contained in:
Jim906
2025-09-08 15:58:36 +00:00
committed by waddlesplash
parent 7270c1788f
commit 0f9d0e5cda
18 changed files with 380 additions and 55 deletions
+27 -9
View File
@@ -31,20 +31,38 @@ int
kprintf_inode(int argc, char** argv)
{
if ((argc == 1) || strcmp(argv[1], "--help") == 0) {
kprintf("usage: nfs4_inode <address(es) ...>\n"
" address(es): address of one or more nfs4 private nodes (VnodeToInode), "
kprintf("usage: nfs4_inode [-i] <address(es) ...>\n"
" -i specifies that the address is that of an Inode (rather than a VnodeToInode)\n"
" address(es): address of one or more objects of the same type, "
"separated by spaces\n"
" Addresses can be found with the 'vnodes' command.\n");
" VnodeToInode addresses can be found with the 'vnodes' command.\n"
" Output of the 'nfs4' command refers to nodes by their Inode address.\n");
return 0;
}
for (int i = 1; i < argc; i++) {
VnodeToInode* node = reinterpret_cast<VnodeToInode*>(strtoul(argv[1], NULL, 0));
if (node == NULL)
continue;
node->Dump(kprintf);
kprintf("----------\n");
int argIndex = 1;
bool dumpVti = true;
if (strcmp(argv[argIndex], "-i") == 0) {
dumpVti = false;
++argIndex;
}
for (; argIndex < argc; ++argIndex) {
if (dumpVti) {
VnodeToInode* vti = reinterpret_cast<VnodeToInode*>(strtoul(argv[argIndex], NULL, 0));
if (vti == NULL)
continue;
vti->Dump(kprintf);
} else {
Inode* inode = reinterpret_cast<Inode*>(strtoul(argv[argIndex], NULL, 0));
if (inode == NULL)
continue;
inode->Dump(kprintf);
}
kprintf("\n");
}
return 0;
}
+11 -4
View File
@@ -16,13 +16,20 @@
#include <DebugSupport.h>
#ifdef DEBUG
#define TRACE(x...) FUNCTION(x)
#define CALLED() FUNCTION_START()
#if KDEBUG
# define ASSERT_WITH_DUMP(expr,obj) \
do { \
if (!(expr)) { \
obj->Dump(); \
panic("ASSERT FAILED (%s:%d): %s", __FILE__, __LINE__, #expr); \
} \
} while (0)
#else
#define TRACE(x...)
#define CALLED()
#endif
# define ASSERT_WITH_DUMP(expr,obj) do { } while(0)
#endif // KDEBUG
#if USER
extern "C" void dprintf(const char *format, ...);
@@ -39,6 +39,22 @@ Delegation::GiveUp(bool truncate)
}
void
Delegation::Dump(void (*xprintf)(const char*, ...)) const
{
xprintf("Delegation at %p for Inode at %p (ino %" B_PRIdINO ")\n", this, fInode, fInode->ID());
if (fData.fType == OPEN_DELEGATE_READ)
xprintf("\ttype OPEN_DELEGATE_READ, ");
else if (fData.fType == OPEN_DELEGATE_WRITE)
xprintf("\ttype OPEN_DELEGATE_WRITE, ");
xprintf("attribute %d, uid %" B_PRIu32 ", gid %" B_PRIu32 "\n", fAttribute, fUid, fGid);
xprintf("\tstate id and sequence %" B_PRIu32 " %" B_PRIu32 " %" B_PRIu32 " %" B_PRIu32 "\n",
fData.fStateID[0], fData.fStateID[1], fData.fStateID[2], fData.fStateSeq);
return;
}
status_t
Delegation::ReturnDelegation()
{
@@ -26,9 +26,11 @@ public:
status_t GiveUp(bool truncate = false);
inline void SetData(const OpenDelegationData& data);
inline Inode* GetInode();
inline Inode* GetInode() const;
inline OpenDelegation Type();
void Dump(void (*xprintf)(const char*, ...) = dprintf) const;
protected:
status_t ReturnDelegation();
@@ -50,7 +52,7 @@ Delegation::SetData(const OpenDelegationData& data)
inline Inode*
Delegation::GetInode()
Delegation::GetInode() const
{
return fInode;
}
@@ -86,7 +86,7 @@ DirectoryCache::DirectoryCache(Inode* inode, bool attr)
{
ASSERT(inode != NULL);
mutex_init(&fLock, NULL);
mutex_init(&fLock, "nfs4 DirectoryCache");
}
@@ -299,7 +299,7 @@ DirectoryCache::_DumpLocked(void (*xprintf)(const char*, ...)) const
for (SinglyLinkedList<NameCacheEntry>::ConstIterator it = fNameCache.GetIterator();
const NameCacheEntry* entry = it.Next();) {
xprintf("\t\tino: %" B_PRIdINO "\t", entry->fNode);
xprintf("\tino: %" B_PRIdINO "\t", entry->fNode);
if (entry->fName != NULL)
xprintf("name: %s\n", entry->fName);
}
@@ -115,6 +115,7 @@ InodeNames::Dump(void (*xprintf)(const char*, ...))
void
InodeNames::_DumpLocked(void (*xprintf)(const char*, ...)) const
{
xprintf("InodeNames ");
for (SinglyLinkedList<InodeName>::ConstIterator it = fNames.GetIterator();
const InodeName* name = it.Next();) {
if (name->fName != NULL)
@@ -18,6 +18,7 @@
#include "Request.h"
#include "RootInode.h"
#include "VnodeToInode.h"
#include "WorkQueue.h"
extern RPC::ServerManager* gRPCServerManager;
@@ -37,10 +38,10 @@ FileSystem::FileSystem(const MountConfiguration& configuration)
{
fOpenOwner = get_random<uint64>();
mutex_init(&fOpenOwnerLock, NULL);
mutex_init(&fOpenLock, NULL);
mutex_init(&fDelegationLock, NULL);
mutex_init(&fCreateFileLock, NULL);
mutex_init(&fOpenOwnerLock, "nfs4 FileSystem::fOpenOwnerLock");
mutex_init(&fOpenLock, "nfs4 FileSystem::fOpenLock");
mutex_init(&fDelegationLock, "nfs4 FileSystem::fDelegationLock");
mutex_init(&fCreateFileLock, "nfs4 FileSystem::fCreateFileLock");
}
@@ -554,13 +555,32 @@ FileSystem::ServerUnlinkCleanup(ino_t id, Inode* parent, const char* missingName
void
FileSystem::Dump(void (*xprintf)(const char*, ...))
{
MutexLocker locker;
if (xprintf != kprintf)
locker.SetTo(fOpenLock, false);
xprintf("FileSystem at %p\n", this);
bool dumpDelegations = true;
bool dumpOpenFiles = true;
if (xprintf != kprintf) {
status_t status = mutex_trylock(&fDelegationLock);
if (status != B_OK)
dumpDelegations = false;
status = mutex_trylock(&fOpenLock);
if (status != B_OK)
dumpOpenFiles = false;
}
_DumpLocked(xprintf, dumpDelegations, dumpOpenFiles);
if (xprintf != kprintf) {
if (dumpDelegations)
mutex_unlock(&fDelegationLock);
if (dumpOpenFiles)
mutex_unlock(&fOpenLock);
}
xprintf("\n");
fInoIdMap.Dump(xprintf);
_DumpLocked(xprintf);
xprintf("\n");
gWorkQueue->Dump(xprintf);
return;
}
@@ -607,17 +627,36 @@ FileSystem::_ParsePath(RequestBuilder& req, uint32& count, const char* _path)
void
FileSystem::_DumpLocked(void (*xprintf)(const char*, ...)) const
FileSystem::_DumpLocked(void (*xprintf)(const char*, ...), bool dumpDelegations,
bool dumpOpenFiles) const
{
xprintf("fOpenFiles:\n", fOpenFiles);
for (DoublyLinkedList<OpenState>::ConstIterator it = fOpenFiles.GetIterator();
const OpenState* state = it.Next();) {
xprintf("\tID\t\t%" B_PRIu64 "\n", state->fInfo.fFileId);
xprintf("\tFileHandle\t");
state->fInfo.fHandle.Dump(xprintf);
xprintf("\tInodeNames\t");
state->fInfo.fNames->Dump(xprintf);
xprintf("\t----------\n");
xprintf("\tRootInode at %p\n", fRoot);
xprintf("\tfOpenFiles\n", fOpenFiles);
if (dumpOpenFiles) {
uint64 entries = 0;
for (DoublyLinkedList<OpenState>::ConstIterator it = fOpenFiles.GetIterator();
const OpenState* state = it.Next(); ++entries) {
xprintf("\t\tOpenState at %p for ino %" B_PRIdINO "\n", state, state->fInfo.fFileId);
}
if (entries == 0)
xprintf("\t\tNone\n");
} else {
xprintf("\tfOpenLock is locked\n");
}
xprintf("\tDelegations\n");
if (dumpDelegations) {
uint64 entries = 0;
for (DoublyLinkedList<Delegation>::ConstIterator it = fDelegationList.GetIterator();
const Delegation* del = it.Next(); ++entries) {
xprintf("\t\tDelegation at %p for Inode at %p (ino %" B_PRIdINO ")\n", del,
del->GetInode(), del->GetInode()->ID());
}
if (entries == 0)
xprintf("\t\tNone");
} else {
xprintf("\tfDelegationLock is locked\n");
}
return;
@@ -98,7 +98,8 @@ private:
static status_t _ParsePath(RequestBuilder& req, uint32& count,
const char* _path);
void _DumpLocked(void (*xprintf)(const char*, ...)) const;
void _DumpLocked(void (*xprintf)(const char*, ...),
bool dumpDelegations, bool dumpOpenFiles) const;
mutex fCreateFileLock;
+79 -11
View File
@@ -19,6 +19,7 @@
#include "IdMap.h"
#include "Request.h"
#include "RootInode.h"
#include "WorkQueue.h"
Inode::Inode()
@@ -35,11 +36,11 @@ Inode::Inode()
fAIOCount(0),
fStale(false)
{
rw_lock_init(&fDelegationLock, NULL);
mutex_init(&fStateLock, NULL);
mutex_init(&fFileCacheLock, NULL);
rw_lock_init(&fWriteLock, NULL);
mutex_init(&fAIOLock, NULL);
rw_lock_init(&fDelegationLock, "nfs4 Inode::fDelegationLock");
mutex_init(&fStateLock, "nfs4 Inode::fStateLock");
mutex_init(&fFileCacheLock, "nfs4 Inode::fFileCacheLock");
rw_lock_init(&fWriteLock, "nfs4 Inode::fWriteLock");
mutex_init(&fAIOLock, "nfs4 Inode::fAIOLock");
}
@@ -1051,14 +1052,81 @@ Inode::EndAIOOp()
@pre The parent VnodeToInode is locked.
*/
void
Inode::Dump(void (*xprintf)(const char*, ...)) const
Inode::Dump(void (*xprintf)(const char*, ...))
{
xprintf("Inode\t%" B_PRIu64 " at %p\n", fInfo.fFileId, this);
xprintf("FileHandle\t");
fInfo.fHandle.Dump(xprintf);
xprintf("InodeNames\t");
fInfo.fNames->Dump(xprintf);
bool dumpDelegation = true;
bool dumpAIO = true;
if (xprintf != kprintf) {
status_t status = rw_lock_read_lock_with_timeout(&fDelegationLock, B_RELATIVE_TIMEOUT, 0);
if (status != B_OK)
dumpDelegation = false;
status = mutex_trylock(&fAIOLock);
if (status != B_OK)
dumpAIO = false;
}
_DumpLocked(xprintf, dumpDelegation, dumpAIO);
if (xprintf != kprintf) {
if (dumpDelegation)
rw_lock_read_unlock(&fDelegationLock);
if (dumpAIO)
mutex_unlock(&fAIOLock);
}
if (GetFileSystem()->Root() != this)
fInfo.fNames->Dump(xprintf);
if (fCache != NULL)
fCache->Dump(xprintf);
fMetaCache.Dump(xprintf);
if (fOpenState == NULL) {
xprintf("No OpenState\n");
} else {
status_t status = mutex_trylock(&fStateLock);
if (status == B_OK) {
fOpenState->Dump(xprintf);
mutex_unlock(&fStateLock);
} else {
xprintf("fStateLock locked\n");
}
}
gWorkQueue->Dump(xprintf);
return;
}
/*! Dump members that have const Dump methods or are dumped manually.
*/
void
Inode::_DumpLocked(void (*xprintf)(const char*, ...), bool dumpDelegation, bool dumpAIO) const
{
if (GetFileSystem()->Root() == this)
xprintf("Root inode\t%" B_PRIu64 " at %p\n", fInfo.fFileId, this);
else
xprintf("Inode\t%" B_PRIu64 " at %p\n", fInfo.fFileId, this);
xprintf("FileHandle ");
fInfo.fHandle.Dump(xprintf);
xprintf("\tfType %" B_PRIu32 ", fChange %" B_PRIu64 ", fStale %d\n", fType, fChange, fStale);
if (dumpAIO)
xprintf("\tfAIOCount %" B_PRIu32 "\n", fAIOCount);
else
xprintf("\tAIO locked\n");
if (fDelegation == NULL)
xprintf("\tNo Delegation\n");
else if (dumpDelegation)
fDelegation->Dump();
else
xprintf("Delegation locked\n");
return;
}
+4 -1
View File
@@ -122,7 +122,7 @@ public:
inline void SetStale(bool stale = true);
inline bool IsStale() const;
void Dump(void (*xprintf)(const char*, ...) = dprintf) const;
void Dump(void (*xprintf)(const char*, ...) = dprintf);
protected:
Inode();
@@ -150,6 +150,9 @@ protected:
static inline status_t CheckLockType(short ltype, uint32 mode);
private:
void _DumpLocked(void (*xprintf)(const char*, ...), bool dumpDelegation,
bool dumpAIO) const;
private:
uint32 fType;
@@ -22,7 +22,7 @@ MetadataCache::MetadataCache(Inode* inode)
fInited(false)
{
ASSERT(inode != NULL);
mutex_init(&fLock, NULL);
mutex_init(&fLock, "nfs4 MetadataCache");
}
@@ -148,6 +148,26 @@ MetadataCache::UnlockValid()
}
void
MetadataCache::Dump(void (*xprintf)(const char*, ...))
{
if (xprintf != kprintf) {
status_t status = mutex_trylock(&fLock);
if (status != B_OK) {
xprintf("MetadataCache at %p locked\n", this);
return;
}
}
_DumpLocked(xprintf);
if (xprintf != kprintf)
mutex_unlock(&fLock);
return;
}
void
MetadataCache::NotifyChanges(const struct stat* oldStat,
const struct stat* newStat)
@@ -185,3 +205,23 @@ MetadataCache::NotifyChanges(const struct stat* oldStat,
flags);
}
void
MetadataCache::_DumpLocked(void (*xprintf)(const char*, ...)) const
{
xprintf("MetadataCache at %p for Inode at %p\n", this, fInode);
xprintf("\tfInited %d, fForceValid %d\n", fInited, fForceValid);
if (time(NULL) < fExpire)
xprintf("\tExpires at %" B_PRIdTIME "\n", fExpire);
else
xprintf("\tExpired\n");
xprintf("\tst_mode %" B_PRIo32 "\n", fStatCache.st_mode);
xprintf("\tst_nlink %" B_PRId32 "\n", fStatCache.st_nlink);
xprintf("\tst_uid %" B_PRIu32 "\n", fStatCache.st_uid);
xprintf("\tst_gid %" B_PRIu32 "\n", fStatCache.st_gid);
xprintf("\tst_size %" B_PRIdOFF "\n", fStatCache.st_size);
return;
}
@@ -15,6 +15,7 @@
#include <util/AutoLock.h>
#include <util/AVLTreeMap.h>
#include "Debug.h"
class Inode;
@@ -45,12 +46,17 @@ public:
inline void Invalidate();
void Dump(void (*xprintf)(const char*, ...) = dprintf);
static const time_t kExpirationTime = 60;
protected:
void NotifyChanges(const struct stat* oldStat,
const struct stat* newStat);
private:
void _DumpLocked(void (*xprintf)(const char*, ...)) const;
private:
struct stat fStatCache;
time_t fExpire;
@@ -25,10 +25,10 @@ OpenState::OpenState()
fUid(geteuid()),
fGid(getegid())
{
mutex_init(&fLock, NULL);
mutex_init(&fLock, "nfs4 OpenState::fLock");
mutex_init(&fLocksLock, NULL);
mutex_init(&fOwnerLock, NULL);
mutex_init(&fLocksLock, "nfs4 OpenState::fLocksLock");
mutex_init(&fOwnerLock, "nfs4 OpenState::fOwnerLock");
}
@@ -330,3 +330,45 @@ OpenState::Close()
} while (true);
}
void
OpenState::Dump(void (*xprintf)(const char*, ...))
{
status_t status = B_OK;
if (xprintf != kprintf)
status = mutex_trylock(&fLock);
if (status == B_OK)
_DumpLocked(xprintf);
else
xprintf("OpenState at %p locked\n", this);
if (xprintf != kprintf && status == B_OK)
mutex_unlock(&fLock);
return;
}
void
OpenState::_DumpLocked(void (*xprintf)(const char*, ...)) const
{
xprintf("OpenState at %p for ino %" B_PRIdINO "\n", this, Inode::FileIdToInoT(fInfo.fFileId));
xprintf("\tFileHandle ");
fInfo.fHandle.Dump(xprintf);
xprintf("\t");
fInfo.fNames->Dump(xprintf);
xprintf("\tmode %x, opened %d, delegation %p, refs %" B_PRIu32 "\n",
static_cast<unsigned int>(fMode), fOpened, fDelegation, CountReferences());
xprintf("\tuid %" B_PRIu32 ", gid %" B_PRIu32 "\n", fUid, fGid);
xprintf("\tstate id and sequence %" B_PRIu32 " %" B_PRIu32 " %" B_PRIu32 " %" B_PRIu32 "\n",
fStateID[0], fStateID[1], fStateID[2], fStateSeq);
return;
}
@@ -52,10 +52,14 @@ struct OpenState : public NFS4Object, public KernelReferenceable,
status_t Close();
void Dump(void (*xprintf)(const char*, ...) = dprintf);
private:
status_t _ReclaimOpen(uint64 newClientID);
status_t _ReclaimLocks(uint64 newClientID);
status_t _ReleaseLockOwner(LockOwner* owner);
void _DumpLocked(void (*xprintf)(const char*, ...)) const;
};
@@ -899,7 +899,13 @@ ReplyInterpreter::_OperationError(Opcode op)
status_t result = _NFS4ErrorToHaiku(fReply->Stream().GetUInt());
if (result != B_OK) {
#if DEBUG
ERROR("NFS Error: %s\n", strerror(result));
#else
// Lookup failures are routine. Reporting them could obscure more important error messages.
if (op != OpLookUp || result != B_ENTRY_NOT_FOUND)
ERROR("NFS Error: %s\n", strerror(result));
#endif
fDecodeError = true;
}
return result;
@@ -17,6 +17,28 @@
WorkQueue* gWorkQueue = NULL;
void
WorkQueueEntry::Dump(void (*xprintf)(const char*, ...)) const
{
if (fType == DelegationRecall) {
xprintf("\tType: DelegationRecall\n");
DelegationRecallArgs* args = reinterpret_cast<DelegationRecallArgs*>(fArguments);
xprintf("\t\tDelegation at %p for Inode at %p (ino %" B_PRIdINO "), truncate %d\n",
args->fDelegation, args->fDelegation->GetInode(), args->fDelegation->GetInode()->ID(),
args->fTruncate);
} else if (fType == IORequest) {
xprintf("\tType: IORequest\n");
IORequestArgs* args = reinterpret_cast<IORequestArgs*>(fArguments);
xprintf("\t\tFor Inode at %p (ino %" B_PRIdINO ")\n", args->fInode, args->fInode->ID());
xprintf("\t\twrite %d, offset %" B_PRIdOFF ", length %" B_PRIdOFF "\n",
io_request_is_write(args->fRequest), io_request_offset(args->fRequest),
io_request_length(args->fRequest));
}
return;
}
WorkQueue::WorkQueue()
:
fQueueSemaphore(create_sem(0, NULL)),
@@ -76,6 +98,28 @@ WorkQueue::EnqueueJob(JobType type, void* args)
}
void
WorkQueue::Dump(void (*xprintf)(const char*, ...))
{
xprintf("WorkQueue\n");
if (xprintf != kprintf) {
status_t status = mutex_trylock(&fQueueLock);
if (status != B_OK) {
xprintf("\t Locked\n");
return;
}
}
_DumpLocked(xprintf);
if (xprintf != kprintf)
mutex_unlock(&fQueueLock);
return;
}
status_t
WorkQueue::LaunchWorkingThread(void* object)
{
@@ -216,3 +260,19 @@ WorkQueue::JobIO(IORequestArgs* args)
args->fInode->EndAIOOp();
}
void
WorkQueue::_DumpLocked(void (*xprintf)(const char*, ...)) const
{
uint64 entries = 0;
for (DoublyLinkedList<WorkQueueEntry>::ConstIterator it = fQueue.GetIterator();
const WorkQueueEntry* entry = it.Next(); ++entries) {
entry->Dump(xprintf);
}
if (entries == 0)
xprintf("\tEmpty\n");
return;
}
@@ -36,6 +36,8 @@ struct IORequestArgs {
struct WorkQueueEntry : public DoublyLinkedListLinkImpl<WorkQueueEntry> {
JobType fType;
void* fArguments;
void Dump(void (*xprintf)(const char*, ...)) const;
};
class WorkQueue {
@@ -47,6 +49,8 @@ public:
status_t EnqueueJob(JobType type, void* args);
void Dump(void (*xprintf)(const char*, ...) = dprintf);
protected:
static status_t LaunchWorkingThread(void* object);
status_t WorkingThread();
@@ -56,6 +60,9 @@ protected:
void JobRecall(DelegationRecallArgs* args);
void JobIO(IORequestArgs* args);
private:
void _DumpLocked(void (*xprintf)(const char*, ...)) const;
private:
status_t fInitError;
@@ -602,10 +602,15 @@ nfs4_unlink(fs_volume* volume, fs_vnode* dir, const char* name)
return B_ENTRY_NOT_FOUND;
ino_t id;
inode->LookUp(name, &id);
status_t result = inode->LookUp(name, &id);
if (result != B_OK)
return B_ENTRY_NOT_FOUND;
VnodeToInode* childVti = NULL;
status_t result = get_vnode(volume, id, reinterpret_cast<void**>(&childVti));
result = get_vnode(volume, id, reinterpret_cast<void**>(&childVti));
if (result == B_OK) {
childVti->Get();
// Needed to ensure childVti::fInode is non-NULL prior to VnodeToInode::Unlink.
ino_t removedId;
status_t result = inode->Remove(name, NF4REG, &removedId);
if (result != B_OK)
@@ -613,7 +618,7 @@ nfs4_unlink(fs_volume* volume, fs_vnode* dir, const char* name)
ASSERT(removedId == id);
locker.Unlock();
if (vti->Unlink(inode->fInfo.fNames, name))
if (childVti->Unlink(inode->fInfo.fNames, name))
remove_vnode(volume, id);
put_vnode(volume, id);