PURGE BINARY LOGS inherits an automatic purge's refusal through a stale can_purge_log() cache

An interactive PURGE BINARY LOGS is refused because can_purge_log() replays a refusal that an automatic purge recorded, even though an interactive purge is supposed to ignore slave_connections_needed_for_purge since MDEV-34504.

Where

can_purge_log() caches the last refused purge in waiting_for_slave_to_change_binlog / purge_binlog_name and tests that cache in the same condition as is_active() (sql/log.cc), which is above the point where the interactive argument is used:

  if (is_active(log_file_name_arg) ||

      (!is_relay_log && waiting_for_slave_to_change_binlog &&

       purge_sending_new_binlog_file == sending_new_binlog_file &&

       !strcmp(log_file_name_arg, purge_binlog_name)))

  {

    reason= "it is the current active binlog";

    goto error;

  }

The refusal is recorded by a non-interactive call, which passes slave_connections_needed_for_purge to log_in_use(). An interactive call passes 0, but never gets that far: it matches the cache first and is refused.

Net effect on a master with no connected slaves and default settings: once any automatic purge has been refused, a manual PURGE BINARY LOGS naming the same file is refused too, until something increments sending_new_binlog_file.

The refusal also borrows is_active()'s reason string, so the file is reported as the current active binlog when it is not. That part is filed separately.

Steps to reproduce

An mtr test is attached: binlog_purge_stale_refusal_cache.test plus binlog_purge_stale_refusal_cache.opt, for suite/binlog. Please read the caveat at the end of this description before running it.

Manually, on a standalone master with log_bin on, no slave ever connected, and defaults (slave_connections_needed_for_purge=1, binlog_expire_logs_seconds=0, max_binlog_total_size=0, expire_logs_days=0):

Step 1, control. With nothing having attempted a purge yet:

FLUSH BINARY LOGS; FLUSH BINARY LOGS; FLUSH BINARY LOGS;

-- ...-bin.000001..000004 exist, 000004 is active

PURGE BINARY LOGS TO '...-bin.000003';

000001 and 000002 are deleted, no warning is raised. This is MDEV-34504 behaving as intended.

Step 2, let one automatic purge be refused first:

FLUSH BINARY LOGS; FLUSH BINARY LOGS; FLUSH BINARY LOGS;

-- 000003..000007 exist, 000007 is active

SET GLOBAL binlog_expire_logs_seconds=1;

-- wait 2 seconds

FLUSH BINARY LOGS;

-- 000008 is now active

The error log correctly states why the automatic purge was refused:

[Note] Binary log '...-bin.000003' is not purged because less than

'slave_connections_needed_for_purge' slaves have processed it

Step 3, repeat the statement from step 1:

PURGE BINARY LOGS TO '...-bin.000006';

Expected

As in step 1: 000003, 000004 and 000005 deleted, no warning, because an interactive purge passes 0 for slave_connections_needed_for_purge.

Actual

Nothing is deleted, and the client gets:

Note 1375  Binary log '...-bin.000003' is not purged because it is the

           current active binlog

while 000008 is the active binlog.

Isolating the cause

1. SET GLOBAL binlog_expire_logs_seconds=0, then repeat the identical statement: same refusal. So it is not the expiry setting. This variable's ON_UPDATE is copy_to_expire_logs_days, which neither purges nor touches sending_new_binlog_file, so the cached refusal survives.
2. Assign slave_connections_needed_for_purge its own current value (1 to 1), then repeat the identical statement: 000003 to 000005 are purged, no warning.

Point 2 is the diagnostic. The user-visible value does not change. Its ON_UPDATE is update_binlog_space_limit() (sql/sys_vars.cc), which increments sending_new_binlog_file – "Inform can_purge_log() that it should do a recheck of log_in_use()" – falsifying the purge_sending_new_binlog_file == sending_new_binlog_file term and so skipping the short circuit.

Two things worth noting about that hook, because they make the ordering of the two steps above load-bearing rather than incidental:

• It also calls mysql_bin_log.purge(1), and that call is non-interactive: purge(bool all) passes 0 to purge_logs_before_date(). With expiry still armed, that purge is refused in turn and re-populates the cache with the new counter value, so step 2 only works after step 1 has zeroed the expiry.
• max_binlog_total_size and binlog_space_limit share the same ON_UPDATE, so writing either of them releases the block in the same way.

A user-visible consequence of point 2 in its own right: assigning a system variable its existing value changes the outcome of the next PURGE BINARY LOGS.

Suggested direction, not a patch

Consult the cached refusal only when the call is non-interactive: keep is_active() unconditional but move the waiting_for_slave_to_change_binlog test behind !interactive. The cache exists to spare automatic purges a repeated log_in_use() scan; an interactive purge is not on that path and is asking a different question.

Caveat on the attached test

It has not been executed. There is no MariaDB build on the machine this was investigated from – the oracle was an installed 13.0.2 server – so the test is written to the conventions of suite/binlog/t/max_binlog_total_size.test and its assertions are derived from the behavior observed live, not from an mtr run. No .result is supplied on purpose: each stage ends in an explicit -die, so the test carries its own verdict, and on affected versions it fails at the part 2 assertion with "Interactive PURGE BINARY LOGS inherited the automatic purge refusal". Generate the .result with -record once the failure has been seen. If the log numbering or the error-log search pattern needs adjusting, that is an artifact of the test never having been run, not of the bug.

Two notes on the test's design, since they are easy to trip over:

• The .opt sets slave_connections_needed_for_purge=1, the server default. The binlog suite's my.cnf sets it to 0, which hides this bug completely.
• It uses the expire_logs_always DBUG keyword instead of a wall-clock sleep, hence have_debug.inc. On a non-debug build, use binlog_expire_logs_seconds=1 plus --real_sleep 2.

Versions

The cache arrives in 11.4.1 with 18dfcfdecf4 (MDEV-31404). The contradiction only becomes observable in 11.4.3, when dd997809679 (MDEV-34504) made an interactive purge ignore the gate; before that a manual purge was refused by design. Reproduced on 13.0.2-MariaDB-log.

Priority deliberately left at the project default: severity is not mine to rate.