Behind the scenes of shell IO redirection

In the day to day toils on a command-line, it can be easy to overlook some of the complexities that lie behind many of the constructs used pervasively.

In a POSIX shell, one such construct is the ability to pipe between, as well as redirect input and output of various commands with <, > and |.

If we stop to smell the roses, the question thus becomes; How does it actually work?

As an example, have you ever wondered, what actually happens under the hood, when you write a command like this?

cat foo.txt > bar.txt

That’s what we’ll take a look at in this post.

dtruss

In order for us to look into the belly of the beast so to speak, we’ll need a tool to monitor system calls for a given process.

Since I’m doing this on an OS X system, the tool of choice is dtruss, a DTrace version of truss. On Linux strace can be used instead.

If you’re not interested in trying this out for yourself, skip on ahead to the Inspection section.

Preflight checklist

By default dtruss doesn’t work because of the System Integrity Protection (SIP), security feature of OS X. If you try to attach to a running process, you’ll get this error message from dtrace initially:

$ sudo dtruss -f -p 43334
dtrace: system integrity protection is on, some features will not be available

And then the log will be filled with dtrace errors like this, as soon as the process makes any system calls:

dtrace: error on enabled probe ID 2633 (ID 265: syscall::ioctl:return): invalid user access in action #5 at DIF offset 0

In order to work around this problem, it’s possible to disable SIP for dtrace exclusively. Reboot OS X in recovery mode and enter the following command in a terminal:

csrutil enable --without dtrace

You’ll see the following warning message:

This is an unsupported configuration, likely to break in the future and leave your machine in an unknown state.

That’s ok for now. Restoring the default configuration later can be done with:

csrutil enable

Reboot to normal mode again and open a terminal.

Noise reduction

To reduce the amount of unrelated events in the output from dtruss, it’s a good idea to run commands in a minimal environment without various hooks and other modern shell niceties.

Starting up, e.g. a new instance of bash, without inheriting the parent environment and loading a profile or rc, can be done like so:

env -i bash --noprofile --norc

Take-off

In the minimal bash instance just started, get the process ID of the shell:

bash-3.2$ echo $$
529

Now we’re ready to start monitoring. Open up a separate shell; note this doesn’t have to be minimal like above. Start up dtruss, attaching it to the bash process:

$ sudo dtruss -p 529 -f

The -f here makes sure any forked children is followed as well. If all went well, you’ll see this header appear:

PID/THRD SYSCALL(args) = return

Now we’re ready to issue our command with output redirection.

Run

I’m using this small test file in this example, but any file will do really:

Back in our minimal bash shell, we’ll issue this simple command, redirecting stdout to the file bar.txt:

cat foo.txt > bar.txt

Now let’s take a look at what dtruss has picked up.

Inspection

After running the command, we should see a lot of stuff in the log output from dtruss.

The full output I got from dtruss can be found in this gist. For a better overview, I created a filtered version with irrelevant system calls omitted:

grep -v -E "ioctl|sigaction|sigprocmask|stat64|mprotect" dtruss.log > dtruss.short.log

Here’s the shortened version:

Target file

Quickly skimming the log reveals, that we’re looking at two different process ID / thread ID pairs. Namely 1436/0x5b3d on lines 1-5 and 36-39, as well as 1458/0x5c1d from 6 to 35.

The reason for this, is that the shell utilises a fork-exec approach, for running program binaries, e.g. cat, or anything that isn’t a shell builtin really.

The way it works, is by the parent process, in this case 1436, calling fork. This makes a copy of the current process and continues execution in both, albeit with some important differences.

In the child, fork returns with a value of zero and in the parent, it returns the process id of the forked child. That way it’s determined which of the two will subsequently transform into a new process through one of the exec family of system calls. In this case the dtrace probe is unable to properly trace it, but on line 21 we see an error for an execve call, so that is most likely the one in this case.

From line 6 the log output is coming from the child process. The first lines of interest here is 11-13. Let’s look at them one at a time.

On line 11, we can see an open system call for the file bar.txt returning successfully with a file descriptor value of 3, or 0x3 if you will.

Next on line 12, there is a dup2 call, with the descriptor value for bar.txt and then 0x1.

The man page for dup2 is somewhat awkwardly worded, but in short, this means “change whatever file descriptor 0x1 is pointing to, to whatever file descriptor 0x3 is pointing to”.

