Check firebird.log [no messages found for interval when this test was running]
Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
assert   
  - EXPECTED: gbak total statistics for writes NOT LESS than ratio DB_FILE_SIZE / PAGE_SIZE
  + UNEXPECTED: gbak_total_writes=1003 -- LESS than restored_file_size/PAGE_SIZE=2638.0

LOG DETAILS:

2025-02-14 12:51:14.546
2025-02-14 12:51:14.553 act = <firebird.qa.plugin.Action object at [hex]>
2025-02-14 12:51:14.561 tmp_fbk = PosixPath('/var/tmp/qa_2024/test_11681/tmp_gh_8391.restored.fbk')
2025-02-14 12:51:14.575 tmp_log = PosixPath('/var/tmp/qa_2024/test_11681/tmp_gh_8391.restored.log')
2025-02-14 12:51:14.591 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-02-14 12:51:14.604
2025-02-14 12:51:14.613 @pytest.mark.version('>=4.0.6')
2025-02-14 12:51:14.620 def test_1(act: Action, tmp_fbk: Path, tmp_log: Path, capsys):
2025-02-14 12:51:14.627
2025-02-14 12:51:14.634 if act.get_server_architecture() != 'SuperServer':
2025-02-14 12:51:14.642 pytest.skip('Applies only to SuperServer')
2025-02-14 12:51:14.652
2025-02-14 12:51:14.660 # Scan line-by-line through databases.conf, find line starting with REQUIRED_ALIAS and extract name of file that
2025-02-14 12:51:14.669 # must be created in the $(dir_sampleDb)/qa/ folder.
2025-02-14 12:51:14.683 # NOTE: we have to SKIP lines which are commented out, i.e. if they starts with '#':
2025-02-14 12:51:14.691 p_required_alias_ptn =  re.compile( '^(?!#)((^|\\s+)' + REQUIRED_ALIAS + ')\\s*=\\s*\\$\\(dir_sampleDb\\)/qa/', re.IGNORECASE )
2025-02-14 12:51:14.699 fname_in_dbconf = None
2025-02-14 12:51:14.707
2025-02-14 12:51:14.714 with open(act.home_dir/'databases.conf', 'r') as f:
2025-02-14 12:51:14.726 for line in f:
2025-02-14 12:51:14.739 if p_required_alias_ptn.search(line):
2025-02-14 12:51:14.752 # If databases.conf contains line like this:
2025-02-14 12:51:14.763 #     tmp_8391_alias = $(dir_sampleDb)/qa/tmp_qa_8391.fdb
2025-02-14 12:51:14.771 # - then we extract filename: 'tmp_qa_8391.fdb' (see below):
2025-02-14 12:51:14.779 fname_in_dbconf = Path(line.split('=')[1].strip()).name
2025-02-14 12:51:14.789 break
2025-02-14 12:51:14.798
2025-02-14 12:51:14.807 # if 'fname_in_dbconf' remains undefined here then propably REQUIRED_ALIAS not equals to specified in the databases.conf!
2025-02-14 12:51:14.814 #
2025-02-14 12:51:14.821 assert fname_in_dbconf
2025-02-14 12:51:14.829
2025-02-14 12:51:14.836 test_sql = f"""
2025-02-14 12:51:14.844 set list on;
2025-02-14 12:51:14.851 create database '{REQUIRED_ALIAS}' user {act.db.user} password '{act.db.password}' page_size {PAGE_SIZE};
2025-02-14 12:51:14.857 commit;
2025-02-14 12:51:14.865 recreate sequence g;
2025-02-14 12:51:14.879 recreate table test(id int, b blob);
2025-02-14 12:51:14.887
2025-02-14 12:51:14.896 set autoterm on;
2025-02-14 12:51:14.903 execute block as
2025-02-14 12:51:14.914 declare n int;
2025-02-14 12:51:14.925 begin
2025-02-14 12:51:14.932 insert into test(id, b) values(gen_id(g,1), gen_uuid());
2025-02-14 12:51:14.944 insert into test(id, b)
2025-02-14 12:51:14.958 values(
2025-02-14 12:51:14.970 gen_id(g,1)
2025-02-14 12:51:14.980 ,(select list(gen_uuid()) as s from rdb$types,rdb$types)
2025-02-14 12:51:14.989 );
2025-02-14 12:51:15.002
2025-02-14 12:51:15.012 insert into test(id, b)
2025-02-14 12:51:15.021 values(
2025-02-14 12:51:15.036 gen_id(g,1)
2025-02-14 12:51:15.049 ,(select list(gen_uuid()) as s from (select 1 x from rdb$types,rdb$types,rdb$types rows 800000))
2025-02-14 12:51:15.058 );
2025-02-14 12:51:15.065 end
2025-02-14 12:51:15.072 ;
2025-02-14 12:51:15.078 commit;
2025-02-14 12:51:15.086 select mon$database_name, mon$page_buffers from mon$database;
2025-02-14 12:51:15.099 """
2025-02-14 12:51:15.113
2025-02-14 12:51:15.124 test_fdb_file = 'UNDEFINED'
2025-02-14 12:51:15.136 act.isql(switches=['-q'], input = test_sql, connect_db = False, credentials = False, combine_output = True, io_enc = locale.getpreferredencoding())
2025-02-14 12:51:15.149 for line in act.stdout.splitlines():
2025-02-14 12:51:15.159 if line.startswith('mon$database_name'.upper()):
2025-02-14 12:51:15.167 test_fdb_file = line.split()[1]
2025-02-14 12:51:15.175 if line.startswith('mon$page_buffers'.upper()):
2025-02-14 12:51:15.183 test_fdb_buffers = int(line.split()[1])
2025-02-14 12:51:15.193
2025-02-14 12:51:15.201 assert test_fdb_buffers == 128
2025-02-14 12:51:15.208 act.reset()
2025-02-14 12:51:15.215
2025-02-14 12:51:15.223 act.gbak(switches=['-b', act.db.dsn, str(tmp_fbk)], combine_output = True, io_enc = locale.getpreferredencoding())
2025-02-14 12:51:15.231 assert act.clean_stdout == ''
2025-02-14 12:51:15.239 act.reset()
2025-02-14 12:51:15.247
2025-02-14 12:51:15.258 act.gbak(switches=['-rep', '-v', '-st', 'w', str(tmp_fbk), REQUIRED_ALIAS], combine_output = True, io_enc = locale.getpreferredencoding())
2025-02-14 12:51:15.270
2025-02-14 12:51:15.282 # gbak: NNNN total statistics
2025-02-14 12:51:15.291 gbak_write_total_stat_ptn = re.compile( r'gbak(:)?\s+\d+\s+total\s+statistics', re.IGNORECASE )
2025-02-14 12:51:15.300
2025-02-14 12:51:15.309 EXPECTED_MSG = 'EXPECTED: gbak total statistics for writes NOT LESS than ratio DB_FILE_SIZE / PAGE_SIZE'
2025-02-14 12:51:15.317 for line in act.stdout.splitlines():
2025-02-14 12:51:15.325 if gbak_write_total_stat_ptn.search(line):
2025-02-14 12:51:15.338 gbak_total_writes = int(line.split()[1])
2025-02-14 12:51:15.350 restored_file_size = os.stat(test_fdb_file).st_size
2025-02-14 12:51:15.364 if gbak_total_writes >= restored_file_size / PAGE_SIZE:
2025-02-14 12:51:15.375 print(EXPECTED_MSG)
2025-02-14 12:51:15.382 else:
2025-02-14 12:51:15.390 print(f'UNEXPECTED: {gbak_total_writes=} -- LESS than {restored_file_size/PAGE_SIZE=}')
2025-02-14 12:51:15.398
2025-02-14 12:51:15.407 act.expected_stdout = EXPECTED_MSG
2025-02-14 12:51:15.418 act.stdout = capsys.readouterr().out
2025-02-14 12:51:15.427 >       assert act.clean_stdout == act.clean_expected_stdout
2025-02-14 12:51:15.435 E       assert
2025-02-14 12:51:15.444 E         - EXPECTED: gbak total statistics for writes NOT LESS than ratio DB_FILE_SIZE / PAGE_SIZE
2025-02-14 12:51:15.452 E         + UNEXPECTED: gbak_total_writes=1003 -- LESS than restored_file_size/PAGE_SIZE=2638.0
2025-02-14 12:51:15.458
2025-02-14 12:51:15.466 tests/bugs/gh_8391_test.py:136: AssertionError
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
tmp_fbk = PosixPath('/var/tmp/qa_2024/test_11681/tmp_gh_8391.restored.fbk')
tmp_log = PosixPath('/var/tmp/qa_2024/test_11681/tmp_gh_8391.restored.log')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=4.0.6')
    def test_1(act: Action, tmp_fbk: Path, tmp_log: Path, capsys):
    
        if act.get_server_architecture() != 'SuperServer':
            pytest.skip('Applies only to SuperServer')
    
        # Scan line-by-line through databases.conf, find line starting with REQUIRED_ALIAS and extract name of file that
        # must be created in the $(dir_sampleDb)/qa/ folder.
        # NOTE: we have to SKIP lines which are commented out, i.e. if they starts with '#':
        p_required_alias_ptn =  re.compile( '^(?!#)((^|\\s+)' + REQUIRED_ALIAS + ')\\s*=\\s*\\$\\(dir_sampleDb\\)/qa/', re.IGNORECASE )
        fname_in_dbconf = None
    
        with open(act.home_dir/'databases.conf', 'r') as f:
            for line in f:
                if p_required_alias_ptn.search(line):
                    # If databases.conf contains line like this:
                    #     tmp_8391_alias = $(dir_sampleDb)/qa/tmp_qa_8391.fdb
                    # - then we extract filename: 'tmp_qa_8391.fdb' (see below):
                    fname_in_dbconf = Path(line.split('=')[1].strip()).name
                    break
    
        # if 'fname_in_dbconf' remains undefined here then propably REQUIRED_ALIAS not equals to specified in the databases.conf!
        #
        assert fname_in_dbconf
    
        test_sql = f"""
            set list on;
            create database '{REQUIRED_ALIAS}' user {act.db.user} password '{act.db.password}' page_size {PAGE_SIZE};
            commit;
            recreate sequence g;
            recreate table test(id int, b blob);
    
            set autoterm on;
            execute block as
                declare n int;
            begin
                insert into test(id, b) values(gen_id(g,1), gen_uuid());
                insert into test(id, b)
                values(
                        gen_id(g,1)
                        ,(select list(gen_uuid()) as s from rdb$types,rdb$types)
                      );
    
                insert into test(id, b)
                values(
                        gen_id(g,1)
                        ,(select list(gen_uuid()) as s from (select 1 x from rdb$types,rdb$types,rdb$types rows 800000))
                      );
            end
            ;
            commit;
            select mon$database_name, mon$page_buffers from mon$database;
        """
    
        test_fdb_file = 'UNDEFINED'
        act.isql(switches=['-q'], input = test_sql, connect_db = False, credentials = False, combine_output = True, io_enc = locale.getpreferredencoding())
        for line in act.stdout.splitlines():
            if line.startswith('mon$database_name'.upper()):
                test_fdb_file = line.split()[1]
            if line.startswith('mon$page_buffers'.upper()):
                test_fdb_buffers = int(line.split()[1])
    
        assert test_fdb_buffers == 128
        act.reset()
    
        act.gbak(switches=['-b', act.db.dsn, str(tmp_fbk)], combine_output = True, io_enc = locale.getpreferredencoding())
        assert act.clean_stdout == ''
        act.reset()
    
        act.gbak(switches=['-rep', '-v', '-st', 'w', str(tmp_fbk), REQUIRED_ALIAS], combine_output = True, io_enc = locale.getpreferredencoding())
    
        # gbak: NNNN total statistics
        gbak_write_total_stat_ptn = re.compile( r'gbak(:)?\s+\d+\s+total\s+statistics', re.IGNORECASE )
    
        EXPECTED_MSG = 'EXPECTED: gbak total statistics for writes NOT LESS than ratio DB_FILE_SIZE / PAGE_SIZE'
        for line in act.stdout.splitlines():
            if gbak_write_total_stat_ptn.search(line):
                gbak_total_writes = int(line.split()[1])
                restored_file_size = os.stat(test_fdb_file).st_size
                if gbak_total_writes >= restored_file_size / PAGE_SIZE:
                    print(EXPECTED_MSG)
                else:
                    print(f'UNEXPECTED: {gbak_total_writes=} -- LESS than {restored_file_size/PAGE_SIZE=}')
    
        act.expected_stdout = EXPECTED_MSG
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - EXPECTED: gbak total statistics for writes NOT LESS than ratio DB_FILE_SIZE / PAGE_SIZE
E         + UNEXPECTED: gbak_total_writes=1003 -- LESS than restored_file_size/PAGE_SIZE=2638.0

