Czech techie's adventures
Archives
« December 2009
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
  
       
Today
Click me to subscribe
Search

Links
 

Today's Page Hits: 78

« Previous page | Main
Monday Feb 11, 2008
Grepping dtrace logs

I have been working on a tough bug for some non-trivial time. The bug is a combination of race condition and data consistency issues. To debug this I am using multi-threaded apache process and dtrace heavily. The logs produced by dtrace are huge and contain mostly dumps of internal data structures.

The excerpt from such log looks e.g. like this:

  1  50244       pk11_return_session:return       128   8155.698
  1  50223            pk11_RSA_verify:entry       128   8155.7069
  1  50224           pk11_get_session:entry       128   8155.7199
  1  50234          pk11_get_session:return       128   8155.7266
PK11_SESSION:
  pid = 1802
  session handle = 0x00273998
  rsa_pub_key handle -> 0x00184e70
  rsa_priv_key handle -> 0x00274428
  rsa_pub = 0x00186248
  rsa_priv = 0x001865f8

  1  50224           pk11_get_session:entry       128   8155.7199

  1  50244       pk11_return_session:return       128   8155.698

Side note: This is post-processed log (probe together with their bodies are timestamp sorted, time stamps are converted to miliseconds - see Coloring dtrace output entry for details and scripts).

Increasingly, I was asking myself questions which resembled this one: "when function foo() was called with data which contained value bar ?"

This quickly lead to a script which does the tedious job for me. dtrace-grep.pl accepts 2 or 3 parameters. First 2 are probe pattern and data pattern, respectively. Third, which is optional, is input file (if not supplied, stdin will be used). Example of use on the above pasted file looks like this:

~/bin$ ./dtrace-grep.pl pk11_get_session 0x00186248 /tmp/test
  1  50234          pk11_get_session:return       128   8155.7266
PK11_SESSION:
  pid = 1802
  session handle = 0x00273998
  rsa_pub_key handle -> 0x00184e70
  rsa_priv_key handle -> 0x00274428
  rsa_pub = 0x00186248
  rsa_priv = 0x001865f8


~/bin$ 

Now I have to get back to work, to do some more pattern matching. Oh, and the script is here.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 06:24PM Feb 11, 2008  |  Permanent link to this entry  |  Comments[0]

Thursday Jan 17, 2008
Adding dtrace SDT probes

It seems that many developers and dtrace users found themselves in a position where they wanted to add some SDT probes to a module to get more insight into what's going on but the had to pause and were thinking "okay, more probes. But where to put them ? Do I really need the additional probes when I already have the fbt ones ?". To do this, systematic approach is needed in order not to over-do or under-do. I will use KSSL (Solaris kernel SSL proxy [1]) for illustration.

With CR 6556447, tens of SDT probes were introduced into KSSL module and other modules which interface with it. Also, in addition to the new SDT probes, in KSSL we got rid of the KSSL_DEBUG macros compiled only in DEBUG kernels and substituted them with SDT probes. As a result, much better observability and error detection was achieved with both debug and non-debug kernels. The other option would be to create KSSL dtrace provider but that would be too big gun for what is needed to achieve.

Generically, the following interesting data points for data gathering/observation can be identified in code:

You've surely noticed that same of the probe definitions above have common prefix (kssl_mblk-). This is one of the things which make SDT probes so attractive. With prefixes it is possible to do the e.g. following:

sdt:::kssl_err-*
{
  trace(timestamp);
  printf("hit error in %s\n", probefunc);
  stack(); ustack();
}

The important part is that we do not specify module of function name. The implicit wildcard (funcname/probename left out) combined with explicit wildcard (prefix + asterisk) will lead to all KSSL error probes to be activated regardless of in which module or function there are defined. This is obviously very useful for technologies which span multiple Solaris subsystems or modules (such as KSSL).

The nice thing about the error probes is that they could be leveraged in test suites. For each test case we can first run dtrace script with the above probeset covering all KSSL errors in the background and after the test completes just check if it produced some data. If it did, then the test case can be considered as failed. No need to check kstat(1M) (and other counters), log files, etc.

