holland-discuss team mailing list archive

[Robert Navarro <rnavarro@xxxxxxxxxxxxxx>]

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