binlog cache I/O error might be reported twice

Bug #1420303 reported by Laurynas Biveinis on 2015-02-10
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Low
Laurynas Biveinis
5.1
Invalid
Undecided
Unassigned
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
Low
Laurynas Biveinis

Bug Description

By code review:

bool MYSQL_BIN_LOG::write_cache(THD *thd, binlog_cache_data *cache_data)
{
...
  IO_CACHE *cache= &cache_data->cache_log;
...
      if ((write_error= do_write_cache(thd, cache)))
        goto err;
...
      if (cache->error) // Error on read
      {
        char errbuf[MYSYS_STRERROR_SIZE];
        sql_print_error(ER(ER_ERROR_ON_READ), cache->file_name,
                        errno, my_strerror(errbuf, sizeof(errbuf), errno));
        write_error=1; // Don't give more errors
        goto err;
      }
...
err:
  if (!write_error)
    write_error= 1;
  {
    char errbuf[MYSYS_STRERROR_SIZE];
    sql_print_error(ER(ER_ERROR_ON_WRITE), name,
                    errno, my_strerror(errbuf, sizeof(errbuf), errno));
  }
  thd->commit_error= THD::CE_FLUSH_ERROR;

  DBUG_RETURN(1);
}

In the case of cache->error will result in two sql_print_errors. This is a regression from upstream 5.6, introduced in the initial 5.6 merge. The upstream has

err:
  if (!write_error)
  {
    char errbuf[MYSYS_STRERROR_SIZE];
    write_error= 1;
    sql_print_error(ER(ER_ERROR_ON_WRITE), name,
                    errno, my_strerror(errbuf, sizeof(errbuf), errno));
  }
  thd->commit_error= THD::CE_FLUSH_ERROR;

  DBUG_RETURN(1);
}

which will result in a single sql_print_error as intended. I am unable to tell right now whether cache->error (presumably by my_b_fill in do_write_cache) might ever possibly happen in the first place. This bug is about restoring the upstream behavior regardless of this.

Related branches

This is uncovered by

$ ./mysql-test-run --big-test rpl_semi_sync_group_commit_deadlock
...
rpl.rpl_semi_sync_group_commit_deadlock 'stmt' [ fail ] Found warnings/errors in server log file!
        Test ended at 2015-02-10 16:16:44
line
2015-02-10 17:16:05 94862 [ERROR] Error writing file 'master-bin' (errno: 2 - No such file or directory)
.... repeated 2 times: [ERROR] Error writing file 'master-bin' (errno: 2 - No such file or directory)
2015-02-10 17:16:05 94862 [ERROR] Error writing file 'master-bin' (errno: 35 - Resource temporarily unavailable)
.... repeated 1681 times: [ERROR] Error writing file 'master-bin' (errno: 35 - Resource temporarily unavailable)
2015-02-10 17:16:25 94862 [ERROR] Error writing file 'master-bin' (errno: 2 - No such file or directory)
.... repeated 4 times: [ERROR] Error writing file 'master-bin' (errno: 2 - No such file or directory)
2015-02-10 17:16:25 94862 [ERROR] Error writing file 'master-bin' (errno: 35 - Resource temporarily unavailable)
.... repeated 1699 times: [ERROR] Error writing file 'master-bin' (errno: 35 - Resource temporarily unavailable)
^ Found warnings in /Users/laurynas/percona/lp-mysql-server/big-test-fixes/obj-debug/mysql-test/var/log/mysqld.1.err
ok

because the testcase uses error injection simulate_binlog_flush_error hitting the same difference in err: code path between Percona Server and MySQL.

tags: added: ci merge-regression

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2108

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers