MySQL Bugs: #40975: Database restored through named pipes brings up a corrupt database.

Bug #40975	Database restored through named pipes brings up a corrupt database.
Submitted:	24 Nov 2008 12:31	Modified:	8 Apr 2009 0:21
Reporter:	Priyesh Narayanan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S3 (Non-critical)
Version:	6.0.7-alpha-debug	OS:	Any
Assigned to:	Rafal Somla	CPU Architecture:	Any

Description:
Database restored is corrupt when done through a named pipe. Observed this on Linux now, but have observed this on Windows earlier too. The online_backup table shows the operation as complete without any errors.

---

What I tried and got:
1. Backup a database to a regular file on disk:

mysql> backup database world to '/tmp/bak_world';
+-----------+
| backup_id |
+-----------+
| 34        | 
+-----------+
1 row in set, 1 warning (0.37 sec)

2. Create a named pipe with appropriate permissions.
$mkfifo /tmp/bakPipe
$chmod 666 /tmp/bakPipe

3. Restore from the pipe while simultaneously writing to the pipe.
mysql> restore from '/tmp/bakPipe'; 
//the command hangs until something is written to the pipe

In parallel do the following:

$cat /tmp/bak_world > /tmp/bakPipe 
//this writes the backed up data to the pipe.

4. The mysql prompt is returned and the following is seen:

mysql> restore from '/tmp/bakPipe';
+-----------+
| backup_id |
+-----------+
| 35        | 
+-----------+
1 row in set (2 min 25.04 sec)

5. Querying about the backup and restore provides the following information:

mysql> select backup_state, operation, error_num, num_objects, total_bytes from mysql.online_backup where backup_id=34;
+--------------+-----------+-----------+-------------+-------------+
| backup_state | operation | error_num | num_objects | total_bytes |
+--------------+-----------+-----------+-------------+-------------+
| complete     | backup    |         0 |           3 |      445734 | 
+--------------+-----------+-----------+-------------+-------------+
1 row in set (0.00 sec)

mysql> select backup_state, operation, error_num, num_objects, total_bytes from mysql.online_backup where backup_id=35;
+--------------+-----------+-----------+-------------+-------------+
| backup_state | operation | error_num | num_objects | total_bytes |
+--------------+-----------+-----------+-------------+-------------+
| complete     | restore   |         0 |           3 |      957679 | 
+--------------+-----------+-----------+-------------+-------------+
1 row in set (0.00 sec)

Notice that the total_bytes is also much more than original backed up data. When I do a normal restore through a regular file, it shows the exact total_bytes as in backup and the restored database is good. When done through pipes though, the database I get is corrupt.

What is expected:

Restore completing successfully through pipes as well and the online_backup table showing the right values.

How to repeat:
Steps provided in the description.

Repeated with 6.0.7 release:

mysql> backup database world to '/tmp/bak_world';
+-----------+
| backup_id |
+-----------+
| 1         | 
+-----------+
1 row in set (0.05 sec)

mysql> restore from '/tmp/bakPipe'; 
+-----------+
| backup_id |
+-----------+
| 2         | 
+-----------+
1 row in set (2.54 sec)

mysql> select backup_state, operation, error_num, num_objects, total_bytes from
    -> mysql.online_backup where backup_id=1;
+--------------+-----------+-----------+-------------+-------------+
| backup_state | operation | error_num | num_objects | total_bytes |
+--------------+-----------+-----------+-------------+-------------+
| complete     | backup    |         0 |           3 |      445734 | 
+--------------+-----------+-----------+-------------+-------------+
1 row in set (0.00 sec)

mysql> select backup_state, operation, error_num, num_objects, total_bytes from mysql.online_backup where backup_id=2;
+--------------+-----------+-----------+-------------+-------------+
| backup_state | operation | error_num | num_objects | total_bytes |
+--------------+-----------+-----------+-------------+-------------+
| complete     | restore   |         0 |           3 |      957679 | 
+--------------+-----------+-----------+-------------+-------------+
1 row in set (0.00 sec)

mysql> show variables like "%version%";
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| protocol_version        | 10                           | 
| version                 | 6.0.7-alpha                  | 
| version_comment         | MySQL Community Server (GPL) | 
| version_compile_machine | x86_64                       | 
| version_compile_os      | unknown-linux-gnu            | 
+-------------------------+------------------------------+
5 rows in set (0.01 sec)

Thank you for the bug report.

mysql> check table City;
+------------+-------+----------+---------------------------------------------------------------+
| Table      | Op    | Msg_type | Msg_text                                                      |
+------------+-------+----------+---------------------------------------------------------------+
| world.City | check | warning  | Size of indexfile is: 92161      Should be: 43008             | 
| world.City | check | warning  | Size of datafile is: 580496       Should be: 273293           | 
| world.City | check | error    | Found key at page 7168 that points to record outside datafile | 
| world.City | check | error    | Corrupt                                                       | 
+------------+-------+----------+---------------------------------------------------------------+
4 rows in set (0.00 sec)

I can easily repeat on 6.0.7, but not on current development branch. I'll retry with the binaries once 6.0.8 has been released.

Output:
-------
(...)
backup database world to 'wrld.bup';
backup_id
270

restore from '../../mypipe' overwrite;
backup_id
271

select backup_id, backup_state, operation, total_bytes from mysql.backup_history;
backup_id	backup_state	operation	total_bytes
270	complete	backup	445734
271	complete	restore	445734

check table City;
Table	Op	Msg_type	Msg_text
world.City	check	status	OK

I just repeated this bug on development branch.

Bug seems to only appear when the MyISAM driver is used. Repeating the script 10 times for each of InnoDB and Falcon (snapshot driver) and memory (default driver) does not result in corruption. As a comparison, repeating the script for MyISAM results in corruption approximately every second try.

