Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
assert   
  + FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
  + FIREBIRD.LOG: + OIT, OAT, OST, NEXT
    FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
    FIREBIRD.LOG: + OIT, OAT, OST, NEXT
    FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
    FIREBIRD.LOG: + CONNECTION SHUTDOWN
  + FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
  + FIREBIRD.LOG: + CONNECTION SHUTDOWN

LOG DETAILS:

2024-05-12 19:15:51.355
2024-05-12 19:15:51.360 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-12 19:15:51.365 sweep_log = PosixPath('/var/tmp/qa_2024/test_1824/tmp_4337_sweep.log')
2024-05-12 19:15:51.370 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-12 19:15:51.374
2024-05-12 19:15:51.379 @pytest.mark.version('>=3.0')
2024-05-12 19:15:51.384 def test_1(act: Action, sweep_log: Path, capsys):
2024-05-12 19:15:51.389
2024-05-12 19:15:51.393 with act.connect_server() as srv:
2024-05-12 19:15:51.398
2024-05-12 19:15:51.403 # REDUCE number of cache buffers in DB header in order to sweep make its work as long as possible
2024-05-12 19:15:51.408 srv.database.set_default_cache_size(database=act.db.db_path, size=75)
2024-05-12 19:15:51.413
2024-05-12 19:15:51.417 # Change FW to ON (in order to make sweep life harder :))
2024-05-12 19:15:51.423 srv.database.set_write_mode(database=act.db.db_path, mode=DbWriteMode.SYNC)
2024-05-12 19:15:51.428
2024-05-12 19:15:51.432 srv.info.get_log()
2024-05-12 19:15:51.437 log_before = srv.readlines()
2024-05-12 19:15:51.441
2024-05-12 19:15:51.446 #---------------------------------------------------------------
2024-05-12 19:15:51.451
2024-05-12 19:15:51.456 # How long can we wait (milliseconds) for the FIRST appearance of 'gfix' process in mon$attachments:
2024-05-12 19:15:51.461 #
2024-05-12 19:15:51.466 MAX_WAIT_FOR_SWEEP_START_MS = 3000
2024-05-12 19:15:51.470
2024-05-12 19:15:51.475 # How long we wait (milliseconds) for SECOND appearance of 'gfix' process in mon$attachments, after it was killed.
2024-05-12 19:15:51.480 # NOTE. If it appears then we have a BUG
2024-05-12 19:15:51.485 MAX_WAIT_FOR_GFIX_RESTART_MS = 3000
2024-05-12 19:15:51.489
2024-05-12 19:15:51.494 sweep_attach_id = None
2024-05-12 19:15:51.499 sweep_reconnect = None
2024-05-12 19:15:51.504 # Start trace
2024-05-12 19:15:51.509 with act.trace(db_events=trace):
2024-05-12 19:15:51.514 with act.db.connect() as con:
2024-05-12 19:15:51.519 f_sweep_log = open(sweep_log,'w')
2024-05-12 19:15:51.524 stm = r"select first 1 a.mon$attachment_id from mon$attachments a where a.mon$system_flag <> 1 and lower(a.mon$remote_process) similar to '(%[\\/](gfix|fbsvcmgr)(.exe)?)'"
2024-05-12 19:15:51.529 t1=py_dt.datetime.now()
2024-05-12 19:15:51.534 with con.cursor() as cur1:
2024-05-12 19:15:51.539 ps1 = cur1.prepare(stm)
2024-05-12 19:15:51.544 p_sweep = subprocess.Popen( [act.vars['gfix'], '-sweep', '-user', act.db.user, '-password', act.db.password, act.db.dsn],
2024-05-12 19:15:51.549 stdout = f_sweep_log,
2024-05-12 19:15:51.554 stderr = subprocess.STDOUT
2024-05-12 19:15:51.559 )
2024-05-12 19:15:51.564
2024-05-12 19:15:51.568 ##########################################################################
2024-05-12 19:15:51.574 # LOOP-1: WAIT FOR FIRST APPEARANCE OF GFIX PROCESS IN THE MON$ATTACHMENTS
2024-05-12 19:15:51.578 ##########################################################################
2024-05-12 19:15:51.584 while True:
2024-05-12 19:15:51.589 t2=py_dt.datetime.now()
2024-05-12 19:15:51.594 d1=t2-t1
2024-05-12 19:15:51.599 dd = d1.seconds*1000 + d1.microseconds//1000
2024-05-12 19:15:51.604 if dd > MAX_WAIT_FOR_SWEEP_START_MS:
2024-05-12 19:15:51.609 print(f'TIMEOUT EXPIRATION: waiting for SWEEP process took {dd} ms which exceeds limit = {MAX_WAIT_FOR_SWEEP_START_MS} ms.')
2024-05-12 19:15:51.614 break
2024-05-12 19:15:51.619
2024-05-12 19:15:51.624 cur1.execute(ps1)
2024-05-12 19:15:51.629 for r in cur1:
2024-05-12 19:15:51.634 sweep_attach_id = r[0]
2024-05-12 19:15:51.639
2024-05-12 19:15:51.644 con.commit()
2024-05-12 19:15:51.648 if sweep_attach_id:
2024-05-12 19:15:51.654 break
2024-05-12 19:15:51.659 else:
2024-05-12 19:15:51.663 time.sleep(0.1)
2024-05-12 19:15:51.668 #<while True (loop for search gfix process in mon$attachments)
2024-05-12 19:15:51.673
2024-05-12 19:15:51.678 #< with con.cursor() as cur1
2024-05-12 19:15:51.683
2024-05-12 19:15:51.687 #assert sweep_attach_id is None, f'attacment_id of SWEEP process is {sweep_attach_id}'
2024-05-12 19:15:51.694 assert sweep_attach_id, 'attacment_id of SWEEP process was not found.'
2024-05-12 19:15:51.700
2024-05-12 19:15:51.705 # Let sweep to have some 'useful work':
2024-05-12 19:15:51.710 #
2024-05-12 19:15:51.715 time.sleep(1)
2024-05-12 19:15:51.720
2024-05-12 19:15:51.725 # Now we can KILL attachment that belongs to SWEEP process, <sweep_attach_id>:
2024-05-12 19:15:51.730 con.execute_immediate(f'delete from mon$attachments where mon$attachment_id = {sweep_attach_id}')
2024-05-12 19:15:51.735
2024-05-12 19:15:51.739 p_sweep.wait()
2024-05-12 19:15:51.744 f_sweep_log.close()
2024-05-12 19:15:51.749
2024-05-12 19:15:51.754 assert p_sweep.returncode == 1, 'p_sweep.returncode: {p_sweep.returncode}'
2024-05-12 19:15:51.759
2024-05-12 19:15:51.764
2024-05-12 19:15:51.769 ##################################################################################################
2024-05-12 19:15:51.774 # LOOP-2: WAIT FOR POSSIBLE SECOND APPEARENCE (RECONNECT) OF GFIX. IF IT OCCURS THEN WE HAVE A BUG
2024-05-12 19:15:51.779 ##################################################################################################
2024-05-12 19:15:51.784 t1=py_dt.datetime.now()
2024-05-12 19:15:51.789 with con.cursor() as cur2:
2024-05-12 19:15:51.793 ps2 = cur2.prepare( stm.replace('select ', 'select /* search re-connect that could be made */ ') )
2024-05-12 19:15:51.798 while True:
2024-05-12 19:15:51.803 t2=py_dt.datetime.now()
2024-05-12 19:15:51.808 d1=t2-t1
2024-05-12 19:15:51.814 dd = d1.seconds*1000 + d1.microseconds//1000
2024-05-12 19:15:51.821 if dd > MAX_WAIT_FOR_GFIX_RESTART_MS:
2024-05-12 19:15:51.827 # Expected: gfix reconnect was not detected for last {MAX_WAIT_FOR_GFIX_RESTART_MS} ms.
2024-05-12 19:15:51.832 break
2024-05-12 19:15:51.836 con.commit()
2024-05-12 19:15:51.841 cur2.execute(ps2)
2024-05-12 19:15:51.845 # Resultset now must be EMPTY. we must not find any record!
2024-05-12 19:15:51.850 for r in cur2:
2024-05-12 19:15:51.855 sweep_reconnect = r[0]
2024-05-12 19:15:51.860
2024-05-12 19:15:51.865 #con.commit()
2024-05-12 19:15:51.871 if sweep_reconnect:
2024-05-12 19:15:51.877 # UNEXPECTED: gfix reconnect found, with attach_id={sweep_reconnect}
2024-05-12 19:15:51.883 break
2024-05-12 19:15:51.888 else:
2024-05-12 19:15:51.893 time.sleep(0.1)
2024-05-12 19:15:51.898 #< with con.cursor() as cur2
2024-05-12 19:15:51.903
2024-05-12 19:15:51.907 assert sweep_reconnect is None, f'Found re-connect of SWEEP process, attachment: {sweep_reconnect}'
2024-05-12 19:15:51.912
2024-05-12 19:15:51.917 #< with db.connect as con
2024-05-12 19:15:51.922
2024-05-12 19:15:51.927 #---------------------------------------------------------------
2024-05-12 19:15:51.931 # DISABLED 25.09.2022. SWEEP log can remain empty (4.0.1.2692 Classic)
2024-05-12 19:15:51.936 ## Check-1: log of sweep must contain text: 'connection shutdown':
2024-05-12 19:15:51.941 #for line in sweep_log.read_text().splitlines():
2024-05-12 19:15:51.946 #    if line:
2024-05-12 19:15:51.950 #        print('SWEEP LOG:', line.upper())
2024-05-12 19:15:51.955 #
2024-05-12 19:15:51.959 #act.expected_stdout = 'sweep log: connection shutdown'.upper()
2024-05-12 19:15:51.964 #act.stdout = capsys.readouterr().out
2024-05-12 19:15:51.969 #assert act.clean_stdout == act.clean_expected_stdout
2024-05-12 19:15:51.973 #act.reset()
2024-05-12 19:15:51.978 #---------------------------------------------------------------
2024-05-12 19:15:51.982
2024-05-12 19:15:51.987 # Trace log
2024-05-12 19:15:51.991 found_sweep_failed = 0
2024-05-12 19:15:51.996 p_sweep_failed = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+SWEEP_FAILED$', re.IGNORECASE)
2024-05-12 19:15:52.001 p_att_success = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+ATTACH_DATABASE$', re.IGNORECASE)
2024-05-12 19:15:52.006
2024-05-12 19:15:52.012 trace_expected = 'FOUND SWEEP_FAILED MESSAGE.'
2024-05-12 19:15:52.017 for i,line in enumerate(act.trace_log):
2024-05-12 19:15:52.022 if line.strip():
2024-05-12 19:15:52.027 if p_sweep_failed.search(line.strip()):
2024-05-12 19:15:52.032 print(trace_expected)
2024-05-12 19:15:52.037 found_sweep_failed = 1
2024-05-12 19:15:52.042 if found_sweep_failed == 1 and p_att_success.search(line) and i < len(act.trace_log)-2 and 'gfix' in act.trace_log[i+2].lower():
2024-05-12 19:15:52.047 # NB: we have to ignore "FAILED ATTACH_DATABASE".
2024-05-12 19:15:52.052 # It can occur in some cases.
2024-05-12 19:15:52.058 print('TRACE: UNEXPECTED ATTACH FOUND AFTER KILL SWEEP! CHECK LINE N {i}:')
2024-05-12 19:15:52.063 print('TRACE_LOG: ' + line)
2024-05-12 19:15:52.068
2024-05-12 19:15:52.072 act.expected_stdout = trace_expected
2024-05-12 19:15:52.077 act.stdout = capsys.readouterr().out
2024-05-12 19:15:52.081 assert act.clean_stdout == act.clean_expected_stdout
2024-05-12 19:15:52.089 act.reset()
2024-05-12 19:15:52.093
2024-05-12 19:15:52.098 #----------------------------------------------------------------
2024-05-12 19:15:52.103
2024-05-12 19:15:52.107 with act.connect_server() as srv:
2024-05-12 19:15:52.112 srv.info.get_log()
2024-05-12 19:15:52.117 log_after = srv.readlines()
2024-05-12 19:15:52.122
2024-05-12 19:15:52.127 '''
2024-05-12 19:15:52.132 Example of diff:
2024-05-12 19:15:52.136 COMPUTERNAME	Wed Sep 14 15:58:37 2022
2024-05-12 19:15:52.141 Sweep is started by SYSDBA
2024-05-12 19:15:52.146 Database "C:/TEMP/PYTEST_PATH/TEST.FDB"
2024-05-12 19:15:52.151 OIT 20, OAT 21, OST 21, Next 21
2024-05-12 19:15:52.156
2024-05-12 19:15:52.161 COMPUTERNAME	Wed Sep 14 15:58:37 2022
2024-05-12 19:15:52.166 Error during sweep of C:/PYTEST_PATH/TEST.FDB:
2024-05-12 19:15:52.171 connection shutdown
2024-05-12 19:15:52.176 '''
2024-05-12 19:15:52.181
2024-05-12 19:15:52.186 p_tx_counter  = re.compile("\\+[\\s]+OIT[ ]+\\d+,[\\s]*OAT[\\s]+\\d+,[\\s]*OST[\\s]+\\d+,[\\s]*NEXT[\\s]+\\d+")
2024-05-12 19:15:52.191 for line in unified_diff(log_before, log_after):
2024-05-12 19:15:52.197 if line.startswith('+'):
2024-05-12 19:15:52.202 line = line.upper()
2024-05-12 19:15:52.207 if 'SWEEP' in line or 'CONNECTION' in line or p_tx_counter.match(line):
2024-05-12 19:15:52.212 print( 'FIREBIRD.LOG: ' + (' '.join(line.split())) )
2024-05-12 19:15:52.217
2024-05-12 19:15:52.222 fb_log_expected = """
2024-05-12 19:15:52.226 FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
2024-05-12 19:15:52.231 FIREBIRD.LOG: + OIT, OAT, OST, NEXT
2024-05-12 19:15:52.236 FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
2024-05-12 19:15:52.241 FIREBIRD.LOG: + CONNECTION SHUTDOWN
2024-05-12 19:15:52.246 """
2024-05-12 19:15:52.250
2024-05-12 19:15:52.256 act.expected_stdout = fb_log_expected
2024-05-12 19:15:52.261 act.stdout = capsys.readouterr().out
2024-05-12 19:15:52.266 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-12 19:15:52.271 E       assert
2024-05-12 19:15:52.275 E         + FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
2024-05-12 19:15:52.280 E         + FIREBIRD.LOG: + OIT, OAT, OST, NEXT
2024-05-12 19:15:52.285 E           FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
2024-05-12 19:15:52.289 E           FIREBIRD.LOG: + OIT, OAT, OST, NEXT
2024-05-12 19:15:52.294 E           FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
2024-05-12 19:15:52.299 E           FIREBIRD.LOG: + CONNECTION SHUTDOWN
2024-05-12 19:15:52.303 E         + FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
2024-05-12 19:15:52.309 E         + FIREBIRD.LOG: + CONNECTION SHUTDOWN
2024-05-12 19:15:52.314
2024-05-12 19:15:52.320 tests/bugs/core_4337_test.py:315: AssertionError
2024-05-12 19:15:52.325 ---------------------------- Captured stdout setup -----------------------------
2024-05-12 19:15:52.330 Cached db: db-12.0-16384-None-NONE.fdb [page_size=16384, sql_dialect=None, charset='NONE'
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
sweep_log = PosixPath('/var/tmp/qa_2024/test_1824/tmp_4337_sweep.log')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=3.0')
    def test_1(act: Action, sweep_log: Path, capsys):
    
        with act.connect_server() as srv:
    
            # REDUCE number of cache buffers in DB header in order to sweep make its work as long as possible
            srv.database.set_default_cache_size(database=act.db.db_path, size=75)
    
            # Change FW to ON (in order to make sweep life harder :))
            srv.database.set_write_mode(database=act.db.db_path, mode=DbWriteMode.SYNC)
    
            srv.info.get_log()
            log_before = srv.readlines()
    
        #---------------------------------------------------------------
    
        # How long can we wait (milliseconds) for the FIRST appearance of 'gfix' process in mon$attachments:
        #
        MAX_WAIT_FOR_SWEEP_START_MS = 3000
    
        # How long we wait (milliseconds) for SECOND appearance of 'gfix' process in mon$attachments, after it was killed.
        # NOTE. If it appears then we have a BUG
        MAX_WAIT_FOR_GFIX_RESTART_MS = 3000
    
        sweep_attach_id = None
        sweep_reconnect = None
        # Start trace
        with act.trace(db_events=trace):
            with act.db.connect() as con:
                f_sweep_log = open(sweep_log,'w')
                stm = r"select first 1 a.mon$attachment_id from mon$attachments a where a.mon$system_flag <> 1 and lower(a.mon$remote_process) similar to '(%[\\/](gfix|fbsvcmgr)(.exe)?)'"
                t1=py_dt.datetime.now()
                with con.cursor() as cur1:
                    ps1 = cur1.prepare(stm)
                    p_sweep = subprocess.Popen( [act.vars['gfix'], '-sweep', '-user', act.db.user, '-password', act.db.password, act.db.dsn],
                                                stdout = f_sweep_log,
                                                stderr = subprocess.STDOUT
                                              )
    
                    ##########################################################################
                    # LOOP-1: WAIT FOR FIRST APPEARANCE OF GFIX PROCESS IN THE MON$ATTACHMENTS
                    ##########################################################################
                    while True:
                        t2=py_dt.datetime.now()
                        d1=t2-t1
                        dd = d1.seconds*1000 + d1.microseconds//1000
                        if dd > MAX_WAIT_FOR_SWEEP_START_MS:
                            print(f'TIMEOUT EXPIRATION: waiting for SWEEP process took {dd} ms which exceeds limit = {MAX_WAIT_FOR_SWEEP_START_MS} ms.')
                            break
    
                        cur1.execute(ps1)
                        for r in cur1:
                            sweep_attach_id = r[0]
    
                        con.commit()
                        if sweep_attach_id:
                            break
                        else:
                            time.sleep(0.1)
                    #<while True (loop for search gfix process in mon$attachments)
    
                #< with con.cursor() as cur1
    
                #assert sweep_attach_id is None, f'attacment_id of SWEEP process is {sweep_attach_id}'
                assert sweep_attach_id, 'attacment_id of SWEEP process was not found.'
    
                # Let sweep to have some 'useful work':
                #
                time.sleep(1)
    
                # Now we can KILL attachment that belongs to SWEEP process, <sweep_attach_id>:
                con.execute_immediate(f'delete from mon$attachments where mon$attachment_id = {sweep_attach_id}')
    
                p_sweep.wait()
                f_sweep_log.close()
    
                assert p_sweep.returncode == 1, 'p_sweep.returncode: {p_sweep.returncode}'
    
    
                ##################################################################################################
                # LOOP-2: WAIT FOR POSSIBLE SECOND APPEARENCE (RECONNECT) OF GFIX. IF IT OCCURS THEN WE HAVE A BUG
                ##################################################################################################
                t1=py_dt.datetime.now()
                with con.cursor() as cur2:
                    ps2 = cur2.prepare( stm.replace('select ', 'select /* search re-connect that could be made */ ') )
                    while True:
                        t2=py_dt.datetime.now()
                        d1=t2-t1
                        dd = d1.seconds*1000 + d1.microseconds//1000
                        if dd > MAX_WAIT_FOR_GFIX_RESTART_MS:
                            # Expected: gfix reconnect was not detected for last {MAX_WAIT_FOR_GFIX_RESTART_MS} ms.
                            break
                        con.commit()
                        cur2.execute(ps2)
                        # Resultset now must be EMPTY. we must not find any record!
                        for r in cur2:
                            sweep_reconnect = r[0]
    
                        #con.commit()
                        if sweep_reconnect:
                            # UNEXPECTED: gfix reconnect found, with attach_id={sweep_reconnect}
                            break
                        else:
                            time.sleep(0.1)
                #< with con.cursor() as cur2
    
                assert sweep_reconnect is None, f'Found re-connect of SWEEP process, attachment: {sweep_reconnect}'
    
            #< with db.connect as con
    
        #---------------------------------------------------------------
        # DISABLED 25.09.2022. SWEEP log can remain empty (4.0.1.2692 Classic)
        ## Check-1: log of sweep must contain text: 'connection shutdown':
        #for line in sweep_log.read_text().splitlines():
        #    if line:
        #        print('SWEEP LOG:', line.upper())
        #
        #act.expected_stdout = 'sweep log: connection shutdown'.upper()
        #act.stdout = capsys.readouterr().out
        #assert act.clean_stdout == act.clean_expected_stdout
        #act.reset()
        #---------------------------------------------------------------
    
        # Trace log
        found_sweep_failed = 0
        p_sweep_failed = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+SWEEP_FAILED$', re.IGNORECASE)
        p_att_success = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+ATTACH_DATABASE$', re.IGNORECASE)
    
        trace_expected = 'FOUND SWEEP_FAILED MESSAGE.'
        for i,line in enumerate(act.trace_log):
            if line.strip():
                if p_sweep_failed.search(line.strip()):
                    print(trace_expected)
                    found_sweep_failed = 1
                if found_sweep_failed == 1 and p_att_success.search(line) and i < len(act.trace_log)-2 and 'gfix' in act.trace_log[i+2].lower():
                    # NB: we have to ignore "FAILED ATTACH_DATABASE".
                    # It can occur in some cases.
                    print('TRACE: UNEXPECTED ATTACH FOUND AFTER KILL SWEEP! CHECK LINE N {i}:')
                    print('TRACE_LOG: ' + line)
    
        act.expected_stdout = trace_expected
        act.stdout = capsys.readouterr().out
        assert act.clean_stdout == act.clean_expected_stdout
        act.reset()
    
        #----------------------------------------------------------------
    
        with act.connect_server() as srv:
            srv.info.get_log()
            log_after = srv.readlines()
    
        '''
        Example of diff:
        COMPUTERNAME	Wed Sep 14 15:58:37 2022
        	Sweep is started by SYSDBA
        	Database "C:/TEMP/PYTEST_PATH/TEST.FDB"
        	OIT 20, OAT 21, OST 21, Next 21
    
        COMPUTERNAME	Wed Sep 14 15:58:37 2022
        	Error during sweep of C:/PYTEST_PATH/TEST.FDB:
        	connection shutdown
        '''
    
        p_tx_counter  = re.compile("\\+[\\s]+OIT[ ]+\\d+,[\\s]*OAT[\\s]+\\d+,[\\s]*OST[\\s]+\\d+,[\\s]*NEXT[\\s]+\\d+")
        for line in unified_diff(log_before, log_after):
            if line.startswith('+'):
                line = line.upper()
                if 'SWEEP' in line or 'CONNECTION' in line or p_tx_counter.match(line):
                    print( 'FIREBIRD.LOG: ' + (' '.join(line.split())) )
    
        fb_log_expected = """
            FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
            FIREBIRD.LOG: + OIT, OAT, OST, NEXT
            FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
            FIREBIRD.LOG: + CONNECTION SHUTDOWN
        """
    
        act.expected_stdout = fb_log_expected
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         + FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
E         + FIREBIRD.LOG: + OIT, OAT, OST, NEXT
E           FIREBIRD.LOG: + SWEEP IS STARTED BY SYSDBA
E           FIREBIRD.LOG: + OIT, OAT, OST, NEXT
E           FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
E           FIREBIRD.LOG: + CONNECTION SHUTDOWN
E         + FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB
E         + FIREBIRD.LOG: + CONNECTION SHUTDOWN

tests/bugs/core_4337_test.py:315: 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 3.0.13.33809 2025.05.06 28ad0 P P 12757 12178 2025.06.30 14:41:07.629 2025.06.30 14:41:20.386 2025.06.30 13:53:15.497 2025.06.30 13:53:27.675
2 3.0.13.33808 2025.04.25 28426 P P 13808 13253 2025.05.06 13:39:29.946 2025.05.06 13:39:43.754 2025.05.06 12:43:02.014 2025.05.06 12:43:15.267
3 3.0.13.33803 2025.02.25 08ebd P P 13823 13151 2025.04.25 16:54:27.642 2025.04.25 16:54:41.465 2025.04.25 15:58:28.802 2025.04.25 15:58:41.953
4 3.0.13.33796 2025.01.29 0ab85 P P 3208 1224 2025.02.25 15:27:17.840 2025.02.25 15:27:21.048 2025.02.25 14:31:33.565 2025.02.25 14:31:34.789
5 3.0.13.33796 2025.01.14 99b3b P P 3311 1190 2025.01.28 17:41:00.416 2025.01.28 17:41:03.727 2025.01.28 16:44:04.275 2025.01.28 16:44:05.465
6 3.0.13.33795 2024.11.24 b8847 P P 3049 1244 2025.01.13 15:18:46.091 2025.01.13 15:18:49.140 2025.01.13 14:22:26.740 2025.01.13 14:22:27.984
7 3.0.13.33794 2024.10.15 abe09 P P 2359 968 2024.11.23 06:27:17.924 2024.11.23 06:27:20.283 2024.11.23 05:44:38.529 2024.11.23 05:44:39.497
8 3.0.13.33793 2024.10.04 82ccc P P 3092 1239 2024.10.14 04:22:47.595 2024.10.14 04:22:50.687 2024.10.14 03:36:03.441 2024.10.14 03:36:04.680
9 3.0.13.33792 2024.08.31 d8791 P P 3162 1166 2024.10.03 09:28:59.369 2024.10.03 09:29:02.531 2024.10.03 08:39:04.122 2024.10.03 08:39:05.288
10 3.0.13.33787 2024.08.17 2e0d6 P P 6459 2244 2024.08.25 15:10:27.574 2024.08.25 15:10:34.033 2024.08.25 13:21:31.007 2024.08.25 13:21:33.251
11 3.0.13.33787 2024.08.09 df740 P P 3610 1532 2024.08.16 12:43:27.650 2024.08.16 12:43:31.260 2024.08.16 11:47:17.699 2024.08.16 11:47:19.231
12 3.0.12.33746 2024.07.15 11dd4 P P 3243 1535 2024.08.09 12:40:27.854 2024.08.09 12:40:31.097 2024.08.09 11:42:16.621 2024.08.09 11:42:18.156
13 3.0.12.33746 2024.06.11 8a5eb P P 3091 1282 2024.07.15 10:31:54.589 2024.07.15 10:31:57.680 2024.07.15 09:44:05.520 2024.07.15 09:44:06.802
14 3.0.12.33744 2024.05.09 9cf37 F P 3041 1125 2024.05.12 15:39:50.123 2024.05.12 15:39:53.164 2024.05.12 14:56:11.457 2024.05.12 14:56:12.582
15 3.0.12.33744 2024.04.20 af6b2 P P 2834 1028 2024.05.08 16:55:25.890 2024.05.08 16:55:28.724 2024.05.08 16:14:09.973 2024.05.08 16:14:11.001

Elapsed time, ms. Chart for last 15 runs:

Last commits information (all timestamps in UTC):