Skip to main content

Fun with SSH ControlMaster

So, there was this user, wondering why a different group membership is displayed depending on the host name used in the SSH login process:

$ ssh mallory id; ssh id                 # Both point to the same machine!
uid=1000(dummy) gid=100(users) groups=100(users),16(dialout),33(video)
uid=1000(dummy) gid=100(users) groups=100(users),7(lp),16(dialout),33(video)
Huh? What happened here? After quite some digging, I found the following in the user's ~/.ssh/config:
Host *
        ControlMaster   no
        ControlPath     /home/dummy/tmp/ssh-%r@%h
And sure enough there was an active SSH connection and an active socket file in the ControlPath directory with a timestamp from a few weeks ago:
$ netstat -nl | grep tmp
unix  2      [ ACC ]     STREAM     LISTENING     16314    /home/dummy/tmp/ssh-dummy@mallory.Xnmcb2CghSke46qz
$ ls -l /home/dummy/tmp
srw-------. 1 dummy dummy 0 Jan 02 14:22 ssh-dummy@mallory
The use case for ControlMaster is, in short: establish an SSH connection once and then establish later SSH connections to the same host (and as the same user) over the already established socket.
And a ControlMaster connection has been established, but only to mallory, not to (even though both adresses point to the same host). With ControlMaster=no set in ~/.ssh/config, new connections will 1) not try to set up a new ControlMaster but 2) will try to use existing sockets in ControlPath.

And that's exactly what happened: the "ssh mallory" would use the existing socket, the "ssh" would create a completely new connection.

Now, some time after the ControlMaster has been created (after January 2), the group membership of the user has changed: the user got added to another group ("lp").

New SSH connections to the host are just that: "new". And will therefore see the real thing. Old SSH connections over the ControlMaster socket will be spawned as a child process off that already existing SSH process that has been in place from before the group membership changed and will have an old view of the system. This can be reproduced quite nicely, using two terminals:
1|dummy@fedora0$ ssh -o ControlMaster=yes localhost

2|dummy@fedora0$ ssh localhost id; ssh id
uid=1000(dummy) gid=1000(dummy) groups=1000(dummy)
uid=1000(dummy) gid=1000(dummy) groups=1000(dummy)
Now let's add dummy to a group and try again:
fedora0# usermod -a -G lp dummy
fedora0# id dummy
uid=1000(dummy) gid=1000(dummy) groups=1000(dummy),7(lp)

2|dummy@fedora0$ ssh localhost id; ssh id
uid=1000(dummy) gid=1000(dummy) groups=1000(dummy)
uid=1000(dummy) gid=1000(dummy) groups=1000(dummy),7(lp)
I still don't know if this is a feature or bug, but I found it interesting enough to document :-)

Getting rid of serendipity_spamblocklog

This Serendipity installation has a Spamblock feature which is currently logging comment spam to a database. Over time, this database grew quite a bit and while I'd like to keep the data around I don't need the data right away. Since the machine the database is running on is low on memory anyway, I wanted to archive & then purge old records from the spamblock logging table.

This is where we are:

$ ls -lhgo serendipity_spamblocklog*
-rw-rw----. 1 8.7K Nov 21 20:28 serendipity_spamblocklog.frm
-rw-rw----. 1 1.2G Jan 25 07:29 serendipity_spamblocklog.MYD
-rw-rw----. 1  41M Jan 25 07:39 serendipity_spamblocklog.MYI

$ for a in {2008..2015}; do
     printf "year: $a       "
     mysql -B -N -D s9y -e "select count(*) from serendipity_spamblocklog \
           where year(from_unixtime(timestamp)) = $a;"
year: 2008      12
year: 2009      14901
year: 2010      93232
year: 2011      12332
year: 2012      4373
year: 2013      245002
year: 2014      1232742
year: 2015      131898
Yeah, 2014 was really the year-of-the-spam :-)

