Josef “Jeff” Sipek

2017-11-14

Doug Engelbart Institute — Online exhibits, historic videos, texts, archive photos, and stories about Doug Engelbart, the inventor of the mouse, hypertext, and GUIs…all in the 1960s

Flight recorders data inspection by Airbus

Parsing JSON is a Minefield

Completely Painless Programmer’s Guide to XYZ, RGB, ICC, xyY, and TRCs — Brain-hurting amount of information about color profiles, etc.

darktable — A Lightroom-like open source software

World plugs — Info about every electric plug form factor in the world

Working @ Dovecot

It’s been a hectic couple of weeks, and so this post is a bit delayed. Oh well.

A couple of months ago, I decided that it was time for me to move on work-wise. As a result, four weeks ago, I joined Dovecot Oy (a part of Open-Xchange).

As you may have guessed from the name of the company, I get to spend my time making the Dovecot email server code better, more featureful, and otherwise more excellent. It is certainly a significant but fun change—going from kernel hacking on a fairly unknown operating system to hacking on the world’s most popular IMAP server. Not a day goes by where I’m not surprised just how much functionality is in the Dovecot codebase, or when I get to consult an RFC related to some IMAP extension I didn’t even know existed.

So, with this said, you should expect to see some posts related to Dovecot, Dovecot code, and email in general.

Grub Composite Console

In the past, I’ve described how to get a serial console going on Illumos based systems. If you ever used a serial console in Grub (regardless of the OS you ended up booting), you probably know that telling Grub to output to a serial port causes the VGA console to become totally useless — it’s blank.

Well, if you are using Illumos, you are in luck. About 5 months ago, Joyent integrated a “composite console” in Grub. You can read the full description in the bug report/feature request. The short version is: all grub output can be sent to both the VGA console as well as over a serial port.

It is very easy to configure. In your menu.lst, change the terminal to composite. For example, this comes from my test box’s config file (omitting the uninteresting bits):

serial --unit=0 --speed=115200
terminal composite

Note the use of composite instead of serial. That’s all there is to it.

Task Spooler

For a couple of years now, I wished that I could have a mini-batch system on my computers that’d let me submit jobs and they’d execute when the resources became available. This would let me queue up large amount of work and it’d eventually all get processed. I even tried to hack up a dumb little Python script that’d loop over a file executing no more than one per core.

Then, yesterday, I stumbled across Task Spooler. It’s exactly what I was looking for! It lets me queue jobs, supports dependencies between jobs, etc.

I’m hoping to experiment with it in the next couple of days. I’ll let you know how it turns out.

Netflix Chaos Monkey

Somehow, I managed to miss that about two years ago Netflix open sourced their chaos monkey.

Based on my quick look over the code, it appears to be written in Java. Meh. Regardless of the language, it’s great to see large companies open source their code.

Greetings from Nexenta

In case you missed it, back in mid-2011 I discovered Illumos and OpenIndiana. At that point, I already missed hacking on the (Linux) kernel. Based on my blahg posts [1,2], it shouldn’t surprise you that it didn’t take long before I wanted to hack on the Illumos kernel…and so I did.

If you ever contributed to an open source project in your free time while employed full-time, you understand that there’s only so much time you can devote to the open source project and therefore there is only so much you can do.

A couple of months ago, I decided to explore the possibility of working full-time on Illumos. There are only a handful of companies that visibly participate in the Illumos ecosystem, but their use of Illumos is pretty varied (from public clouds to virtualized databases to SAN/NAS appliances). As of this past Tuesday (Monday was a holiday), I’m at Nexenta. At least for now, I’m working remotely (from Ann Arbor) with the fine folks in the Wikipedia article: Lowell office. It feels great to work on open source again.

MongoDB - First Impressions

I just ssh’ed into a server that’s running MongoDB to see if it was doing anything and if there were any cool commands to get stats from it. (I’ve never used MongoDB.) I accidentally ran mongod as non-root. It died because it didn’t have the right permissions — good. However, something in the output seemed completely and utterly retarded.

warning: 32-bit servers don't have journaling enabled by default. Please use
	--journal if you want durability.

[initandlisten] MongoDB starting : pid=12682 port=27017 dbpath=/data/db/
	32-bit host=hkn2012
[initandlisten] 
[initandlisten] ** NOTE: when using MongoDB 32 bit, you are limited to about
	2 gigabytes of data
[initandlisten] **       see http://blog.mongodb.org/post/137788967/32-bit-limitations
[initandlisten] **       with --journal, the limit is lower

