Skip to content

Instantly share code, notes, and snippets.

@drj11
Last active April 29, 2016 11:18
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save drj11/930a7288ad623b7714e0c3d92e3586da to your computer and use it in GitHub Desktop.
Save drj11/930a7288ad623b7714e0c3d92e3586da to your computer and use it in GitHub Desktop.

How to use strace to solve a mystery (with bash)

So I'm dabbling with iceberg, The University of Sheffield's HPC, and I finally get round to putting my .profile on there. And I remember that I don't like the way less clears the screen when I've finished reading a man page.

I need to set my LESS environment variable to -X. So I add that to my .profile. I do exec bash -l to emulate logging back in.

Doesn't work. Still clears screen when reading man pages. Turns out LESS isn't set. What is going wrong with my .profile?

I'm becoming a fan of strace for this sort of debugging.

Have a look at this. When I run this command:

strace -e signal= -e open bash -l -c 'echo SCRIPT GOT HERE'

I get this output:

open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libtinfo.so.5", O_RDONLY)  = 3
open("/lib64/libdl.so.2", O_RDONLY)     = 3
open("/lib64/libc.so.6", O_RDONLY)      = 3
open("/dev/tty", O_RDWR|O_NONBLOCK)     = 3
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3
open("/etc/profile", O_RDONLY)          = 3
open("/etc/profile.d/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/colorls.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/cvs.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/ge.sh", O_RDONLY)  = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/glib2.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/lang.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/less.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/modules.sh", O_RDONLY) = 3
open("/usr/share/Modules/init/bash", O_RDONLY) = 3
open("/usr/share/Modules/init/bash_completion", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/qt.sh", O_RDONLY)  = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/set-bmc-url.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/shef-login.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/udisks-bash-completion.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/vim.sh", O_RDONLY) = 3
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
open("/usr/share/locale/en_GB.UTF-8/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en_GB.utf8/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en_GB/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en.UTF-8/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en.utf8/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en/LC_MESSAGES/bash.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("/etc/profile.d/which2.sh", O_RDONLY) = 3
open("/home/md1xdrj/.bash_profile", O_RDONLY) = 3
open("/home/md1xdrj/.bashrc", O_RDONLY) = 3
open("/etc/bashrc", O_RDONLY)           = 3
open("/etc/profile.d/modules.sh", O_RDONLY) = 3
open("/usr/share/Modules/init/bash", O_RDONLY) = 3
open("/usr/share/Modules/init/bash_completion", O_RDONLY) = 3
SCRIPT GOT HERE
+++ exited with 0 +++

strace runs a command and traces the system calls (so I suppose strace is short for System Trace). I'm running the command line bash -l -c 'echo SCRIPT GOT HERE' under strace. bash -l is a login shell, so it should source my .profile.

First thing to notice about running things with strace is that you get lots of output. And that's after I've used two options to reduce the ammount of output. The -e open option to strace restricts it so that it only shows open() system calls; normally it will show all system calls, which is way more output. The -e signal= option to strace means that it won't show any signals, without it you see all signals. Most programs don't see many signals, but in this case there are a fair number of child process management signals that are not particularly interesting.

The first few files are related to C runtimes and dynamic linking (/etc/ld.so.cache, /lib64/libc.so.6, and so on). Then we get /etc/profile.Aha! bash is reading the system wide profile file. Which it turns out causes it to reading the bag of little profile scripts kept in /etc/profile.d/ (most of which are specific to the Sheffield HPC).

(I've no idea what the obsession with opening /dev/null in between every script is by the way; some crazy bash thing. whatever)

Then, eventually, near the bottom, we see bash opening /home/md1xdrj/.bash_profile. And this is the culprit. I'm like "wait, WAT!?", "I have a .bash_profile?"

And so I do. Not created by me. A quick perusal of man bash[*1] reveals that if ~/.bash_profile exists then it will be sourced and .profile will not.

So I remove my ~/.bash_profile and life is good again.

Reflection

strace is a great tool and well worth exploring a little bit (fun fact: you can attach to already running processes with strace -p). So in this case I could've read the manual and inspected the file system to see what files bash would source, but strace is more direct. The manual might be out of date, misunderstood, or just plain wrong. But strace cannot lie, it shows me what system calls a tool is actually making.

The Truth.

Of course The Truth that strace provides is really just a truth. There is a whole world of complexity (most obviously, all the instructions that get executed in between the system calls are not shown) and strace is hiding that from us, in the name of Truth.

Footnotes

[*1] This is what I call "a joke". Everyone should read man bash, but it is like Joyce's Ulysses: better read the Cliffs Notes[*2]. [*2] There are no Cliffs Notes for bash.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment