Here’s another example where I use DTrace to fix a problem I was having:
The problem I was having is trying to upload something via FTP through a web application and it wasn’t uploading for some reason. The FTP daemon was receiving the commands but the file wasn’t showing up in the directory.
FTP log of the session trying to upload:
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 165209 daemon.info] USER pinnftp
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 125383 daemon.info] PASS password
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 201503 daemon.info] CWD /
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 313182 daemon.info] PORT
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 307055 daemon.info] TYPE Image
Oct 27 14:54:26 callacctweb ftpd[25157]: [ID 206289 daemon.info] STOR logo-left.jpg
Nothing looks suspicious here, and even to test if it was a permission error I went ahead and made the directory +w by everyone. Still, I kept getting the same stuff, and no file showing up in the directory.
So I run opensnoop (as I tell the web app to upload the file):
Oct 27 15:05:23 0 25165 -1 2 /var/ld/ld.config
Oct 27 15:05:23 0 25165 3 0 /lib/libsocket.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libnsl.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libpam.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libbsm.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libsendfile.so.1
Oct 27 15:05:23 0 25165 3 0 /usr/lib/libgss.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libc.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libcmd.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libmd5.so.1
Oct 27 15:05:23 0 25165 3 0 /lib/libsecdb.so.1
Oct 27 15:05:23 0 25165 3 0 /platform/SUNW,Sun-Fire-V240/lib/libc_psr.so.1
Oct 27 15:05:23 0 25165 3 0 /dev/conslog
Oct 27 15:05:23 0 25165 2 0 /dev/null
Oct 27 15:05:23 0 25165 4 0 /etc/ftpd/ftpservers
Oct 27 15:05:23 0 25165 4 0 /etc/ftpd/ftpaccess
Oct 27 15:05:23 0 25165 4 0 /etc/netconfig
Oct 27 15:05:23 0 25165 4 0 /dev/udp
Oct 27 15:05:23 0 25165 4 0 /etc/nsswitch.conf
Oct 27 15:05:23 0 25165 4 0 /lib/nss_files.so.1
Oct 27 15:05:23 0 25165 4 0 /etc/services
Oct 27 15:05:23 0 25165 4 0 /var/run/name_service_door
Oct 27 15:05:23 0 25165 5 0 /etc/ftpd/ftpconversions
Oct 27 15:05:23 0 25165 -1 2 /etc/ftpd/banner.msg
Oct 27 15:05:23 0 25165 5 0 /etc/ftpd/ftphosts
Oct 27 15:05:23 0 25165 5 0 /etc/shadow
Oct 27 15:05:23 0 25165 -1 2 /etc/shells
Oct 27 15:05:23 0 25165 5 0 /etc/ftpd/ftpusers
Oct 27 15:05:23 0 25165 -1 2 /etc/ftpusers
Oct 27 15:05:23 0 25165 5 0 /var/run/ftp.pids-realusers
Oct 27 15:05:23 0 25165 6 0 /usr/share/lib/zoneinfo/US/Central
Oct 27 15:05:23 0 25165 6 0 /var/run/syslog_door
Oct 27 15:05:23 0 25165 6 0 /var/run/syslog_door
Oct 27 15:05:23 0 25165 -1 2 /etc/pam_debug
Oct 27 15:05:23 0 25165 6 0 /etc/pam.conf
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_authtok_get.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/passwdutil.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/libsldap.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/libldap.so.5
Oct 27 15:05:23 0 25165 6 0 /lib/libdoor.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/libsasl.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libnspr4.so
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libplc4.so
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libnss3.so
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libssl3.so
Oct 27 15:05:23 0 25165 6 0 /lib/libpthread.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libthread.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/librt.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libdl.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libsoftokn3.so
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/libplds4.so
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/.htaccess
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/web/.htaccess
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/web/app/.htaccess
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 0 23893 30 0 /system/contract/process/latest
Oct 27 15:05:23 0 23893 30 0 /proc/25165/psinfo
Oct 27 15:05:23 0 18224 13 0 /etc/svc/volatile/svc_nonpersist.db-journal
Oct 27 15:05:23 0 18224 17 0 /etc/svc/volatile/sqlite_9C3PWfLqAwfyW8l
Oct 27 15:05:23 0 18224 13 0 /etc/svc/volatile/svc_nonpersist.db-journal
Oct 27 15:05:23 0 18224 17 0 /etc/svc/volatile/sqlite_KPSalwKdewEwutR
Oct 27 15:05:23 155 25165 -1 2 .message
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 155 25165 7 0 /var/run/syslog_door
Oct 27 15:05:23 155 25165 7 0 /var/run/syslog_door
Oct 27 15:05:23 155 25165 7 0 /var/run/syslog_door
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 155 25165 -1 13 logo-left.jpg
Oct 27 15:05:23 0 18224 13 0 /etc/svc/volatile/svc_nonpersist.db-journal
Oct 27 15:05:23 0 18224 17 0 /etc/svc/volatile/sqlite_3bPs9j3k6YGQuOq
Oct 27 15:05:23 0 18224 13 0 /etc/svc/volatile/svc_nonpersist.db-journal
Oct 27 15:05:23 0 18224 17 0 /etc/svc/volatile/sqlite_fcgHWsRuwiXRABD
Oct 27 15:05:23 0 23893 29 0 /system/contract/process/5264/ctl
Oct 27 15:05:23 0 25165 6 0 /lib/libaio.so.1
Oct 27 15:05:23 0 25165 6 0 /platform/SUNW,Sun-Fire-V240/lib/libmd5_psr.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/mps/cpu/sparcv8plus/libnspr_flt4.so
Oct 27 15:05:23 0 25165 6 0 /lib/libscf.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libuutil.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_dhkeys.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_unix_cred.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/libproject.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libproc.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/librtld_db.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libelf.so.1
Oct 27 15:05:23 0 25165 6 0 /lib/libctf.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_unix_auth.so.1
Oct 27 15:05:23 0 25165 6 0 /etc/nsswitch.conf
Oct 27 15:05:23 0 25165 6 0 /etc/shadow
Oct 27 15:05:23 0 25165 6 0 /etc/shadow
Oct 27 15:05:23 0 25165 6 0 /etc/passwd
Oct 27 15:05:23 0 25165 6 0 /etc/shadow
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_roles.so.1
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_unix_account.so.1
Oct 27 15:05:23 0 18260 5 0 /etc/user_attr
Oct 27 15:05:23 0 25165 6 0 /etc/shadow
Oct 27 15:05:23 0 25165 6 0 /var/adm/lastlog
Oct 27 15:05:23 0 25165 6 0 /etc/default/login
Oct 27 15:05:23 0 25165 6 0 /usr/lib/security/pam_unix_session.so.1
Oct 27 15:05:23 0 25165 6 0 /var/adm/lastlog
Oct 27 15:05:23 0 25165 6 0 /etc/shadow
Oct 27 15:05:23 0 25165 6 0 /etc/project
Oct 27 15:05:23 0 25165 6 0 /etc/project
Oct 27 15:05:23 0 25165 6 0 /etc/project
Oct 27 15:05:23 0 25165 6 0 /etc/project
Oct 27 15:05:23 0 25165 6 0 /etc/project
Oct 27 15:05:23 0 25165 6 0 /etc/security/policy.conf
Oct 27 15:05:23 0 25165 6 0 /etc/default/nss
Oct 27 15:05:23 0 25165 6 0 /etc/group
Oct 27 15:05:23 0 25165 6 0 /var/adm/wtmpx
Oct 27 15:05:23 0 25165 -1 2 /etc/ftpd/welcome.msg
Oct 27 15:05:23 0 25165 7 0 .
Oct 27 15:05:23 0 25165 -1 2 .message
Oct 27 15:05:23 0 25165 7 0 .
Oct 27 15:05:23 0 25165 7 0 .
Oct 27 15:05:23 155 25165 7 0 /var/run/syslog_door
Oct 27 15:05:23 155 25165 7 0 .
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 7 0 /var/apache/logs/owalog.log
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/.htaccess
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/web/.htaccess
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/web/app/.htaccess
Oct 27 15:05:23 60001 24924 -1 2 /usr/apache/pinnacleweb/web/app/uploads/.htaccess
Oct 27 15:05:24 0 99 4 0 /devices/pci@1c,600000/scsi@2:devctl
Oct 27 15:05:24 0 99 4 0 /devices/pci@1c,600000/scsi@2:devctl
Oct 27 15:05:24 0 99 4 0 /devices/pci@1c,600000/scsi@2:devctl
Oct 27 15:05:24 0 99 4 0 /devices/pci@1c,600000/scsi@2:devctl
^C
What were looking for here is all of the ‘-1‘ FD values. This indicates there was an error somewhere. Looking at all of them, there’s only one that really sticks out, and its the name of the image I was trying to upload, logo-left.jpg
It has an error number of 13, lets see what this means:
root@callacct:~/DTraceToolkit-0.83# grep 13 /usr/include/sys/errno.h
#define EACCES 13 /* Permission denied */
#define ECONNABORTED 130 /* Software caused connection abort */
#define ECONNRESET 131 /* Connection reset by peer */
#define ENOBUFS 132 /* No buffer space available */
#define EISCONN 133 /* Socket is already connected */
#define ENOTCONN 134 /* Socket is not connected */
/* XENIX has 135 - 142 */
It is showing I’m getting a permission denied. This makes more sense if you look at the FTP log it shows it issuing “CWD /” then trying to upload a file which means its changing to the root (/) directory first then uploading the file and failing with the permission denied. The root directory doesn’t have permission to let anyone upload there and the FTP web app shouldn’t be issuing a ‘cd /’ and then trying to upload the file.
Available here in txt format.