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

Annotation type Annotation details
2 @message
assert   
  - RESULT_MSG                      OK: second EDS was fast
  + RESULT_MSG                      FAILED: second EDS waited too long, 675.0 ms - more than max_wait_ms=500

LOG DETAILS:

2024-08-30 14:20:49.538
2024-08-30 14:20:49.549 act = <firebird.qa.plugin.Action object at [hex]>
2024-08-30 14:20:49.557 eds_script = PosixPath('/var/tmp/qa_2024/test_11121/eds_script.sql')
2024-08-30 14:20:49.564
2024-08-30 14:20:49.573 @pytest.mark.es_eds
2024-08-30 14:20:49.579 @pytest.mark.version('>=3.0.3')
2024-08-30 14:20:49.587 def test_1(act: Action, eds_script: Path):
2024-08-30 14:20:49.594 eds_sql = f"""
2024-08-30 14:20:49.603 set bail on;
2024-08-30 14:20:49.612 set list on;
2024-08-30 14:20:49.623 --select current_timestamp as " " from rdb$database;
2024-08-30 14:20:49.631 set term ^;
2024-08-30 14:20:49.640 execute block as
2024-08-30 14:20:49.649 declare c smallint;
2024-08-30 14:20:49.657 declare remote_host varchar(50) = '%(remote_host)s'; -- never unreachable: 192.0.2.2
2024-08-30 14:20:49.663 begin
2024-08-30 14:20:49.670 rdb$set_context('USER_SESSION','DTS_BEG', cast('now' as timestamp) );
2024-08-30 14:20:49.676 execute statement 'select 1 from rdb$database'
2024-08-30 14:20:49.683 on external remote_host || ':' || rdb$get_context('SYSTEM', 'DB_NAME')
2024-08-30 14:20:49.689 as user '{act.db.user}' password '{act.db.password}'
2024-08-30 14:20:49.695 into c;
2024-08-30 14:20:50.317 end
2024-08-30 14:20:50.331 ^
2024-08-30 14:20:50.341 set term ;^
2024-08-30 14:20:50.350 --select current_timestamp as " " from rdb$database;
2024-08-30 14:20:50.358 select iif( waited_ms < max_wait_ms,
2024-08-30 14:20:50.367 'OK: second EDS was fast',
2024-08-30 14:20:50.375 'FAILED: second EDS waited too long, ' || waited_ms || ' ms - more than max_wait_ms='||max_wait_ms
2024-08-30 14:20:50.383 ) as result_msg
2024-08-30 14:20:50.391 from (
2024-08-30 14:20:50.399 select
2024-08-30 14:20:50.407 datediff( millisecond from cast( rdb$get_context('USER_SESSION','DTS_BEG') as timestamp) to current_timestamp ) as waited_ms
2024-08-30 14:20:50.415 ,500 as max_wait_ms
2024-08-30 14:20:50.423 --   ^
2024-08-30 14:20:50.430 --   |                                  #################
2024-08-30 14:20:50.439 --   +--------------------------------  T H R E S H O L D
2024-08-30 14:20:50.447 --                                      #################
2024-08-30 14:20:50.454 from rdb$database
2024-08-30 14:20:50.461 );
2024-08-30 14:20:50.469 """
2024-08-30 14:20:50.476 #
2024-08-30 14:20:50.483 remote_host = '192.0.2.2'
2024-08-30 14:20:50.491 eds_script.write_text(eds_sql % locals())
2024-08-30 14:20:50.499 p_unavail_host = subprocess.Popen([act.vars['isql'], '-n', '-i', str(eds_script),
2024-08-30 14:20:50.509 '-user', act.db.user,
2024-08-30 14:20:50.518 '-password', act.db.password, act.db.dsn],
2024-08-30 14:20:50.526 stdout=subprocess.DEVNULL, stderr=subprocess.STDOUT)
2024-08-30 14:20:50.534 try:
2024-08-30 14:20:50.542 time.sleep(2)
2024-08-30 14:20:50.551 remote_host = 'localhost'
2024-08-30 14:20:50.559 act.expected_stdout = expected_stdout
2024-08-30 14:20:50.569 act.isql(switches=['-n'], input=eds_sql % locals())
2024-08-30 14:20:50.577 finally:
2024-08-30 14:20:50.593 p_unavail_host.terminate()
2024-08-30 14:20:50.613 # Ensure that database is not busy
2024-08-30 14:20:50.621 with act.connect_server() as srv:
2024-08-30 14:20:50.630 srv.database.shutdown(database=act.db.db_path, mode=ShutdownMode.FULL,
2024-08-30 14:20:50.638 method=ShutdownMethod.FORCED, timeout=0)
2024-08-30 14:20:50.645 srv.database.bring_online(database=act.db.db_path)
2024-08-30 14:20:50.652 # Check
2024-08-30 14:20:50.660 >       assert act.clean_stdout == act.clean_expected_stdout
2024-08-30 14:20:50.676 E       assert
2024-08-30 14:20:50.684 E         - RESULT_MSG                      OK: second EDS was fast
2024-08-30 14:20:50.692 E         + RESULT_MSG                      FAILED: second EDS waited too long, 675.0 ms - more than max_wait_ms=500
2024-08-30 14:20:50.700
2024-08-30 14:20:50.709 tests/bugs/core_5648_test.py:99: AssertionError
2024-08-30 14:20:50.716 ---------------------------- Captured stdout setup -----------------------------
2024-08-30 14:20:50.725 Creating db: localhost:/var/tmp/qa_2024/test_11121/test.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
eds_script = PosixPath('/var/tmp/qa_2024/test_11121/eds_script.sql')

    @pytest.mark.es_eds
    @pytest.mark.version('>=3.0.3')
    def test_1(act: Action, eds_script: Path):
        eds_sql = f"""
        set bail on;
        set list on;
        --select current_timestamp as " " from rdb$database;
        set term ^;
        execute block as
            declare c smallint;
            declare remote_host varchar(50) = '%(remote_host)s'; -- never unreachable: 192.0.2.2
        begin
            rdb$set_context('USER_SESSION','DTS_BEG', cast('now' as timestamp) );
            execute statement 'select 1 from rdb$database'
            on external remote_host || ':' || rdb$get_context('SYSTEM', 'DB_NAME')
            as user '{act.db.user}' password '{act.db.password}'
            into c;
        end
        ^
        set term ;^
        --select current_timestamp as " " from rdb$database;
        select iif( waited_ms < max_wait_ms,
                    'OK: second EDS was fast',
                    'FAILED: second EDS waited too long, ' || waited_ms || ' ms - more than max_wait_ms='||max_wait_ms
                  ) as result_msg
        from (
            select
                datediff( millisecond from cast( rdb$get_context('USER_SESSION','DTS_BEG') as timestamp) to current_timestamp ) as waited_ms
               ,500 as max_wait_ms
            --   ^
            --   |                                  #################
            --   +--------------------------------  T H R E S H O L D
            --                                      #################
            from rdb$database
        );
        """
        #
        remote_host = '192.0.2.2'
        eds_script.write_text(eds_sql % locals())
        p_unavail_host = subprocess.Popen([act.vars['isql'], '-n', '-i', str(eds_script),
                                           '-user', act.db.user,
                                           '-password', act.db.password, act.db.dsn],
                                          stdout=subprocess.DEVNULL, stderr=subprocess.STDOUT)
        try:
            time.sleep(2)
            remote_host = 'localhost'
            act.expected_stdout = expected_stdout
            act.isql(switches=['-n'], input=eds_sql % locals())
        finally:
            p_unavail_host.terminate()
        # Ensure that database is not busy
        with act.connect_server() as srv:
            srv.database.shutdown(database=act.db.db_path, mode=ShutdownMode.FULL,
                                  method=ShutdownMethod.FORCED, timeout=0)
            srv.database.bring_online(database=act.db.db_path)
        # Check
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - RESULT_MSG                      OK: second EDS was fast
E         + RESULT_MSG                      FAILED: second EDS waited too long, 675.0 ms - more than max_wait_ms=500

