firebird-qa/tests/bugs/core_5222_test.py

#coding:utf-8

"""
ID:          issue-5502
ISSUE:       5502
TITLE:       SELECT WITH LOCK may raise unexpected update conflict errors under concurrent load
DESCRIPTION:
  Prototype: https://groups.yahoo.com/neo/groups/firebird-support/conversations/messages/128920
  Done with suggestions from dimitr, see letter 01-may-2016 09:15.
  Confirmed on WI-V3.0.0.32366, WI-V3.0.0.32483, 3.0.0.32501 (SS,SC,CS) - it was enough to
  async. start THREE child ISQLs sessions, one or two of them always raise exception after
  few seconds with text: 'deadlock / update conflicts' and could not finish its job.
NOTES:
[12.08.2018]
  It is unclear now how this test can be implemented on 4.0 after introduction of READ CONSISTENCY
  with default value ReadConsistency = 1. According to doc:
  ===
    If ReadConsistency set to 1 (by default) engine ignores
    [NO] RECORD VERSION flags and makes all read-committed
    transactions READ COMMITTED READ CONSISTENCY.
  ===

  Also, doc\\README.read_consistency.md  says that:
  "Old read-committed isolation modes (**RECORD VERSION** and **NO RECORD VERSION**) are still
  allowed but considered as legacy and not recommended to use."

  This mean that one can NOT to check issues of this ticket under 4.0 using default (and recommended)
  value of config parameter 'ReadConsistency'.
  For that reason it was decided to make new EMPTY section of test for 4.0.
JIRA:        CORE-5222
FBTEST:      bugs.core_5222
"""

from __future__ import annotations
from typing import List
import pytest
import subprocess
import time
import re
from pathlib import Path
from firebird.qa import *

# version: 3.0

init_script = """
    create or alter procedure p_increment as begin end;
    commit;
    recreate table gen_tab(
        id bigint primary key
    );
    recreate table gen_log (
        id bigint primary key,
        id_new bigint not null,
        id_diff bigint not null
    );

    set term ^;
    alter procedure p_increment (a_iter_cnt int default 1000)
    returns (
        proc_start timestamp,
        selected_id bigint,
        proc_finish timestamp
    ) as
        declare i bigint;
        declare id_new bigint;
    begin
        i = 1;
        proc_start = 'now';
        while (i <= a_iter_cnt ) do
        begin
            in autonomous transaction do
            begin

                select id
                from gen_tab with lock -- this raised SQLSTATE = 40001 / -update conflicts with concurrent update
                into selected_id;
                i = i + 1;

                id_new = selected_id + 1;
                insert into gen_log(id, id_new, id_diff)
                            values( :selected_id, :id_new, :id_new - :selected_id);

                update gen_tab set id = :id_new
                where id = :selected_id;

            end
        end
        proc_finish = 'now';

        suspend; -- outputs row with three fields: 'PROC_START <timestamp>', 'SELECTED_ID <id>', 'PROC_FINISH <timestamp>'
    end ^
    set term ;^
    commit;

    insert into gen_tab (id) values (0);
    commit;
"""

db = db_factory(init=init_script)

act = python_act('db')

test_script = """
    commit;
    set list on;
    set transaction read committed no record_version lock timeout 3;
    select current_timestamp as before_proc
    from rdb$database;

    select * from p_increment(10);

    select current_timestamp as after_proc
    from rdb$database;
"""

expected_stdout = """
    EXPECTED, LOG #0: BEFORE_PROC
    EXPECTED, LOG #0: PROC_START
    EXPECTED, LOG #0: SELECTED_ID
    EXPECTED, LOG #0: PROC_FINISH
    EXPECTED, LOG #0: AFTER_PROC

    EXPECTED, LOG #1: BEFORE_PROC
    EXPECTED, LOG #1: PROC_START
    EXPECTED, LOG #1: SELECTED_ID
    EXPECTED, LOG #1: PROC_FINISH
    EXPECTED, LOG #1: AFTER_PROC

    EXPECTED, LOG #2: BEFORE_PROC
    EXPECTED, LOG #2: PROC_START
    EXPECTED, LOG #2: SELECTED_ID
    EXPECTED, LOG #2: PROC_FINISH
    EXPECTED, LOG #2: AFTER_PROC
"""

PLANNED_DML_ATTACHMENTS = 3

run_sql = temp_file('core_5222_run.sql')
dml_logs = temp_files([f'tmp_dml_5222_{i+1}' for i in range(PLANNED_DML_ATTACHMENTS)])

@pytest.mark.version('>=3.0,<4')
def test_1(act: Action, run_sql: Path, dml_logs: List[Path], capsys):
    pattern = re.compile("BEFORE_PROC*|PROC_START*|SELECTED_ID*|PROC_FINISH*|AFTER_PROC*")
    run_sql.write_text(test_script)
    # Launching several concurrent child ISQL processes which perform `run_sql` script
    f_logs = []
    p_dml = []
    try:
        for dml_log in dml_logs: # Contains PLANNED_DML_ATTACHMENTS items
            f = open(dml_log, mode='w')
            f_logs.append(f)
            p_dml.append(subprocess.Popen([act.vars['isql'],
                                           '-i', str(run_sql),
                                           '-user', act.db.user,
                                           '-password', act.db.password,
                                           act.db.dsn],
                                          stdout=f, stderr=subprocess.STDOUT))
        #
        time.sleep(PLANNED_DML_ATTACHMENTS * 5)
    finally:
        for f in f_logs:
            f.close()
        for p in p_dml:
            p.terminate()
    #
    # 1. Each log _should_ contain ONLY following lines:
    #    BEFORE_PROC                     2016-05-03 09:27:57.6210
    #    PROC_START                      2016-05-03 09:27:57.6210
    #    SELECTED_ID                     1569
    #    PROC_FINISH                     2016-05-03 09:28:04.0740
    #    AFTER_PROC                      2016-05-03 09:28:04.0740
    # 2. _NO_ log should contain 'SQLSTATE = 40001'
    #
    # Open every log and print 1st word from each line, ignoring values of timestamp and ID.
    i = 0
    for dml_log in dml_logs:
        for line in dml_log.read_text().splitlines():
            if line.split():
                if pattern.match(line):
                    print(f'EXPECTED, LOG #{i}: {line.split()[0]}')
                else:
                    print(f'UNEXPECTED, LOG #{i}: {line}')
        i += 1
    # Check
    act.expected_stdout = expected_stdout
    act.stdout = capsys.readouterr().out
    assert act.clean_stdout == act.clean_expected_stdout

# version: 4.0

@pytest.mark.skip('FIXME: Not IMPLEMENTED')
@pytest.mark.version('>=4.0')
def test_2(act: Action):
    pytest.fail("Not IMPLEMENTED")