Export those into CSV files:
$ for a in {2008..2014}; do
     echo "year: $a"
     mysql -D s9y -e "select * from serendipity_spamblocklog \
        where year(from_unixtime(timestamp)) = \"$a\" into outfile \
        \"spamblocklog-$a.csv\" fields terminated by ',' enclosed by '\"' \
        lines terminated by '\n';"
year: 2008
year: 2009
year: 2010
year: 2011
year: 2012
year: 2013
year: 2014
Which gives us (in datadir):
$ ls -hgo
total 1.2G
-r--------. 1 4.7K Jan 25 07:07 serendipity_spamblocklog-2008.csv
-r--------. 1 4.2M Jan 25 07:07 serendipity_spamblocklog-2009.csv
-r--------. 1  91M Jan 25 07:08 serendipity_spamblocklog-2010.csv
-r--------. 1 5.4M Jan 25 07:08 serendipity_spamblocklog-2011.csv
-r--------. 1 6.4M Jan 25 07:09 serendipity_spamblocklog-2012.csv
-r--------. 1 146M Jan 25 07:09 serendipity_spamblocklog-2013.csv
-r--------. 1 860M Jan 25 07:10 serendipity_spamblocklog-2014.csv
To count records, we can't use "wc -l" just like that because comments may contain newlines as well - so let's count timestamps instead:
$ grep -c '^\"1' *
Delete the exported records:
$ for a in {2008..2014}; do
     echo "year: $a"
     mysql -D s9y -e "delete from serendipity_spamblocklog \
        where year(from_unixtime(timestamp)) = $a;"
The size of the database file may not decrease until after we run OPTIMIZE TABLE on the table:
$ mysqlcheck --optimize s9y serendipity_spamblocklog
$ ls -lhgo serendipity_spamblocklog.*
-rw-rw----. 1 8.7K Nov 21 20:28 serendipity_spamblocklog.frm
-rw-rw----. 1  88M Jan 25 08:15 serendipity_spamblocklog.MYD
-rw-rw----. 1 3.2M Jan 25 08:15 serendipity_spamblocklog.MYI
And we can still run some stats on the CSV files:
$ awk -F\",\" '/^\"1/ {print $2}' serendipity_spamblocklog-2013.csv | sort | uniq -c | sort -n
    30 "API_ERROR"
   119 "moderate"
 98045 "REJECTED"
146808 "MODERATE"

$ awk -F\",\" '/^\"1/ {print $8}' serendipity_spamblocklog-2014.csv | awk '{print $1}' | sort | uniq -c | sort -n | tail
   251 PHP/5.3.89
   252 PHP/5.3.59
   252 PHP/5.3.94
   261 PHP/5.2.19
   270 PHP/5.2.62
  1125 Opera/9.80
 30848 PHP/5.2.10
509019 Mozilla/4.0
646256 Mozilla/5.0

gpg: rejected by import filter

Trying to import a GPG key failed:

$ gpg --verify SHA512SUMS.asc
gpg: Signature made Thu Dec  4 18:03:53 2014 PST using RSA key ID 15A0A4BC
gpg: Can't check signature: public key not found

$ gpg --recv-keys 15A0A4BC
gpg: requesting key 15A0A4BC from hkp server
gpg: key 3A06537A: rejected by import filter
gpg: Total number processed: 1
The thing is, 0x15A0A4BC points to a subkey and GnuPG v1.4.18 has problem when only the keyid of the subkey is specified. There are a few ways to tackle that:

Upgrade to at least GnuPG v2.0.26. While the 1.4-branch is said to be maintained, the release notes are not. If you're really using v1.4, make sure that commit d585527 is included, which fixes bug #1680

If updating GnuPG is not an option, we can also download the key and import it locally:
$ curl
$ gpg --import 
gpg: key 3A06537A: public key "Mozilla Software Releases <>" imported
gpg: Total number processed: 1
gpg:               imported: 1  (RSA: 1)
gpg: 3 marginal(s) needed, 1 complete(s) needed, PGP trust model
gpg: depth: 0  valid:  18  signed:  11  trust: 0-, 0q, 0n, 0m, 0f, 18u
gpg: depth: 1  valid:  11  signed:   3  trust: 11-, 0q, 0n, 0m, 0f, 0u
gpg: next trustdb check due at 2015-03-14
Or, now that we know the real keyid, we can import it too:
$ gpg --yes --batch --delete-keys 0x15a0a4bc