Was it the 2 GB data limit? Nope! Was it the fact that 32-bit systems default to non-durable mode while 64-bit default to durable? Bingo! Seriously, that is retarded. Why would anyone think that it is a good idea to cripple 32-bit systems like that? Was performance so bad with journaling that to avoid gaining a reputation for being slow the developers decided to keep the data unsafe by default? I doubt it. Was it to squeeze in a couple more MB of addressable data? Probably. Good job, folks.

For what it is worth, I decided to see if the 2 GB limit was something silly (i.e., using an int in some on-disk structure). It turns out that mongod likes to mmap the data for fast access. This is reasonable. (More so than using architecture specific integral types in on-disk structures.)

I wonder what other gems are hiding in this software.

DTrace: The utmp_update Debugger

For the past 2 years, I am a happy user of rxvt-unicode, aka urxvt. Recently, I noticed that my logs contained rather mysterious error messages:

Nov  3 22:46:03 meili utmp_update[1613]: [ID 845426 user.error] Wrong number of
	arguments or invalid user 

Sometimes, there were a dozen of these. Of course I filed a bug with the Illumos folks. Rich Lowe suggested using DTrace to figure out what is actually going on. It was time to look at the exit codes for utmp_update.

syscall::rexit:entry
/execname=="utmp_update"/
{
	printf("utmp_update exited with code %d", arg0);
	@[arg0] = count();
}

tick-60sec
{
	printa(@);
}

Since utmp is involved, it had something to do with terminals, so I tried to open some terminals and close them. That did it!

# dtrace -s catch-errors.d 
dtrace: script 'catch-errors.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  0     49                      rexit:entry utmp_update exited with code 0
  1     49                      rexit:entry utmp_update exited with code 0
  0     49                      rexit:entry utmp_update exited with code 7
  0     49                      rexit:entry utmp_update exited with code 7
  1     49                      rexit:entry utmp_update exited with code 0
  5     49                      rexit:entry utmp_update exited with code 0
  1     49                      rexit:entry utmp_update exited with code 0
  2     49                      rexit:entry utmp_update exited with code 0
  3     49                      rexit:entry utmp_update exited with code 7
  1  67549                      :tick-60sec 
                7                3
                0                6

It turns out that every time I closed a terminal, utmp_update exited with error 7. A quick glance at usr/src/cmd/utmp_update/utmp_update.c reveals:

/*
 * Return codes
 */
#define	NORMAL_EXIT		0
#define	BAD_ARGS		1
#define	PUTUTXLINE_FAILURE	2
#define	FORK_FAILURE		3
#define	SETSID_FAILURE		4
#define	ALREADY_DEAD		5
#define	ENTRY_NOTFOUND		6
#define	ILLEGAL_ARGUMENT	7
#define	DEVICE_ERROR		8

Aha! It really is an invalid argument. At this point, Rich pointed me to setutxline in libc.so. Sadly, for whatever reason, the probe pid*:libc.so.1:pututxline:entry didn’t work (it didn’t match anything). Rich suggested the following DTrace script:

proc:::exec
/strstr(args[0], "utmp") != NULL/
{
	trace(execname);
}

Pretty straightforward — the output told me that it was urxvt causing all this trouble.

Now, I knew to watch out for pututxline in urxvt. I tried to set a probe pid$target::pututxline:entry and use the new print function in DTrace, but due to a user error (read: sometimes I write stupid code) it didn’t work. Rich helped me navigate through mdb to get a print-out of the utx structure. At this point, it was a bit too late in the night and so I went to bed.

The next morning, I tried the print function again and this time I used it right and it printed out the structure:

struct utmpx {
    char [32] ut_user = [ "" ]
    char [4] ut_id = [ 'v', 't', '0', '2' ]
    char [32] ut_line = [ "pts/2" ]
    pid_t ut_pid = 0x193ec
    short ut_type = 0x8
    struct exit_status ut_exit = {
        short e_termination = 0
        short e_exit = 0
    }
    struct timeval ut_tv = {
        time_t tv_sec = 0x4eb55d2a
        suseconds_t tv_usec = 0x18adc
    }
    int ut_session = 0
    int [5] pad = [ 0, 0, 0, 0, 0 ]
    short ut_syslen = 0
    char [257] ut_host = [ "" ]
}

Everything looks right, except that the ut_user field is blank. I wonder if this could be the cause of it. Time to look at the urxvt code! (The ustack() action in a DTrace probe for pututxline:entry will tell you where to look.) Here’s a snippet from rxvt-unicode-9.12/libptytty/src/logging.C:

