Thanks for your feedback and suggestions. I double checked which vnode_t is returned by my vnop_lookup. It is indeed the one that references both the original file and the hardlink. vnop_lookup: cat-1235 vnop_lookup: -> lookuprpc(/hlf.txt) lookuprpc: cat-1235 lookuprpc: lookup successful entry exists lookuprpc: -> cache_lookup(/hlf.txt) lookuprpc: <- cache_lookup(/hlf.txt) -> -1 ;VFS_CACHE_HIT vnop_lookup: <- vp fffffe2a45cf6b60 /hlf.txt The vnop_open call that comes immediately after the previous vnop_lookup call is for the parent directory, not the file being returned by the previous lookup: vnop_open: zsh-570 vnop_open: vnode_isdir( root) -> 1 With no open vnop_open calls made afterwards. Here's a similar backtrace for the original file being looked up. vnop_lookup: cat-1236 vnop_lookup: -> lookuprpc(/f.txt) lookuprpc: cat-1236 lookuprpc: lookup successful entry exists lookuprpc: -> cache_lookup(/f.txt) lookuprpc: <- cache_lookup(/f.txt) -> -1 ;VFS_CACHE_HIT vnop_lookup: <- vp fffffe2a45cf6b60 /f.txt If my vnop_lookup returns the correct vnode_t for the file being looked up, what causes ENOENT to be returned to open(2) in userspace? How do we track it down?

Thanks for clarifying that point. Hopefully, Xcode will soon come invested with the symbolication capabilities on Apple Silicon which will certainly be much appreciated. I have closed FB17497530. Thanks.

If you haven't already, please file a bug asking for us to provide a tool/tools for this process and then post the bug number back here. That's very kind of you to suggest that. Please see FB17733912. Please advise if I should close my previous bug report, FB17497530, which you've already looked into.

Further diagnostics have shown that ubc_msync(UBC_PUSHDIRTY|UBC_SYNC|UBC_INVALIDATE) was being called, for the file being written, through the VNOP_GETATTR path on each change of the file size while cluster_write() of the same file was in progress. The change I made now calls ubc_msync() only if there's no cluster_write() in progress when getting file attributes. To test the patch I extracted the zip file a few times in a row with the system no longer crashing and the following metrics being reported by vm_stat(1): % vm_stat 30 | awk '/Statistics/; !/Statistics/{print $3,"|",$13}' Mach Virtual Memory Statistics: (page size of 16384 bytes) specul | file-backed 165368 | 653350 65896 | 888301 66724 | 920760 65872 | 907261 63935 | 898648 67795 | 885978 63295 | 871778 59696 | 863204 3309 | 807539 188881 | 859100 60996 | 1018163 63041 | 1015598 59276 | 1013489 57392 | 1013524 60394 | 1013068 56646 | 1009342 634 | 953419 333949 | 1003401 59119 | 1132207 60277 | 1131932 56650 | 1128616 59147 | 1124974 56620 | 1124759 57165 | 1123408 55714 | 1122087 Thanks very much for all your help. Are you at liberty to disclose how you obtained the backtraces from the full panic long I'd supplied?

I was able to collect some diagnostics which revealed an interesting pattern of things that were happening prior to the kernel panic occurring. Depending on the amount of memory available, one or more files are able to get extracted from the zip file before the panic occurs. Calls being made cluster_write() gets called repeatedly until all file data is stored in VM. Then VNOP_PAGEOUT gets called. I thought that VNOP_PAGEOUT was only called for mmapped files. But there are no VNOP_MMAP/VNOP_MNOMAP calls being made for the files being extracted. The current VNOP_PAGEOUT implementation ends up calling err_pageout() for files that didn't get tagged as being memory mapped by VNOP_MMAP. After a number of VNOP_PAGEOUT calls, VNOP_STRATEGY is called which commits file data to remote storage via a do_write() rpc. This pattern is repeated until the system ultimately runs out of VM with kernel panic ensuing. My intuition is telling me that those VNOP_PAGEOUT calls are being made for a reason. Possibly, to free up the memory pages used up by the cluster API. I tried calling cluster_pageout() from VNOP_PAGEOUT despite VNOP_MMAP never being called. But that resulted in VNOP_STRATEGY being called through two separate paths, VNOP_PAGEOUT and cluster API, which resulted in I/O stalling. Any further pointers would be much appreciated.