Working hypothesis.

When reading trough a pipe, the backup stream library gets confused and does not detect end of a table data chunk. This is most probably the bstream_rd_part() function in stream_v1_transport.cc which should return BSTREAM_EOC when a complete chunk has been read.

The problem can be seen by inserting code into bstream_rd_data_chunk() function in stream_v1.c at this place:

    /*
      Read bytes until current buffer is full or end of chunk is reached.
     */
    while (ret == BSTREAM_OK && (to_read.end > to_read.begin))
      ret= bstream_read_part(s,&to_read,*envelope);

+   if (to_read.begin > envelope->begin + <biggest data chunk size>)
+     <set breakpoint here> 

Then one can see that the code is trying to read more data that there is in the biggest chunk. The biggest chunk size can be determined using Ingo's mysqlbackup client (WL#4630 - not pushed at the time of writing this).

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63725

2753 Rafal Somla	2009-01-21
      Bug #40975 - Database restored through named pipes brings up a corrupt database. 
      
      The problem was buried deep inside the backup stream library code. Inside 
      bstream_read_part() function (in backup/stream_v1_transpor.c) there is a branch 
      which reads bytes directly from an underlying stream to the provided input 
      buffer (the old code):
      
        else
        {
          /* read directly into data area */
          ASSERT(s->buf.header > s->buf.pos);
      
          howmuch= data->end - data->begin;
          if ((s->buf.pos + howmuch) > s->buf.header)
            howmuch= s->buf.header - s->buf.pos;
      
          saved= *data;
          data->end= data->begin + howmuch;
      
          ret= as_read(&s->stream, data, buf);
          if (ret == BSTREAM_ERROR)
            return SERROR(s);
          if (ret == BSTREAM_EOS)
            s->state= EOS;
      
          s->buf.begin += data->begin - saved.begin;
          s->buf.pos= s->buf.begin;
      
          data->begin= data->end;
          data->end= saved.end;
        }
      
      After determining how much data can be read (howmuch variable) the data blob 
      describes the memory area where the data should be stored. as_read() function 
      reads bytes from the underlying stream to the area described by data and updates 
      data blob to describe the space which was *not* filled with bytes:
      
           |- the original data blob |
           |                         |
        ---[***************[---------]------
           |               |         |
           |- bytes read --|- data --|
              from stream     blob after the operation
      
      In the case depicted above, when not all the available area was filled with 
      bytes from the stream and data blob is non-empty, the assignment 
      
       data->begin= data->end
      
      incorrectly modifies data->begin pointer which in this situation is different 
      from data->end. This causes further confusion in the internal buffering code.
      
      The assignment is completely wrong and serves no purpose here - the patch 
      removes it. This problem was not detected before due to the fact that in the 
      usual situation the whole available area is filled with data from the stream so 
      that after as_read() data->begin == data->end. In this situation the assignment 
      has no effect. However, when reading from a pipe, not always enough bytes is 
      available in the stream to fill the buffer and above situation can happen.
      
      In the test we trigger the errornous situation using error injection code.

Good to push

Approved

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/65571

2762 Rafal Somla	2009-02-09
      Bug #40975 - Database restored through named pipes brings up a corrupt database. 
      
      The problem was buried deep inside the backup stream library code. Inside 
      bstream_read_part() function (in backup/stream_v1_transpor.c) there is a branch 
      which reads bytes directly from an underlying stream to the provided input 
      buffer (the old code):
      
        else
        {
          /* read directly into data area */
          ASSERT(s->buf.header > s->buf.pos);
      
          howmuch= data->end - data->begin;
          if ((s->buf.pos + howmuch) > s->buf.header)
            howmuch= s->buf.header - s->buf.pos;
      
          saved= *data;
          data->end= data->begin + howmuch;
      
          ret= as_read(&s->stream, data, buf);
          if (ret == BSTREAM_ERROR)
            return SERROR(s);
          if (ret == BSTREAM_EOS)
            s->state= EOS;
      
          s->buf.begin += data->begin - saved.begin;
          s->buf.pos= s->buf.begin;
      
          data->begin= data->end;
          data->end= saved.end;
        }
      
      After determining how much data can be read (howmuch variable) the data blob 
      describes the memory area where the data should be stored. as_read() function 
      reads bytes from the underlying stream to the area described by data and updates 
      data blob to describe the space which was *not* filled with bytes:
      
           |- the original data blob |
           |                         |
        ---[***************[---------]------
           |               |         |
           |- bytes read --|- data --|
              from stream     blob after the operation
      
      In the case depicted above, when not all the available area was filled with 
      bytes from the stream and data blob is non-empty, the assignment 
      
       data->begin= data->end
      
      incorrectly modifies data->begin pointer which in this situation is different 
      from data->end. This causes further confusion in the internal buffering code.
      
      The assignment is completely wrong and serves no purpose here - the patch 
      removes it. This problem was not detected before due to the fact that in the 
      usual situation the whole available area is filled with data from the stream so 
      that after as_read() data->begin == data->end. In this situation the assignment 
      has no effect. However, when reading from a pipe, not always enough bytes is 
      available in the stream to fill the buffer and above situation can happen.
      
      In the test we trigger the errornous situation using error injection code.

Pushed to mysql-6.0-backup tree on Feb 9.

Pushed into 6.0.11-alpha (revid:alik@sun.com-20090326121822-pt84kzxxayzho4mn) (version source revid:rafal.somla@sun.com-20090302164601-znhm4tadplfi2iqu) (merge vers: 6.0.11-alpha) (pib:6)

Noted in 6.0.11 changelog.

Using RESTORE to restore a database through a named pipe resulted in
corrupt data.