firebird-qa/tests/bugs/core_5475_test.py

#coding:utf-8

"""
ID:          issue-5745
ISSUE:       5745
TITLE:       Provide ability to filter out info and warnings from trace log
DESCRIPTION:
  For FB 3.0 and above we check that trace log contains only those gdscodes which we expect.
  Also, trace should NOT contain gdscodes which we explicitly prohibit or which we do not expect
  because not empty list in 'include_gds_codes' parameter.
  Also, we verify that no more TRACE_INIT / TRACE_FINI in trace because log_initfini=false.
NOTES:
[01.04.2020]
  Up to 4.0.0.1820 (~29.03.2020, including) cursor.execute() with SELECT
  statement did NOT actually fetch record until we explicitly do futher actions, e.g:
    for r in cur:
        print(r[0])
  For this reason code which did only cur.execute('SELECT <too_long_literal_to_be_fitted> ...' )
  was useless: it did not lead to any error and trace log did NOT contain any "undesired" gdscodes
  like 335544914 or 335545033. It was exactly because of THIS rather than "good behaviour" of filter
  that we specify in the trace config (i.e. include_gdscodes or exclude_gdscodes).
  It was decided to replace selectable cursor with DML and use value that will violates limits
  of Firebird implementation (timestamp field, assign value = '01.01.0000' - it can not be used in FB).

  See letter from Vlad, 31-mar-2020 14:29.
JIRA:        CORE-5475
FBTEST:      bugs.core_5475
"""

import pytest
from firebird.qa import *
from firebird.driver import DatabaseError, FirebirdWarning

init_script = """
    recreate table test(
        id int generated by default as identity constraint test_pk primary key using index test_id,
        tiny_num smallint,
        dts timestamp,
        s varchar(4) -- added 01.04.2020
    );
    commit;
    insert into test(id, tiny_num, dts) values(1,32767, null);
    commit;
"""

db = db_factory(sql_dialect=1, init=init_script)

act = python_act('db')

# Following gdscodes MUST BE found in the trace log:
MISSED_EXPECTED_TOKEN = 'ERROR: missed expected token which MUST be in the trace log'
EXPECTED_SET = {'335544321' : MISSED_EXPECTED_TOKEN,
                '335544916' : MISSED_EXPECTED_TOKEN,
                '335544665' : MISSED_EXPECTED_TOKEN,
                '336068855' : MISSED_EXPECTED_TOKEN
                }

# Following gdscodes must NOT present on trace log because we explicitly PROHIBIT them:
NOT_FOUND_EXPLICITLY_PROHIBITED = 'SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list'
PROHIBIT_SET = {'335544772' : NOT_FOUND_EXPLICITLY_PROHIBITED,
                '335544778' : NOT_FOUND_EXPLICITLY_PROHIBITED,
                '335544808' : NOT_FOUND_EXPLICITLY_PROHIBITED,
                'TRACE_INIT' : NOT_FOUND_EXPLICITLY_PROHIBITED,
                'TRACE_FINI' : NOT_FOUND_EXPLICITLY_PROHIBITED
                }

# Following gdscodes are UNEXPECTED, i.e. we did not prohibit them explicitly
# but none of them are in include_gds_codes ==> they should NOT appear in the trace:
NOT_FOUND_IMPLICITLY_PROHIBITED = 'SUCCESS: no tokens which are not in include_gds_codes list.'
UNEXPECT_SET = {'335544347' : NOT_FOUND_IMPLICITLY_PROHIBITED,
                '335544913' : NOT_FOUND_IMPLICITLY_PROHIBITED
                }

expected_stdout = """
    expected_token: 335544321 ; trace search result: SUCCESS: found expected token which MUST be in the trace log.
    expected_token: 335544665 ; trace search result: SUCCESS: found expected token which MUST be in the trace log.
    expected_token: 335544916 ; trace search result: SUCCESS: found expected token which MUST be in the trace log.
    expected_token: 336068855 ; trace search result: SUCCESS: found expected token which MUST be in the trace log.
    prohibit_token: 335544772 ; trace search result: SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list
    prohibit_token: 335544778 ; trace search result: SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list
    prohibit_token: 335544808 ; trace search result: SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list
    prohibit_token: TRACE_FINI ; trace search result: SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list
    prohibit_token: TRACE_INIT ; trace search result: SUCCESS: no tokens which are explicitly prohibited in exclude_gds_codes list
    unexpect_token: 335544347 ; trace search result: SUCCESS: no tokens which are not in include_gds_codes list.
    unexpect_token: 335544913 ; trace search result: SUCCESS: no tokens which are not in include_gds_codes list.
"""