Also, thanks to the way how dtrace probes are activated we can have both generic probeset (using this for lack of better term) as above with addition of probe specific action, e.g.:

/* probeset of all KSSL error probes */
sdt:::kssl_err-*
{
  trace(timestamp);
  printf("hit error in %s\n", probefunc);
}

/* 
  the probe definition is:
     DTRACE_PROBE2(kssl_err__bad_record_size,
         uint16_t, rec_sz, int, spec->cipher_bsize);
 */
sdt:kssl:kssl_handle_record:kssl_err-bad_record_size
{
  trace(timestamp);
  tracemem(arg0, 32);
  printf("rec_sz = %d , cipher_bsize = %d\n", arg1, arg2);
}

If probe kssl_err-bad_record_size gets activated the generic probe will be activated (and fires) too because the probeset contains the probe.

Similarly to the error prefix, we can have data specific prefix. For KSSL it is kssl_mblk- prefix which could be used for tracing all mblks (msgb(9S)) as they flow through TCP/IP, STREAMS and KSSL modules. With such probes it is possible to do e.g. the following:

/* how many bytes from a mblk to dump */
#define DUMP_SIZE       48

/* use macros from  */
#define MBLKL(mp)       ((mp)->b_wptr - (mp)->b_rptr)
#define DB_FLAGS(mp)    ((mp)->b_datap->db_flags)

#define PRINT_MBLK_INFO(mp)                                             \
        printf("mblk = 0x%p\n", mp);                                    \
        printf("mblk size = %d\n", MBLKL((mblk_t *)mp));                \
        PRINT_MBLK_PTRS(mp);

#define PRINT_MBLK(mp)                                                  \
                trace(timestamp);                                       \
                printf("\n");                                           \
                PRINT_MBLK_INFO(mp);                                    \
                printf("DB_FLAGS = 0x%x", DB_FLAGS((mblk_t *)mp));      \
                tracemem(((mblk_t *)mp)->b_rptr, DUMP_SIZE);            \
                tracemem(((mblk_t *)mp)->b_wptr - DUMP_SIZE,            \
                        DUMP_SIZE);

sdt:::kssl_mblk-*
{
  trace(timestamp);
  printf("\n");
  PRINT_MBLK(arg0)
}

This is actually an excerpt from my (currently internal) KSSL debugging suite.
An example of output from such probe can be seen in my Coloring dtrace output post.

For more complex projects it would be waste to stop here. Prefixes could be further structured. However, this has some drawbacks. In particular, I was thinking about having kssl_mblk- and kssl_err- prefixes. Now what to do for places where an error condition occurred _and_ we would like to see the associated mblk ? Using something like kssl_mblk_err-* comes to ones mind. However, there is a problem with that - what about the singleton cases (only mblk, only err). Sure, using multiple wildcards in dtrace is possible (e.g. syscall::*read*:) but this will make it ugly and complicated given the number of mblk+err cases (it's probably safe to assume that the number of such cases will be low). Simply, it's not worth the hassle. Rather, I went with 2 probes.
To conclude, using structured prefixes is highly beneficial only for set of probes where categories/sub-prefixes create non-intersecting sets (e.g. data type and debug level).

Of course, all of the above is not valid only for kernel but also for custom userland probes !

[1] High-level description of KSSL can be found in blueprint 819-5782.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 11:33AM Jan 17, 2008  |  Permanent link to this entry  |  Comments[0]

Saturday Dec 01, 2007
Netcat in Solaris

CR 4664622 has been integrated into Nevada and will be part of build 80 (which means it will not be part of next SXDE release but I can live with that :)).

During the course of getting the process done I have stumbled upon several interesting obstacles. For example, during ingress Open Source Review I was asked by our open-source caretaker what will be the "support model" for Netcat once it is integrated. I was puzzled. Because, for Netcat, support is not really needed since it has been around for ages (ok, since 1996 according to wikipedia) and is pretty stable piece of code which is basically no longer developed. Nonetheless, this brings some interesting challenges with move to a community model where more and more projects are integrated by people outside Sun (e.g. ksh93 project).