$ gpg --recv-keys 3A06537A
$ gpg --verify SHA512SUMS.asc 
gpg: Signature made Thu Dec  4 18:03:53 2014 PST using RSA key ID 15A0A4BC
gpg: Good signature from "Mozilla Software Releases <>"
gpg: WARNING: This key is not certified with a trusted signature!
gpg:          There is no indication that the signature belongs to the owner.
Primary key fingerprint: 2B90 598A 745E 992F 315E  22C5 8AB1 3296 3A06 537A
     Subkey fingerprint: 5445 390E F5D0 C2EC FB8A  6201 057C C3EB 15A0 A4BC

SSH & the while loop

Somehow this loop stops after the first element:

$ head -2 hosts

$ head -2 hosts | while read a; do ssh $a "uname -n"; done
The best explanation I could find, comes from a forum post*):
> The "cat list.txt" is providing stdin for the entire "while" loop. It is not 
> constrained to only the read statement. ssh is eating all of the input
> and feeding it to "date" as stdin. And date just ignores the input. Use
> the -n option to ssh to stop this from happening.
And indeed, this is working now:
$ head -2 hosts | while read a; do ssh -n $a "uname -n"; done
Thanks, Perderabo!

*) copied w/o permission

On Password Strength

Password generation may seem to be trival these days, as various password generators do exist. But I wanted to know if they are any good and I found two programs for the command line trying to examine the strength of a password:

  • cracklib-check from the CrackLib project is a standalone program derived from the pam_cracklib module.
  • An alternative to pam_cracklib is passwdqc from the Openwall Project which also provides standalone programs to generate and check passwords.
Let's use these two programs on a few password generators. For the sake of simplicity, let's only generate random looking passwords that are exactly 12 characters long. Nobody should have to type passwords these days anyway and a password manager is recommended.


pwgen (v2.06 from 2007) is maybe the most popular one, and easy to use too. The last version has been released in 2007, let's see if it is any good:
$ time pwgen -s -1 12 100000 | /usr/sbin/cracklib-check | fgrep -c -v ': OK'

real    0m31.722s
user    0m20.072s
sys     0m13.736s
→ We generated 100k passwords in 32 seconds, 20 of them (0.02%) did not pass the cracklib test.
$ time pwgen -s -1 12 100000 | pwqcheck -1 --multi | fgrep -c -v OK:

real    2m42.557s
user    2m43.156s
sys     0m1.668s
→ We generated 100k passwords in 163 seconds, 2731 of them (2.7%) did not pass the pwqcheck test. Clearly, pwqcheck seems to be much stricter. It also takes much longer to check, but this should only matter when checking thousands of passwords, as we just did.


pwqgen (v1.3.0 from 2013) from the passwdqc project has a weird syntax, probably due to the fact that it's mostly used as a PAM module rather than as a standalone program. I couldn't figure out how to generate passwords of exactly 12 characters long, the following use of cut(1) will miss passwords shorter than 12 characters:
$ seq 1 100000 | while read a; do pwqgen; done | cut -c-12 | ...
So, for the sake of correctness, let's do this instead (although this takes ~3 times longer to complete):
$ i=0; time while [ $i -lt 100000 ]; do pwqgen | cut -c-12 | egrep -o '^.{12}$' && i=$((i+1)); done \
          | /usr/sbin/cracklib-check | fgrep -c -v ': OK'

real    6m4.756s
user    3m51.396s
sys     1m22.528s
→ We generated 100k passwords in 364 seconds, 9 of them (0.009%) did not pass the cracklib test. Clearly, pwqgen is generating much better passwords than pwgen, according to cracklib. And again with pwqcheck:
$ i=0; time while [ $i -lt 100000 ]; do pwqgen | cut -c-12 | egrep -o '^.{12}$' && i=$((i+1)); done \
          | pwqcheck -1 --multi | fgrep -c -v OK:

real    6m16.043s
user    6m0.292s
sys     1m8.708s
→ We generated 100k passwords in 376 seconds, 29083 of them (29%) did not pass the pwqcheck test. Wow. This even contradicts the finding above: while pwqgen does seem to generate better passwords than pwgen according to cracklib, when checked with pwqcheck, password quality seems to be much lower. Let's attribute that to our cut -c-12 hack and move on to another password generator:


apg (v2.2.3 from 2003) hasn't had a release in 10 years and is kinda slow, since it's using /dev/random directly, for whatever reason:
$ time apg -a 1 -m 12 -x 12 -n 100000 | /usr/sbin/cracklib-check | fgrep -c -v ': OK'

real    4m28.997s
user    4m56.896s
sys     0m17.712s
→ We generated 100k passwords in 269 seconds, 67 of them (0.067%) did not pass the cracklib test. And again with pwqcheck:
$ time apg -a 1 -m 12 -x 12 -n 100000 | pwqcheck -1 --multi | fgrep -c -v OK:

real    5m15.415s
user    9m30.960s
sys     0m0.420s
→ We generated 100k passwords in 315 seconds, 291 of them (0.29%) did not pass the pwqcheck test.


gpw (v0.0.19940601 from 2006) attempts to produce pronounceable passwords, so our criteria for random passwords won't hold. Let's test it anyway and see what happens:
$ time gpw 100000 12 | /usr/sbin/cracklib-check | fgrep -c -v ': OK'

real    0m28.195s
user    0m19.640s
sys     0m10.756s
→ We generated 100k passwords in 28 seconds, 540 of them (0.54%) did not pass the cracklib test.
$ time gpw 100000 12 | pwqcheck -1 --multi | fgrep -c -v OK:

real    0m1.670s
user    0m1.768s
sys     0m0.016s
Wow - none of the passwords generated by gpw was accepted by pwqcheck! Execution time was very fast, though :-)


makepasswd (v1.10 from 2013) is a Perl program, and a very fast one too:
$ time makepasswd --chars=12 --count=100000 | /usr/sbin/cracklib-check | fgrep -c -v ': OK'

real    0m34.404s
user    0m32.624s
sys     0m13.428s
→ We generated 100k passwords in 34 seconds, 22 of them (0.022%) did not pass the cracklib test.
$ time makepasswd --chars=12 --count=100000 | pwqcheck -1 --multi | fgrep -c -v OK:

real    2m29.020s
user    2m40.328s
sys     0m0.024s
→ We generated 100k passwords in 149 seconds, 12742 of them (12.74%) did not pass the pwqcheck test.

So, in conclusion: use pwqcheck to check for passwords and apg or pwgen for password generation. To always use a password checker when generating a password, use something like this:
$ pwgen_check() { pwgen $@ | pwqcheck -1 --multi; }
$ pwgen_check -s 12 10
OK: CjgR1nC4t9t5
OK: iggW9u3hMAnd
OK: E7fAY7fjF5KJ
Bad passphrase (not enough different characters or classes for this length): FexzFoJRxpO5
OK: JnIcezRq39SY
OK: TUmzflKP3npZ
OK: pSkPzf0fHnlw
While the "benchmarks" above were made up as I discovered more and more password generators, I wrote a small script combining all these, generating the following results:
$ time ./ 12 1000000
     pwgen - 148 passwords (0%) failed for cracklib, runtime: 239 seconds.
    pwqgen - 127 passwords (0%) failed for cracklib, runtime: 1605 seconds.
       apg - 635 passwords (0%) failed for cracklib, runtime: 3225 seconds.
       gpw - 5249 passwords (0%) failed for cracklib, runtime: 188 seconds.
