shutdown from within Drizzle panics on assertion - upstart respawn consequences

[Henrik Ingo]

This seems to be specific to running drizzled under upstart, ie modern Ubuntu versions. It happens as installed with the debs that come with Ubuntu and also the basis for our future own deb downloads. I don't know if this is an error in our upstart script, or upstart itself. In particular, should upstart with a respawn directive allow the service to shutdown when it exits without error?

The symptom is that "shutdown" given via the client is ineffective / becomes a restart.

hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
root 19723 0.0 0.0 2040 508 ? Ss 23:33 0:00 /bin/sh -e -c exec /usr/sbin/drizzled --user drizzle 2>&1 | logger -t drizzle -p daemon.err /bin/sh
drizzle 19724 0.6 1.9 395252 39592 ? Sl 23:33 0:00 /usr/sbin/drizzled --user drizzle
root 19725 0.0 0.0 1952 540 ? S 23:33 0:00 logger -t drizzle -p daemon.err
hingo 19749 0.0 0.0 5656 800 pts/0 S+ 23:33 0:00 grep drizzle
hingo@mermaid:~/hacking/drizzle/deb$ drizzle --execute="shutdown"
hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
root 19752 0.0 0.0 2040 512 ? Ss 23:33 0:00 /bin/sh -e -c exec /usr/sbin/drizzled --user drizzle 2>&1 | logger -t drizzle -p daemon.err /bin/sh
drizzle 19753 10.0 1.9 387056 38948 ? Sl 23:33 0:00 /usr/sbin/drizzled --user drizzle
root 19754 0.0 0.0 1952 544 ? S 23:33 0:00 logger -t drizzle -p daemon.err
hingo 19776 0.0 0.0 5656 796 pts/0 S+ 23:33 0:00 grep drizzle
hingo@mermaid:~/hacking/drizzle/deb$ sudo service drizzle stop
drizzle stop/waiting
hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
hingo 19836 0.0 0.0 5656 800 pts/0 S+ 23:40 0:00 grep drizzle
hingo@mermaid:~/hacking/drizzle/deb$

The standard way "service drizzle stop" works.

[Clint Byrum (clint-fewbar)]

Excerpts from Henrik Ingo's message of Sun Jan 22 21:43:11 UTC 2012:
> Public bug reported:
>
> This seems to be specific to running drizzled under upstart, ie modern
> Ubuntu versions. It happens as installed with the debs that come with
> Ubuntu and also the basis for our future own deb downloads. I don't know
> if this is an error in our upstart script, or upstart itself. In
> particular, should upstart with a respawn directive allow the service to
> shutdown when it exits without error?
>
> The symptom is that "shutdown" given via the client is ineffective /
> becomes a restart.
>
>
> hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
> root 19723 0.0 0.0 2040 508 ? Ss 23:33 0:00 /bin/sh -e -c exec /usr/sbin/drizzled --user drizzle 2>&1 | logger -t drizzle -p daemon.err /bin/sh
> drizzle 19724 0.6 1.9 395252 39592 ? Sl 23:33 0:00 /usr/sbin/drizzled --user drizzle
> root 19725 0.0 0.0 1952 540 ? S 23:33 0:00 logger -t drizzle -p daemon.err
> hingo 19749 0.0 0.0 5656 800 pts/0 S+ 23:33 0:00 grep drizzle
> hingo@mermaid:~/hacking/drizzle/deb$ drizzle --execute="shutdown"
> hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
> root 19752 0.0 0.0 2040 512 ? Ss 23:33 0:00 /bin/sh -e -c exec /usr/sbin/drizzled --user drizzle 2>&1 | logger -t drizzle -p daemon.err /bin/sh
> drizzle 19753 10.0 1.9 387056 38948 ? Sl 23:33 0:00 /usr/sbin/drizzled --user drizzle
> root 19754 0.0 0.0 1952 544 ? S 23:33 0:00 logger -t drizzle -p daemon.err
> hingo 19776 0.0 0.0 5656 796 pts/0 S+ 23:33 0:00 grep drizzle
> hingo@mermaid:~/hacking/drizzle/deb$ sudo service drizzle stop
> drizzle stop/waiting
> hingo@mermaid:~/hacking/drizzle/deb$ ps aux|grep drizzle
> hingo 19836 0.0 0.0 5656 800 pts/0 S+ 23:40 0:00 grep drizzle
> hingo@mermaid:~/hacking/drizzle/deb$
>

Hi Henrik, this makes sense.

We need to define 0 as a normal exit code for drizzle.

man 5 init states that using respawn on a job will cause upstart to respawn
the process unless you change the "goal" of the job to 'stop'. However, you
can also define a normal exit code that will allow the job to transition to
stop.

