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   
  - Changed ID: -1
  + Dynamic SQL Error
  + -SQL error code = -901
  + -invalid request handle
  + gds codes:
  + 335544569
  + 335544436
  + 335544327

LOG DETAILS:

2025-02-14 09:37:03.837
2025-02-14 09:37:03.837 act = <firebird.qa.plugin.Action object at [hex]>
2025-02-14 09:37:03.837 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-02-14 09:37:03.837
2025-02-14 09:37:03.837     @pytest.mark.version('>=5.0.1')
2025-02-14 09:37:03.837     def test_1(act: Action, capsys):
2025-02-14 09:37:03.837
2025-02-14 09:37:03.838         srv_cfg = driver_config.register_server(name = 'test_srv_gh_8185', config = '')
2025-02-14 09:37:03.838         db_cfg_name = f'db_cfg_8185'
2025-02-14 09:37:03.838         db_cfg_object = driver_config.register_database(name = db_cfg_name)
2025-02-14 09:37:03.838         db_cfg_object.server.value = srv_cfg.name
2025-02-14 09:37:03.838         db_cfg_object.database.value = str(act.db.db_path)
2025-02-14 09:37:03.838         db_cfg_object.config.value = f"""
2025-02-14 09:37:03.838             MaxStatementCacheSize = 1M
2025-02-14 09:37:03.838         """
2025-02-14 09:37:03.838
2025-02-14 09:37:03.838         # Pre-check:
2025-02-14 09:37:03.838         with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-02-14 09:37:03.838             cur = con.cursor()
2025-02-14 09:37:03.838             cur.execute("select a.mon$remote_protocol, g.rdb$config_value from mon$attachments a left join rdb$config g on g.rdb$config_name = 'MaxStatementCacheSize' where a.mon$attachment_id = current_connection")
2025-02-14 09:37:03.838             for r in cur:
2025-02-14 09:37:03.838                 conn_protocol = r[0]
2025-02-14 09:37:03.838                 db_sttm_cache_size = int(r[1])
2025-02-14 09:37:03.838             assert conn_protocol is None, "Test must use LOCAL protocol."
2025-02-14 09:37:03.838             assert db_sttm_cache_size > 0, "Parameter 'MaxStatementCacheSize' (per-database) must be greater than zero for this test."
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839         #---------------------------------------------
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839         CURSOR_NAME = 'k1'
2025-02-14 09:37:03.839         SELECT_STTM = 'select /* ps-1*/ id, f01 from test where id > 0 for update'
2025-02-14 09:37:03.839         UPDATE_STTM = f'update /* ps-2 */ test set id = -id where current of {CURSOR_NAME} returning id'
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839         update_tpb = tpb( access_mode = TraAccessMode.WRITE,
2025-02-14 09:37:03.839                           isolation = Isolation.READ_COMMITTED_RECORD_VERSION,
2025-02-14 09:37:03.839                           lock_timeout = 1)
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839         with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839             tx2 = con.transaction_manager(update_tpb)
2025-02-14 09:37:03.839             tx2.begin()
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839             with con.cursor() as cur1, tx2.cursor() as cur2, con.cursor() as cur3:
2025-02-14 09:37:03.839
2025-02-14 09:37:03.839                 ps1, rs1, ps2, rs2, ps3, rs3 = None, None, None, None, None, None
2025-02-14 09:37:03.840                 try:
2025-02-14 09:37:03.840                     ps1 = cur1.prepare(SELECT_STTM)         # 1. [ticket, DS] Prepare statement 1 "select ... for update"
2025-02-14 09:37:03.840                     ps1._istmt.set_cursor_name(CURSOR_NAME) # 2. [ticket, DS] Set cursor name for statement 1 // ~hack.
2025-02-14 09:37:03.840
2025-02-14 09:37:03.840                     # DO NOT use it because subsequent update statement will get 'deadlock /  update conflict' and not able to start:
2025-02-14 09:37:03.840                     #rs1 = cur1.execute(ps1)
2025-02-14 09:37:03.840                     #cur1.set_cursor_name(CURSOR_NAME)
2025-02-14 09:37:03.840
2025-02-14 09:37:03.840                     # DS example: "// Prepare positioned update statement"
2025-02-14 09:37:03.840                     ps2 = cur2.prepare(UPDATE_STTM)         # 3. [ticket, DS] Prepare statement 2 "update ... where current of <cursor name from step 2>"
2025-02-14 09:37:03.840
2025-02-14 09:37:03.840                     # DS .cpp: // fetch records from cursor and print them
2025-02-14 09:37:03.840                     rs1 = cur1.execute(ps1)
2025-02-14 09:37:03.840                     rs1.fetchall()
2025-02-14 09:37:03.840
2025-02-14 09:37:03.840                     # DS .cpp: // IStatement* stmt2 = att->prepare(&status, tra, 0, "select * from pos where a > 1 for update",
2025-02-14 09:37:03.840                     ps3 = cur3.prepare(SELECT_STTM)         # 4. [ticket, DS] Prepare statement 3 similar to statement 1
2025-02-14 09:37:03.840
2025-02-14 09:37:03.841                     rs1.close()                             # 5. [ticket, DS] Release statement 1 // see hvlad recipe, 26.10.2024
2025-02-14 09:37:03.841                     ps1.free()
2025-02-14 09:37:03.841
2025-02-14 09:37:03.841                     # DS .cpp: updStmt->free(&status);
2025-02-14 09:37:03.841                     ps2.free()                              # 6. [ticket, DS] Release statement 2 // see hvlad recipe, 26.10.2024
2025-02-14 09:37:03.841
2025-02-14 09:37:03.841                     # DS .cpp: stmt = stmt2
2025-02-14 09:37:03.841                     ps3._istmt.set_cursor_name(CURSOR_NAME) # 7. [ticket, DS] Set cursor name to statement 3 as in step 2
2025-02-14 09:37:03.841
2025-02-14 09:37:03.841                     ps2 = cur2.prepare(UPDATE_STTM)         # 8. [ticket, DS] Prepare statement 2 again (it will be got from cache keeping reference to statement 1)
2025-02-14 09:37:03.841
2025-02-14 09:37:03.841                     rs3 = cur3.execute(ps3)
2025-02-14 09:37:03.841                     rs3.fetchone()                          # 9. [ticket, DS] Run statement 3 and fetch one record
2025-02-14 09:37:03.841
2025-02-14 09:37:03.841                     # At step 10 you can get "Invalid handle" error or a crash if you swap steps 5 and 6.
2025-02-14 09:37:03.841                     rs2 = cur2.execute(ps2)                 # 10. [ticket, DS] Execute statement 2
2025-02-14 09:37:03.841                     data2 = rs2.fetchone()
2025-02-14 09:37:03.841                     print('Changed ID:', data2[0])
2025-02-14 09:37:03.842                     # print(f'{rs2.rowcount=}')
2025-02-14 09:37:03.842
2025-02-14 09:37:03.842                 except DatabaseError as e:
2025-02-14 09:37:03.842                     print(e.__str__())
2025-02-14 09:37:03.842                     print('gds codes:')
2025-02-14 09:37:03.842                     for i in e.gds_codes:
2025-02-14 09:37:03.842                         print(i)
2025-02-14 09:37:03.842
2025-02-14 09:37:03.842                 finally:
2025-02-14 09:37:03.842                     if rs1:
2025-02-14 09:37:03.842                         rs1.close()
2025-02-14 09:37:03.842                     if ps1:
2025-02-14 09:37:03.842                         ps1.free()
2025-02-14 09:37:03.842
2025-02-14 09:37:03.842                     if rs2:
2025-02-14 09:37:03.842                         rs2.close()
2025-02-14 09:37:03.842                     if ps2:
2025-02-14 09:37:03.842                         ps2.free()
2025-02-14 09:37:03.843
2025-02-14 09:37:03.843                     if rs3:
2025-02-14 09:37:03.843                         rs3.close()
2025-02-14 09:37:03.843                     if ps3:
2025-02-14 09:37:03.843                         ps3.free()
2025-02-14 09:37:03.843
2025-02-14 09:37:03.843         #---------------------------------------------
2025-02-14 09:37:03.843
2025-02-14 09:37:03.843         act.expected_stdout = 'Changed ID: -1'
2025-02-14 09:37:03.843         act.stdout = capsys.readouterr().out
2025-02-14 09:37:03.843 >       assert act.clean_stdout == act.clean_expected_stdout
2025-02-14 09:37:03.843 E       assert
2025-02-14 09:37:03.843 E         - Changed ID: -1
2025-02-14 09:37:03.843 E         + Dynamic SQL Error
2025-02-14 09:37:03.843 E         + -SQL error code = -901
2025-02-14 09:37:03.843 E         + -invalid request handle
2025-02-14 09:37:03.843 E         + gds codes:
2025-02-14 09:37:03.843 E         + 335544569
2025-02-14 09:37:03.843 E         + 335544436
2025-02-14 09:37:03.844 E         + 335544327
2025-02-14 09:37:03.844
2025-02-14 09:37:03.844 tests\bugs\gh_8185_test.py:155: AssertionError
2025-02-14 09:37:03.844 ---------------------------- Captured stdout setup ----------------------------
2025-02-14 09:37:03.844 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_11677\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]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=5.0.1')
    def test_1(act: Action, capsys):
    
        srv_cfg = driver_config.register_server(name = 'test_srv_gh_8185', config = '')
        db_cfg_name = f'db_cfg_8185'
        db_cfg_object = driver_config.register_database(name = db_cfg_name)
        db_cfg_object.server.value = srv_cfg.name
        db_cfg_object.database.value = str(act.db.db_path)
        db_cfg_object.config.value = f"""
            MaxStatementCacheSize = 1M
        """
    
        # Pre-check:
        with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
            cur = con.cursor()
            cur.execute("select a.mon$remote_protocol, g.rdb$config_value from mon$attachments a left join rdb$config g on g.rdb$config_name = 'MaxStatementCacheSize' where a.mon$attachment_id = current_connection")
            for r in cur:
                conn_protocol = r[0]
                db_sttm_cache_size = int(r[1])
            assert conn_protocol is None, "Test must use LOCAL protocol."
            assert db_sttm_cache_size > 0, "Parameter 'MaxStatementCacheSize' (per-database) must be greater than zero for this test."
    
        #---------------------------------------------
    
        CURSOR_NAME = 'k1'
        SELECT_STTM = 'select /* ps-1*/ id, f01 from test where id > 0 for update'
        UPDATE_STTM = f'update /* ps-2 */ test set id = -id where current of {CURSOR_NAME} returning id'
    
        update_tpb = tpb( access_mode = TraAccessMode.WRITE,
                          isolation = Isolation.READ_COMMITTED_RECORD_VERSION,
                          lock_timeout = 1)
    
        with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
    
            tx2 = con.transaction_manager(update_tpb)
            tx2.begin()
    
            with con.cursor() as cur1, tx2.cursor() as cur2, con.cursor() as cur3:
    
                ps1, rs1, ps2, rs2, ps3, rs3 = None, None, None, None, None, None
                try:
                    ps1 = cur1.prepare(SELECT_STTM)         # 1. [ticket, DS] Prepare statement 1 "select ... for update"
                    ps1._istmt.set_cursor_name(CURSOR_NAME) # 2. [ticket, DS] Set cursor name for statement 1 // ~hack.
    
                    # DO NOT use it because subsequent update statement will get 'deadlock /  update conflict' and not able to start:
                    #rs1 = cur1.execute(ps1)
                    #cur1.set_cursor_name(CURSOR_NAME)
    
                    # DS example: "// Prepare positioned update statement"
                    ps2 = cur2.prepare(UPDATE_STTM)         # 3. [ticket, DS] Prepare statement 2 "update ... where current of <cursor name from step 2>"
    
                    # DS .cpp: // fetch records from cursor and print them
                    rs1 = cur1.execute(ps1)
                    rs1.fetchall()
    
                    # DS .cpp: // IStatement* stmt2 = att->prepare(&status, tra, 0, "select * from pos where a > 1 for update",
                    ps3 = cur3.prepare(SELECT_STTM)         # 4. [ticket, DS] Prepare statement 3 similar to statement 1
    
                    rs1.close()                             # 5. [ticket, DS] Release statement 1 // see hvlad recipe, 26.10.2024
                    ps1.free()
    
                    # DS .cpp: updStmt->free(&status);
                    ps2.free()                              # 6. [ticket, DS] Release statement 2 // see hvlad recipe, 26.10.2024
    
                    # DS .cpp: stmt = stmt2
                    ps3._istmt.set_cursor_name(CURSOR_NAME) # 7. [ticket, DS] Set cursor name to statement 3 as in step 2
    
                    ps2 = cur2.prepare(UPDATE_STTM)         # 8. [ticket, DS] Prepare statement 2 again (it will be got from cache keeping reference to statement 1)
    
                    rs3 = cur3.execute(ps3)
                    rs3.fetchone()                          # 9. [ticket, DS] Run statement 3 and fetch one record
    
                    # At step 10 you can get "Invalid handle" error or a crash if you swap steps 5 and 6.
                    rs2 = cur2.execute(ps2)                 # 10. [ticket, DS] Execute statement 2
                    data2 = rs2.fetchone()
                    print('Changed ID:', data2[0])
                    # print(f'{rs2.rowcount=}')
    
                except DatabaseError as e:
                    print(e.__str__())
                    print('gds codes:')
                    for i in e.gds_codes:
                        print(i)
    
                finally:
                    if rs1:
                        rs1.close()
                    if ps1:
                        ps1.free()
    
                    if rs2:
                        rs2.close()
                    if ps2:
                        ps2.free()
    
                    if rs3:
                        rs3.close()
                    if ps3:
                        ps3.free()
    
        #---------------------------------------------
    
        act.expected_stdout = 'Changed ID: -1'
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - Changed ID: -1
E         + Dynamic SQL Error
E         + -SQL error code = -901
E         + -invalid request handle
E         + gds codes:
E         + 335544569
E         + 335544436
E         + 335544327

