| One of the best things I ever did for myself was to add logging tricks to my filesystem. My favorite trick is to log filesystem events on your network adapter. This has these advantages:
- The logged events can be traced using the standard tcpdump or Wireshark
- It is very fast and won't slow down your kernel like printf does. It is also 'atomic' so messages don't get mixed up like printf does.
- If your filesystem is a network file system, then you can see your log messages mixed in with your network traffic AND in the proper time relationship
- You can write a simple script to turn a tcpdump or Wireshark file into text using strings and grep.
- When using Wireshark, you can display your filesystem traffic and/or your log messages by adding or removing || udp to your filter (eg: nfs || udp)
- It is easy to see what app is calling your filesystem. Once you have your log as text, you can grep for just that one app. Remember that the Finder leverages many other processes besides its own.
- You can use Wireshark to look for vnop calls by searching your trace for text
- You can leave it in your shipping code if you like. Even novice Mac users can be instructed on how to collect the trace data. No special software need be installed since tcpdump comes standard.
Here is what I do:
a) Add some code to your kpi module start function to set up the multicast socket // global stuff - static socket_t mcast_logging_socket = 0; struct sockaddr_in mcast_logging; uint32_t com_mycompany_netlog = 0; . . .
// in your start function, where error is your intended return value #if MCAST_LOGGING errno_t err = sock_socket(AF_INET, SOCK_DGRAM, 0, NULL, NULL, &mcast_logging_socket); xdebug_printf("sock_socket: %p\n", mcast_logging_socket); sock_setpriv(mcast_logging_socket, 1); uint32_t sndsize = 65536; sock_setsockopt(mcast_logging_socket, SOL_SOCKET, SO_SNDBUF, (void*)&sndsize, (int)sizeof(sndsize)); memset( &mcast_logging, 0, sizeof(mcast_logging)); mcast_logging.sin_family = AF_INET; mcast_logging.sin_len = sizeof(mcast_logging); // INET_ADDRSTRLEN? mcast_logging.sin_addr.s_addr = htonl(0xef0000ef); mcast_logging.sin_port = htons(9); else printf("cifs_module_start_kpi sock_socket failed: %d\n", err);
b) Be sure you close the socket when your kext is unloaded. sock_close(mcast_logging_socket); c) Write a logging function that just logs raw data: void mykext_log_msgbuf( const char * pmsg, void* buf, size_t buflen) if( ! com_mycompany_netlog ) return; if( mcast_logging_socket ) memset(&msg, 0, sizeof(msg)); aio[ii].iov_base = (void*)pmsg; aio[ii].iov_len = strlen(pmsg)+1; if( buf!=NULL && buflen > 0 ) aio[ii].iov_len = buflen; msg.msg_name = &mcast_logging; msg.msg_namelen = sizeof(mcast_logging); errno_t err = sock_send(mcast_logging_socket, &msg, 0, &sent); xdebug_printf("sock_send failed: %d\n", err); // EINVAL sock_close(mcast_logging_socket);
d) Write a more useful log function that fills out the log message with useful info. Mine looks like this: __private_extern__ void mykext_log_operation( pid_t pid, mount_t mp, const char * operation, vnode_t vp, const char * inFmt, ...) if( ! com_mycompany_netlog ) return; static uint8_t sglogseq = 0; // log a sequence number in case we suspect log messages getting dropped fpath = mykext_vnode_path(vp); // your filesystem function to allocate and fill in a textual path to vp // log a basic header that is the same for all messages proc_name(pid, pname, sizeof(pname)); snprintf(pmsg, sizeof(pmsg), "%s[%s,%d(%p) %2.2x]:", operation, pname, pid, current_thread(), sglogseq++); vsnprintf(fmsg, sizeof(fmsg), inFmt, listp); strlcat(pmsg, fmsg, sizeof(pmsg)); snprintf(vpinfo, sizeof(vpinfo), "- (%p:%p):", vnode_mount(vp), vp); strlcat(pmsg, vpinfo, sizeof(pmsg)); strlcat(pmsg, fpath ? fpath : "***", sizeof(pmsg)); mykext_log_msgbuf(pmsg, NULL, 0); _FREE(fpath, M_CIFSTEMP);
e) Add some logging to critical spots like your open function: static int mykext_vnodeop_open(struct vnop_open_args *ap) if( SHOULD_LOG(LOG_OPENCLOSE)) mykext_log_operation(vfs_context_pid(ap->a_context), vnode_mount(ap->a_vp), "mykext_vnodeop_open", ap->a_vp, "enter a_mode=%x", ap->a_mode);
for example. You might want to use a macro for mykext_log_operation so it is easy to leave out: #define log_operation mykext_log_operation #define xlog_operation
f) Add some way to turn the beast on and off. I use a sysctl: SYSCTL_UINT(_com_mycompany, OID_AUTO, netlog, CTLFLAG_RW|CTLFLAG_LOCKED, &com_mycompany_netlog, 0, "MYKEXT netlog enabled" ); // register your sysctls! // after loading your kext sysctl_register_oid(& sysctl__com_mycompany_netlog); // before unloading your kext: sysctl_unregister_oid(&sysctl__com_mycompany_netlog);
Set your logging control from the command line: sudo sysctl -w com_mycompany.netlog=1; # turn on network logging sudo sysctl -w com_mycompany.netlog=0; # turn off network logging
f) log your messages using tcpdump: tcpdump -s 0 -i en0 -B 1024000 -w mykext.pcap
ctrl c to stop. If you name your trace file with .pcap you can open it with Wireshark using the terminal command: open mykext.pcap
g) script to print out your trace file: strings "$1" | egrep "mykext_||vnodeop_"
I may have made some errors typing this up. If so they should be easy to fix.Hope this is useful to someone! Paul |