tests/bugs/core_5648_test.py:99: 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.33814 2025.06.21 85255 P P 134980 134523 2025.07.01 10:15:42.771 2025.07.01 10:17:57.751 2025.07.01 09:27:48.394 2025.07.01 09:30:02.917
2 3.0.13.33813 2025.06.14 222a9 P P 134713 135628 2025.06.20 03:55:37.497 2025.06.20 03:57:52.210 2025.06.20 03:07:50.075 2025.06.20 03:10:05.703
3 3.0.13.33811 2025.05.07 16491 P P 133865 136582 2025.06.14 10:24:20.997 2025.06.14 10:26:34.862 2025.06.14 09:35:48.917 2025.06.14 09:38:05.499
4 3.0.13.33810 2025.05.06 02b1d P P 135957 134600 2025.05.07 08:52:05.266 2025.05.07 08:54:21.223 2025.05.07 07:56:34.575 2025.05.07 07:58:49.175
5 3.0.13.33809 2025.05.05 4ec6d P P 134308 134681 2025.05.06 08:58:18.624 2025.05.06 09:00:32.932 2025.05.06 08:02:25.943 2025.05.06 08:04:40.624
6 3.0.13.33808 2025.04.18 bf513 P P 135127 134729 2025.05.04 22:52:33.022 2025.05.04 22:54:48.149 2025.05.04 21:43:08.501 2025.05.04 21:45:23.230
7 3.0.13.33807 2025.04.14 73e94 P P 134816 135636 2025.04.18 08:51:32.615 2025.04.18 08:53:47.431 2025.04.18 07:54:58.870 2025.04.18 07:57:14.506
8 3.0.13.33806 2025.03.26 b6cfe P P 134643 134551 2025.04.14 07:43:55.684 2025.04.14 07:46:10.327 2025.04.14 06:52:52.429 2025.04.14 06:55:06.980
9 3.0.13.33805 2025.03.17 98320 P P 134745 134548 2025.03.25 05:08:43.304 2025.03.25 05:10:58.049 2025.03.25 04:18:33.455 2025.03.25 04:20:48.003
10 3.0.13.33804 2025.02.25 1439d P P 2185 1784 2025.03.17 05:21:35.024 2025.03.17 05:21:37.209 2025.03.17 04:25:11.993 2025.03.17 04:25:13.777
11 3.0.13.33803 2025.01.29 f1848 P P 2138 1875 2025.02.25 08:00:44.805 2025.02.25 08:00:46.943 2025.02.25 07:06:23.222 2025.02.25 07:06:25.097
12 3.0.13.33802 2025.01.28 650bd P P 3130 1511 2025.01.29 22:51:08.125 2025.01.29 22:51:11.255 2025.01.29 21:43:55.917 2025.01.29 21:43:57.428
13 3.0.13.33800 2025.01.20 f20ab P P 2217 1679 2025.01.28 08:17:40.620 2025.01.28 08:17:42.837 2025.01.28 07:20:47.156 2025.01.28 07:20:48.835
14 3.0.13.33798 2025.01.16 0c3bb P P 1961 1629 2025.01.20 07:49:31.010 2025.01.20 07:49:32.971 2025.01.20 06:53:26.785 2025.01.20 06:53:28.414
15 3.0.13.33795 2024.12.23 1bf0b P P 2119 1563 2025.01.16 07:46:12.347 2025.01.16 07:46:14.466 2025.01.16 06:51:33.774 2025.01.16 06:51:35.337
16 3.0.13.33794 2024.10.23 e2a6b P P 1534 1277 2024.12.23 01:29:09.765 2024.12.23 01:29:11.299 2024.12.23 00:47:02.852 2024.12.23 00:47:04.129
17 3.0.13.33793 2024.09.02 3e627 P P 1957 1420 2024.10.23 07:35:11.348 2024.10.23 07:35:13.305 2024.10.23 06:47:49.366 2024.10.23 06:47:50.786
18 3.0.13.33792 2024.08.30 d9f38 P P 2926 2260 2024.09.02 11:07:11.540 2024.09.02 11:07:14.466 2024.09.02 09:29:40.569 2024.09.02 09:29:42.829
19 3.0.13.33791 2024.08.21 c8a36 F P 3067 2247 2024.08.30 10:41:16.452 2024.08.30 10:41:19.519 2024.08.30 09:13:06.383 2024.08.30 09:13:08.630
20 3.0.13.33790 2024.08.20 3bf52 P P 3519 2807 2024.08.21 10:10:36.049 2024.08.21 10:10:39.568 2024.08.21 08:48:06.534 2024.08.21 08:48:09.341
21 3.0.13.33789 2024.08.09 7933a P P 2161 1652 2024.08.19 06:26:51.342 2024.08.19 06:26:53.503 2024.08.19 05:29:51.189 2024.08.19 05:29:52.841
22 3.0.12.33787 2024.08.06 bf180 P P 2274 1716 2024.08.09 06:13:44.912 2024.08.09 06:13:47.186 2024.08.09 05:17:09.461 2024.08.09 05:17:11.177
23 3.0.12.33784 2024.08.01 cd857 P P 1775 1552 2024.08.06 05:12:19.522 2024.08.06 05:12:21.297 2024.08.06 04:24:22.221 2024.08.06 04:24:23.773
24 3.0.12.33779 2024.07.31 ae35d P P 1802 1630 2024.08.01 05:10:44.323 2024.08.01 05:10:46.125 2024.08.01 04:22:53.706 2024.08.01 04:22:55.336
25 3.0.12.33778 2024.07.21 4680d P P 1736 1479 2024.07.30 05:07:48.204 2024.07.30 05:07:49.940 2024.07.30 04:19:57.403 2024.07.30 04:19:58.882
26 3.0.12.33777 2024.07.19 8e912 P P 1704 1456 2024.07.21 05:09:52.052 2024.07.21 05:09:53.756 2024.07.21 04:22:04.940 2024.07.21 04:22:06.396
27 3.0.12.33766 2024.07.13 b5086 P P 1832 1430 2024.07.19 05:02:17.472 2024.07.19 05:02:19.304 2024.07.19 04:14:55.236 2024.07.19 04:14:56.666
28 3.0.12.33765 2024.07.10 06f2a P P 1677 1616 2024.07.13 05:05:11.466 2024.07.13 05:05:13.143 2024.07.13 04:17:25.037 2024.07.13 04:17:26.653
29 3.0.12.33764 2024.06.18 4d0c0 P P 1785 1443 2024.07.10 04:54:06.940 2024.07.10 04:54:08.725 2024.07.10 04:07:58.755 2024.07.10 04:08:00.198
30 3.0.12.33761 2024.06.17 b259d P P 1792 1416 2024.06.18 04:55:39.424 2024.06.18 04:55:41.216 2024.06.18 04:08:58.075 2024.06.18 04:08:59.491
31 3.0.12.33758 2024.06.14 4f9bc P P 1934 1545 2024.06.17 04:51:12.191 2024.06.17 04:51:14.125 2024.06.17 04:03:07.339 2024.06.17 04:03:08.884
32 3.0.12.33757 2024.06.13 c7a1c P P 1660 1299 2024.06.14 05:04:21.757 2024.06.14 05:04:23.417 2024.06.14 04:23:46.751 2024.06.14 04:23:48.050
33 3.0.12.33744 2024.04.19 ecf36 P P 1697 1461 2024.05.08 15:44:44.430 2024.05.08 15:44:46.127 2024.05.08 15:03:33.396 2024.05.08 15:03:34.857

Elapsed time, ms. Chart for last 33 runs:

Last commits information (all timestamps in UTC):