On 26/12/2011, at 4:48 AM, Prashant wrote:
> innobackupex: Error: Failed to stream 'backup-my.cnf': Inappropriate
> ioctl for device at /usr/bin/innobackupex line 341.
>
> The xbm user can login into the mysql@FQHN without password. The
> backup volume is owned by the user xbm.
>
> FYI:
>
> OS: CentOS 5.7 64 bit
> MySQL: 5.1.54 64 bit
> PHP: 5.1.6
> PHP-MySQL: 5.1.6
> xtrabackup: 1.6.4-314.rhel5
>
> What is causing the error and how to resolve it ?
This error that you are seeing says that there was an issue sending the backup via netcat from the MySQL database machine to your XtraBackup Manager server.
From the log information, you can see that XBM is setting up a netcat listener on port 10000 on your backup host and attempting to stream the data over the network through that.
The error "Inappropriate ioctl for device" usually means that the xtrabackup/innobackupex was trying to write to the stream, but something happened where it could not.
This generally means a problem with the netcat stream -- please can you check the following things:
#1. Does the hostname of your XtraBackup Manager resolve via DNS on the database you are trying to backup:
eg. Run "hostname" command on the XtraBackup Manager host -- Then on the database machine, try to execute "ping <output from hostname>" and confirm the ping will resolve the host and ping correctly.
#2. Can you netcat a sample file via port 10000 from the DB system to your XBM host?
On the XtraBackup Manager host try and manually start a netcat listener on port 10000 with:
cd /tmp ; nc -l 10000 > testfile
The above command should seem to hang as it is waiting for a remote connection.
Then, on the Database system you are trying to backup:
echo "1234" > /tmp/testfile
cat /tmp/testfile | nc <xtrabackup-manager-hostname> 10000
This will just create a small testfile and attempt to send it via netcat port 10000.
If this completes correctly you should be able to confirm that /tmp/testfile exists on the XBM machine and contains "1234".
#3. Can you provide output of "nc -h" on both your XBM system and the database you are trying to backup?
#4. Provide output of "ls -la /backup/tds/xbm/blr-
cos-mtarc.digi.com/"
The above should help us figure out why the backup is not able to write to the stream correctly.
If we are still having some issues, I can add some extra logging to the code so we can try to capture any output from the netcat listener on the XBM server, rather than just discard it to /dev/null.
Let me know how you go.
Best Regards,
Lachlan
Please find my answers to your questions
below:============================================================
#1. Does the hostname of your XtraBackup Manager resolve via DNS on
the database you are trying to backup:
Prashant: Yes it does resolve the DNS to IP Address and IP Address to
DNS. xbm $> ping FQHNPING FQHN (a.b.c.d) 56(84) bytes of data.--- FQHN
ping statistics ---20 packets transmitted, 20 received, 0% packet
loss, time 1000msrtt min/avg/max/mdev = 0.228/0.332/0.437/0.106 ms
xbm $> hostnameOutput: FQHN ... exactly the same as the ping output,
host in the xbm's
host-list============================================================
#2. Can you netcat a sample file via port 10000 from the DB system to
your XBM host?
Prashant:xbm $> cd \tmp; Â nc -l 10000 > nctestfileYes the command
results in a socket is waiting for a remote connection. The netstat
output:netstat -tulpn |grep 10000tcp     0    0 0.0.0.0:10000
     0.0.0.0:*          LISTEN    32174/nc
In another shell sessionxbm $> echo "1234" > /tmp/testfilexbm $> cat
/tmp/testfile | nc <xtrabackup-manager-hostname> 10000
The above gets completed sucessfully and the "nctestfile" has the
"1234" entries in it and the netcat socket closes itself after the
successful transmission of the
file============================================================
#3. Can you provide output of "nc -h" on both your XBM system and the
database you are trying to backup?
Prashant:Â xbm $> nc -husage: nc [-46DdhklnrStUuvzC] [-i interval] [-p
source_port]Â Â Â Â Â [-s source_ip_address] [-T ToS] [-w timeout] [-X
proxy_version]Â Â Â Â Â [-x proxy_address[:port]] [hostname] [port[s]]
   Command Summary:        -4        Use IPv4
    -6        Use IPv6        -D        Enable
the debug socket option        -d        Detach from
stdin        -h        This help text        -i
secs     Delay interval for lines sent, ports scanned
 -k        Keep inbound sockets open for multiple connects
     -l        Listen mode, for inbound connects
  -n        Suppress name/port resolutions        -p
