Tesla Model3: 8 Months ownership

I’ve never really considered myself as a Car guy. I like cars, sure, but in a more general way, I like sensations: speed, acceleration, you name it. Although, I would never have thought blogging about one in the past.

Today as I woke up, I noticed that my car received the latest Over The Air update. I consider updates for any other device I own as being more annoying than useful but, Tesla’s updates are the exception. I thought I’d do a retrospective view of the past 8 months that I’ve owned the car and driven it beyond the 40,000 Km line, trying to list what happened and what changed…

First of all, let me present you the car I bought, the Tesla Model 3 Performance:

When I bought the car, it was the early days of Tesla shipping Model 3’s to Europe and I was among the first lucky persons to receive it! The delivery day of the car was a truly exciting experience and, the first reaction as I drove away from the delivery center was to tell my 6 years old: “Dang, we’re in the future now!”.

Over the following weeks, I have gotten used to receive periodic updates to the car, whose have been bringing a handful of new features. A lot of people out there would eventually make fun of the car getting Netflix and YouTube.. as it may not be that useful, but it’s not just about that usefulness. Imagine buying a car, capable of so many things, but improving as you are owning it. This is quite a unique feeling which you can not even wrap your head around with about any other car manufacturer. Let me try to, retrospectively, list the features that I did not have at the delivery of my car but which have been pushed later on:

  • Auto High/Low beam: Okay, this one is still a WIP in my opinion, but that’s something that was not in the initial specs of the car!
  • Sentry: Originally, my car only had the DashCam (!!)
  • Navigate on Autopilot: Originally, in Belgium at least, only Auto-steer was available, Navigate on Autopilot came in later along with the car being able to get on ramp and off ramp!
  • Netflix, YouTube, Caraoke: Part of the recent V10 roll-out.
  • CupHead, Chess, … — Infotainment like nowhere else: Who can boast plugging a USB controller to its car and start playing retro games?
  • HomeLink: The original list of supported device by the HomeLink chip present in my car was not including my garage door, this one came supported after an update!
  • Link driver’s profile with the Key Card (or Phone), so my seats readjust whenever I enter the car!
  • Dog Mode — Or as we are able to use it: the Bird mode! (see below)
Dog Mode: Keeping our Bird at temperature 😉
  • Scheduled departure (The charge ends when you leave and the air conditioning prepare the car!)
  • Automatic Navigation: Select the address based off your habits.
  • Faster supercharging!
  • Single Pedal driving

I’m actually confident that I forgot to list a ton of other improvements that I received (and feel free to supplement my list in the comments if you see I’ve missed some!). I can’t remember all of the new stuff that have been pushed to this car… There’s one though that I have purposefully not listed above as I wanted to treat it separately… Let’s try to imagine that you have bought a car from any mainstream manufacturer which, one day, call you and say:

“We just found out that your engine is more capable than we initially thought, so let’s get you some more horsepower for free…”

No car manufacturer ever.

With this car, it’s not just one increase in power but two, that I have received over time. This morning, my car has greeted me with the following message:

Overall, the car has gained close to 100hp from the time I took delivery! This was not even something I would’ve dream about in the past…

To wrap this post up, let me just mention that for a month now, we’ve became a Tesla family, since my wife decided to make the step as well and buy her Model 3! She was looking at me in a strange way when I initially got the car and wondered a lot when I was getting those updates. Now I can only smile happily when I see her being excited about the new release being deployed.

Let me close with a picture of us doing some gardening in the summer, the “Tesla Way” 😉

Please also share how you’re having fun in the comment section…

Posted in Tesla | Tagged , , | 1 Comment

It’s all about some encounters…

About 9 years ago, a friend of mine was thinking about his life and had what I can recall as being the following thought:

It’s odd how sometimes in life, certain people you meet are going to impact your life and change it forever. There are very few of those encounters in a lifetime, but they’re quite impressive in how impactful they are.

Indeed, he was referencing how meeting one of our common colleague had impacted his life so much that it took a drastically different direction and had a positive influence on his situation.

It’s been a few days that this discussion has been sticking in my head and I wanted to write about it. I’d like to take myself back to this thinking and reflect on what have been the highly impactful encounters I had in my life so far.

In 2006, as I was working as a Linux System Administrator, I was up for a professional change and started getting into interviews for Freelance roles. I thought that moving into a Freelancer life could get me more exposure and ability to constantly new things and I wanted to give it a try. I was 20.

I interviewed for a Solaris Administrator role at Belgacom with Rob. Rob was a Solaris Administrator for many years and was technically leading the Team I was interviewing for. I, on the other side, had never touched a Solaris system more than 30 minutes in a row. This was a phone interview, which I was taking in the entrance of my current workplace as all of the meeting rooms were busy. In hindsight, the conversation I keep in mind is the following:

  • Rob: “Can you tell me about disksuite and how to handle disk mirroring in Solaris?”
  • Me: “I don’t really know disksuite in much details. I could only tell about a few commands I’ve learnt so far to handle a Solaris installation.”
  • Rob: “Uhm, OK. Anything you can say about crashdump management?”
  • Me: “Unfortunately not either. What I can tell though, is that I can read manpage pretty efficiently. I have very limited knowledge of Solaris right now, but I learn fast.”
  • Rob: “Heh. What about your favorite beer?”
  • Me: “Ah sure, Chimay Bleue.”
  • Rob: “So that’s a 9/10, Duvel was the answer. You’re in.”

Of course, this was unexpected, but, as I mentioned to him, I was eager and willing to learn. Fast. During the following 2 years, I have been reading anything I could on Solaris, Kernel code, debugging, crash dumps and anything else that would be presented to me. I’ve been sipping knowledge out of Rob as much as I could and eventually went beyond: I started learning about Clusters and ZFS. Ultimately, when Sun Microsystems got acquired by Oracle and decided to close down Sun Solve, — in between other bad decisions — I thought it’d be cool to see what information I could get out of patches archives. This got me to build WeSunSolve over the next 6 months.

This is a long course of action but again, I don’t feel like I would have spent that much good and valuable time on Solaris had I not met Rob. After building WeSunSolve, I’ve been sued by Oracle and ultimately closed the website, but it got me to the next chapter!

In 2012, After I had just closed the aforementioned website, an email landed my Inbox whose subject was: “Solaris contract or job at eFolder”. It was from John. John was the VP of IT at eFolder at that time and offered to chat about potential work I could get done there. His email mentioned that they were a fast growing company that would see no problems into having someone working remotely from Belgium. 3 months later, I was taking a plane for the first ever trip of a series to the US and joined eFolder.

I spent around 5 years working with John as my boss. Over these years, there’s been so many things I’ve learnt on work ethics and integrity from him that it actually drove my career on a path I would never have guessed. As we were getting bigger, I started leading a small but growing team. I did not wanted to be the team leader that every team I was part of in the past had. I started reading about how to become a leader, how to involve remote people into a team, how to build a team dynamic and, eventually, did some trial and error with them as guinea pigs. I started an MBA on the next year having in mind to become a better boss. The journey transformed me and I started learning my style. To this day, I still sometimes think about John and how he was behaving as a boss, so that I can reflect on how I’m myself behaving.