makepasswd - 248 passwords (0%) failed for cracklib, runtime: 285 seconds.
   openssl - 175 passwords (0%) failed for cracklib, runtime: 5509 seconds.

     pwgen - 29523 passwords (2.00%) failed for pwqcheck, runtime: 1133 seconds.
    pwqgen - 290042 passwords (29.00%) failed for pwqcheck, runtime: 2248 seconds.
       apg - 3013 passwords (0%) failed for pwqcheck, runtime: 4082 seconds.
       gpw - 1000000 passwords (100.00%) failed for pwqcheck, runtime: 21 seconds.
makepasswd - 128036 passwords (12.00%) failed for pwqcheck, runtime: 1029 seconds.
   openssl - 100438 passwords (10.00%) failed for pwqcheck, runtime: 6417 seconds.

real    433m0.997s
user    352m16.577s
sys     120m52.305s

Fun with Debian DKMS

Running VirtualBox on Debian needs the virtualbox-dkms package installed. DKMS stands for Dynamic Kernel Module Support and is an attempt to build out-of-tree drivers for the kernel versions installed instead of offering multiple package versions of the same driver.

So, virtualbox-dkms was installed and all was good - until a change in the kernel sources broke the VirtualBox build and needed a patch against the virtualbox-dkms sources. However, only recent kernel versions were affected, the patched virtualbox-dkms code would not run correctly with an older kernel.

On this box, two kernel versions are installed: linux-image-3.14-2-amd64 and linux-image-3.17.0-rc1+, compiled from vanilla sources. A "dpkg-reconfigure virtualbox-dkms" would build the virtualbox-dkms for both kernel versions, but for the reasons explained above, we can't do this now.

Let's rebuild virtualbox-dkms only for the kernel that needs to be built with the patched version of virtualbox-dkms:

# rmmod vboxpci vboxnetadp vboxnetflt vboxdrv

# ls -lgo /var/lib/dkms/virtualbox/
total 4
drwxr-xr-x 5 4096 Aug 31 01:49 4.3.14
lrwxrwxrwx 1   26 Aug 31 01:49 kernel-3.14-2-amd64-x86_64 -> 4.3.14/3.14-2-amd64/x86_64
lrwxrwxrwx 1   25 Aug 31 01:37 kernel-3.17.0-rc1+-x86_64 -> 4.3.14/3.17.0-rc1+/x86_64

# dkms remove virtualbox/4.3.14 -k 3.17.0-rc1+/x86_64

# cd /usr/src/virtualbox-4.3.14
# patch -p0 < ~/virtualbox-alloc_netdev.diff
# dkms install virtualbox/4.3.14 -k 3.17.0-rc1+/x86_64
And that should be all to it :)

On SSH ciphers, MACs and key exchange algorithms

Inspired by a some question on StackExchange on the taxonomy of Ciphers/MACs/Kex available in SSH, I wondered what would be the fastest combination of Ciphers, MACs and KexAlgorithms that OpenSSH has to offer.

I've tested with OpenSSH 6.6 (released 2014-03-14) on a Debian/Jessie system (ThinkPad E431). Initially I ran these tests against an SSH server in a virtual machine but realized that the server is not supporting newer Cipher/MAC/KexAlgorithm combinations, so before I ran the actual benchmark I ran to test all working combinations. Later on I ended up running the performance test on localhost, making the evaluation step obsolete. Still, I decided to keep it around so that one can peform the benchmark on real-world situations where the remote SSH server is not located on localhost :-)

This OpenSSH version supports 15 different Ciphers, 18 MAC algorithms and 8 Key-Exchange algorithms - that's 2160 combinations to test. will go through the output of and transfer a certain amount of data from local /dev/zero to remote /dev/null. Connecting to localhost was fast so I opted to transfer 4GB of data.

Before we get into the details, let's see the top-5 combinations of the results:

cipher: aes192-ctr mac: kex: ecdh-sha2-nistp256 - 6 seconds
cipher: aes192-ctr mac: kex: diffie-hellman-group1-sha1 - 6 seconds
cipher: aes128-ctr mac: kex: ecdh-sha2-nistp384 - 6 seconds
cipher: aes192-ctr mac: kex: ecdh-sha2-nistp384 - 6 seconds
cipher: aes192-ctr mac: kex: diffie-hellman-group-exchange-sha1 - 6 seconds
The UMAC message authentication code has been introduced in OpenSSH 4.7 (released 2007-09-04) and is indeed the fastest MAC in this little contest. Looking at the results reveals that there indeed some variation in the results when it comes to different MAC or Kex choices. Iterating through all ciphers, we calculate the average run time of each combination:
$ for c in `awk '{print $4}' ssh-performance.log | sort | uniq`; do
     printf "cipher: $c  "
     grep -w $c ssh-performance.log | awk '{sum+=$(NF-1); n++} END {print sum/n}'
done | sort -nk3
cipher:  8.8125
cipher:  9.23611
cipher: aes128-ctr  15.6875
cipher: aes192-ctr  15.6944
cipher: aes256-ctr  16.1319
cipher: arcfour     20.26391)
cipher: arcfour128  20.3403
cipher: arcfour256  20.5278
cipher: aes128-cbc  21.125
cipher: aes192-cbc  22.4583
cipher:  23.2361
cipher: aes256-cbc  23.9722
cipher: blowfish-cbc  55.6875
cipher: cast128-cbc  59.5139
cipher: 3des-cbc  200.854
So, (included in OpenSSH 6.2, released 2013-03-22) comes out fastest across all combinations while 3des-cbc is indeed the slowest cipher. While the major performance factor is still the choice of the cipher, both MAC and Kex still play a role. As an example, let's look at aes192-ctr mac, the results range from 6 to 46 seconds:
cipher: aes192-ctr mac: kex: ecdh-sha2-nistp256 - 6 seconds
cipher: aes192-ctr mac: kex: ecdh-sha2-nistp256 - 46 seconds
Let's see how MAC and Kex choices rank up across all (15) different ciphers. That is, we calculate the average time for each MAC:
$ for m in `awk '{print $6}' ssh-performance.log | sort | uniq`; do
     printf "mac: $m  "
     grep -w $m ssh-performance.log | awk '{sum+=$(NF-1); n++} END {print sum/n}'
done | sort -nk3
mac:  28.45
mac:  28.8167
mac:  29.8583
mac:  30.1
mac: hmac-sha1-96  33.4417
mac:  33.5167
mac:  33.6333
mac: hmac-sha1  33.7104
mac: hmac-md5-96  33.7792
mac:  33.8167
mac: hmac-md5  33.825
mac:  34.2
mac:  38.2333
mac: hmac-sha2-512  38.2833
mac:  43.775
mac: hmac-ripemd160  43.7792
mac: hmac-sha2-256  44.3792
mac:  44.45
And again for the key exchange algorithms:
$ for k in `awk '{print $8}' ssh-performance.log | sort | uniq`; do
     printf "kex: $k  "
     grep -w $k ssh-performance.log | awk '{sum+=$(NF-1); n++} END {print sum/n}'
done | sort -nk3
kex: ecdh-sha2-nistp256  35.2926
kex: diffie-hellman-group14-sha1  35.3148
kex: diffie-hellman-group1-sha1  35.4296
kex: diffie-hellman-group-exchange-sha256  35.563
kex: ecdh-sha2-nistp521  35.563
kex: diffie-hellman-group-exchange-sha1  35.6926
kex: ecdh-sha2-nistp384  35.8333
kex:  35.8667
The differences for Kex here are in the sub-second range, so even the recently added Curve25519 option would not be much of a performance impact here.

