holland-discuss team mailing list archive

[Andrew Garner <muzazzi@xxxxxxxxx>]

This " [sh] <defunct>" process is the 'mysql' process forked by the
innobackupex perl script. The perl script slightly lies here when it
says "innobackupex:
Connection to database server closed" - certainly the connection is closed,
but the forked shell is never reaped, so that will stay defunct/zombie
until xtrabackup starts actively using the mysql connection towards the end
of the backup.

If your zombie killing script is terminating innobackupex with a normal
signal, this will just terminate the perl script and xtrabackup will
certainly continue to run.  You probably want to avoid killing anything the
xtrabackup process chain, but if you do you probably want to send a signal
to the entire process group rather than just the innobackupex script.

~Andrew






On Tue, Mar 19, 2013 at 8:47 PM, Robert Navarro <rnavarro@xxxxxxxxxxxxxx>wrote:

> So it looks like the actual innobackupex dies, but the
> underlying xtrabackup_55 process is still running. Here's the process
> output right after I start the backup (pre failure)
>
> 0:00 SCREEN -S holland
> 0:00  \_ /bin/bash
> 0:00      \_ /usr/bin/python /usr/sbin/holland bk
> 0:00          \_ perl /usr/bin/innobackupex
> --defaults-file=/var/backups/default/20130319_183505/my.cnf --stream=tar
> --tmpdir=/var/backups/default/20130319_183505 --slave-info --no-timestamp
> /var/backups/default/20130319_183505
> 0:00              \_ [sh] <defunct>
> 0:00              \_ sh -c xtrabackup_55
>  --defaults-file="/var/backups/default/20130319_183505/my.cnf"
>  --defaults-group="mysqld" --backup --suspend-at-end
> --target-dir=/var/backups/default/20130319_183505 --stream=tar
> 0:23                  \_ xtrabackup_55
> --defaults-file=/var/backups/default/20130319_183505/my.cnf
> --defaults-group=mysqld --backup --suspend-at-end
> --target-dir=/var/backups/default/20130319_183505 --stream=tar
>
> Here's the output post-failure:
>
> 0:00 SCREEN -S holland
> 0:00  \_ /bin/bash
> 0:00 sh -c xtrabackup_55
>  --defaults-file="/var/backups/default/20130319_183505/my.cnf"
>  --defaults-group="mysqld" --backup --suspend-at-end
> --target-dir=/var/backups/default/20130319_183505 --stream=tar
> 1:01  \_ xtrabackup_55
> --defaults-file=/var/backups/default/20130319_183505/my.cnf
> --defaults-group=mysqld --backup --suspend-at-end
> --target-dir=/var/backups/default/20130319_183505 --stream=tar
>
> Sorry for the bad formatting, might want to paste this into an editor that
> doesn't line wrap.
>
> Here's a pastebin if you prefer that
> http://pastebin.ca/2336238
>
> Another interesting note, it looks like an orphaned shell prompt is opened
> up. I have some scripts that run on our boxes to kill zombie processes so I
> wonder if when I kill this zombie it shuts everything down. Is there a
> reason this zombie process window is opened?
>
> On Tue, Mar 19, 2013 at 5:37 PM, Andrew Garner <muzazzi@xxxxxxxxx> wrote:
>
>> Hmm.  This looks like innobackupex was terminated with a SIGKILL for some
>> reason, since the exit status is -9.  Of course any negative exit status
>> will be due to a signal.
>>
>> You are saying that if you disable auto-purge-failures that the behavior
>> is changing, and innobackupex is actually running in the background even
>> though holland seems to have failed?
>>
>> ~Andrew
>>
>>
>>
>>
>> On Tue, Mar 19, 2013 at 7:15 PM, Robert Navarro <rnavarro@xxxxxxxxxxxxxx>wrote:
>>
>>> Hello,
>>>
>>> I'm trying to run Holland with the xtrabackup plugin bug I keep running
>>> into an error.
>>>
>>> By default holland just spits out an error and everything dies.
>>>
>>> However, if I set auto-purge-failures = no, holland spits out and error
>>> and it dies, however the underlying innobackupex process continues to run
>>> backing up the database as intended.
>>>
>>> Here is my backup configuration:
>>>
>>> [holland:backup]
>>> plugin = xtrabackup
>>> backups-to-keep = 7
>>> purge-policy = after-backup
>>> estimated-size-factor = 1.0
>>>
>>> [xtrabackup]
>>> innobackupex = innobackupex
>>> slave-info = yes
>>> apply-logs = yes
>>> global-defaults = /etc/mysql/my.cnf
>>>
>>> [compression]
>>> method             = gzip-rsyncable
>>> inline             = yes
>>>  level              = 1
>>>
>>> [mysql:client]
>>> defaults-extra-file       = /root/.my.cnf
>>>
>>> Here is the log from the backup:
>>>
>>> 2013-03-19 16:57:37,816 [INFO] Holland 1.0.8 started with pid 3644
>>> 2013-03-19 16:57:37,825 [INFO] --- Starting backup run ---
>>> 2013-03-19 16:57:37,829 [INFO] Creating backup path
>>> /var/backups/default/20130319_165737
>>> 2013-03-19 16:57:37,839 [INFO] * Generating mysql option file:
>>> /var/backups/default/20130319_165737/my.cnf
>>> 2013-03-19 16:57:37,839 [INFO]   + Added !include /etc/mysql/my.cnf
>>> 2013-03-19 16:57:37,839 [INFO]   + Added !include /root/.my.cnf
>>> 2013-03-19 16:57:37,865 [INFO] Estimated Backup Size: 143.73GB
>>> 2013-03-19 16:57:37,866 [INFO] Starting backup[default/20130319_165737]
>>> via plugin xtrabackup
>>> 2013-03-19 16:57:37,866 [INFO] Executing: /usr/bin/innobackupex
>>> --defaults-file=/var/backups/default/20130319_165737/my.cnf --stream=tar
>>> --tmpdir=/var/backups/default/20130319_165737 --slave-info --no-timestamp
>>> /var/backups/default/20130319_165737
>>> 2013-03-19 16:57:37,867 [INFO]   > /dev/null 2 >
>>> /var/backups/default/20130319_165737/xtrabackup.log
>>> 2013-03-19 17:00:01,850 [INFO] !! innobackupex exited with failure
>>> status [-9]
>>> 2013-03-19 17:00:01,852 [ERROR]     !
>>> 2013-03-19 17:00:01,852 [ERROR]     ! InnoDB Backup Utility
>>> v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
>>> 2013-03-19 17:00:01,852 [ERROR]     ! and Percona Ireland Ltd 2009-2012.
>>>  All Rights Reserved.
>>> 2013-03-19 17:00:01,852 [ERROR]     !
>>> 2013-03-19 17:00:01,852 [ERROR]     ! This software is published under
>>> 2013-03-19 17:00:01,853 [ERROR]     ! the GNU GENERAL PUBLIC LICENSE
>>> Version 2, June 1991.
>>> 2013-03-19 17:00:01,853 [ERROR]     !
>>> 2013-03-19 17:00:01,853 [ERROR]     ! 130319 16:57:38  innobackupex:
>>> Starting mysql with options:
>>>  --defaults-file='/var/backups/default/20130319_165737/my.cnf' --unbuffered
>>> --
>>> 2013-03-19 17:00:01,853 [ERROR]     ! 130319 16:57:38  innobackupex:
>>> Connected to database with mysql child process (pid=3647)
>>> 2013-03-19 17:00:01,853 [ERROR]     ! 130319 16:57:44  innobackupex:
>>> Connection to database server closed
>>> 2013-03-19 17:00:01,854 [ERROR]     ! IMPORTANT: Please check that the
>>> backup run completes successfully.
>>> 2013-03-19 17:00:01,854 [ERROR]     !            At the end of a
>>> successful backup run innobackupex
>>> 2013-03-19 17:00:01,854 [ERROR]     !            prints "completed OK!".
>>> 2013-03-19 17:00:01,854 [ERROR]     !
>>> 2013-03-19 17:00:01,854 [ERROR]     ! innobackupex: Using mysql  Ver
>>> 14.14 Distrib 5.5.30, for Linux (x86_64) using readline 5.1
>>> 2013-03-19 17:00:01,854 [ERROR]     ! innobackupex: Using mysql server
>>> version Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights
>>> reserved.
>>> 2013-03-19 17:00:01,854 [ERROR]     !
>>> 2013-03-19 17:00:01,855 [ERROR]     ! innobackupex: Created backup
>>> directory /var/backups/default/20130319_165737
>>> 2013-03-19 17:00:01,855 [ERROR]     ! 130319 16:57:44  innobackupex:
>>> Starting mysql with options:
>>>  --defaults-file='/var/backups/default/20130319_165737/my.cnf' --unbuffered
>>> --
>>> 2013-03-19 17:00:01,855 [ERROR]     ! 130319 16:57:44  innobackupex:
>>> Connected to database with mysql child process (pid=3682)
>>> 2013-03-19 17:00:01,855 [ERROR]     ! 130319 16:57:46  innobackupex:
>>> Connection to database server closed
>>> 2013-03-19 17:00:01,855 [ERROR]     !
>>> 2013-03-19 17:00:01,855 [ERROR]     ! 130319 16:57:46  innobackupex:
>>> Starting ibbackup with command: xtrabackup_55
>>>  --defaults-file="/var/backups/default/20130319_165737/my.cnf"
>>>  --defaults-group="mysqld" --backup --suspend-at-end
>>> --target-dir=/var/backups/default/20130319_165737 --stream=tar
>>> 2013-03-19 17:00:01,856 [ERROR]     ! innobackupex: Waiting for ibbackup
>>> (pid=3689) to suspend
>>> 2013-03-19 17:00:01,856 [ERROR]     ! innobackupex: Suspend file
>>> '/var/backups/default/20130319_165737/xtrabackup_suspended'
>>> 2013-03-19 17:00:01,856 [ERROR]     !
>>> 2013-03-19 17:00:01,856 [ERROR]     ! xtrabackup_55 version 2.0.5 for
>>> Percona Server 5.5.16 Linux (x86_64) (revision id: undefined)
>>> 2013-03-19 17:00:01,856 [ERROR]     ! xtrabackup: uses posix_fadvise().
>>> 2013-03-19 17:00:01,856 [ERROR]     ! xtrabackup: cd to /var/lib/mysql
>>> 2013-03-19 17:00:01,856 [ERROR]     ! xtrabackup: Target instance is
>>> assumed as followings.
>>> 2013-03-19 17:00:01,857 [ERROR]     ! xtrabackup:   innodb_data_home_dir
>>> = ./
>>> 2013-03-19 17:00:01,857 [ERROR]     ! xtrabackup:
>>> innodb_data_file_path = ibdata1:10M:autoextend
>>> 2013-03-19 17:00:01,857 [ERROR]     ! xtrabackup:
>>> innodb_log_group_home_dir = ./
>>> 2013-03-19 17:00:01,857 [ERROR]     ! xtrabackup:
>>> innodb_log_files_in_group = 2
>>> 2013-03-19 17:00:01,857 [ERROR]     ! xtrabackup:   innodb_log_file_size
>>> = 268435456
>>> 2013-03-19 17:00:01,858 [ERROR]     ! xtrabackup: using O_DIRECT
>>> 2013-03-19 17:00:01,858 [ERROR]     ! 130319 16:57:46  InnoDB: Warning:
>>> allocated tablespace 10, old maximum was 9
>>> 2013-03-19 17:00:01,858 [ERROR]     ! >> log scanned up to
>>> (1405741884514)
>>> 2013-03-19 17:00:01,858 [ERROR]     ! [01] Streaming ./ibdata1
>>> 2013-03-19 17:00:01,858 [ERROR]     ! >> log scanned up to
>>> (1405741971676)
>>> 2013-03-19 17:00:01,858 [ERROR]     ! >> log scanned up to
>>> (1405742071652)
>>> 2013-03-19 17:00:01,858 [ERROR]     ! >> log scanned up to
>>> (1405742142798)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405742353893)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405742916821)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405743051035)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405743370487)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405743548944)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405743698799)
>>> 2013-03-19 17:00:01,859 [ERROR]     ! >> log scanned up to
>>> (1405743882676)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405743954700)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744054154)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744145553)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744217159)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744288130)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744379874)
>>> 2013-03-19 17:00:01,860 [ERROR]     ! >> log scanned up to
>>> (1405744576745)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405744644134)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405744746000)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405744821309)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405744916951)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405745030577)
>>> 2013-03-19 17:00:01,861 [ERROR]     ! >> log scanned up to
>>> (1405745142619)
>>> 2013-03-19 17:00:01,862 [ERROR]     ! >> log scanned up to
>>> (1405745223352)
>>> 2013-03-19 17:00:01,862 [ERROR]     ! [01]        ...done
>>> 2013-03-19 17:00:01,862 [ERROR]     ! [01] Streaming
>>> ./<dbname>/gearman_queue.ibd
>>> 2013-03-19 17:00:01,862 [ERROR]     ! [01]        ...done
>>> 2013-03-19 17:00:01,862 [ERROR]     ! [01] Streaming
>>> ./<dbname>/map_contact.ibd
>>> 2013-03-19 17:00:01,862 [ERROR]     ! >> log scanned up to
>>> (1405745324018)
>>> 2013-03-19 17:00:01,863 [ERROR]     ! >> log scanned up to
>>> (1405745446764)
>>> 2013-03-19 17:00:01,863 [ERROR]     ! [01]        ...done
>>> 2013-03-19 17:00:01,863 [ERROR]     ! [01] Streaming
>>> ./<dbname>/profile_log.ibd
>>> 2013-03-19 17:00:01,863 [ERROR] Backup failed after 2 minutes, 24.02
>>> seconds
>>> 2013-03-19 17:00:01,864 [INFO] auto-purge-failures not enabled. Failed
>>> backup not purged.
>>> 2013-03-19 17:00:01,864 [ERROR] Backup failed: innobackupex exited with
>>> failure status [-9]
>>> 2013-03-19 17:00:01,864 [INFO] Released lock
>>> /etc/holland/backupsets/default.conf
>>> 2013-03-19 17:00:01,864 [INFO] --- Ending backup run ---
>>>
>>> Any help with this would be most appreciated!
>>>
>>> Also, let me know if you need any additional information to debug.
>>>
>>> --
>>> Robert Navarro
>>> Lead Backend Developer
>>> rnavarro@xxxxxxxxxxxxxx
>>> www.stitchlabs.com
>>> <http://www.stitchlabs.com/>San Francisco, CA
>>>
>>> _______________________________________________
>>> Mailing list: https://launchpad.net/~holland-discuss
>>> Post to     : holland-discuss@xxxxxxxxxxxxxxxxxxx
>>> Unsubscribe : https://launchpad.net/~holland-discuss
>>> More help   : https://help.launchpad.net/ListHelp
>>>
>>>
>>
>
>
> --
> Robert Navarro
> Lead Backend Developer
> rnavarro@xxxxxxxxxxxxxx
> www.stitchlabs.com
>  <http://www.stitchlabs.com/>San Francisco, CA
>