The last two years I spent at eFolder, John left the company and refereed me to be succeeding him. That was yet another stage of personal growth that I was going through: I was suddenly responsible for a 30+ people department in a growing company which had just merged with another one. Everything had to be built up from scratch and this was really intense, but exciting times. The team accomplished so much in about 18 months that I am proud of; We turned around things we thought were impossible to materialize, either meeting or beating deadlines one after another. This chapter closed 6 months ago when I decided to go for the next endeavor and join Voxbone.

Finally, looking back at the last 10+ years of my life, the last encounter I can’t forget to mention is Vanessa. It may sounds cliché, but without her I wouldn’t be me, I wouldn’t be here; In fact, I probably wouldn’t be at all. That one definitely changed my life for the good!

Posted in Uncategorized, wildness' Life | 1 Comment

Solaris m4 broken on latest 11.3 SRU

Today I’ve had to troubleshoot an issue with sendmail where the make in the config directory would create an error message like this:

# make              
test ! -f sendmail.cf || /usr/bin/mv sendmail.cf sendmail.cf.prev
/usr/bin/m4 ../m4/cf.m4 sendmail.mc > sendmail.cf

/usr/bin/m4:sendmail.mc:../domain/solaris-generic.m4:../feature/redirect.m4:20 can't open file
divert(3)
*** Error code 1
make: Fatal error: Command failed for target `sendmail.cf'

Looking further at that m4 command, I can see it is causing the issue:

# m4 ../m4/cf.m4 sendmail.mc > /dev/null

m4:sendmail.mc:../domain/solaris-generic.m4:../feature/redirect.m4:20 can't open file
divert(3)

This was really odd and seems to be related to the current 11.3 SRU I am running:

# pkg info entire|grep Branch
           Branch: 0.175.3.9.0.4.0

On an older host, this is just running file with equals sendmail configs:

# make clean && make
/usr/bin/rm -f sendmail.cf submit.cf core
test ! -f sendmail.cf || /usr/bin/mv sendmail.cf sendmail.cf.prev
/usr/bin/m4 ../m4/cf.m4 sendmail.mc > sendmail.cf
test ! -f submit.cf || /usr/bin/mv submit.cf submit.cf.prev
/usr/bin/m4 ../m4/cf.m4 submit.mc > submit.cf
# pkg info entire|grep Branch
        Branch: 0.175.3.5.0.6.0

Where to look at this? well first I’ve been trussing the `m4` call:

# truss -ff m4 ../m4/cf.m4 sendmail.mc > /var/tmp/m4.truss 2>&1

Looking at the end of the truss output, close to where it echo the “Can’t open file” message, here is what we can see:

4850:   open("../feature/masquerade_entire_domain.m4", O_RDONLY|O_XPG4OPEN) = 4
4850:   fstat64(4, 0xFDB5C950)                          = 0
4850:   fstat64(4, 0xFDB5C860)                          = 0
4850:   ioctl(4, TCGETA, 0xFDB5C900)                    Err#25 ENOTTY
4850:   read(4, " d i v e r t ( - 1 )\n #".., 1024)     = 565
4850:   read(4, 0x088C123C, 1024)                       = 0
4850:   llseek(4, 0, SEEK_CUR)                          = 565
4850:   close(4)                                        = 0
4850:   open("", O_WRONLY|O_CREAT|O_TRUNC|O_XPG4OPEN, 0666) Err#2 ENOENT
4850:   open("/usr/lib/locale/en_US.UTF-8/LC_MESSAGES/SUNW_OST_OSCMD.mo", O_RDONLY|O_XPG4OPEN) Err#2 ENOENT
4850:   fstat64(2, 0xFDB5BA50)                          = 0

m4:4850:        write(2, "\n m 4 :", 4)                         = 4
sendmail.mc4850:        write(2, " s e n d m a i l . m c", 11)          = 11
:22 4850:       write(2, " : 2 2  ", 4)                         = 4
can't open file4850:    write(2, " c a n ' t   o p e n   f".., 15)      = 15

4850:   write(2, "\n", 1)                               = 1
divert4850:     write(2, " d i v e r t", 6)                     = 6
(4850:  write(2, " (", 1)                               = 1
54850:  write(2, " 5", 1)                               = 1
)4850:  write(2, " )", 1)                               = 1

4850:   write(2, "\n", 1)                               = 1
4850:   unlink("")                                      Err#2 ENOENT

What is interesting into that output are the following lines:

4850:   open("", O_WRONLY|O_CREAT|O_TRUNC|O_XPG4OPEN, 0666) Err#2 ENOENT
4850:   unlink("")                                      Err#2 ENOENT

It looks like `m4` is trying to open a file with an empty filename and upon error and exiting the program, it tries to `unlink` it.
To me, this sounds pretty much like what should’ve been a temporary file… Let’s try to apptrace that software now…

# apptrace m4 ../m4/cf.m4 sendmail.mc > /var/tmp/apptrace.out 2>&1=


Again, at the end of that output, let’s try to catch the `fopen` call with the empty filename:

-> m4       -> libc.so.1:FILE * fopen(const char * = 0x8068298 "", const char * = 0x8053464 "w")
<- m4       -> libc.so.1:fopen()
-> m4       -> libc.so.1:char * gettext(const char * = 0x8052e74 "can't open file")

Here it is! Now we can see that the `char *` buffer passed to `fopen` is `0x8068298`. Let’s search for that
address through the whole apptrace output so we can see where it comes from:

# grep 0x8068298 /var/tmp/apptrace.out 
-> m4       -> libc.so.1:char * mktemp(char * = 0x8068298 "/tmp/m4aXXXXX")
<- m4       -> libc.so.1:mktemp() = 0x8068298
-> m4       -> libc.so.1:int creat(const char * = 0x8068298 "", mode_t = 0x0)
-> m4       -> libc.so.1:FILE * fopen(const char * = 0x8068298 "", const char * = 0x8053464 "w")
-> m4       -> libc.so.1:int unlink(const char * = 0x8068298 "")

Huh Hoh! Look at that… exactly what we’ve thought, this should actually be a `/tmp/m4aXXXXX` kind of temporary file, but it seems the `mktemp()` call is returning an empty string.

The `mktemp()` manpage say:

RETURN VALUES
     The mktemp() function returns the  pointer  template.  If  a
     unique  name  cannot  be  created, template points to a null
     string.

     Upon successful completion, mkdtemp()  returns  the  pointer
     template.  If   a  unique   directory   cannot  be  created,
     mkdtemp() returns a null pointer.

ERRORS
     The mkdtemp() function can set errno to the same  values  as
     lstat(2) and mkdir(2).

So, we now know that `m4` is not checking the return value expected for mktemp() and hence, can not detect its call being failling.

What is also interesting, is that `errno` should give us a bit more detail over what’s happening, let’s see how to get that with gdb:

# /usr/bin/gdb m4 ../m4/cf.m4 sendmail.mc 
Excess command line arguments ignored. (sendmail.mc)
GNU gdb (GDB) 7.6
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i386-pc-solaris2.11".
For bug reporting instructions, please see:
...
Reading symbols from /usr/bin/m4...(no debugging symbols found)...done.
/usr/include/sys/../m4/cf.m4: No such file or directory.
(gdb) break mktemp
Breakpoint 1 at 0x805357c
(gdb) run
Starting program: /usr/bin/m4 
[Thread debugging using libthread_db enabled]
[New Thread 1 (LWP 1)]
[Switching to Thread 1 (LWP 1)]

Breakpoint 1, 0x07f90393 in mktemp () from /lib/libc.so.1
(gdb) finish
Run till exit from #0  0x07f90393 in mktemp () from /lib/libc.so.1
0x080539a3 in main ()
(gdb) p errno
$1 = 22
(gdb) bt
#0  0x07f901c0 in libc_mktemps () from /lib/libc.so.1
#1  0x07f903b2 in mktemp () from /lib/libc.so.1
#2  0x080539a3 in main ()
(gdb) ^C
ROOT # grep 22 /usr/include/sys/errno.h
#define EINVAL  22      /* Invalid argument                     */

Here we go, it seems `EINVAL` is triggered from mktemp in `/lib/libc.so.1` which itself call `libc_mktemps`.
So, Solaris is closed source but looking at the old opensolaris code, we might have a pretty good idea about what could go wrong, hopefully, let’s have a look at `mktemp.c` file from opensolaris last public revision available.

The interesting part starts at line 98, we can however not find any reference to `errno = 22` in that code. Would the libc changed? Let’s quickly compare `libc.so.1` checksum on the two systems we have:

On the NOT working system:

3df7fcc46656bf516f792403f638e4c1  /lib/libc.so.1

On the working system:

1c24a7fbeb0badf6a33d7f9d62e8280d  /lib/libc.so.1

Aouch. While this in itself does not mean the mktemp function itself has changed, it is a signal that the libc between the two system is indeed different.

Let’s try to reproduce the call of mktemp() on a small code to see if we can indeed reproduce the issue:

#include 
#include 

int main(void) {
        char template[]="/tmp/m4aXXXXX";
        char *b = mktemp(template);
        printf("mktemp ret: %s\n", b);
}

Let’s compile and run:

# gcc -o mktemp-gcc mktemp.c
# ./mktemp-gcc
mktemp ret: /tmp/m4a6Ltbn

Mmh. this is actually working… what the hell is wrong with `m4` then?

Let’s look at IDA code dump for the `libc_mktemps()` function on the *OLD* system:

char *__cdecl libc_mktemps(char *as, int slen)
{
  if ( as && *as )
  {
    lmutex_lock(&unk_167070);
    v29 = getpid();
    if ( v29 != dword_167064 )
    {
      gettimeofday(&tv, 0);
      if ( ((tv.tv_usec + 0x4000) | 0x43E8u) >> 15 )
        v2 = tv.tv_usec / 1000;
      else
        LOWORD(v2) = SLOWORD(tv.tv_usec) / 1000;
      dword_167068 = (1000 * LOWORD(tv.tv_sec) + (_WORD)v2) & 0xFFF;
      dword_167064 = v29;
      Ddata_data_11 = 6;
    }
    if ( !dword_16706C )
    {
      v3 = sysconf(514);
      dword_16706C = fls(v3);
    }
    v4 = strlen(as);
    if ( slen < v4 && slen >= 0 )
    {
      v5 = v4 - slen;
      v6 = &as[v5 - 1];
      v24 = 0;
      if ( v5 && as[v5 - 1] == 88 )
      {
        do
        {
          v7 = v24++ + 1;
          --v5;
          --v6;
        }
        while ( v5 && v7 < 6 && *v6 == 'X' );
      }
      v23 = (int)(v6 + 1);
      v8 = 6 * v24 - dword_16706C;
      if ( v8 < 0 )
      {
        v15 = &as[v5];
        v28 = v15;
        v26 = Ddata_data_11;
        v16 = 0;
        for ( i = 0; v26 && v28 > as; --v26 )
        {
          --v28;
          v18 = 0;
          v19 = chars;
          while ( *v28 != *v19 )
          {
            ++v19;
            if ( ++v18 >= 64 )
            {
              if ( v18 == 64 )
                goto LABEL_47;
              break;
            }
          }
          i = (v18 + __PAIR__((i << 6) + ((unsigned __int64)(unsigned int)v16 >> 26), v16 << 6)) >> 32;
          v16 = v18 + (v16 << 6);
        }
        v20 = 6 * Ddata_data_11 - dword_16706C;
        if ( v20 >= 32 )
        {
          LOBYTE(v20) = v20 - 32;
          v16 = i;
          i = 0;
        }
        if ( v29 == __PAIR__(
                      (((1 << dword_16706C) - 1) >> 31) & (i >> v20),
                      (unsigned int)(__PAIR__(i, v16) >> v20) & ((1 << dword_16706C) - 1))
          && lstat64(as, &v32) == -1
          && *(_DWORD *)__errno() == 2 )
        {
          lmutex_unlock(&unk_167070);
          return as;
        }
      }
      else
      {
        v25 = dword_167068;
        v22 = 1 << v8;
        if ( dword_167068 >= 1 << v8 )
        {
          dword_167068 = 0;
          v25 = 0;
        }
        v9 = v29;
        if ( v8 >= 32 )
        {
          LOBYTE(v8) = v8 - 32;
          HIDWORD(v9) = v29;
          v29 = 0;
        }
        v27 = __PAIR__(HIDWORD(v9), v29) << v8 >> 32;
        v30 = v29 << v8;
        while ( 1 )
        {
          v10 = (v25 + __PAIR__(v27, v30)) >> 32;
          v11 = v25 + v30;
          v12 = (_BYTE *)v23;
          if ( v24 )
          {
            v13 = 0;
            do
            {
              *v12++ = chars[v11 & 0x3F];
              v11 = __PAIR__(v10, v11) >> 6;
              v10 >>= 6;
              ++v13;
            }
            while ( v13 < v24 );
          }
          if ( lstat64(as, &v32) == -1 )
            break;
          v14 = v25 + 1;
          if ( v25 + 1 == v22 )
            v14 = 0;
          v25 = v14;
          if ( v14 == dword_167068 )
            goto LABEL_47;
        }
        if ( *(_DWORD *)__errno() == 2 )
        {
          dword_167068 = v25 + 1;
          Ddata_data_11 = v24;
          lmutex_unlock(&unk_167070);
          return as;
        }
      }
    }
LABEL_47:
    lmutex_unlock(&unk_167070);
    *as = 0;
  }
  return as;
}

This code pretty much look like the code we can find in the opensolaris’ mktemp.c. let’s now check the *NOT* working system libc’s code:

char *__cdecl libc_mktemps(char *as, int slen)
{
  if ( !as || !*as )
  {
    *(_DWORD *)__errno() = 22;
    return as;
  }
  v2 = strlen(as);
  if ( slen >= v2 || slen < 0 )
  {
    *(_DWORD *)__errno() = 22;
    *as = 0;
    return as;
  }
  v3 = v2 - slen;
  v4 = &as[v3 - 1];
  v17 = 0;
  if ( v3 && as[v3 - 1] == 'X' )
  {
    do
    {
      v5 = v17++ + 1;
      --v3;
      --v4;
    }
    while ( v3 && v5 < 6 && *v4 == 'X' );
  }
  v14 = (int)(v4 + 1);
  if ( v17 != 6 && _xpg6 )
  {
    *(_DWORD *)__errno() = 22;
    *as = 0;
    return as;
  }
  v15 = (1 << 6 * v17) - 1;
  v16 = 0LL;
  if ( 1 << 6 * v17 == 1 )
    goto LABEL_23;
  while ( 1 )
  {
    pthread_setcancelstate(1, &v18);
    if ( v17 < 6 )
    {
      v7 = arc4random_uniform(v15);
      pthread_setcancelstate(v18, 0);
      v8 = 0;
      v9 = (_BYTE *)v14;
      if ( !v17 )
        goto LABEL_19;
    }
    else
    {
      v6 = arc4random_uniform(1 << 6 * (v17 - 1));
      v7 = arc4random_uniform(64) + (v6 << 6);
      pthread_setcancelstate(v18, 0);
      v8 = 0;
      v9 = (_BYTE *)v14;
    }
    v10 = 0;
    do
    {
      *v9++ = chars[v7 & 0x3F];
      v7 = __PAIR__(v10, v7) >> 6;
      v10 >>= 6;
      ++v8;
    }
    while ( v8 < v17 );
LABEL_19:
    if ( lstat64(as, &v19) == -1 )
      break;
    v11 = v16;
    LODWORD(v16) = v16 + 1;
    v12 = __PAIR__(HIDWORD(v16), v11) + 1;
    HIDWORD(v16) = (__PAIR__(HIDWORD(v16), v11) + 1) >> 32;
    if ( HIDWORD(v12) >= (unsigned int)((unsigned int)v12 < (unsigned int)v15) + HIDWORD(v15) )
      goto LABEL_23;
  }
  if ( *(_DWORD *)__errno() != 2 )
  {
LABEL_23:
    if ( v15 == v16 )
      *(_DWORD *)__errno() = 28;
    *as = 0;
  }
  return as;
}

NOTE: I have tried to remove useless part of code to make it more readable, but the complete files can be found there:

Man! this is looking completely different! Indeed, the old libc version doesn’t even have a reference to setting errno to 22, while the new code has a lot. Let’s check what can trigger an errno=22 in that new code:

  if ( !as || !*as )
  {
    *(_DWORD *)__errno() = 22;
    return as;
  }

This one is pretty much if the provided string is NULL or if the string pointed to starts with ‘\0’. Not our case here.

  v2 = strlen(as);
  if ( slen >= v2 || slen < 0 )
  {
    *(_DWORD *)__errno() = 22;
    *as = 0;
    return as;
  }

Then, let’s check if the `as`’s length is over `slen` (which is 0 in every call of libc_mktemps), or if slen is less than 0, which is not our case here.

  v3 = v2 - slen;
  v4 = &as[v3 - 1];
  v17 = 0;
  if ( v3 && as[v3 - 1] == 'X' )
  {
    do
    {
      v5 = v17++ + 1;
      --v3;
      --v4;
    }
    while ( v3 && v5 < 6 && *v4 == 'X' );
  }
  v14 = (int)(v4 + 1);
  if ( v17 != 6 && _xpg6 )
  {
    *(_DWORD *)__errno() = 22;
    *as = 0;
    return as;
  }

This one is more tricky, what the code does (if I got it right!):

  • v3 = strlen(as) – slen(0); // so basically always == strlen(as)
  • v4 == last valid character of `as`
  • if the last character of `as` is ‘X’, then it is counting backwards the amount of trailing ‘X’ present in as.
  • if the number of trailing ‘X’ is not 6, and _xpg6 is set, then errno=22!

Wait a minute, WTF is that `_xpg6` in the first place? We do have less than 6 ‘X’ in the trailing of our string, still we don’t hit that code with out mktemp.c test code.

A google search later, I found this document which gets us to learn about the different standards implemented in the Solaris code. One of them (XPG6), also referenced `SUSv3` is apparently what this flag mean. Let’s try then to compile our test software the way Oracle suggest it for `SUSv3`:

$ /opt/solarisstudio12.4/bin/c99  $(getconf POSIX_V6_LP64_OFF64_CFLAGS) \
             -D_XOPEN_SOURCE=600  $(getconf POSIX_V6_LP64_OFF64_LDFLAGS) mktemp.c -o mktemp  \
                                  $(getconf POSIX_V6_LP64_OFF64_LIBS) 

And then run it on both our working and not working systems:

# ./mktemp
mktemp ret: 
# ./mktemp
mktemp ret: /tmp/m4aAEiQ0

Hurray! so we found the root cause of the issue. It seems after the libc changes made by Oracle, the `m4` program has not been adapted to take into account the standards it is supposed to be compiled against. Let’s open a case and get oracle working on this. Note, the “simple” fix for this would probably be to just add a trailing ‘X’ to that m4.c source code.

Thanks a bunch to ar1s for getting to the bottom of this with me and providing the IDA code dumps 😉

Posted in Solaris | Tagged , , , , , | Leave a comment

OpenVPN: Listen on TCP and UDP with TUN

Today I’ll describe how to get OpenVPN to listen both to UDP and TCP port, using both tun device and the same network for clients. Meaning the same client can connect on either TCP or UDP and get the same IP Address assigned.

To achieve this, we’re gonna need:

  • OpenVPN
  • Sudo

I’m running this on a Debian Wheezy installation, but any Linux distribution can do the trick.

Let’s create the first OpenVPN instance, to listen on UDP/1194, creation of certificate is not covered by this HOWTO, as plenty of resources can already be found online.

port 1194
proto udp
dev tun0
ca /etc/openvpn/MYVPN/keys/ca.crt
cert /etc/openvpn/MYVPN/keys/server.crt
key /etc/openvpn/MYVPN/keys/server.key

dh /etc/openvpn/MYVPN/keys/dh1024.pem

tls-server
server 10.1.2.0 255.255.255.0
ifconfig-pool-persist /etc/openvpn/MYVPN/ipp.txt
client-config-dir /etc/openvpn/MYVPN/ccd
ccd-exclusive

keepalive 10 60
tls-auth /etc/openvpn/MYVPN/keys/ta.key 0
cipher AES-256-CBC   # AES

max-clients 20
user vpn
group vpn

persist-key
persist-tun
ping-timer-rem
status /etc/openvpn/MYVPN/status.log
status-version 2

verb 4
mute 20

script-security 2
learn-address /etc/openvpn/MYVPN/learn-address.sh

Note that, the only difference with a standard VPN configuration, is the following line:


learn-address /etc/openvpn/MYVPN/learn-address.sh

This configuration line will make the script ‘learn-address.sh’ be ran whenever a client’s address is learned or unlearned. This will allow us to modify the kernel’s routing table upon client connection/disconnection and specify which tunnel interface we should use for that particular client.

Let’s now configure the TCP VPN:

port 1194
proto tcp
dev tun1
ca /etc/openvpn/MYVPN/keys/ca.crt
cert /etc/openvpn/MYVPN/keys/server.crt
key /etc/openvpn/MYVPN/keys/server.key

dh /etc/openvpn/MYVPN/keys/dh1024.pem

tls-server
server 10.1.2.0 255.255.255.0
ifconfig-pool-persist /etc/openvpn/MYVPN/ipp-tcp.txt
client-config-dir /etc/openvpn/MYVPN/ccd
ccd-exclusive

keepalive 10 60
tls-auth /etc/openvpn/MYVPN/keys/ta.key 0
cipher AES-256-CBC   # AES

max-clients 20
user vpn
group vpn

persist-key
persist-tun
ping-timer-rem
status /etc/openvpn/MYVPN/status-tcp.log
status-version 2

verb 4
mute 20

script-security 2
learn-address /etc/openvpn/MYVPN/learn-address.sh

Note that we only changed the name of log files, IPP, the tun device name and of course, the protocol.

Now, let’s configure a client’s CCD file like the following:

ifconfig-push 10.1.2.6 10.1.2.5
iroute 10.1.2.6

Allow vpn user to run /sbin/ip through sudo, to be able to make routing table changes within the learn-address.sh script; Let’s create a ‘/etc/sudoers.d/openvpn’ file with the following content:


vpn ALL=(ALL:ALL) NOPASSWD: /sbin/ip

And last but not least, let’s put together the learn-address.sh script which will make all the magic:

#!/bin/bash
#!/bin/bash
##
# learn-address script which allow
# OpenVPN to run on both TCP and UDP
# with the same range of address on both
# protocol.
#
# tgouverneur -- 2014
##

if [ $# -lt 2 ]; then
  exit 0;
fi
action=$1;
addr=$2;

case ${action} in
        add|update)
                echo "[-] ${addr} logged in to ${dev}" >> /etc/openvpn/MYVPN/vpn.log
                /usr/bin/sudo /sbin/ip ro del ${addr}/32
                /usr/bin/sudo /sbin/ip ro add ${addr}/32 dev ${dev};
        ;;
        delete)
                # Found out we'd better do nothing when delete is called.
#               echo "[-] Deleting addr ${addr} -> ${dev}" >> /etc/openvpn/MYVPN/vpn.log
#               /usr/bin/sudo /sbin/ip ro del ${addr}/32
        ;;
        *)
        ;;
esac

exit 0;

As some comments have mentioned, you also need to run these:


# adduser --system --group vpn
# chmod +x learn-address.sh

Now, you can try and make your client connect to the UDP instance, disconnect and connect again to the TCP one. You can tail -f the /tmp/learn.log file in which you can see routing changes if everything is working:


[-] Adding addr 10.1.2.6 -> tun0
[-] Deleting addr 10.1.2.6 ->
[-] Adding addr 10.1.2.6 -> tun1
[-] Deleting addr 10.1.2.6 ->

This was useful to you? Have questions? Thoughts? Don’t hesitate to leave a comment if so.

Posted in GNU/Linux, Networking | Tagged , , , | 16 Comments

Solaris 11: The signature value did not match the expected value.

Since quite sime time now I’ve been unable to upgrade my test system to Solaris 11.1.
The system was running 11.0 SRU 10.4 and for some reason, when I wanted to run ‘pkg update’, I faced this message:

pkg install: A signature in pkg://solaris/system/locale@0.5.11,5.11-0.175.1.0.0.23.1134:20120820T160256Z could not be verified for this reason:
The signature value did not match the expected value. Res: 0
The signature's hash is 235c7674d821032ae3eeda280c7837d1f1f4fdb5

I’ve finally found (1) a solution to upgrade anyway and (2) a way to install the system/locale package, discarding this message.

pkg uninstall system/locale
LC_ALL=C pkg update --accept
reboot

Then, I’ve discovered that pkg signatures can be avoided using a pkg property:

# LC_ALL=C pkg set-property signature-policy ignore
# LC_ALL=C pkg install system/locale

And that’s it! As I’ve never had any answer to this issue anywhere, I’d thought I would share the resolution 😉

Posted in Solaris | Tagged , , | Leave a comment

VirtualBox IPS Package for Solaris 11

Some time ago I had to write a script to convert currently downloadable VirtualBox Package into IPS Packages for Solaris 11. As I found the thing really useful, I decided to setup a repository to provide everyone easy access over these packages.

You can find the different version available here:

http://mdma.igh.cnrs.fr/vbox/en/catalog.shtml?show_all_versions=1&action=Refresh

To install one version, follow these steps:

First, add the publisher:

pkg set-publisher -g 'http://mdma.igh.cnrs.fr/vbox' solaris

Then refresh the publisher cache:

pkg refresh --full

And finally, install the virtualbox version you want:

pkg install virtualbox@4.2.12

You can also install the virtualbox’s additions:

pkg install virtualbox-extpack@4.2.12

If you have any question on that, don’t hesitate to contact me.

Posted in Solaris | Tagged , , , | 2 Comments

IPS Repository

I’ve recently been able to build two IPS repositories for Solaris 11, so I’m now sharing access to these here.

The first repository concern some package that I’m using on a daily basis, so I’m just sharing them:

http://mdma.igh.cnrs.fr/espix/en/catalog.shtml

To add it as part of your Solaris 11, installation, simply type:

pkg set-publisher -P -g http://pkg.espix.net/espix espix

Currently, package listed are:

  • openvpn
  • tuntap driver
  • rssh

I’m planning of releasing much more soon. Puppet and Facter are to come and JRDS is also in my plans.

I’ll make a separate post for the second repository 😉

Posted in Solaris | Tagged , , , | Leave a comment

Solaris Hotplug: Manage your devices!

Solaris Hotplug can be used in various ways, let’s see what we can get out of it!

Enable the daemon

First of all, we should enable the daemon before anything else:

# svcadm enable hotplug

Listing devices

You can list devices in different ways, first you can have the list of devices and their corresponding driver attach:

# hotplug list -d
pci@0,0  npe#0
    pci8086,100  <pci.0,0>  OFFLINE  #0
    pci8086,101@1  <pci.1,0>  ONLINE  pcieb#0
        pci1095,7132@0  <pci.0,0>  ONLINE  si3124#0
            disk@0,0  sd#7
            disk@1,0  sd#8
    pci8086,105@1,1  <pci.1,1>  ONLINE  pcieb#1
        display@0  <pci.0,0>  ONLINE  vgatext#0
        pci10de,be3  <pci.0,1>  OFFLINE  #0
    pci1458,1c3a  <pci.16,0>  OFFLINE  #0
    pci1458,5006@1a  <pci.1a,0>  ONLINE  ehci#0
        hub@1  hubd#0
    pci1458,a102  <pci.1b,0>  OFFLINE  #0
    pci8086,1c10@1c  <pci.1c,0>  ONLINE  pcieb#2
        pci108e,125e@0  <pci.0,0>  ONLINE  e1000g#0
        pci108e,125e@0,1  <pci.0,1>  ONLINE  e1000g#1
    pci8086,1c18@1c,4  <pci.1c,4>  ONLINE  pcieb#3
        pci1458,5007  <pci.0,0>  OFFLINE  #0
    pci8086,1c1a@1c,5  <pci.1c,5>  ONLINE  pcieb#4
        pci1458,e000@0  <pci.0,0>  ONLINE  rge#0
    pci8086,244e@1c,6  <pci.1c,6>  ONLINE  pcieb#5
        pci1283,8892@0  <pci.0,0>  ONLINE  pci_pci#0
            pci1458,1000@3  <pci.3,0>  ONLINE  hci1394#0
    pci1458,5006@1d  <pci.1d,0>  ONLINE  ehci#1
        hub@1  hubd#1
            hub@5  hubd#3
            hub@6  hubd#4
    isa@1f  <pci.1f,0>  ONLINE  isa#0
        fdc  #0
        motherboard  #0
        pit_beep  pit_beep#0
    pci1458,b005@1f,2  <pci.1f,2>  ONLINE  ahci#0
        disk@0,0  sd#0
        disk@1,0  sd#1
        disk@2,0  sd#2
        disk@3,0  sd#3
        disk@4,0  sd#4
        disk@5,0  sd#5
    pci1458,5001  <pci.1f,3>  OFFLINE  #0

On another side, you can see the device attached. I found that really interesting especially for the network cards:

# hotplug list -lv
/pci@0,0
/pci@0,0/pci8086,100    OFFLINE
/pci@0,0/pci8086,101@1    ONLINE
/pci@0,0/pci8086,101@1/pci1095,7132@0    ONLINE
/pci@0,0/pci8086,101@1/pci1095,7132@0/disk@0,0
/pci@0,0/pci8086,101@1/pci1095,7132@0/disk@1,0
/pci@0,0/pci8086,105@1,1    ONLINE
/pci@0,0/pci8086,105@1,1/display@0    ONLINE
/pci@0,0/pci8086,105@1,1/pci10de,be3    OFFLINE
/pci@0,0/pci1458,1c3a    OFFLINE
/pci@0,0/pci1458,5006@1a    ONLINE
/pci@0,0/pci1458,5006@1a/hub@1
/pci@0,0/pci1458,a102    OFFLINE
/pci@0,0/pci8086,1c10@1c    ONLINE
/pci@0,0/pci8086,1c10@1c/pci108e,125e@0    ONLINE
    { Network interface net0 }
    { net0: hosts IP addresses: 10.42.5.12 }
/pci@0,0/pci8086,1c10@1c/pci108e,125e@0,1    ONLINE
    { Network interface net1 }
    { net1: hosts IP addresses: 10.42.3.252 }
/pci@0,0/pci8086,1c18@1c,4    ONLINE
/pci@0,0/pci8086,1c18@1c,4/pci1458,5007    OFFLINE
/pci@0,0/pci8086,1c1a@1c,5    ONLINE
/pci@0,0/pci8086,1c1a@1c,5/pci1458,e000@0    ONLINE
    { Network interface net2 }
    { net2: hosts IP addresses: fe80::1e6f:65ff:fec4:2299, 10.42.2.2 }
/pci@0,0/pci8086,244e@1c,6    ONLINE
/pci@0,0/pci8086,244e@1c,6/pci1283,8892@0    ONLINE
/pci@0,0/pci8086,244e@1c,6/pci1283,8892@0/pci1458,1000@3    ONLINE
/pci@0,0/pci1458,5006@1d    ONLINE
/pci@0,0/pci1458,5006@1d/hub@1
/pci@0,0/pci1458,5006@1d/hub@1/hub@5
/pci@0,0/pci1458,5006@1d/hub@1/hub@6
/pci@0,0/isa@1f    ONLINE
/pci@0,0/isa@1f/fdc
/pci@0,0/isa@1f/motherboard
/pci@0,0/isa@1f/pit_beep
/pci@0,0/pci1458,b005@1f,2    ONLINE
/pci@0,0/pci1458,b005@1f,2/disk@0,0
/pci@0,0/pci1458,b005@1f,2/disk@1,0
/pci@0,0/pci1458,b005@1f,2/disk@2,0
/pci@0,0/pci1458,b005@1f,2/disk@3,0
/pci@0,0/pci1458,b005@1f,2/disk@4,0
/pci@0,0/pci1458,b005@1f,2/disk@5,0
/pci@0,0/pci1458,5001    OFFLINE

Practical use: resetting a PCIEX card

When you have a hardware failure or something that looks like it, it’s sometime good to be able to reset the device prior to replacing the hardware. The easiest way to do that is simply to power-cycle the server. Although, that’s really not convenient when you have to do that on a production machine.

You can then give a try to the following procedure:

Find the device to reset

We want to reset the PCIEX device behind net1:

# hotplug list -lv | ggrep -B6 -A2 net1
/pci@0,0/pci1458,a102    OFFLINE
/pci@0,0/pci8086,1c10@1c    ONLINE
/pci@0,0/pci8086,1c10@1c/pci108e,125e@0    ONLINE
    { Network interface net0 }
    { net0: hosts IP addresses: 10.42.5.12 }
/pci@0,0/pci8086,1c10@1c/pci108e,125e@0,1    ONLINE
    { Network interface net1 }
    { net1: hosts IP addresses: 10.42.3.252 }
/pci@0,0/pci8086,1c18@1c,4    ONLINE
/pci@0,0/pci8086,1c18@1c,4/pci1458,5007    OFFLINE

We can see that the device behind net1 is /pci@0,0/pci8086,1c10@1c/pci108e,125e@0,1, this is a dualport network card and the two ports are in use. As we don’t want to disable the other port, we’ll try first to offline only one port of the card. If that does not suits our needs, we’ll power-cycle the whole card.

Power-Cycle a single port


# hotplug offline /pci@0,0/pci8086,1c10@1c pci.0,1 # second port of the PCIEX card
# hotplug online /pci@0,0/pci8086,1c10@1c pci.0,1

We can find the corresponding messages in the /var/adm/messages file:


Apr 30 21:42:48 [hostname] mac: [ID 736570 kern.info] NOTICE: e1000g1 unregistered
Apr 30 21:42:48 [hostname] genunix: [ID 408114 kern.notice] /pci@0,0/pci8086,1c10@1c/pci108e,125e@0,1 (e1000g1) offline
Apr 30 21:42:33 [hostname] mac: [ID 469746 kern.info] NOTICE: e1000g1 registered
Apr 30 21:42:33 [hostname] genunix: [ID 408114 kern.notice] /pci@0,0/pci8086,1c10@1c/pci108e,125e@0,1 (e1000g1) online

Power-cycle the whole PCIEX card


# hotplug offline /pci@0,0/pci1458,a102 pci.1b,0
# hotplug online /pci@0,0/pci1458,a102 pci.1b,0

Here we are! The card and the two ports have been reset.

Sometimes, I’ve seen some people unloading the drivers to get the device reloaded by the OS: with hotplug, you can get even further by reloading only the particular device you want to.

If that was useful to you, don’t hesitate to tell me so 😉

Posted in Solaris | Tagged , , | 1 Comment

Solaris: Tracing your application

Every Solaris system administrator already know the truss utility, which allow you to trace the system calls as your application is running.

I recently discovered another tool which I found to be really helpful when you want to know what an application is really doing: apptrace.

Apptrace is tracing the _function_ calls instead of the _system_ calls: You can then see which library and function your program is using!

This comes very handy in your daily sysadmin life, when you have to port a software or simply check what function of which library that software is using!

Here is a simple example of this utility against the “hostid” binary:

# apptrace hostid
-> hostid -> libc.so.1:int atexit(int (*)() = 0xeef93ee4)
<- hostid -> libc.so.1:atexit()
-> hostid -> libc.so.1:int atexit(int (*)() = 0x8050bac)
<- hostid -> libc.so.1:atexit()
-> hostid -> libc.so.1:void __fpstart(void)
<- hostid -> libc.so.1:__fpstart() = 0xeebfd484
-> hostid -> libc.so.1:long gethostid(void)
<- hostid -> libc.so.1:gethostid() = 0xcfabcc
-> hostid -> libc.so.1:int printf(const char * = 0x8050bcc "%08lx
", void * = 0xcfabcc, ...)
00cfabcc
<- hostid -> libc.so.1:printf() = 0x9
-> hostid -> libc.so.1:exit(0x0, 0xeec00088, 0xf10c8c04) ** NR

Have you ever wondered “How does that application is getting that system information?”, apptrace is there to help answering.
For the purpose of this post, I was simply wondering how zpool list was using libzfs.so to get the list of existing system pools, here is below the output of “apptrace zpool list”. I’ve removed useless output for clarity:


-> zpool -> libzfs.so.1:libzfs_handle_t * libzfs_init(void)
<- zpool -> libzfs.so.1:libzfs_init() = 0x851b648
-> zpool -> libzfs.so.1:void libzfs_print_on_error(libzfs_handle_t * = 0x851b648, boolean_t = 0x1)
<- zpool -> libzfs.so.1:libzfs_print_on_error() = 0x851b648
...[SNIPPED]...
-> zpool -> libzfs.so.1:int zpool_iter(libzfs_handle_t * = 0x851b648, zpool_iter_f = 0x805d608, void * = 0x8516ec8)
...[SNIPPED]...
-> zpool -> libzfs.so.1:const char * zpool_get_name(zpool_handle_t * = 0x8536e08)
<- zpool -> libzfs.so.1:zpool_get_name() = 0x8536e10
-> zpool -> libzfs.so.1:const char * zpool_get_name(zpool_handle_t * = 0x8536cc8)
<- zpool -> libzfs.so.1:zpool_get_name() = 0x8536cd0
...[SNIPPED]...

We can build the following .c code based on apptrace’s output:

#include <libzfs.h>
#include <stdio.h>
#include <stdlib.h>

extern int zp_iter(zpool_handle_t *, void *);

int main(void) {
  libzfs_handle_t *zh = libzfs_init();
  libzfs_print_on_error(zh, 1);
  zpool_iter(zh, zp_iter, NULL);
  exit(0);
}

int zp_iter(zpool_handle_t *z, void *a) {
  printf("name:\t%s\n", zpool_get_name(z));
  return 0; 
}

Compile and try:


$ gcc zl.c -lzfs -lcryptoutil -m64 -o zl
$ ./zl
name: rpool
name: tank

And voila! If you find other useful usage for apptrace, please leave a comment below 😉

Posted in Solaris | Tagged , , , , | Leave a comment

Analyze System Hangs using SCAT

There are already a lot of Howto’s out there explaining how to use the SCAT tool to analyze some Solaris Crash-dumps;
Although, I will try here to describe how to analyze a HANG of a system instead of a pure Crash.

First of all, when you find a system unresponsive, you must gather a crash-dump to allow further analysis of what happened; To allow crash-dump collection, you must of course have a dump device configured in beforehand and when the crash happen, you must force the system to dump. If you still have access or a connected console, you might use one of the following command to dump:

After the reboot of the system, the vmdump file will get saved into /var/crash, first extract that file:

savecore -f /var/crash/vmdump.3 /var/crash/

Then, fire up SCAT on that crash-dump:

# /opt/SUNWscat/bin/scat unix.3 vmcore.3

Oracle Solaris Crash Analysis Tool
Version 5.3 (SV5415, Jan 31 2012) for Oracle Solaris 11 64-bit x64

Copyright � 1989, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle proprietary - DO NOT RE-DISTRIBUTE!

Feedback regarding the tool should be sent to
SolarisCAT-feedback@opensolaris.org. For support, please use the
Oracle Solaris Performance, Hangs, Panics, and Dtrace community on
http://communities.oracle.com/.

opening unix.3 vmcore.3 ...dumphdr...symtab...core...done
loading core data: modules...symbols...CTF...done

core file: vmcore.3
user: Super-User (root:0)
release: 5.11 (64-bit)
version: 11.1
machine: i86pc
node name: .undisclosed.
system type: i86pc
hostid: .undisclosed.
dump_conflags: 0x10000 (DUMP_KERNEL) on /dev/zvol/dsk/rpool/dump(64G)
boothowto: 0x2000 (VERBOSE)
dump_uuid: .undisclosed.
time of crash: Wed Mar 20 14:02:30 MDT 2013 (core is 32 days old)
age of system: 14 days 23 hours 3 minutes 39.12 seconds
panic CPU: 18 (24 CPUs, 143G memory)
panic string: forced crash dump initiated at user request

sanity checks: settings...vmem...sysent...clock...misc...lookup failed for symbol freemem_wait: symbol not found

WARNING: 252 severe kstat errors (run "kstat xck")
WARNING: kernelbase 0xffff810000000000, expected 0xfffffd8000000000, resetting
done
CAT(vmcore.3/11X)>

You can indeed see there that the crash-dump has been forced at user request.

Now, let’s check the output of analyze command and check what was going on:


CAT(vmcore.3/11X)> analyze

core file: vmcore.3
user: Super-User (root:0)
release: 5.11 (64-bit)
version: 11.1
machine: i86pc
node name: .undisclosed.
system type: i86pc
hostid: .undisclosed.
dump_conflags: 0x10000 (DUMP_KERNEL) on /dev/zvol/dsk/rpool/dump(64G)
boothowto: 0x2000 (VERBOSE)
dump_uuid: .undisclosed.
time of crash: Wed Mar 20 14:02:30 MDT 2013 (core is 32 days old)
age of system: 14 days 23 hours 3 minutes 39.12 seconds
panic CPU: 18 (24 CPUs, 143G memory)
panic string: forced crash dump initiated at user request

==== system appears to have been Stop-A'ed ====

==== reporting thread summary ====

reference clock = panic_lbolt: 0x7b46158, panic_hrtime: 0x497cacd510312
3752 threads ran after current tick (1973 user, 1779 kernel)
3752 threads ran since 1 second before current tick (1973 user, 1779 kernel)
3752 threads ran since 1 minute before current tick (1973 user, 1779 kernel)

3 TS_RUN threads (0 user, 3 kernel)
1 TS_STOPPED threads (0 user, 1 kernel)
216 TS_FREE threads (0 user, 216 kernel)
0 !TS_LOAD (swapped) threads

0 threads trying to get a mutex
5* threads trying to get an rwlock (5 user, 0 kernel)
longest sleeping 0 seconds later
3486 threads waiting for a condition variable (1737 user, 1749 kernel)
0 threads sleeping on a semaphore
0 threads sleeping on a user-level sobj
230 threads sleeping on a shuttle (door) (230 user, 0 kernel)

0 threads in biowait()
1* proc with SIGKILL posted (see "tlist killed")
1* threads with procs with SIGKILL posted (1 user, 0 kernel)
4* threads in zio_wait() (4 user, 0 kernel)

3 threads in dispatch queues (0 user, 3 kernel)
1* threads in dispq of CPU running idle thread (0 user, 1 kernel)

3991 total threads in allthreads list (1973 user, 2018 kernel)
9 thread_reapcnt
7 lwp_reapcnt
4007 nthread

==== found thread waiting for rwlock, reporting owner thread ====

thread pri pctcpu idle PID wchan command
0xffffc102271710e0 59 0.000 -518665257d11h26m28.89s 21016 0xffffc1007a432658 /usr/sbin/zfs snapshot -r .undisclosed.
0xffffc1029a5184c0 59 0.000 -518422609d23h19m44.46s 20381 0xffffc1007a432658 zfs list -H -t filesystem -o name,used,available
0xffffc1024ee31c00 59 0.000 -518441533d15h25m10.24s 20524 0xffffc1007a432658 df -h .
0xffffc1029a6d87e0 59 0.000 -518485332d18h58m29.99s 20776 0xffffc1007a432658 df -h .
0xffffc10236741800 59 0.000 -518615477d18h57m37.74s 20871 0xffffc1007a432658 zfs list -H -t filesystem -o name,used,available

5 threads with that sobj found.

==== there are runnable threads, may have a CPU hog ====

==== reporting stopped threads ====

thread pri pctcpu idle PID wchan command
0xfffffffffc038460 96 0.000 -83391d15h40m14.01s 0 0 sched

From the output here, we can see a lot of useful information:

  • 5 Threads are waiting on a rwlock. We need to check whose command are actually waiting;
  • The thread’s waiting on a rwlock are all filesystem based, which is likely the cause of our hang;

Let’s dig into the rwlock’ed threads and see on what they are waiting:


CAT(vmcore.3/11X)> thread 0xffffc1029a5184c0
==== user (LWP_SYS) thread: 0xffffc1029a5184c0 PID: 20381 ====
cmd: zfs list -H -t filesystem -o name,used,available
fmri: svc:/network/ssh:default
t_wchan: 0xffffc1007a432658 sobj: reader/writer lock owner: 0xfffffffc82695c20
top owner (0xfffffffc82695c20) is waiting for cv 0xfffffffc8269576c

t_procp: 0xffffc101a8bc3118
p_as: 0xffffc10056765028 size: 13086720 RSS: 6676480
hat: 0xffffc100ab5fa948
cpuset:
zone: global
t_stk: 0xfffffffc85af0f10 sp: 0xfffffffc85af07e0 t_stkbase: 0xfffffffc85aec000
t_pri: 59(TS) t_tid: 1 pctcpu: 0.000000
t_lwp: 0xffffc10243526180 lwp_regs: 0xfffffffc85af0f10
mstate: LMS_SLEEP ms_prev: LMS_SYSTEM
lookup failed for symbol nsec_scale: symbol not found
ms_state_start: 14 days 23 hours 6 minutes 37.190669074 seconds earlier
lookup failed for symbol nsec_scale: symbol not found
ms_start: 14 days 23 hours 6 minutes 37.190669074 seconds earlier
psrset: 0 last CPU: 8
idle: -4479171350158446 ticks (518422609 days 23 hours 19 minutes 44.46 seconds)
start: Wed Mar 20 13:49:54 2013
age: 756 seconds (12 minutes 36 seconds)
syscall: #54 ioctl(, 0x0) (sysent: genunix:ioctl+0x0)
tstate: TS_SLEEP - awaiting an event
tflg:tpflg: TP_TWAIT - wait to be freed by lwp_wait
TP_MSACCT - collect micro-state accounting information
tsched: TS_LOAD - thread is in memory
TS_DONT_SWAP - thread/LWP should not be swapped
pflag: SMSACCT - process is keeping micro-state accounting
SMSFORK - child inherits micro-state accounting

pc: unix:_resume_from_idle+0xf5 resume_return: addq $0x8,%rsp

unix:_resume_from_idle+0xf5 resume_return()
unix:swtch+0x13c()
genunix:turnstile_block+0x6ff()
unix:rw_enter_sleep+0x20d()
zfs:dsl_dir_open_spa+0xdd()
zfs:dsl_dataset_hold+0x44()
zfs:dmu_objset_hold+0x2f()
zfs:zfs_ioc_objset_stats+0x30()
zfs:zfsdev_ioctl+0x1f1()
genunix:cdev_ioctl+0x6e()
specfs:spec_ioctl+0x5d()
genunix:fop_ioctl+0xd6()
genunix:ioctl+0x188()
unix:_sys_sysenter_post_swapgs+0x149()
-- switch to user thread's user stack --

We can see here that this thread (cmd: zfs list -H -t filesystem -o name,used,available), is currently waiting over the rwlock 0xffffc1007a432658 which is owned by the thread 0xfffffffc82695c20. This rwlock owner thread is also waiting on a conditional variable 0xfffffffc8269576c.

Let’s check what the owner thread is stuck on:


CAT(vmcore.3/11X)> thread 0xfffffffc82695c20
==== kernel thread: 0xfffffffc82695c20 PID: 0 ====
cmd: sched
t_wchan: 0xfffffffc8269576c sobj: condition var (from zfs:dsl_dataset_drain_refs+0xa6)
t_procp: 0xfffffffffc037440(proc_sched)
p_as: 0xfffffffffc039460(kas)
zone: global
t_stk: 0xfffffffc82695c20 sp: 0xfffffffc826956f0 t_stkbase: 0xfffffffc8268e000
t_pri: 60(SYS) pctcpu: 0.002182
t_lwp: 0x0 psrset: 0 last CPU: 0
idle: -4479141744163556 ticks (518419183 days 8 hours 27 minutes 15.56 seconds)
start: Tue Mar 5 14:03:27 2013
age: 1292343 seconds (14 days 22 hours 59 minutes 3 seconds)
tstate: TS_SLEEP - awaiting an event
tflg: T_TALLOCSTK - thread structure allocated from stk
tpflg: none set
tsched: TS_LOAD - thread is in memory
TS_DONT_SWAP - thread/LWP should not be swapped
pflag: SSYS - system resident process

pc: unix:_resume_from_idle+0xf5 resume_return: addq $0x8,%rsp
startpc: zfs:txg_sync_thread+0x0: pushq %rbp

unix:_resume_from_idle+0xf5 resume_return()
unix:swtch+0x13c()
genunix:cv_wait+0x60()
zfs:dsl_dataset_drain_refs+0xa6()
zfs:dsl_dataset_destroy_sync+0x890()
zfs:dsl_sync_task_group_sync+0xf6()

zfs:dsl_pool_sync+0x20c()
zfs:spa_sync+0x395()
zfs:txg_sync_thread+0x244()
unix:thread_start+0x8()
-- end of kernel thread's stack --

This thread is currently stuck on draining some references from a dataset destroy previously run.
This is most likely where the system is hanging.
We can now check the list of the running process for an on-going destroy:


CAT(vmcore.3/11X)> proc|grep destr
0xffffc100947dd050 20372 20273 0 12943360 6717440 18442588409967410656 0 zfs destroy -r .undisclosed.
CAT(vmcore.3/11X)>

We can now open a support case with that basic analysis and upload the core-dump.
We couldn’t match the actual code with that information, but we can as much as possible direct the Oracle’s support to the actual bug.

As well, sometimes the first level of Oracle support are quickly closing the cases with an unrelated problem: using SCAT to make a first analysis can help you to pin point the actual bug you want to get support for!

For the record, this crash-dump has been analyzed by the support and we dig to the actual bug which is:

15810518 ZFS STUCK BEHIND A "ZFS DESTROY" JOB WAITING IN DSL_DATASET_DR

Posted in Solaris | Tagged , , , , , | 1 Comment