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 14:31:20.340
2025-02-14 14:31:20.356 act = <firebird.qa.plugin.Action object at [hex]>
2025-02-14 14:31:20.370 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-02-14 14:31:20.385
2025-02-14 14:31:20.395 @pytest.mark.version('>=5.0.1')
2025-02-14 14:31:20.403 def test_1(act: Action, capsys):
2025-02-14 14:31:20.411
2025-02-14 14:31:20.420 srv_cfg = driver_config.register_server(name = 'test_srv_gh_8185', config = '')
2025-02-14 14:31:20.428 db_cfg_name = f'db_cfg_8185'
2025-02-14 14:31:20.435 db_cfg_object = driver_config.register_database(name = db_cfg_name)
2025-02-14 14:31:20.441 db_cfg_object.server.value = srv_cfg.name
2025-02-14 14:31:20.448 db_cfg_object.database.value = str(act.db.db_path)
2025-02-14 14:31:20.456 db_cfg_object.config.value = f"""
2025-02-14 14:31:20.469 MaxStatementCacheSize = 1M
2025-02-14 14:31:20.480 """
2025-02-14 14:31:20.491
2025-02-14 14:31:20.506 # Pre-check:
2025-02-14 14:31:20.517 with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-02-14 14:31:20.531 cur = con.cursor()
2025-02-14 14:31:20.544 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 14:31:20.553 for r in cur:
2025-02-14 14:31:20.567 conn_protocol = r[0]
2025-02-14 14:31:20.582 db_sttm_cache_size = int(r[1])
2025-02-14 14:31:20.593 assert conn_protocol is None, "Test must use LOCAL protocol."
2025-02-14 14:31:20.601 assert db_sttm_cache_size > 0, "Parameter 'MaxStatementCacheSize' (per-database) must be greater than zero for this test."
2025-02-14 14:31:20.609
2025-02-14 14:31:20.617 #---------------------------------------------
2025-02-14 14:31:20.624
2025-02-14 14:31:20.630 CURSOR_NAME = 'k1'
2025-02-14 14:31:20.643 SELECT_STTM = 'select /* ps-1*/ id, f01 from test where id > 0 for update'
2025-02-14 14:31:20.655 UPDATE_STTM = f'update /* ps-2 */ test set id = -id where current of {CURSOR_NAME} returning id'
2025-02-14 14:31:20.663
2025-02-14 14:31:20.676 update_tpb = tpb( access_mode = TraAccessMode.WRITE,
2025-02-14 14:31:20.692 isolation = Isolation.READ_COMMITTED_RECORD_VERSION,
2025-02-14 14:31:20.705 lock_timeout = 1)
2025-02-14 14:31:20.716
2025-02-14 14:31:20.724 with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-02-14 14:31:20.732
2025-02-14 14:31:20.741 tx2 = con.transaction_manager(update_tpb)
2025-02-14 14:31:20.753 tx2.begin()
2025-02-14 14:31:20.764
2025-02-14 14:31:20.772 with con.cursor() as cur1, tx2.cursor() as cur2, con.cursor() as cur3:
2025-02-14 14:31:20.779
2025-02-14 14:31:20.790 ps1, rs1, ps2, rs2, ps3, rs3 = None, None, None, None, None, None
2025-02-14 14:31:20.804 try:
2025-02-14 14:31:20.816 ps1 = cur1.prepare(SELECT_STTM)         # 1. [ticket, DS] Prepare statement 1 "select ... for update"
2025-02-14 14:31:20.825 ps1._istmt.set_cursor_name(CURSOR_NAME) # 2. [ticket, DS] Set cursor name for statement 1 // ~hack.
2025-02-14 14:31:20.841
2025-02-14 14:31:20.856 # DO NOT use it because subsequent update statement will get 'deadlock /  update conflict' and not able to start:
2025-02-14 14:31:20.868 #rs1 = cur1.execute(ps1)
2025-02-14 14:31:20.880 #cur1.set_cursor_name(CURSOR_NAME)
2025-02-14 14:31:20.889
2025-02-14 14:31:20.900 # DS example: "// Prepare positioned update statement"
2025-02-14 14:31:20.908 ps2 = cur2.prepare(UPDATE_STTM)         # 3. [ticket, DS] Prepare statement 2 "update ... where current of <cursor name from step 2>"
2025-02-14 14:31:20.918
2025-02-14 14:31:20.929 # DS .cpp: // fetch records from cursor and print them
2025-02-14 14:31:20.937 rs1 = cur1.execute(ps1)
2025-02-14 14:31:20.944 rs1.fetchall()
2025-02-14 14:31:20.951
2025-02-14 14:31:20.960 # DS .cpp: // IStatement* stmt2 = att->prepare(&status, tra, 0, "select * from pos where a > 1 for update",
2025-02-14 14:31:20.969 ps3 = cur3.prepare(SELECT_STTM)         # 4. [ticket, DS] Prepare statement 3 similar to statement 1
2025-02-14 14:31:20.978
2025-02-14 14:31:20.986 rs1.close()                             # 5. [ticket, DS] Release statement 1 // see hvlad recipe, 26.10.2024
2025-02-14 14:31:20.996 ps1.free()
2025-02-14 14:31:21.012
2025-02-14 14:31:21.022 # DS .cpp: updStmt->free(&status);
2025-02-14 14:31:21.031 ps2.free()                              # 6. [ticket, DS] Release statement 2 // see hvlad recipe, 26.10.2024
2025-02-14 14:31:21.038
2025-02-14 14:31:21.046 # DS .cpp: stmt = stmt2
2025-02-14 14:31:21.054 ps3._istmt.set_cursor_name(CURSOR_NAME) # 7. [ticket, DS] Set cursor name to statement 3 as in step 2
2025-02-14 14:31:21.063
2025-02-14 14:31:21.077 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 14:31:21.092
2025-02-14 14:31:21.103 rs3 = cur3.execute(ps3)
2025-02-14 14:31:21.112 rs3.fetchone()                          # 9. [ticket, DS] Run statement 3 and fetch one record
2025-02-14 14:31:21.119
2025-02-14 14:31:21.128 # At step 10 you can get "Invalid handle" error or a crash if you swap steps 5 and 6.
2025-02-14 14:31:21.137 rs2 = cur2.execute(ps2)                 # 10. [ticket, DS] Execute statement 2
2025-02-14 14:31:21.145 data2 = rs2.fetchone()
2025-02-14 14:31:21.154 print('Changed ID:', data2[0])
2025-02-14 14:31:21.165 # print(f'{rs2.rowcount=}')
2025-02-14 14:31:21.174
2025-02-14 14:31:21.182 except DatabaseError as e:
2025-02-14 14:31:21.192 print(e.__str__())
2025-02-14 14:31:21.200 print('gds codes:')
2025-02-14 14:31:21.207 for i in e.gds_codes:
2025-02-14 14:31:21.215 print(i)
2025-02-14 14:31:21.222
2025-02-14 14:31:21.232 finally:
2025-02-14 14:31:21.240 if rs1:
2025-02-14 14:31:21.252 rs1.close()
2025-02-14 14:31:21.265 if ps1:
2025-02-14 14:31:21.280 ps1.free()
2025-02-14 14:31:21.295
2025-02-14 14:31:21.312 if rs2:
2025-02-14 14:31:21.325 rs2.close()
2025-02-14 14:31:21.339 if ps2:
2025-02-14 14:31:21.351 ps2.free()
2025-02-14 14:31:21.364
2025-02-14 14:31:21.382 if rs3:
2025-02-14 14:31:21.397 rs3.close()
2025-02-14 14:31:21.407 if ps3:
2025-02-14 14:31:21.414 ps3.free()
2025-02-14 14:31:21.421
2025-02-14 14:31:21.434 #---------------------------------------------
2025-02-14 14:31:21.445
2025-02-14 14:31:21.455 act.expected_stdout = 'Changed ID: -1'
2025-02-14 14:31:21.463 act.stdout = capsys.readouterr().out
2025-02-14 14:31:21.472 >       assert act.clean_stdout == act.clean_expected_stdout
2025-02-14 14:31:21.482 E       assert
2025-02-14 14:31:21.490 E         - Changed ID: -1
2025-02-14 14:31:21.498 E         + Dynamic SQL Error
2025-02-14 14:31:21.506 E         + -SQL error code = -901
2025-02-14 14:31:21.516 E         + -invalid request handle
2025-02-14 14:31:21.529 E         + gds codes:
2025-02-14 14:31:21.538 E         + 335544569
2025-02-14 14:31:21.550 E         + 335544436
2025-02-14 14:31:21.559 E         + 335544327
2025-02-14 14:31:21.567
2025-02-14 14:31:21.576 tests/bugs/gh_8185_test.py:155: AssertionError
2025-02-14 14:31:21.585 ---------------------------- Captured stdout setup -----------------------------
2025-02-14 14:31:21.594 Creating db: localhost:/var/tmp/qa_2024/test_11656/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.1674 2025.06.27 3ee5c P P 785 395 2025.07.01 12:58:05.186 2025.07.01 12:58:05.971 2025.07.01 11:33:52.837 2025.07.01 11:33:53.232
2 5.0.3.1657 2025.06.19 4bd4c P P 687 379 2025.06.27 12:19:52.530 2025.06.27 12:19:53.217 2025.06.27 11:01:04.689 2025.06.27 11:01:05.068
3 5.0.3.1657 2025.06.11 dae6f P P 734 468 2025.06.17 07:24:54.932 2025.06.17 07:24:55.666 2025.06.17 06:04:55.810 2025.06.17 06:04:56.278
4 5.0.3.1657 2025.06.10 dbc92 P P 685 525 2025.06.11 12:15:22.168 2025.06.11 12:15:22.853 2025.06.11 10:46:30.540 2025.06.11 10:46:31.065
5 5.0.3.1656 2025.05.20 c4b11 P P 728 409 2025.06.10 12:09:04.843 2025.06.10 12:09:05.571 2025.06.10 10:45:05.641 2025.06.10 10:45:06.050
6 5.0.3.1652 2025.05.13 f51c6 P P 922 472 2025.05.20 05:13:07.379 2025.05.20 05:13:08.301 2025.05.20 03:37:17.163 2025.05.20 03:37:17.635
7 5.0.3.1651 2025.04.30 141ef P P 854 510 2025.05.13 12:11:07.659 2025.05.13 12:11:08.513 2025.05.13 10:34:14.375 2025.05.13 10:34:14.885
8 5.0.3.1650 2025.04.28 4cbff P P 792 520 2025.05.01 11:44:56.528 2025.05.01 11:44:57.320 2025.05.01 10:08:59.337 2025.05.01 10:08:59.857
9 5.0.3.1649 2025.04.21 5b2d0 P P 844 463 2025.04.28 05:42:44.574 2025.04.28 05:42:45.418 2025.04.28 04:08:43.954 2025.04.28 04:08:44.417
10 5.0.3.1648 2025.04.18 2f4c5 P P 877 426 2025.04.20 05:34:29.439 2025.04.20 05:34:30.316 2025.04.20 04:03:09.095 2025.04.20 04:03:09.521
11 5.0.3.1635 2025.03.31 22ec6 P P 871 495 2025.04.18 11:57:33.020 2025.04.18 11:57:33.891 2025.04.18 10:22:13.528 2025.04.18 10:22:14.023
12 5.0.3.1633 2025.03.28 3123a P P 858 458 2025.03.31 10:31:35.866 2025.03.31 10:31:36.724 2025.03.31 09:02:31.069 2025.03.31 09:02:31.527
13 5.0.3.1633 2025.03.27 e0fb8 P P 903 467 2025.03.28 11:06:54.993 2025.03.28 11:06:55.896 2025.03.28 09:34:47.396 2025.03.28 09:34:47.863
14 5.0.3.1631 2025.03.21 1925b P P 799 543 2025.03.27 10:54:38.348 2025.03.27 10:54:39.147 2025.03.27 09:23:40.002 2025.03.27 09:23:40.545
15 5.0.3.1628 2025.03.14 16d05 P P 11940 11848 2025.03.17 08:27:35.890 2025.03.17 08:27:47.830 2025.03.17 06:47:47.615 2025.03.17 06:47:59.463
16 5.0.3.1627 2025.02.26 4e218 P P 11878 12374 2025.03.14 11:42:00.396 2025.03.14 11:42:12.274 2025.03.14 10:01:05.823 2025.03.14 10:01:18.197
17 5.0.3.1624 2025.02.25 dc3b2 P P 12760 12966 2025.02.26 10:32:34.971 2025.02.26 10:32:47.731 2025.02.26 08:57:11.900 2025.02.26 08:57:24.866
18 5.0.2.1615 2025.02.20 4a726 P P 13910 12454 2025.02.25 11:00:00.342 2025.02.25 11:00:14.252 2025.02.25 09:22:47.647 2025.02.25 09:23:00.101
19 5.0.2.1615 2025.02.14 9cb76 P P 12525 12483 2025.02.20 07:49:12.809 2025.02.20 07:49:25.334 2025.02.20 06:15:43.596 2025.02.20 06:15:56.079
20 5.0.2.1577 2024.12.24 3c80e F F 15162 13657 2025.02.14 11:02:59.814 2025.02.14 11:03:14.976 2025.02.14 09:29:16.109 2025.02.14 09:29:29.766
21 5.0.2.1576 2024.12.17 646b0 F F 9622 9669 2024.12.24 20:26:01.483 2024.12.24 20:26:11.105 2024.12.24 17:14:58.747 2024.12.24 17:15:08.416
22 5.0.2.1575 2024.12.08 63d39 F F 9737 9425 2024.12.16 08:07:27.067 2024.12.16 08:07:36.804 2024.12.16 06:57:43.892 2024.12.16 06:57:53.317
23 5.0.2.1567 2024.11.26 56e63 F F 10106 9676 2024.12.04 07:48:29.133 2024.12.04 07:48:39.239 2024.12.04 06:37:03.334 2024.12.04 06:37:13.010
24 5.0.2.1567 2024.11.21 96f61 F F 9638 9216 2024.11.26 05:30:21.092 2024.11.26 05:30:30.730 2024.11.26 04:22:14.903 2024.11.26 04:22:24.119
25 5.0.2.1567 2024.11.18 e1289 F F 9430 9273 2024.11.21 07:34:42.625 2024.11.21 07:34:52.055 2024.11.21 06:27:19.748 2024.11.21 06:27:29.021
26 5.0.2.1533 2024.10.23 0ec43 P P 9776 9898 2024.11.18 07:51:01.952 2024.11.18 07:51:11.728 2024.11.18 06:41:41.966 2024.11.18 06:41:51.864

Elapsed time, ms. Chart for last 26 runs:

Last commits information (all timestamps in UTC):