/*
 * remove utmp and wtmp entries
 */
void
ptytty_unix::logout ()
{
  ...
#ifdef HAVE_STRUCT_UTMPX
  setutxent ();
  tmputx = getutxid (utx);
  if (tmputx && tmputx->ut_pid == cmd_pid)
    pututxline (utx);
  endutxent ();
#endif
  ...
}

Ok, so it gets a utx struct and then it puts a different one. Let’s see how different those two are:

# cat getutxid.d
#include <utmpx.h>

pid$target::getutxid:return
{
	ustack();
	print(*(struct utmpx*)copyin(arg1, sizeof(struct utmpx)));
}
# dtrace -Cs getutxid.d -p 103403
dtrace: script 'getutxid.d' matched 1 probes
dtrace: pid 103403 has exited
CPU     ID                    FUNCTION:NAME
  4  67555                  getutxid:return 
              libc.so.1`getutxid+0xf1
              urxvt`_ZN11ptytty_unixD0Ev+0x16
              urxvt`_ZN9rxvt_termD1Ev+0x59b
              urxvt`_ZN9rxvt_term10destroy_cbERN2ev4idleEi+0x70
              urxvt`_ZN2ev4baseI7ev_idleNS_4idleEE12method_thunkI9rxvt_termXadL_ZNS5_10destroy_cbERS2_iEEEEvPS1_i+0x27
              urxvt`ev_invoke_pending+0x35
              urxvt`ev_run+0x520
              urxvt`main+0x29b
              urxvt`_start+0x83
struct utmpx {
    char [32] ut_user = [ "jeffpc" ]
    char [4] ut_id = [ 'v', 't', '0', '2' ]
    char [32] ut_line = [ "pts/2" ]
    pid_t ut_pid = 0x193ec
    short ut_type = 0x7
    struct exit_status ut_exit = {
        short e_termination = 0
        short e_exit = 0x2
    }
    struct timeval ut_tv = {
        time_t tv_sec = 0x4eb55d1f
        suseconds_t tv_usec = 0x18adc
    }
    int ut_session = 0
    int [5] pad = [ 0, 0, 0, 0x303a0005, 0x302e ]
    short ut_syslen = 0
    char [257] ut_host = [ "" ]
}

Ok, it’s more or less the same. It does, however, have a username filled in. I wonder what would happen if I filled in the username. (The urxvt code seems to fill it in only on login updates and it leaves the field empty on logout updates.) Now, I had 3 choices…

  1. Change the urxvt code to fill in the username on logout updates.
  2. Set a breakpoint in gdb or mdb and then tweak the structure before it is passed to utmp_update.
  3. Use DTraces “destructive” option to allow me to modify the process’s memory.

I chose #3.

Here’s the script in all its glory:

#pragma D option destructive

#include <utmpx.h>

pid$target::getutxid:return
{
	ustack();
	print(*(struct utmpx*)copyin(arg1, sizeof(struct utmpx)));
}

pid$target::pututxline:entry
{
	ustack();
	print(*(struct utmpx*)copyin(arg0, sizeof(struct utmpx)));
	printf("\nFIXING...\n");
	copyout("jeffpc\0", (uintptr_t)&((struct utmpx*)arg0)->ut_user[0], 7);
	print(*(struct utmpx*)copyin(arg0, sizeof(struct utmpx)));
}

pid$target::pututxline:return
{
	printf("pututxline returned %p", arg1);
}

And here’s the output:

# dtrace -Cs foo.d -p 103403
dtrace: script 'foo.d' matched 3 probes
dtrace: allowing destructive actions
dtrace: pid 103403 has exited
CPU     ID                    FUNCTION:NAME
  4  67555                  getutxid:return 
              libc.so.1`getutxid+0xf1
              urxvt`_ZN11ptytty_unixD0Ev+0x16
              urxvt`_ZN9rxvt_termD1Ev+0x59b
              urxvt`_ZN9rxvt_term10destroy_cbERN2ev4idleEi+0x70
              urxvt`_ZN2ev4baseI7ev_idleNS_4idleEE12method_thunkI9rxvt_termXadL_ZNS5_10destroy_cbERS2_iEEEEvPS1_i+0x27
              urxvt`ev_invoke_pending+0x35
              urxvt`ev_run+0x520
              urxvt`main+0x29b
              urxvt`_start+0x83