Your description of the write operation logic my filesystem implements is fairly close. I thought I'd feel in a few blanks though. write() called. VNOP_WRITE gets called. Input data gets copied from user space into kernel space. Input data equal to the size of uio_resid() gets split up into smaller chunks and is iteratively transmitted over network until there's no more input data left with sock_send(MSG_DONTWAIT) returning the number of the bytes written in sentlen, which is equal to the value of uio_resid() of the chunk passed into sock_send(). VNOP_WRITE returns once all input data has been transmitted. write() returns. Not sure about the 'driver finishes uploading data at some point' part though. Or were you referring to the TCP stack queueing up the input data after sock_send(MSG_DONTWAIT) returns for subsequent transmission? At some point you need to decide to NOT return from "VNOP_WRITE" and instead block Without first understanding what's using up all that VM, I can't see how such a point may be determined. How would VNOP_WRITE block? For some reason, IOLog() data doesn't wind up in the output of log show|stream on macOS 15.5 running on M4 Max. I've added debug print statements to output buffer sizes and memory (de)allocation for uio_t buffers used to store the chunks of input data. I'll run the zip file extraction while collecting the diagnostics via log stream on an M2 Mac where logging is working and see if that reveals anything of interest.

BTW, how much memory does this machine have? Is it 32g or 16g? It's 36Gb. % expr `sysctl -n hw.memsize` / 1024 / 1024 / 1024 36 The bottom line here is that you ultimately need to constrain how quickly you complete write calls to be roughly in line with your underlying ability to transfer data. My attempt at this was through modifying the socket polling algorithm. The decision on whether it's a read or a write event that's occurred is taken in the sock_upcall callback. The socket's receive buffer is queried about whether there's any data available via a call to sock_getsockopt(SO_NREAD). If there is, a thread waiting to read data is sent a read event wakeup() call. Otherwise, the algorithm considers this to be a write event and a thread waiting to write data is sent a wakeup() call. This doesn't take into account whether or not there's room in the send buffer. It's a 'poor' man's socket polling algo, due to functions like sock_setupcalls(), soreadable(), and sowriteable() being a part of the private API. To try and bring the rate the data is being written in line with the rate it's being transferred, I tried modifying the write part of the algorithm by considering it a write event only if there's no more data left in the socket's send buffer via a call to sock_getsockopt(SO_NWRITE). That didn't help remedy the problem. I can't think of other ways of achieving this at the moment.

Does the panic happen when you're just the source and/or destination or only when your "both"? I suspect it will happen when you're just the destination and won't happen when you''re just the source, but I'd like to confirm that. You were right in assuming that the panic occurred when my filesystem was the destination. I was able to verify that. How fast is the I/O path back to the server? Are you saturating that connection? The connection is not likely to be saturated as this is a 100Gb Link on a thunderbolt 5 interface. Is the I/O pipeline here simply "read compressed file from network-> decompress data-> write data out to network"? Or is there any intermediary in that process? The I/O pipeline is as you described it with no intermediary involved. What actually makes it "back" to the server before the panic occurs? How much data were you actually able to write? On two subsequent runs, around 41-42 Gb out of 64Gb of data were written before the panic ensued. du -smx ./25116_CINEGRAPHER_MARCCAIN 41303 ./25116_CINEGRAPHER_MARCCAIN du -smx ./25116_CINEGRAPHER_MARCCAIN 42600 ./25116_CINEGRAPHER_MARCCAIN How does your write process actually "work"? Is there anything that would limit/constrain how much data you have pending (waiting to be sent over the network)? The source uio_t buffer passed into vnop_write() is userspace. Before passing it down to sock_send() which operates on kernel resident memory buffers, we create a kernelspace copy of the userspace uio_t buffer of size equal to uio_resid(uspace_uio) with copying performed by uiomove() incrementally in chunks equal to either the value of the amount of data left in the userspace buffer or the value of the kernel's copysize_limit_panic, whichever happens to be the smaller of the two. The kernelspace uio_t buffer is further split up into smaller chunks of data pertinent to the filesystem design which end up being passed into sock_send(). Reading is done in a similar fashion, the only difference being the use of sock_receive_mbuf() in stead of sock_receive() which uses an uio_t buffer instead of an mbuf. I'm onto the debugging strategies you suggested now. I'll report back on my findings as they emerge. Thanks once again for all your help. Hopefully, we'll be able to resolve this soon.