We already know 0x3 is a descriptor for bar.txt, but what about 0x1?

In POSIX any process has three standard streams made available by the host system, stdin, stdout and stderr, which by definition have the values 0, 1 and 2.

That means the dup2 call effectively changes the descriptor for stdout to point to the same thing as the descriptor for bar.txt. This is relevant, since cat reads files and writes them to the standard output.

On line 13 there is a close call on the descriptor for bar.txt. Now this may seem weird, since no data has actually been written to the file yet, but keep in mind this is only releasing the file descriptor. It doesn’t do anything to the file itself. Remember the descriptor for stdout now points to bar.txt, so the new descriptor is no longer needed and can just as well be made available to the system again.

Source file

The next lines of interest is 29-33.

On line 29, we again see another open call, but this time for foo.txt. Since the descriptor 0x3 was released on line 13, it is the first one available and is reused here.

On line 30-31 we see a read call on descriptor 0x3, which puts the content of foo.txt into memory, followed by a write on the stdout descriptor. Remembering stdout now points to bar.txt, we can assert the content of foo.txt has been written to bar.txt.

With line 32-33 a final read on the descriptor of foo.txt returns zero, which indicates end-of-file, followed by an immediate close.

On line 35, the last event from the child process closes stdin, with a call to close_nocancel.

Finally, on line 36, we see control return to the parent process with wait4, which waits for the child process to finish.

After this the log trace ends and the command is done.

Recap

So, to come full circle, when you enter a command like this:

cat foo.txt > bar.txt

What really happens behind the scenes, is the following:

  1. A child process is spawned from current process.
    1. The child process is transformed to a new process for cat via an exec type call.
    2. bar.txt is opened for writing, creating a new file descriptor.
    3. The file descriptor for stdout is made to point to bar.txt.
    4. The new descriptor is closed.
    5. foo.txt is opened for reading, creating a new file descriptor.
    6. A read to memory from the new descriptor of foo.txt is done.
    7. A write from memory to the descriptor of stdout is done.
    8. The new descriptor of foo.txt is closed.
    9. The descriptor of stdout is closed.
  2. Parent process waits for child to finish.
  3. Done.

It’s not all magic, but pretty close.

Further reading

References

Setting up Raspberry Pi as an OpenVPN client for the NETGEAR R7000 Nighthawk router

Since OpenVPN isn’t too chatty about failures in its default configuration, this took me a couple of tries to get right. Hopefully this post can save you some of the time I wasted .

In the following example, I’m assuming you already have a Raspberry Pi, running Raspbian and that you can access it over the local network. From the snippets below, change the example ip 192.168.3.14, to the ip of your local device.

Router

Start off by enabling the vpn service on the router, by going to ADVANCED > Advanced Setup > VPN Service, then check off Enable VPN Service and then click Apply.

When that is done and the router has rebooted, go back to the same page and download the VPN configuration zip file, nonwindows.zip, and copy it to the Pi:

rene $ scp nonwindows.zip pi@192.168.3.14:

Pi

Log in to the Pi and set up OpenVPN:

rene $ ssh pi@192.168.3.14
pi:~$ sudo apt-get update && sudo apt-get install openvpn

Once the installation is complete, add the configuration to openvpn:

pi:~$ unzip nonwindows.zip
pi:~$ sudo cp client2.conf ca.crt client.crt client.key /etc/openvpn/
pi:~$ sudo chown root:root /etc/openvpn/{client2.conf,ca.crt,client.crt,client.key}
pi:~$ sudo chmod 600 /etc/openvpn/{client2.conf,ca.crt,client.crt,client.key}
pi:~$ ls -la /etc/openvpn/
total 28
drwxr-xr-x  2 root root 4096 Jul 13 14:13 .
drwxr-xr-x 70 root root 4096 Jul 13 14:44 ..
-rw-------  1 root root 1253 Jul 13 13:57 ca.crt
-rw-------  1 root root 3576 Jul 13 13:57 client.crt
-rw-------  1 root root  891 Jul 13 13:57 client.key
-rw-------  1 root root  180 Jul 13 13:57 client2.conf
-rwxr-xr-x  1 root root 1301 Nov 19  2015 update-resolv-conf

Assuming you’re the only one accessing this Pi, setting the owner and file permissions isn’t strictly necessary, but nevertheless good practice. There’s no reason the these files should be readable by anyone but root.

