binlog cache I/O error might be reported twice

Bug #1420303 reported by Laurynas Biveinis
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

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.