port     Specify local port for remote connects        -r
      Randomize remote ports        -s addr
Local source address        -T ToS      Set IP Type of
Service        -C        Send CRLF as line-ending
    -t        Answer TELNET negotiation        -U
     Use UNIX domain socket        -u        UDP
mode        -v        Verbose        -w secs
  Timeout for connects and final net reads        -X proto
   Proxy protocol: "4", "5" (SOCKS) or "connect"        -x
addr[:port]  Specify proxy address and port        -z
  Zero-I/O mode [used for scanning]    Port numbers can be
individual or ranges: lo-hi
[inclusive]============================================================
#4. Provide output of "ls -la /backup/tds/xbm/blr-cos-mtarc.digi.com/"
Prashant: ls -la /backup/tds/xbm/blr-cos-mtarc.digi.com/ producestotal
8drwx--S--- 2 xbm xbm 4096 Dec 29 16:30 .drwxrwsr-x 3 xbm xbm 4096 Dec
26 17:34 ..============================================================--
Thanks & Regards
Prashant N
It seems like there is a need for some better logging to help troubleshoot this, as I have a report of a similar issue in the Issues system on the Google Code project (issue 39)
I am going to work on adding that to the code and will let you know when that is done. I hope to have it ready soon.
Thanks for your patience.
Lachlan
Please do an svn up and ensure you are running revision 202 or higher and then retry running the backup.
There should now be two log files:
<xbm-installdir>/logs/hosts/hostname.log
<xbm-installdir>/logs/hosts/hostname.netcat.log
Could you please sanitise your logs by removing any password information that may be in there and then attach them?
I would like to see what output we're getting in them.
Thanks,
Lachlan
On 29/12/2011, at 4:58 AM, Prashant N wrote:
bsp.backup_strategy_param_id = sbp.backup_strategy_param_id
WHERE
sb.scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getParameters: Query
took 5.3882598876953E-05 ]
2011-12-31 20:38:37 [DEBUG] : [
scheduledBackup->getSnapshotGroupsNewestToOldest: Sending SQL: SELECT
DISTINCT snapshot_group_num FROM backup_snapshots WHERE
scheduled_backup_id=21 AND status='COMPLETED' ORDER BY
snapshot_group_num DESC ]
2011-12-31 20:38:37 [DEBUG] : [
scheduledBackup->getSnapshotGroupsNewestToOldest: Query took
0.0002138614654541 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
6.103515625E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.9843063354492E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
6.7949295043945E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.6982040405273E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.6028366088867E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.6028366088867E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:37 [DEBUG] : [ scheduledBackup->getInfo: Query took
7.2956085205078E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ mysqlTypeGetter->getById: Sending SQL:
SELECT mysql_type_id FROM mysql_types WHERE mysql_type_id=1 ]
2011-12-31 20:38:37 [DEBUG] : [ mysqlTypeGetter->getById: Query took
4.5061111450195E-05 ]
2011-12-31 20:38:37 [DEBUG] : [ mysqlType->getInfo: Sending SQL:
SELECT * FROM mysql_types WHERE mysql_type_id=1 ]
2011-12-31 20:38:37 [DEBUG] : [ mysqlType->getInfo: Query took
4.5061111450195E-05 ]
2011-12-31 20:38:47 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:47 [DEBUG] : [ scheduledBackup->getInfo: Query took
9.2029571533203E-05 ]
2011-12-31 20:38:47 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2011-12-31 20:38:47 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.1021575927734E-05 ]
======================================
Thanks for taking the time to try that out for me -- sadly I can't seem to find anything helpful in there that is giving me a hint on what might be happening.
It seems like either tar does not like the output it is receiving, or the netcat connection itself is getting broken for another reason.
I am installing CentOS 5.7 on a VM to see if I can reproduce.
Thanks for your patience.
Best,
Lachlan
I believe I was able to reproduce the issue you described on a CentOS 5.7 VM and have now committed a fix. Please update to revision 205 and retry to see if you still experience the issue.
It seems like there was an issue where the proc_open() that spawned the netcat listener process was trying to force STDIN to listen to /dev/null and it was causing a problem for netcat in being able to operate as it should.
Let me know how you go!
Thanks,
Lachlan
On 31/12/2011, at 7:17 AM, Prashant N wrote:
KUDO'S. Its' working now.
Thanks for debugging and nailing the issue. I did "svn up" and I am
able to successfully backup the databases hosted in the configured
FQHN.
For the sake of complete testing I added another host and tried to
back it up. I have issues while backing the newly configured host.
More on that in another thread.
--