Next you should edit /etc/default/openvpn and add a directive for the new configuration to start on boot:

AUTOSTART="client2"

Now reboot the Pi and verify that a new network device has been added for the remote network:

pi:~$ ifconfig
eth0      Link encap:Ethernet  HWaddr b8:27:eb:1c:fa:81
          inet addr:10.0.0.4  Bcast:10.0.0.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST DYNAMIC  MTU:1500  Metric:1
          RX packets:4228 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1781 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:820993 (801.7 KiB)  TX bytes:246368 (240.5 KiB)
 
lo        Link encap:Local Loopback
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:65536  Metric:1
          RX packets:13 errors:0 dropped:0 overruns:0 frame:0
          TX packets:13 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1
          RX bytes:1320 (1.2 KiB)  TX bytes:1320 (1.2 KiB)
 
tap0      Link encap:Ethernet  HWaddr da:dd:3a:80:50:7c
          inet addr:192.168.1.7  Bcast:192.168.1.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST DYNAMIC  MTU:1500  Metric:1
          RX packets:621 errors:0 dropped:0 overruns:0 frame:0
          TX packets:177 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:100
          RX bytes:70344 (68.6 KiB)  TX bytes:15922 (15.5 KiB)

Et voilà, that should be all there is to it!

Addendum

In case something didn’t quite go as planned, enabling some logging might be a good idea. Here’s a filtered list of options related to logging:

pi:~$ openvpn --help | grep log
--topology t    : Set --dev tun topology: 'net30', 'p2p', or 'subnet'.
                  as the program name to the system logger.
--syslog [name] : Output to syslog, but do not become a daemon.
--log file      : Output log to file which is created/truncated on open.
--log-append file : Append log to file, or create file if nonexistent.
--suppress-timestamps : Don't log timestamps to stdout/stderr.
--echo [parms ...] : Echo parameters to log output.
--management-log-cache n : Cache n lines of log file history for usage
--mute-replay-warnings : Silence the output of replay warnings to log file.
--pkcs11-cert-private [0|1] ... : Set if login should be performed before

To make use of one of these options, it used to be that the parameters could be passed in the OPTARGS directive of /etc/default/openvpn, but since OpenVPN has moved to using systemd, this is no longer supported. Relevant bug report.

Instead it is necessary to set them directly in each configuration. E.g. to enable append logging to a file add, edit /etc/openvpn/client2.conf and add the following line:

log-append /var/log/openvpn.log

According the the man page verbosity is set from 0-11, and by default the vpn configuration from the R7000 has verbosity set to 5. This means the log file can quickly become rather large if left in append mode unattended, so make sure you have enough room on the SD card or remove the option again, when you are done debugging. Alternatively use –management-log-cache or truncate on each run by just using –log.

N.B. In my experience the client can be a bit flaky at times and I’ve often seen the first many connection attempts end in the following errors:

TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
TLS Error: TLS handshake failed

And then after a number of tries, suddenly come through. Don’t ask me why.

Interactive visualisation of Pi and friends with D3.js

Inspiration

I recently stumbled onto the magnificent posters created by Martin Krzywinski over at http://mkweb.bcgsc.ca/pi/. He’s come up with some truly original ways to illustrate the appearance and complexity of various irrational numbers.

Specifically, I really liked the minimalism and simplicity of the 2013 edition, shown here:

pi-dots-01

The rules used for generating the coloured dots is fascinatingly simple. Each digit 0-9 is assigned a unique colour. The i’th circle is then coloured according to the value of the i’th digit of Pi. The smaller circle inside is coloured based on the value of the following digit.

Simple rules, complex outcome.

Martin created other versions as well, e.g. one where adjacent equals are connected by same coloured lines. They’re all fascinating and you can even buy them as posters!

Interactive

Looking at these posters I couldn’t help wonder, what lay beyond the chosen boundaries for each poster. What if some great pattern or sequence was lurking just outside of view? If only there was a way to go explore further digits and other constellations using the same visualisation format.

Always the tinkerer, this got me thinking about how to create something like that. One thing led to another and before long I had a rough prototype cobbled together with D3.js.

I spent a bit more time adding a few input controls and polishing it into a neat little demo. I’ve put it up at:

winski.rhardih.io