struct utmpx {
    char [32] ut_user = [ "jeffpc" ]
    char [4] ut_id = [ 'v', 't', '0', '2' ]
    char [32] ut_line = [ "pts/2" ]
    pid_t ut_pid = 0x193ec
    short ut_type = 0x7
    struct exit_status ut_exit = {
        short e_termination = 0
        short e_exit = 0x2
    }
    struct timeval ut_tv = {
        time_t tv_sec = 0x4eb55d1f
        suseconds_t tv_usec = 0x18adc
    }
    int ut_session = 0
    int [5] pad = [ 0, 0, 0, 0x303a0005, 0x302e ]
    short ut_syslen = 0
    char [257] ut_host = [ "" ]
}
  4  67556                 pututxline:entry 
              libc.so.1`pututxline
              urxvt`_ZN11ptytty_unix6logoutEv+0x15c
              urxvt`_ZN11ptytty_unixD0Ev+0x16
              urxvt`_ZN9rxvt_termD1Ev+0x59b
              urxvt`_ZN9rxvt_term10destroy_cbERN2ev4idleEi+0x70
              urxvt`_ZN2ev4baseI7ev_idleNS_4idleEE12method_thunkI9rxvt_termXadL_ZNS5_10destroy_cbERS2_iEEEEvPS1_i+0x27
              urxvt`ev_invoke_pending+0x35
              urxvt`ev_run+0x520
              urxvt`main+0x29b
              urxvt`_start+0x83
struct utmpx {
    char [32] ut_user = [ "" ]
    char [4] ut_id = [ 'v', 't', '0', '2' ]
    char [32] ut_line = [ "pts/2" ]
    pid_t ut_pid = 0x193ec
    short ut_type = 0x8
    struct exit_status ut_exit = {
        short e_termination = 0
        short e_exit = 0
    }
    struct timeval ut_tv = {
        time_t tv_sec = 0x4eb55d2a
        suseconds_t tv_usec = 0x18adc
    }
    int ut_session = 0
    int [5] pad = [ 0, 0, 0, 0, 0 ]
    short ut_syslen = 0
    char [257] ut_host = [ "" ]
}
FIXING...
struct utmpx {
    char [32] ut_user = [ "jeffpc" ]
    char [4] ut_id = [ 'v', 't', '0', '2' ]
    char [32] ut_line = [ "pts/2" ]
    pid_t ut_pid = 0x193ec
    short ut_type = 0x8
    struct exit_status ut_exit = {
        short e_termination = 0
        short e_exit = 0
    }
    struct timeval ut_tv = {
        time_t tv_sec = 0x4eb55d2a
        suseconds_t tv_usec = 0x18adc
    }
    int ut_session = 0
    int [5] pad = [ 0, 0, 0, 0, 0 ]
    short ut_syslen = 0
    char [257] ut_host = [ "" ]
}
  4  67557                pututxline:return pututxline returned fef6ecf0

We can see the getutxid return a reasonable utmpx. Then we see pututxline get a utmpx without a username set. Then there is the fixed up tmpx. Finally, we see that the pututxline returned a non-NULL pointer. (It returns NULL on error — which does indeed happen without the fix-up.)

There you have it, folks. DTrace let me debug an issue without annoying change-compile-install cycles. Now, all I have to do is fix up urxvt in OpenIndiana and possibly, if it applies to other systems, push the fix upstream.

update_drv: adding a driver alias

Over the weekend, I got fed up with my laptop (Thinkpad T520) using the VESA driver even though I have an NVidia card. After some searching online, I came to the conclusion that the nvidia driver I had installed (280.13) should work with my card but there was an alias missing. So, I ran the following to add an alias for the PCI ID:

# update_drv -a -i '"pciex10de,1057"' nvidia

A reboot (really, X restart would have done, but it is nice to know that things come up as expected during a reboot) later, I was greeted by accelerated graphics. Yay!

Of course I created a bug for OpenIndiana to have the missing alias added. This post is supposed to serve as a reminder for myself about how to use update_drv.

DTrace: qsort use in Firefox, part 2

Earlier, I wrote about some silly qsort behavior in Firefox. I couldn’t help but dig a bit deeper.

Before, we concluded that there were a lot of 8-element, 4-byte element sorts. What are these used for? What part of Firefox is causing these? DTrace to the rescue.

First, let’s change the last DTrace command from last time a bit. First of all, let’s look at 4-byte element invocations only (arg2 equals 4) and let’s aggregate on the caller function name:

# dtrace -n 'pid1120:libc:qsort:entry/arg2==4/{@[ufunc(ucaller)]=llquantize(arg1, 10,0,6,20)} tick-60sec{printa(@)}'