So, what do we make of all this? Another StackExchange question suggests that SSH in general holds up pretty good security-wise and even dismisses problems with CBC. Assuming all of that is true, what can we do to get the most performance when transferring big files over SSH? Let's look at the defaults again, from ssh_config(5) of OpenSSH 6.6:
Ciphers: aes128-ctr aes192-ctr aes256-ctr arcfour256 arcfour128 [...]
MACs: [...]
KexAlgorithms: ecdh-sha2-nistp256 ecdh-sha2-nistp384 ecdh-sha2-nistp521 [...]
So, according to the results of this little contest, a faster default for a recent version of OpenSSH could be:
  • The GCM ciphers have been implemented with OpenSSH 6.2 (released 2013-03-22).
  • The EtM (Encrypt-then-MAC) modes and 128-bit UMAC variants have only been supported since OpenSSH 6.2 (released 2013-03-22).
  • The KexAlgorithms option has been added with OpenSSH 5.7 (released 2011-01-24)
As always, when it comes to benchmarks: other SSH implementations (e.g. HPN-SSH) or different setups will most certainly return different results. So please test yourself before drawing any conclusions from these results.

Update October 2014):
OpenSSH 6.7 disables the CBC ciphers by default because of vulnerabilites found when used with SSH (found in 2008).

Update (June 2016):
new benchmark script and new results (averaged over 3 runs):
### Top-5 overall
cipher: aes128-ctr   mac:  kex: -  10 seconds avg.
cipher: aes128-ctr   mac:  kex: ecdh-sha2-nistp521 -  10 seconds avg.
cipher: aes128-ctr   mac:  kex: diffie-hellman-group-exchange-sha256 -  10 seconds avg.
cipher: aes128-ctr   mac:  kex: diffie-hellman-group14-sha1 -  10 seconds avg.
cipher: aes128-ctr   mac:  kex: ecdh-sha2-nistp256 -  9 seconds avg.

If we were to use the Secure Secure Shell recommendations and exclude some of the weaker choices, we would lose only a few seconds (and would basically switch to chacha20-poly1305):
### Top-6 overall
cipher: mac: kex: -  14 seconds avg.
cipher: mac: kex: diffie-hellman-group-exchange-sha256 -  13 seconds avg.
cipher: mac: kex: -  13 seconds avg.
cipher: mac: kex: -  13 seconds avg.
cipher: mac: kex: diffie-hellman-group-exchange-sha256 -  13 seconds avg.
cipher: mac: kex: -  12 seconds avg.

OS X Mavericks & NTP

Only recently I noticed that the system time on this machine running OS X v10.9 is off by almost a second:

$ /opt/local/libexec/nagios/check_ntp_time -H -w 0.5 -c 1.0
NTP WARNING: Offset -0.7461649179 secs|offset=-0.746165s;0.500000;1.000000;
Lengthy discussions and explanations describe the issue quite nicely:
$ cat /var/db/ntp.drift
So, clock drift on this machine is -47.901 PPM or 172.44 ms/h. But the NTP offset is even larger:
$ ntpq -c peers
     remote           refid      st t when poll reach   delay   offset  jitter
 akamai.ruselabs  2 u 1245   64    7  221.876  -740.67 164.885   2 u  37m   64    7  236.627  -731.73 145.745
 gw-kila-wl0.ipv  2 u  35m   64    7  133.689  -768.34 125.425

$ sntp -p no
2014 Aug 06 13:51:09.1000 -0.75187 +/- 0.024338 secs
That's -0.75 seconds off the correct time! Kinda weird for a high precision machine like this. A workaround suggest to disable pacemaker and restart ntpd:
$ ps -ef | grep pac[e]
0  106   1 0    18Jul14   ??  0:12.82 /usr/libexec/pacemaker -b -e 0.0001 -a 10

$ sudo launchctl unload -w /System/Library/LaunchDaemons/

$ sudo launchctl list | grep ntp
84577   -       org.ntp.ntpd
$ sudo launchctl stop org.ntp.ntpd
$ sudo launchctl list | grep ntp
74279   -       org.ntp.ntpd
With pacemaker disabled, our NTP offset is now within acceptable range:
$ sntp -p no
2014 Aug 06 13:54:05.461870 +0.046836 +/- 0.037628 secs