Go try it out! Instructions are at the bottom.

As an example, this is how the Feynman Point looks, at a column width of 31:

Screen Shot 2016-06-10 at 12.30.29

For the more curious out there, I’ve put the code on GitHub at github.com/rhardih/winski.

Happy π hunting!

Dead simple concurrency limitation in Go

Backgrounding long running tasks is a classic and ubiquitous problem for web applications.

E.g. Something triggered the need to download and manipulate a file, but we don’t want to hold up the main thread responsible for bringing a response back to the client.

Most likely you’d want to offload this task to a background worker or another service, but sometimes it’s nice to be able to just handle the processing right then and there.

Go makes concurrency incredibly simple with the go keyword. So simple in fact, that you might quickly run into problems if you are handling files in the this manner and just spin up new goroutines for everything.

File descriptors

Herein lies the problem. Most systems don’t have an unlimited number of file descriptors for a process to use. Probing the two machines within my current reach yields the following:

$ sw_vers
ProductName:    Mac OS X
ProductVersion: 10.11.4
BuildVersion:   15E65
$ ulimit -n
256
~$ cat /etc/issue
Ubuntu 14.04.4 LTS \n \l
 
~$ ulimit -n
1024

Evidently there isn’t all that many available on either system. Opening a ton of sockets and files at once, will inevitably lead to errors; “Too many open files” or similar.

Limitation

Go’s concurrency primitives lends itself to definitions laid out by Tony Hoare in Communicating sequential processes and as such Go has the concept of channels.

Channels provides the necessary “blocking” mechanism, to allow a collection of goroutines to handle a common workload. Instead of creating a lot of goroutines all at once, rather a handful can be created, each waiting to handle incoming items on a channel.

Below is a very simple example, where a, (buffered channel with five slots*), channel is created as a work queue. Subsequently five goroutines are created and each set to wait on incoming work from the queue. In the main thread, the queue is then filled up all at once with work for the goroutines.

Once all the work have been loaded onto the queue, the channel is closed, which is Go’s way of telling consuming goroutines that nothing more will appear on the channel. This works in tandem with the range keyword to keep receiving on the channel until it is closed.

Note, the WaitGroup is effectively a Monitor; another concurrency construct that allows the main thread to wait for all the goroutines to finish.

Running the program produces the following output:

$ go run conc.go
10:25:37 Work a enqueued
10:25:37 Work b enqueued
10:25:37 Work c enqueued
10:25:37 Work d enqueued
10:25:37 Work e enqueued
10:25:37 Work f enqueued
10:25:39 Worker 1 working on a
10:25:39 Worker 3 working on d
10:25:39 Work g enqueued
10:25:39 Work h enqueued
10:25:39 Worker 2 working on b
10:25:39 Work i enqueued
10:25:39 Worker 4 working on e
10:25:39 Work j enqueued
10:25:39 Worker 0 working on c
10:25:39 Work k enqueued
10:25:41 Worker 0 working on j
10:25:41 Worker 3 working on g
10:25:41 Worker 2 working on h
10:25:41 Worker 1 working on f
10:25:41 Worker 4 working on i
10:25:41 Work l enqueued
10:25:41 Work m enqueued
10:25:41 Work n enqueued
10:25:41 Work o enqueued
10:25:43 Worker 0 working on k
10:25:43 Worker 1 working on n
10:25:43 Worker 3 working on l
10:25:43 Worker 2 working on m
10:25:43 Worker 4 working on o

Go’s concurrency primitives is that rare combination of easy and powerful, making it effortless to write threaded code.

It doesn’t save you from inherent limitations of the host system however, which is a good thing. Awareness of what the code actually does on the machine, is a virtue to strive for.

Edit: Thanks to Jemma for pointing out that buffering the channel isn’t needed afterall.

This post was included in the Go Newsletter issue 110.

Moving to a new domain – rhardih.io

This blog has been at my own “dump-all” domain éncoder.dk for ages, so it’s about time to move it to it’s own toplevel domain. As it were, the handle I use in most places, rhardih, is obscure enough to be available pretty much everywhere and as luck would have it, that goes for domain names as well. Hence, I’ve gone ahead and moved everything over to rhardih.io.

If I managed to do the move correctly, all permalinks should still work just fine, albeit with a 301 redirect in front. If not let the confusion begin!

 

WyGzoEr