...
  1  75455                      :tick-60sec 
  libnss3.so`DPCache_GetUpToDate                    
           value  ------------- Distribution ------------- count    
             < 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 14       
               1 |                                         0        

  libglib-2.0.so.0.2501.0`g_array_sort              
           value  ------------- Distribution ------------- count    
             700 |                                         0        
             750 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
             800 |                                         0        

  libfontconfig.so.1`FcFontSetSort                  
           value  ------------- Distribution ------------- count    
              55 |                                         0        
              60 |@                                        4        
              65 |                                         2        
              70 |                                         0        
              75 |@@@@                                     20       
              80 |@@@@@                                    24       
              85 |@@@@@@@                                  36       
              90 |@@@@@                                    26       
              95 |                                         0        
             100 |@@@@@@@@@@@@@@                           76       
             150 |@@@@                                     22       
             200 |                                         0        

  libcairo.so.2.10800.10`_cairo_bentley_ottmann_tessellate_bo_edges
           value  ------------- Distribution ------------- count    
               3 |                                         0        
               4 |@                                        59       
               5 |                                         0        
               6 |                                         32       
               7 |                                         0        
               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            2357     
               9 |                                         0        
              10 |@@                                       137      
              15 |@@@                                      215      
              20 |@                                        52       
              25 |                                         12       
              30 |@                                        58       
              35 |@@                                       200      
              40 |@                                        67       
              45 |                                         3        
              50 |                                         2        
              55 |                                         2        
              60 |                                         7        
              65 |                                         0        
              70 |@                                        67       
              75 |                                         0        
              80 |                                         0        
              85 |                                         0        
              90 |                                         0        
              95 |                                         16       
             100 |                                         0   

We see four unique functions that call qsort. It doesn’t take long to spot the one we were looking for: _cairo_bentley_ottmann_tessellate_bo_edges in libcairo.so. Interesting, so it turns out that it wasn’t Firefox itself doing all these sorts (8-element, 4-byte element) but rather the Cairo graphics library. It would also seem that it is the only place that does these sorts. Let’s see how Firefox is involved in this.

# dtrace -n 'pid1120:libc:qsort:entry/arg2==4 && arg1==8/{@[ustack()]=count()} tick-60sec{printa(@)}'

...
  0  75455                      :tick-60sec 

              libc.so.1`qsort
              libcairo.so.2.10800.10`_cairo_bentley_ottmann_tessellate_bo_edges+0x172
              libcairo.so.2.10800.10`_cairo_bentley_ottmann_tessellate_polygon+0x41f
              libcairo.so.2.10800.10`_cairo_path_fixed_fill_to_traps+0x150
              libcairo.so.2.10800.10`_cairo_clip_clip+0xe3
              libcairo.so.2.10800.10`_cairo_gstate_clip+0x44
              libcairo.so.2.10800.10`cairo_clip_preserve+0x31
              libxul.so`__1cKgfxContextEClip6M_v_+0x24
              libxul.so`__1cInsWindowNOnExposeEvent6MpnK_GtkWidget_pnP_GdkEventExpose__i_+0x56e
              libxul.so`__1cPexpose_event_cb6FpnK_GtkWidget_pnP_GdkEventExpose__i_+0x72
              libgtk-x11-2.0.so.0.2000.0`_gtk_marshal_BOOLEAN__BOXED+0x7b
              libgobject-2.0.so.0.2501.0`g_closure_invoke+0xdf
              libgobject-2.0.so.0.2501.0`signal_emit_unlocked_R+0x9f2
              libgobject-2.0.so.0.2501.0`g_signal_emit_valist+0x6d2
              libgobject-2.0.so.0.2501.0`g_signal_emit+0x28
              libgtk-x11-2.0.so.0.2000.0`gtk_widget_event_internal+0x24d
              libgtk-x11-2.0.so.0.2000.0`gtk_widget_send_expose+0x98
              libgtk-x11-2.0.so.0.2000.0`gtk_main_do_event+0x46f
              libgdk-x11-2.0.so.0.2000.0`_gdk_window_process_updates_recurse+0x291
              libgdk-x11-2.0.so.0.2000.0`_gdk_windowing_window_process_updates_recurse+0x24
              184

This counts the number of 4-byte element, 8-element arrays qsort aggregated on the stack trace. We get to use ustack() here because we are in userspace (stack() would give us the kernel stack trace). Where is Firefox in this mess? libxul.so. This is the limit of my knowledge of Firefox internals and someone more knowledgeable could tell you more.

Your Turn

Do you use DTrace? Do you have some interesting war stories? Let me know in the comments!

Powered by blahgd