tests/bugs/gh_8391_test.py:136: AssertionError
Full history of outcomes and elapsed time, ms:
NN SNAP_INFO CS_outcome SS_outcome CS_run_time SS_run_time CS_run_beg CS_run_end SS_run_beg SS_run_end
1 5.0.3.1657 2025.06.19 4bd4c S P 13 13175 2025.06.27 12:21:38.258 2025.06.27 12:21:38.271 2025.06.27 11:02:27.255 2025.06.27 11:02:40.430
2 5.0.3.1657 2025.06.11 dae6f S P 8 13423 2025.06.17 07:26:43.837 2025.06.17 07:26:43.845 2025.06.17 06:06:19.705 2025.06.17 06:06:33.128
3 5.0.3.1657 2025.06.10 dbc92 S P 5 16549 2025.06.11 12:17:14.658 2025.06.11 12:17:14.663 2025.06.11 10:48:08.466 2025.06.11 10:48:25.015
4 5.0.3.1656 2025.05.20 c4b11 S P 15 15113 2025.06.10 12:11:01.168 2025.06.10 12:11:01.183 2025.06.10 10:46:35.312 2025.06.10 10:46:50.425
5 5.0.3.1652 2025.05.13 f51c6 S P 11 17186 2025.05.20 05:15:18.053 2025.05.20 05:15:18.064 2025.05.20 03:38:55.258 2025.05.20 03:39:12.444
6 5.0.3.1651 2025.04.30 141ef S P 16 17727 2025.05.13 12:13:20.111 2025.05.13 12:13:20.127 2025.05.13 10:35:53.797 2025.05.13 10:36:11.524
7 5.0.3.1650 2025.04.28 4cbff S P 7 17424 2025.05.01 11:47:07.078 2025.05.01 11:47:07.085 2025.05.01 10:10:39.202 2025.05.01 10:10:56.626
8 5.0.3.1649 2025.04.21 5b2d0 S P 9 17568 2025.04.28 05:44:53.211 2025.04.28 05:44:53.220 2025.04.28 04:10:18.687 2025.04.28 04:10:36.255
9 5.0.3.1648 2025.04.18 2f4c5 S P 12 16246 2025.04.20 05:36:38.418 2025.04.20 05:36:38.430 2025.04.20 04:04:39.559 2025.04.20 04:04:55.805
10 5.0.3.1635 2025.03.31 22ec6 S P 9 16232 2025.04.18 11:59:42.986 2025.04.18 11:59:42.995 2025.04.18 10:23:50.487 2025.04.18 10:24:06.719
11 5.0.3.1633 2025.03.28 3123a S P 7 18041 2025.03.31 10:33:30.537 2025.03.31 10:33:30.544 2025.03.31 09:03:57.326 2025.03.31 09:04:15.367
12 5.0.3.1633 2025.03.27 e0fb8 S P 15 15376 2025.03.28 11:08:52.152 2025.03.28 11:08:52.167 2025.03.28 09:36:34.325 2025.03.28 09:36:49.701
13 5.0.3.1631 2025.03.21 1925b S P 14 18611 2025.03.27 10:56:38.062 2025.03.27 10:56:38.076 2025.03.27 09:25:10.390 2025.03.27 09:25:29.001
14 5.0.3.1628 2025.03.14 16d05 S P 8918 9594 2025.03.17 08:29:41.664 2025.03.17 08:29:50.582 2025.03.17 06:49:39.351 2025.03.17 06:49:48.945
15 5.0.3.1627 2025.02.26 4e218 S P 8558 9097 2025.03.14 11:44:04.140 2025.03.14 11:44:12.698 2025.03.14 10:02:58.829 2025.03.14 10:03:07.926
16 5.0.3.1624 2025.02.25 dc3b2 S P 9530 9527 2025.02.26 10:34:36.608 2025.02.26 10:34:46.138 2025.02.26 08:59:01.751 2025.02.26 08:59:11.278
17 5.0.2.1615 2025.02.20 4a726 S P 9682 9022 2025.02.25 11:01:58.430 2025.02.25 11:02:08.112 2025.02.25 09:24:35.789 2025.02.25 09:24:44.811
18 5.0.2.1615 2025.02.14 9cb76 S P 9483 8840 2025.02.20 07:51:11.753 2025.02.20 07:51:21.236 2025.02.20 06:17:31.581 2025.02.20 06:17:40.421
19 5.0.2.1577 2024.12.24 3c80e S F 10461 9316 2025.02.14 11:05:07.022 2025.02.14 11:05:17.483 2025.02.14 09:31:04.799 2025.02.14 09:31:14.115

Elapsed time, ms. Chart for last 19 runs:

Last commits information (all timestamps in UTC):