tests\bugs\gh_8185_test.py:155: 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.26 dcb8a P P 681 448 2025.06.27 11:06:50.013 2025.06.27 11:06:50.694 2025.06.27 10:06:13.809 2025.06.27 10:06:14.257
2 5.0.3.1657 2025.06.20 8b4d2 P P 679 453 2025.06.26 11:21:18.150 2025.06.26 11:21:18.829 2025.06.26 10:20:31.252 2025.06.26 10:20:31.705
3 5.0.3.1657 2025.06.19 4bd4c P P 709 449 2025.06.20 05:25:28.819 2025.06.20 05:25:29.528 2025.06.20 04:24:49.780 2025.06.20 04:24:50.229
4 5.0.3.1657 2025.06.11 dae6f P P 679 449 2025.06.19 10:56:59.913 2025.06.19 10:57:00.592 2025.06.19 09:56:13.203 2025.06.19 09:56:13.652
5 5.0.3.1657 2025.06.10 dbc92 P P 688 450 2025.06.11 08:43:09.282 2025.06.11 08:43:09.970 2025.06.11 07:42:09.527 2025.06.11 07:42:09.977
6 5.0.3.1656 2025.06.05 00512 P P 660 457 2025.06.10 09:58:38.812 2025.06.10 09:58:39.472 2025.06.10 08:57:15.026 2025.06.10 08:57:15.483
7 5.0.3.1656 2025.05.20 c4b11 P P 685 456 2025.06.03 09:45:32.065 2025.06.03 09:45:32.750 2025.06.03 08:45:18.663 2025.06.03 08:45:19.119
8 5.0.3.1652 2025.05.13 f51c6 P P 686 454 2025.05.21 06:26:32.793 2025.05.21 06:26:33.479 2025.05.21 05:26:35.200 2025.05.21 05:26:35.654
9 5.0.3.1651 2025.05.08 ee9d2 P P 702 451 2025.05.13 06:39:10.280 2025.05.13 06:39:10.982 2025.05.13 05:20:41.351 2025.05.13 05:20:41.802
10 5.0.3.1651 2025.05.04 3d914 P P 682 450 2025.05.09 04:28:14.278 2025.05.09 04:28:14.960 2025.05.09 03:09:39.513 2025.05.09 03:09:39.963
11 5.0.3.1651 2025.04.30 141ef P P 675 451 2025.05.02 04:35:52.089 2025.05.02 04:35:52.764 2025.05.02 03:17:32.607 2025.05.02 03:17:33.058
12 5.0.3.1650 2025.04.30 6253f P P 680 490 2025.05.01 04:34:54.543 2025.05.01 04:34:55.223 2025.05.01 03:16:28.713 2025.05.01 03:16:29.203
13 5.0.3.1650 2025.04.28 4cbff P P 674 445 2025.04.30 04:33:55.678 2025.04.30 04:33:56.352 2025.04.30 03:15:43.177 2025.04.30 03:15:43.622
14 5.0.3.1649 2025.04.21 5b2d0 P P 705 459 2025.04.26 10:07:49.974 2025.04.26 10:07:50.679 2025.04.26 08:48:41.872 2025.04.26 08:48:42.331
15 5.0.3.1648 2025.04.18 2f4c5 P P 673 456 2025.04.20 04:19:04.487 2025.04.20 04:19:05.160 2025.04.20 03:18:05.163 2025.04.20 03:18:05.619
16 5.0.3.1635 2025.04.03 f6bd1 P P 666 449 2025.04.18 06:46:45.114 2025.04.18 06:46:45.780 2025.04.18 05:27:22.674 2025.04.18 05:27:23.123
17 5.0.3.1635 2025.03.31 22ec6 P P 694 466 2025.04.03 09:52:38.417 2025.04.03 09:52:39.111 2025.04.03 08:32:54.035 2025.04.03 08:32:54.501
18 5.0.3.1633 2025.03.28 3123a P P 723 504 2025.03.31 09:51:07.579 2025.03.31 09:51:08.302 2025.03.31 08:31:27.616 2025.03.31 08:31:28.120
19 5.0.3.1633 2025.03.27 e0fb8 P P 728 497 2025.03.28 10:22:42.516 2025.03.28 10:22:43.244 2025.03.28 08:59:14.702 2025.03.28 08:59:15.199
20 5.0.3.1631 2025.03.25 bda65 P P 733 505 2025.03.27 10:03:13.005 2025.03.27 10:03:13.738 2025.03.27 08:58:27.842 2025.03.27 08:58:28.347
21 5.0.3.1631 2025.03.21 1925b P P 719 477 2025.03.25 06:37:15.011 2025.03.25 06:37:15.730 2025.03.25 05:32:24.666 2025.03.25 05:32:25.143
22 5.0.3.1629 2025.03.18 506d7 P P 691 457 2025.03.20 09:37:36.888 2025.03.20 09:37:37.579 2025.03.20 08:32:34.261 2025.03.20 08:32:34.718
23 5.0.3.1628 2025.03.14 16d05 P P 726 467 2025.03.18 09:31:45.369 2025.03.18 09:31:46.095 2025.03.18 08:28:16.600 2025.03.18 08:28:17.067
24 5.0.3.1627 2025.02.26 4e218 P P 745 468 2025.03.13 09:50:59.398 2025.03.13 09:51:00.143 2025.03.13 08:45:47.088 2025.03.13 08:45:47.556
25 5.0.3.1624 2025.02.25 dc3b2 P P 741 514 2025.02.26 15:23:14.717 2025.02.26 15:23:15.458 2025.02.26 14:18:45.090 2025.02.26 14:18:45.604
26 5.0.2.1615 2025.02.20 4a726 P P 693 455 2025.02.25 08:37:53.406 2025.02.25 08:37:54.099 2025.02.25 07:16:30.868 2025.02.25 07:16:31.323
27 5.0.2.1615 2025.02.14 9cb76 P P 690 477 2025.02.15 04:05:31.831 2025.02.15 04:05:32.521 2025.02.15 03:02:46.676 2025.02.15 03:02:47.153
28 5.0.2.1577 2025.02.07 f50a2 F F 706 485 2025.02.14 06:18:09.595 2025.02.14 06:18:10.301 2025.02.14 05:16:35.256 2025.02.14 05:16:35.741
29 5.0.2.1577 2024.12.24 3c80e F F 696 710 2025.02.06 09:31:41.492 2025.02.06 09:31:42.188 2025.02.06 08:30:09.822 2025.02.06 08:30:10.532
30 5.0.2.1576 2024.12.17 646b0 F F 715 489 2024.12.24 09:14:48.561 2024.12.24 09:14:49.276 2024.12.24 08:13:31.883 2024.12.24 08:13:32.372
31 5.0.2.1575 2024.12.09 9af52 F F 702 479 2024.12.16 09:11:36.814 2024.12.16 09:11:37.516 2024.12.16 08:10:24.256 2024.12.16 08:10:24.735
32 5.0.2.1575 2024.12.08 63d39 F F 637 663 2024.12.09 15:01:45.629 2024.12.09 15:01:46.266 2024.12.09 14:05:31.277 2024.12.09 14:05:31.940
33 5.0.2.1571 2024.12.08 8d11a F F 933 420 2024.12.09 06:15:21.299 2024.12.09 06:15:22.232 2024.12.09 05:17:06.273 2024.12.09 05:17:06.693
34 5.0.2.1567 2024.12.07 b01a2 F F 689 448 2024.12.08 01:52:39.950 2024.12.08 01:52:40.639 2024.12.08 00:53:51.763 2024.12.08 00:53:52.211
35 5.0.2.1567 2024.12.02 6ae74 F F 640 414 2024.12.04 08:57:18.621 2024.12.04 08:57:19.261 2024.12.04 08:01:00.358 2024.12.04 08:01:00.772
36 5.0.2.1567 2024.11.26 56e63 F F 697 472 2024.11.30 09:02:36.707 2024.11.30 09:02:37.404 2024.11.30 08:01:58.019 2024.11.30 08:01:58.491
37 5.0.2.1567 2024.11.21 96f61 F F 704 475 2024.11.27 08:59:23.486 2024.11.27 08:59:24.190 2024.11.27 07:59:19.293 2024.11.27 07:59:19.768
38 5.0.2.1567 2024.11.18 e1289 F E 694 2394 2024.11.21 09:17:46.514 2024.11.21 09:17:47.208 2024.11.21 07:59:13.624 2024.11.21 07:59:16.018
39 5.0.2.1533 2024.10.23 0ec43 P P 687 480 2024.11.18 08:53:36.563 2024.11.18 08:53:37.250 2024.11.18 07:52:47.767 2024.11.18 07:52:48.247

Elapsed time, ms. Chart for last 39 runs:

Last commits information (all timestamps in UTC):