From man 5 init:

respawn
      A service or task with this stanza will be automatically started
      if it should stop abnormally. All reasons for a service stopping,
      except the stop(8) command itself, are considered abnormal.
      Tasks may exit with a zero exit status to prevent being respawned.

respawn limit COUNT INTERVAL
      Respawning is subject to a limit, if the job is respawned more
      than COUNT times in INTERVAL seconds, it will be considered to be
      hav‐ ing deeper problems and will be stopped. Default COUNT is
      10. Default INTERVAL is 5 seconds.

      This only applies to automatic respawns and not the restart(8)
      command.

normal exit STATUS|SIGNAL...
      Additional exit statuses or even signals may be added, if the
      job process terminates with any of these it will not be considered
      to have failed and will not be respawned.

      normal exit 0 1 TERM HUP

[Clint Byrum (clint-fewbar)]

This needs to be fixed in the upstart job, which is part of the packaging not drizzle itself.

[Henrik Ingo (hingo)]

Ok, I see why it respawns: it doesn't actually exit cleanly. This is what it looks like when you do shutdown from inside drizzled...

hingo@mermaid:~/hacking/drizzle/deb$ sudo /usr/sbin/drizzled --user=drizzle
InnoDB: The log sequence number in ibdata files does not match the log sequence number in the ib_logfiles!
120123 19:46:08 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
drizzled: /usr/include/boost/smart_ptr/shared_ptr.hpp:418: T* boost::shared_ptr<T>::operator->() const [with T = const std::basic_string<char>]: Assertion `px != 0' failed.
120123 19:46:19 - drizzled got signal 6;
This could be because you hit a bug. It is also possible that this binary
 or one of the libraries it was linked against is corrupt, improperly built,
 or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

read_buffer_size=131072
max_used_connections=1
connection_count=1
It is possible that drizzled could use up to
(read_buffer_size + sort_buffer_size)*thread_count
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

call_backtrace() began at drizzled/signal_handler.cc:156 for drizzled_handle_segfault()
Number of stack frames obtained: 19
/usr/sbin/drizzled() [0x81a6fea]
[0x5a1400]
[0x5a1416]
gsignal()
abort()
__assert_fail()
()
()
__gnu_cxx::__normal_iterator<drizzled::plugin::Logging**, std::vector<drizzled::plugin::Logging*, std::allocator<drizzled::plugin::Logging*> > > std::__find_if<__gnu_cxx::__normal_iterator<drizzled::plugin::Logging**, std::vector<drizzled::plugin::Logging*, std::allocator<drizzled::plugin::Logging*> > >, drizzled::PostIterate>(__gnu_cxx::__normal_iterator<drizzled::plugin::Logging**, std::vector<drizzled::plugin::Logging*, std::allocator<drizzled::plugin::Logging*> > >, __gnu_cxx::__normal_iterator<drizzled::plugin::Logging**, std::vector<drizzled::plugin::Logging*, std::allocator<drizzled::plugin::Logging*> > >, drizzled::PostIterate, std::random_access_iterator_tag)
drizzled::plugin::Logging::postDo(drizzled::Session*)
/usr/sbin/drizzled() [0x81c2b87]
drizzled::Session::executeStatement()
drizzled::Session::run()
()
()
thread_proxy()
()
clone()
[1]- Killed sudo /usr/sbin/drizzled --user=drizzle
[2]+ Killed sudo /usr/sbin/drizzled --user=drizzle
hingo@mermaid:~/hacking/drizzle/deb$

It could of course be something related to my own build. Have to continue investigation...

[Henrik Ingo (hingo)]

So this was built from the 2012.01.30 release sources, using updated debian packaging scripts.
TODO:
 - verify that it also happens with plain "make install"
 - (kind of unrelated) I'll upload the deb packaging stuff shortly. (Is it called source deb?)

[Henrik Ingo (hingo)]

It seems when I just build from source and do make install, it works fine:

hingo@mermaid:~/hacking/drizzle/builds/2012.01.30-src$ sbin/drizzled
InnoDB: The log sequence number in ibdata files does not match the log sequence number in the ib_logfiles!
120124 9:58:10 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
"/tmp/mysql.socket" exists already. Do you have another Drizzle or MySQL running? Or perhaps the file is stale and should be removed?
120124 10:01:11 InnoDB: Starting shutdown...
hingo@mermaid:~/hacking/drizzle/builds/2012.01.30-src$

So it only happens with debs and/or in relation to upstart. Clint, did you actually reproduce this yet? Or is it purely an issue with my build?