Thanks very much for looking into this. Here are the points you wanted clarified. How much space is available on the boot volume and is there ANY possibility That it's becoming constrained? That doesn't seem to be the case. See Boot volume size info what's the content you're actually decompressing? One (or several) large files or a bunch of small ones? It is a bunch of files of varying sizes. Here's a List of zip file contents Is your file system the source or the target for the zip file? It's actually both. what's actually providing the storage for your file system? Is it possible that some supporting component has failed? It is a network filesystem with I/O happening via RPC calls. Internally, the filesystem implements a socket polling algorithm that relies on the use of sock_upcall callback that's passed into sock_socket() on socket creation. The backing store on the remote server has been verified to have ample disk space available. Do let me know if there's anything else I can provide that would help identify the cause of the problem.

Hello Kevin, I was wondering if you've had a chance to take a look at FB17497530 yet? Thanks.

Thanks a lot for your really helpful and detailed responses. Two-machine debugging on Apple Silicon has certain limitations, which are worded in the KDK Readme as follows: Note: Apple silicon doesn’t support active kernel debugging. You may inspect the current state of the kernel when it is halted due to a panic or NMI. However, you cannot set breakpoints, continue code execution, step into code, step over code, or step out of the current instruction. x86-64 is better suited for remote kernel debugging. This particular panic doesn't occur on x86-64 though. Only on Apple Silicon. I could try and set up a core dump server/client and see how that pans out. Before I go ahead and file a bug report you suggested by way of submitting a full panic log, you mentioned about ES. In the full log, I found a reference to this: "name":"AFKDCPEXTEndpoint9"},"1597":{"id":1597,"system_usec":104537416,"schedPriority":91,"state":["TH_RUN"],"snapshotFlags":["kKernel64_p","kThreadIOPassive","kThreadOnCore"],"user_usec":0,"kernelFrames":[[0,377776],[0,9311856],[10,23512],[10,18668],[10,6612],[11,6952],[0,1810716],[0,31032],[0,1395328],[0,1395328],[0,6300680],[0,6673156],[0,1049164],[0,1389844],[0,68612]],"basePriority":91,"lastMadeRunnableTime":3.1102084579999998,"userTime":0,"lastRunTime":3.1102656249999998,"systemTime":104.537416333, Which corresponds to the panicked thread id: Panicked thread: 0xfffffe31ffe31fc0, backtrace: 0xfffffe81838478d0, tid: 1597 That thread name, AFKDCPEXTEndpoint9, wouldn't a part of the ES API you were referring to, would it?

Thanks. That makes perfect sense now. I got the same symbolicated output on my system following your instructions. [quote='836958022, DTS Engineer, /thread/782023?answerId=836958022#836958022'] Are they from your KEXT and you just didn't include the KEXT address info? [/quote] Here are the addresses given in the panic log: Kernel Extensions in backtrace That particular kernel panic is reproducible whenever a very large zip file is being extracted over my filesystem. With watchdog panics, is there a way of telling what caused watchdogd to emit a panic?

Found the answer I was looking for by dtrace(1)'ing SMBClient. It calls ubc_msync(vp, 0, ubc_getsize(vp), NULL, UBC_INVALIDATE); in smbfs_vnop_open_common(). The following commentary explains the reasoning behind this.

Thanks. Just a couple of points to clarify. atos -arch arm64e -o <symbol file path) -l <load address + (0x4000/vmaddr)> <address to symbol> In that particular panic log, there's not load address specified for my kext. What address do I specify in that case? 0x4000/vmaddr is that divided by vmaddr or is that saying that 0x4000 is the value of vmaddr?