trace = ['time_threshold = 0',
         'log_initfini = false',
         'log_connections = true',
         'log_errors = true',
         'log_warnings = true',
         'log_statement_prepare = true',
         'log_statement_finish = true',
         # 1. We EXPLICITLY ALLOW to be logged (and EXPECT because of current test scenario):
         # 1.1) any kind of "arithmetic exc, num ovf, or string trunc"
         # 1.2) PK/UK violation
         # 1.3) (warning) 336068855 : Warning: ALL on ALL is not granted to <...>.
         'include_gds_codes = arith_except,unique_key_violation,336068855',
         # We EXPLICITLY PREVENT from logging:
         # 2.1 "FP divide by zero",
         # 2.2 "Integer divide by zero" and
         # 2.3 (warning) "DATE data type is now called TIMESTAMP" (warning)
         'exclude_gds_codes = 335544772,335544778,335544808',
         # We do not prevent (explicitly) but DO NOT expect see in trace following errors:
         # 1) 335544347 : validation error for column ..., value "*** null ***"
         # 2) 335544913 : value exceeds the range for valid timestamps
         ]

@pytest.mark.trace
@pytest.mark.version('>=3.0')
def test_1(act: Action, capsys):
    with act.trace(db_events=trace):
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.raises(DatabaseError, match='.*Floating-point divide by zero.*'):
                c.execute('insert into test(tiny_num) values(1/0)')
        #
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.raises(DatabaseError, match='.*violation of PRIMARY or UNIQUE KEY constraint "TEST_PK" on table "TEST".*'):
                c.execute('insert into test(id,tiny_num) values(?, ?)', [1, 1])
        #
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.raises(DatabaseError, match='.*numeric value is out of range.*'):
                c.execute('update test set tiny_num = tiny_num + 1')
        #
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.raises(DatabaseError, match='.*value exceeds the range for valid timestamps.*'):
                c.execute("insert into test(dts) values('01.01.0000')" )
        #
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.warns(FirebirdWarning, match='.*DATE data type is now called TIMESTAMP.*'):
                # Leads to WARNING in trace:
                # 335544807 : SQL warning code = 301
                # 335544808 : DATE data type is now called TIMESTAMP
                c.execute("update test set dts = cast('now' as date)")
        #
        with act.db.connect(sql_dialect=1) as con:
            c = con.cursor()
            with pytest.raises(DatabaseError, match='.*validation error for column.*'):
                c.execute('insert into test(id) values(null)')
        #
        with act.db.connect(sql_dialect=1) as con:
            with pytest.warns(FirebirdWarning, match='.*ALL on ALL is not granted.*'):
                # (warning) 336068855 : Warning: ALL on ALL is not granted to <...>.
                con.execute_immediate('revoke all on all from tmp$c5475')
    # Process trace
    for line in act.trace_log:
        if line.split():
            starting_word = line.split()[0]
            if starting_word in EXPECTED_SET:
                EXPECTED_SET[starting_word] = 'SUCCESS: found expected token which MUST be in the trace log.'
            elif starting_word in PROHIBIT_SET:
                PROHIBIT_SET[starting_word] = 'ERROR: found token which is EXPLICITLY prohibited in exclude_gds_codes list.'
            elif starting_word in UNEXPECT_SET:
                UNEXPECT_SET[starting_word] = 'ERROR: found token NOT from include_gdscodes list (implicitly prohibited).'
    #
    for k,v in sorted(EXPECTED_SET.items()):
        print(f'expected_token: {k} ; trace search result: {v}')
    for k,v in sorted(PROHIBIT_SET.items()):
        print(f'prohibit_token: {k} ; trace search result: {v}')
    for k,v in sorted(UNEXPECT_SET.items()):
        print(f'unexpect_token: {k} ; trace search result: {v}')
    # Check
    act.expected_stdout = expected_stdout
    act.stdout = capsys.readouterr().out
    assert act.clean_stdout == act.clean_expected_stdout