The nc(1) man page will be delivered in build 81. In the meantime you can read Netcat review blog entry which contains the link to updated man page. The older version of the man page is contained in the mail communication for PSARC 2007/389.
Note: I have realized that the ARC case directory does not have to include most up-to-date man page at the time of integration. Only when something _architectural_ changes, then the man page has to be updated (which was not the case with Netcat since we only added new section describing how to setup nc(1) with RBAC). Thanks to Jim for the explanation.

I have some ideas how to make Netcat in Solaris even better and will work to get them done over time. In particular, there are following RFEs: 6515928, 6573202. However, this does not mean that there is only single person who can work on nc(1). Since it is now part of ONNV, anyone is free to hack it.

So, I'd like to invite everyone to participate - if you have an idea how to extend Netcat, what features to add, it is sitting in ONNV waiting for new RFEs (or bugs) and sponsor requests (be sure to read Jayakara Kini's explanation of how to contribute if you're not OpenSolaris contributor yet).

Also, if you're Netcat user and use Netcat in a cool way, I want to hear that !

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 11:04AM Dec 01, 2007  |  Permanent link to this entry  |  Comments[3]

Sunday Nov 18, 2007
Chemical plants, Linux and dtrace

When my friend from Usti nad Labem (9th biggest city in Czech republic) asked me to present about OpenSolaris at local Linux conference, I got hooked. First, Usti is interesting city (the city is surrounded by beautiful countryside, yet has chemical plants in the vicinity of city center) and I haven't been there for a long time and second, having the opportunity to present about OpenSolaris technologies to Linux folks is unique.

When we (Sasha agreed to go present with me) arrived to Usti we were greeted by slightly apocalyptic weather (see pictures below). The environment where all the presentations took place compensated that, fortunately.

40 minutes to present about something which most people in the room are not very aware of is challenging. The fact that OpenSolaris is open source and it is a home for several disruptive technologies makes that both easier and harder. We have greatly leveraged Bryan Cantrill's Dtrace review video taped at Google for doing second part of the presentation where we demo'ed dtrace. I have even borrowed some of his quotes. I am pretty sure he wouldn't object since his presentations were perused in the past. To make the list of attributions complete, we have substantial material in the first part from Lukas' past presentations about OpenSolaris project.

It's much better to demo the technology than just talk about how great it is (I remember a funny moment in Bryan's presentation where a dtrace probe didn't "want" to fire where Bryan jokingly said "bad demo!" to the screen. I nearly fell off of my chair at that moment.). "So, I have finally seen dtrace in action !" was one of the great things to hear after the presentation.

The "OpenSolaris technologies" presentation can be downloaded here.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 12:02AM Nov 18, 2007  |  Permanent link to this entry  |  Comments[0]

Saturday Nov 03, 2007
Netcat package and code review