$ /opt/local/libexec/nagios/check_ntp_time -H -w 0.5 -c 1.0
NTP OK: Offset 0.01386797428 secs|offset=0.013868s;0.500000;1.000000;

User and system time per process

Long time no blog post - so let's change that :-)

Today I've come across a system with a pretty high load, but couldn't quite make out which processes were responsible for the load. The ps command showed:

$ uptime
 20:16pm  up 1 day  2:40,  12 users,  load average: 132.81, 132.79, 133.43

$ ps -eo user,pid,rsz,vsz,pmem,pcpu,time,args --sort -pcpu
user0    18428   3124    58236   0.0 1.1 00:00:00 LLAWP /www/user0/eam/WebAgent.conf -A
user0     8387  14976   154220   0.0 4.2 01:07:44 LLAWP /www/user0/eam/WebAgent.conf -A
user0     4508  14828   152864   0.0 4.2 01:07:21 LLAWP /www/user0/eam/WebAgent.conf -A
user0     8045  15000   154220   0.0 4.2 01:07:33 LLAWP /www/user0/eam/WebAgent.conf -A
user0    23814  14892   152868   0.0 4.2 01:06:47 LLAWP /www/user0/eam/WebAgent.conf -A
user0    18384   3124    58236   0.0 0.8 00:00:00 LLAWP /www/user0/eam/WebAgent.conf -A
user0    17224  14932   152952   0.0 4.1 01:05:39 LLAWP /www/user0/eam/WebAgent.conf -A
So, while each of these processes is using some CPU time, it didn't quite explain the high load. top(1) shows:
Tasks: 1439 total,   9 running, 1430 sleeping,   0 stopped,   0 zombie
Cpu0  : 14.1%us, 49.5%sy,  0.0%ni, 34.3%id,  0.0%wa,  0.0%hi,  2.0%si,  0.0%st
Cpu1  : 19.0%us, 51.4%sy,  0.0%ni, 28.6%id,  1.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  : 15.2%us, 47.6%sy,  0.0%ni, 35.2%id,  0.0%wa,  0.0%hi,  1.9%si,  0.0%st
Cpu3  : 16.8%us, 45.8%sy,  0.0%ni, 37.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu4  : 17.4%us, 39.4%sy,  0.0%ni, 41.3%id,  0.9%wa,  0.0%hi,  0.9%si,  0.0%st
Cpu5  : 14.7%us, 39.4%sy,  0.0%ni, 14.7%id,  0.0%wa,  0.0%hi, 31.2%si,  0.0%st
Cpu6  : 14.5%us, 30.0%sy,  0.0%ni, 52.7%id,  0.0%wa,  0.0%hi,  2.7%si,  0.0%st
Cpu7  :  9.4%us, 34.9%sy,  0.0%ni, 55.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
So we have 1439 processes, but only 9 are running and 1430 are sleeping - and there's a quite a lot system time being used. But there's no ps option to display user oder system time. However, this being a Linux system, we still have the /proc filesystem. The /proc/PID/stat file of a 2.6.30 kernel contains 52 fields, among them are:
   2: tcomm   filename of the executable
   3: state   state (R=running, S=sleeping, D=uninterruptible wait, Z=zombie, T=traced/stopped)
  14: utime   user mode jiffies
  15: stime   kernel mode jiffies
So let's try this:
$ for PID in `ps -eo pid`; do 
   awk '{print "user: " $14 " kernel: " $15 " state: " $3 " process: " $2}' /proc/$PID/stat
done > foo
$ sort -t: -nk3 foo | tail -5
user: 71232 kernel: 335302 state: D process: (LLAWP)
user: 71105 kernel: 342684 state: D process: (LLAWP)
user: 71290 kernel: 346119 state: D process: (LLAWP)
user: 71009 kernel: 347570 state: D process: (LLAWP)
user: 71278 kernel: 348388 state: D process: (LLAWP)
This is only the top-5, but LLAWP was using the most system on this system while really doing nothing - it was in uninterruptible sleep ("D"). Restarting those processes helped and the system load returned to normal :-)