Thanks for your response. I've downloaded and extracted Kernel_Debug_Kit_15.4_build_24E248.dmg. Here's what I've tried so far to sybolicate the sample kernel panic log. Note: the kernel passed in to the -o flag of atos(1) is the one that is found in kernel.release.t8112.dSYM/Contents/Resources/DWARF/kernel.release.t8112. The load address computed as the kernel base addresses given in the kernel panic log minus the corresponding slide atos -o kernel.release.t8112 -arch arm64e -l FFFFFE0007004000 0xfffffe001cde8ab8 0xfffffe001cf44894 0xfffffe001cf42a90 0xfffffe001cd938c0 0xfffffe001cde83b0 0xfffffe001d66d670 0xfffffe001d86a708 0xfffffe001d86941c 0xfffffe001d866504 0xfffffe001e234bc8 0xfffffe001cf4611c 0xfffffe001cd93938 0xfffffe001cee0a80 0xfffffe001cee0a80 0xfffffe001d38e408 0xfffffe001d3e9304 0xfffffe001ce8c24c 0xfffffe001cedf514 0xfffffe001cd9cc04 No output generated The value of Kernel slide given in the kernel panic log passed to the -s flag atos -o kernel.release.t8112 -arch arm64e -s 0000000014610000 0xfffffe001cde8ab8 0xfffffe001cf44894 0xfffffe001cf42a90 0xfffffe001cd938c0 0xfffffe001cde83b0 0xfffffe001d66d670 0xfffffe001d86a708 0xfffffe001d86941c 0xfffffe001d866504 0xfffffe001e234bc8 0xfffffe001cf4611c 0xfffffe001cd93938 0xfffffe001cee0a80 0xfffffe001cee0a80 0xfffffe001d38e408 0xfffffe001d3e9304 0xfffffe001ce8c24c 0xfffffe001cedf514 0xfffffe001cd9cc04 No output generated The value of KernelCache slide given in the kernel panic log passed to the -s flag atos -o kernel.release.t8112 -arch arm64e -s 0000000014608000 0xfffffe001cde8ab8 0xfffffe001cf44894 0xfffffe001cf42a90 0xfffffe001cd938c0 0xfffffe001cde83b0 0xfffffe001d66d670 0xfffffe001d86a708 0xfffffe001d86941c 0xfffffe001d866504 0xfffffe001e234bc8 0xfffffe001cf4611c 0xfffffe001cd93938 0xfffffe001cee0a80 0xfffffe001cee0a80 0xfffffe001d38e408 0xfffffe001d3e9304 0xfffffe001ce8c24c 0xfffffe001cedf514 0xfffffe001cd9cc04 No output generated The value of Kernel text exec slide given in the kernel panic log passed to the -s flag atos -o kernel.release.t8112 -arch arm64e -s 0000000015D88000 0xfffffe001cde8ab8 0xfffffe001cf44894 0xfffffe001cf42a90 0xfffffe001cd938c0 0xfffffe001cde83b0 0xfffffe001d66d670 0xfffffe001d86a708 0xfffffe001d86941c 0xfffffe001d866504 0xfffffe001e234bc8 0xfffffe001cf4611c 0xfffffe001cd93938 0xfffffe001cee0a80 0xfffffe001cee0a80 0xfffffe001d38e408 0xfffffe001d3e9304 0xfffffe001ce8c24c 0xfffffe001cedf514 0xfffffe001cd9cc04 Output: Looks bogus __doprnt.digits (in kernel.release.t8112) + 103398 bootstrap_pagetables (in kernel.release.t8112) + 329876 bootstrap_pagetables (in kernel.release.t8112) + 322192 table_10bits (in kernel.release.t8112) + 10400 __doprnt.digits (in kernel.release.t8112) + 101598 recvmsg_x (in kernel.release.t8112) + 332 IOMachPort::noMoreSendersForObject(OSObject*, unsigned int, unsigned int*) (in kernel.release.t8112) + 440 IOUserClient::init(OSDictionary*) (in kernel.release.t8112) + 0 IOServiceMessageUserNotification::MetaClass::~MetaClass() (in kernel.release.t8112) + 528 bootstrap_pagetables (in kernel.release.t8112) + 336156 table_10bits (in kernel.release.t8112) + 10520 ropagetable_end (in kernel.release.t8112) + 2688 ropagetable_end (in kernel.release.t8112) + 2688 ipsec_cleanup_family (in kernel.release.t8112) + 920 pf_test (in kernel.release.t8112) + 3700 ropagetable_begin (in kernel.release.t8112) + 324884 nfU16InvMasks (in kernel.release.t8112) + 112 Can you please instruct me how to symbolicate my sample kernel panic log properly.