As you might know, Netcat implementation is going to be part of OpenSolaris. The initial Netcat integration is based on a reimplementation from OpenBSD (here's why).

As Jeff Bonwick said, open sourced code is nothing compared to the fact that all design discussions and decisions suddenly happen in the public (loosely paraphrased). This is a great wave to ride and I have jumped on it when it was not really small so I have at least posted the webrev pointer for initial Netcat integration (CR 4664622) to the opensolaris-code mailing list (which is roughly the equivalent of freebsd-hackers, openbsd-tech or similar mailing lists) to get some code review comments.

Since then couple of things changed. Thanks to Dan Price and others it's now possible to upload webrevs to cr.opensolaris.org. I have started using the service so the new and official place for the Netcat webrev is

The webrev has moved location but what I said in the opensolaris-code post still holds true:

Any constructive notes regarding the code are welcome. (I am mainly looking for functional/logic errors, packaging flaws or parts of code which could mismatch the PSARC case)

The following things could help any potential code reviewer:

The conclusion for non code reviewers ? I hope it is clear the in (Open)Solaris land we value quality and transparency. Peer reviews and architectural reviews are just (albeit crucial) pieces which help to achieve that goal.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 12:46AM Nov 03, 2007  |  Permanent link to this entry  |  Comments[0]

Tuesday Aug 28, 2007
Getting code into libc

In my previous entry about BSD compatibility gap closure process I have promised to provide a guide on how to get new code into libc. I will use changes done via CR 6495220 to illustrate the process with examples.

Process related and technical changes which are usually needed:

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 01:30PM Aug 28, 2007  |  Permanent link to this entry  | 

Thursday Aug 23, 2007
Closing BSD compatibility gap

I do not get to meet customers very often but I clearly remember the last time where I participated in a pseudo-technical session with a new customer. The engineers were keen on learning details about all features which make Solaris outstanding but they were also bewildered by the lack of common functions such as daemon() (see CR 4471189). Yes, there is a number of private implementations in various places in ONNV, however this is not very useful. Until recently, this was also the case of err/warn function family.

With the putback of CR 6495220 there are now the following functions living in libc:

  void err(int, const char *, ...);
  void verr(int, const char *, va_list);
  void errx(int, const char *, ...);
  void verrx(int, const char *, va_list);
  void warn(const char *, ...);
  void vwarn(const char *, va_list);
  void warnx(const char *, ...);
  void vwarnx(const char *, va_list);

These functions were present in BSD systems for a long time (they've been in FreeBSD since 1994). The configure scripts of various pieces of software contain checks for presence and functionality of the err/warn functions in libc (and setting the HAVE_ERR_H define). For Solaris, those checks have now become enabled too.

The err(3C) man page covering these functions will be delivered in the same build as the changes, that is build 72.

The change is covered by PSARC 2006/662 architectural review and the stability level for all the functions is Committed (see Architecture Process and Tools for more details on how this works). Unfortunately, the case is still closed. Hopefully it will be opened soon.
Update 09-28-2007: the PSARC/2006/662 case is now open, including onepager document and e-mail discussion. Thanks to John Plocher, Darren Reed and Bill Sommerfeld.

As I prompted in the err/warn Heads-up there is now time to stop creating new private implementations and to look at purging duplicates (there are many of them, however not all can be gotten rid of in favour of err/warn from libc).

I will write about how to get code into libc in general from a more detailed perspective next time.

However, this does not mean there is nothing left to do in this area. Specifically, FreeBSD's err(3) contains functions err_set_exit(), err_set_file() and errc(), warnc(), verrc() and vwarnc(). These functions could be ported over too. Also, there is __progname or getprogname(3). Moreover, careful (code) reader has realized that err.c contains private implementations of functions with fp suffix. This function (sub)family could be made Committed too. So, there is still lot of work which could be done. Anyone is free to work on any of these. (see Jayakara Kini's blog entry on how to become OpenSolaris contributor if you're not already)

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 09:15AM Aug 23, 2007  |  Permanent link to this entry  |  Comments[0]

Thursday Jun 14, 2007
Coloring dtrace output

Currently I am working on a subtle bug in KSSL. (SSL kernel proxy) In order to diagnose the root cause of the bug I use set of dtrace scripts to gather data in various probes. One of the dtrace scripts I am using looks like this:

#!/usr/sbin/dtrace -Cs
/*
  trace mbuf which caused activation of 
  kssl-i-kssl_handle_any_record_recszerr probe

  NOTE: this presumes that every mblk seen by TCP/KSSL
        is resonably sized (cca 100 bytes)
 */

/* how many bytes from a mblk to dump */
#define DUMP_SIZE       48

/* 
  generic kssl mblk dump probe 
  (covers both input path and special cases)
 */
sdt:::kssl_mblk-*
{
  trace(timestamp);
  printf("\nmblk size = %d",
      ((mblk_t *)arg0)->b_wptr - ((mblk_t *)arg0)->b_rptr);
  tracemem(((mblk_t *)arg0)->b_rptr, DUMP_SIZE);
  tracemem(((mblk_t *)arg0)->b_wptr - DUMP_SIZE, DUMP_SIZE);
}

The scripts usually collect big chunks of data from the various SDT probes I have put into kssl kernel module. After the data are collected I usually spend big chunks of time sifting though it. At one point of time I have got a suspicion that the problem is actually a race condition of sorts. In order to shed some light on what's going on I have used less(1) which provides highlighting of data when searching. While this is sufficient when searching for a single pattern, it does not scale when more patterns are used. This is when I got the idea to color the output from dtrace scripts to see the correlations (or lack of them) of the events with a simple Perl script. Example of the output colored by the script:

colored dtrace output (data)

This looks slightly more useful than plain black output in terminal but even with 19" display the big picture is missing. So, I have changed the dtrace-coloring script to be able to strip the data parts for probes and print just the headers:

colored dtrace output (headers)

This is done via '-n' command line option. (the default is to print everything.) The output containing just the colored headers is especially nice for tracking down race conditions and other time-sensitive misbehaviors. You can download the script for dtrace log coloring here: dtrace-coloring.pl

The colors can be assigned to regular expressions in the hash 'coloring' in the script itself. For the example above I have used the following assignments:

my %coloring = (
  '.*kssl_mblk-i-handle_record_cycle.*' => '4b6983',    # dark blue
  '.*kssl_mblk-enqueue_mp.*'    => '6b7f0d',    # dark green
  '.*kssl_mblk-getnextrecord_retmp.*'   => 'a11c10',    # dark red
);

In the outputs above you might have noticed that a timestamp is printed when a probe fires. This is useful for pre-processing of the log file. dtrace(1) (or libdtrace to be more precise) does not sort events as they come from the kernel. (see CR 6496550 for more details) In cases when hunting down a race condition on multiprocessor machine having the output sorted is crucial. So in order to get consistent image suitable for race condition investigation a sort script is needed. You might use a crude script of mine or you can write yours :)

Technorati Profile

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 12:05PM Jun 14, 2007  |  Permanent link to this entry  |  Comments[1]

Tuesday Mar 27, 2007
Sound Blaster Live! on Solaris

During stressful days of libmd backport to Solaris 10 update 4 I managed to break my iPod mini by sliding on my chair backwards and running to get next coffee cup. (The catch was that I still had my headphones connected to the iPod on so the iPod fell down on the floor. It now only reports the unhappy face of Macintosh.)

Only after that I have realized how music is important for my day-to-day tasks. I cannot simply continue in the same pace as before without steady flow of rhythm into my ears.

Before buying another iPod I wanted to get some interim relief. This is when I entered the not-so-happy world of Solaris audio drivers. My workstation is Acer Aspire E300 which came with integrated TV card and whatnot but also with integrated sound card. The sound card is supported in Solaris but the level of noise coming from it was unbearable. (and I am no HiFi snob, listening mostly to 32kbps radio Akropolis streams) After some googling I have realized that there is a driver for Sound Blaster Live! 5.1 PCI card which I had in my Solaris test workstation at home. The driver was backported by Jürgen Keil (frequent OpenSolaris contributor) from NetBSD among other drivers.

The relevant part of prtconf -v output looks like this:

            pci1102,8027 (driver not attached)
                Hardware properties:
                    name='assigned-addresses' type=int items=5
                        value=81024810.00000000.00009400.00000000.00000020
                    name='reg' type=int items=10
                        value=00024800.00000000.00000000.00000000.00000000.01024
810.00000000.00000000.00000000.00000020
                    name='compatible' type=string items=7
                        value='pci1102,2.1102.8027.7' + 'pci1102,2.1102.8027' + 
'pci1102,8027' + 'pci1102,2.7' + 'pci1102,2' + 'pciclass,040100' + 'pciclass,0401'
                    name='model' type=string items=1
                        value='Audio device'

It's quite easy to get it working:

  1. disable the on-board sound card in BIOS
  2. get the sources and extract them
      /usr/sfw/bin/wget http://www.tools.de/files/opensource/solaris/audio/beta/audio-1.9beta.tar.bz2
      bzcat audio-1.9beta.tar.bz2 | tar -xf -
  3. compile (set the PATH if needed to get access to gcc/ar)
      export PATH=/usr/bin:/usr/sbin:/usr/sfw/bin:/usr/sfw/sbin:/usr/ccs/bin
      cd audio-1.9beta && make
  4. install the driver (audioemu) and its dependency (audiohlp) on x86:
      cp drv/emu/audioemu /platform/i86pc/kernel/drv
      cp drv/emu/amd64/audioemu /platform/i86pc/kernel/drv/amd64
      cp drv/emu/audioemu.conf /platform/i86pc/kernel/drv
      cp misc/audiohlp /kernel/misc
      cp misc/amd64/audiohlp /kernel/misc/amd64
      cp misc/audiohlp.conf /kernel/misc
      
  5. attach the driver (see instructions in drv/emu/Makefile)
    add_drv -i '"pci1102,2" "pci1102,4"' audioemu
  6. reboot

Yes, I could have used the infrastructure provided in Makefiles to create the package and install it but I wanted to have minimalistic install and have just the things which are really needed.

After the reboot you should be able to play sound via e.g. xmms. (installed e.g. from Blastwave) Check for audioemu in modinfo(1M) output and dmesg(1M) output for error messages if something goes wrong. So far it has been working for me rather flawlessly. (no kernel panics ;))

During the search for the driver I have discovered number of complaints from the users trying OpenSolaris for the first time that their Sound Blaster Live! was not recognized. Looking into Device drivers community not much is going on about soundcard drivers.
I wonder how hard would it be to get the audioemu NetBSD-based driver into ON.. the CR number is 6539690.

2007-08-08 update: After asking on opensolaris-discuss mailing list I have realized that there is a project underway which will deliver OSS into (Open)Solaris. Some info can be found in PSARC/2007/238, however there is no project page at opensolaris.org (yet). Hopefully, RFE 6539690 will be closed after OSS integrates into ONNV.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 04:47PM Mar 27, 2007  |  Permanent link to this entry  |  Comments[0]

Monday Nov 13, 2006
Simple Solaris Installation

OpenSolaris was already out before I joined Sun so I had a chance to play with Solaris Express Community release for couple of months and actually look into the source code online thanks to Chandan's OpenGrok. Still, with all these goodies it required fair amount of exploration before I figured things out. Being a BSD person some of them were not surprising, whereas some of them slowed me down substantialy.

I don't remember now the origin of the thought to summarize the installation steps and basic steps after installation to make the system more useable, this is not important. Anyway, the slides containing all of this information (and more) were made.
The slides were originaly meant for CZOSUG Bootcamp where people brought their laptops and installed Solaris on them. I have created the slides together with Jan Pechanec . After watching both external people and new-hires struggle with basic steps after completing Solaris installation I think they could be used also to ease those post-install how-do-I-set-this steps.

They are not perfect, could contain errors (please do report them) but here you go:

Also, do not forget to look at recently founded Immigrants community at opensolaris.org which contains other goodies such as links to Ben Rockwood's Accelerated introduction to Solaris. Also do not forget to subscribe to the Immigrants mailing list.

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 07:11PM Nov 13, 2006  |  Permanent link to this entry  |  Comments[1]

Friday Nov 03, 2006
Cleartext for now !

Ahoj [1], I am Vladimir Kotal and have been working for Sun since February 2006 as "Revenue Product Engineer" in security "technology-management" team [2]. This means that my main job is to fix security bugs (both vulnerabilities and common bugs) in Solaris. I usually work from offices in Prague.

For the time being (as of November 2006) I am the only member of Solaris RPE security technology-management team in Europe.

My fixes usually have to do something with following technologies/products: IPsec, SSH, OpenSSL and crypto. In this blog I will try to present not only security technologies but also Solaris/OpenSolaris-related stuff.

[1] "Ahoj" is "hello" in Czech.
[2] There is also "Security Engineering and Coordination" team which provides fixes for vulnerabilities

tags:
Linkage: Technorati cosmos Technorati cosmos

Posted at 07:29PM Nov 03, 2006  |  Permanent link to this entry  |  Comments[0]