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

Annotation type Annotation details
2 @message
firebird.driver.types.DatabaseError: Service is currently busy: Get Log File

LOG DETAILS:

2024-08-09 09:37:30.783
2024-08-09 09:37:30.789 act = <firebird.qa.plugin.Action object at [hex]>
2024-08-09 09:37:30.794 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-08-09 09:37:30.800
2024-08-09 09:37:30.805 @pytest.mark.version('>=3.0')
2024-08-09 09:37:30.818 def test_1(act: Action, capsys):
2024-08-09 09:37:30.827 PLANNED_DML_ATTACHMENTS = 20
2024-08-09 09:37:30.834 WAIT_FOR_ALL_CONNECTIONS_START_JOB = 10
2024-08-09 09:37:30.840 lock = Lock()
2024-08-09 09:37:30.844 threads = []
2024-08-09 09:37:30.849 result_list = []
2024-08-09 09:37:30.853 # Start multiple ISQL instances with heavy DML job
2024-08-09 09:37:30.858 b = Barrier(PLANNED_DML_ATTACHMENTS + 1)
2024-08-09 09:37:30.862 for i in range(PLANNED_DML_ATTACHMENTS):
2024-08-09 09:37:30.867 isql_thread = Thread(target=isql_job, args=[act, b, lock, result_list])
2024-08-09 09:37:30.872 threads.append(isql_thread)
2024-08-09 09:37:30.876 isql_thread.start()
2024-08-09 09:37:30.881 b.wait()
2024-08-09 09:37:30.886 time.sleep(WAIT_FOR_ALL_CONNECTIONS_START_JOB)
2024-08-09 09:37:30.890 with act.connect_server() as srv:
2024-08-09 09:37:30.896 # Move database to shutdown with ability to run after it validation (prp_sm_single)
2024-08-09 09:37:30.900 srv.database.shutdown(database=act.db.db_path, mode=ShutdownMode.SINGLE,
2024-08-09 09:37:30.904 method=ShutdownMethod.FORCED, timeout=0)
2024-08-09 09:37:30.909 # get firebird.log _before_ validation
2024-08-09 09:37:30.913 srv.info.get_log()
2024-08-09 09:37:30.918 log_before = srv.readlines()
2024-08-09 09:37:30.922 # At this point no further I/O should be inside database, including internal engine actions
2024-08-09 09:37:30.927 # that relate to backouts. This mean that we *must* have ability to run DB validation in
2024-08-09 09:37:30.931 # _exclusive_ mode, like gfix -v -full does.
2024-08-09 09:37:30.936 #
2024-08-09 09:37:30.940 # Run validation that requires exclusive database access.
2024-08-09 09:37:30.945 # This process normally should produce NO output at all, it is "silent".
2024-08-09 09:37:30.949 # If database currently is in use by engine or some attachments than it shoudl fail
2024-08-09 09:37:30.954 # with message "database <db_file> shutdown."
2024-08-09 09:37:30.958
2024-08-09 09:37:30.963 try:
2024-08-09 09:37:30.967 srv.database.repair(database=act.db.db_path,
2024-08-09 09:37:30.972 flags=SrvRepairFlag.FULL | SrvRepairFlag.VALIDATE_DB)
2024-08-09 09:37:30.976 except Exception as exc:
2024-08-09 09:37:30.981 # Prevent from 'fail-alarm' related to WARNINGS found during validation.
2024-08-09 09:37:30.985 # We are interesting only about real errors:
2024-08-09 09:37:30.990 p_validation_problem_msg = re.compile('number of .* errors', re.IGNORECASE)
2024-08-09 09:37:30.994 if p_validation_problem_msg.search(exc.__str__().lower()):
2024-08-09 09:37:30.999 print(f'Database validation failed: {exc}')
2024-08-09 09:37:31.003
2024-08-09 09:37:31.008 # get firebird.log _after_ validation
2024-08-09 09:37:31.012 >             srv.info.get_log()
2024-08-09 09:37:31.016
2024-08-09 09:37:31.021 tests/bugs/core_4236_test.py:143:
2024-08-09 09:37:31.025 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-08-09 09:37:31.030
2024-08-09 09:37:31.034 self = <firebird.driver.core.ServerInfoProvider object at [hex]>
2024-08-09 09:37:31.039 callback = None
2024-08-09 09:37:31.043
2024-08-09 09:37:31.048 def get_log(self, callback: CB_OUTPUT_LINE=None) -> None:
2024-08-09 09:37:31.052 """Request content of Firebird Server log. **(ASYNC service)**
2024-08-09 09:37:31.057
2024-08-09 09:37:31.061 Arguments:
2024-08-09 09:37:31.065 callback: Function to call back with each output line.
2024-08-09 09:37:31.070 """
2024-08-09 09:37:31.074 assert self._srv()._svc is not None
2024-08-09 09:37:31.078 self._srv()._reset_output()
2024-08-09 09:37:31.083 >       self._srv()._svc.start(bytes([ServerAction.GET_FB_LOG]))
2024-08-09 09:37:31.088
2024-08-09 09:37:31.092 ../lib/python3.11/site-packages/firebird/driver/core.py:4150:
2024-08-09 09:37:31.097 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-08-09 09:37:31.101
2024-08-09 09:37:31.105 self = <firebird.driver.interfaces.iService_v3 object at [hex]>
2024-08-09 09:37:31.110 spb = b'\x0c'
2024-08-09 09:37:31.114
2024-08-09 09:37:31.119 def start(self, spb: bytes) -> None:
2024-08-09 09:37:31.123 "Start utility in services manager. Replaces `isc_service_start()`."
2024-08-09 09:37:31.128 self.vtable.start(self, self.status, len(spb), spb)
2024-08-09 09:37:31.132 >       self._check()
2024-08-09 09:37:31.136
2024-08-09 09:37:31.141 ../lib/python3.11/site-packages/firebird/driver/interfaces.py:1262:
2024-08-09 09:37:31.145 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-08-09 09:37:31.150
2024-08-09 09:37:31.154 self = <firebird.driver.interfaces.iService_v3 object at [hex]>
2024-08-09 09:37:31.158
2024-08-09 09:37:31.163 def _check(self) -> None:
2024-08-09 09:37:31.167 state = self.status.get_state()
2024-08-09 09:37:31.172 if StateFlag.ERRORS in state:
2024-08-09 09:37:31.176 >           raise self.__report(DatabaseError, self.status.get_errors())
2024-08-09 09:37:31.181 E           firebird.driver.types.DatabaseError: Service is currently busy: Get Log File
2024-08-09 09:37:31.185
2024-08-09 09:37:31.189 ../lib/python3.11/site-packages/firebird/driver/interfaces.py:113: DatabaseError
2024-08-09 09:37:31.194 ---------------------------- Captured stdout setup -----------------------------
2024-08-09 09:37:31.198 Restoring db: /var/tmp/qa_2024/test_1790/test.fdb from /opt/distr/venv/firebird-qa/backups/core4236.fbk
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=3.0')
    def test_1(act: Action, capsys):
         PLANNED_DML_ATTACHMENTS = 20
         WAIT_FOR_ALL_CONNECTIONS_START_JOB = 10
         lock = Lock()
         threads = []
         result_list = []
         # Start multiple ISQL instances with heavy DML job
         b = Barrier(PLANNED_DML_ATTACHMENTS + 1)
         for i in range(PLANNED_DML_ATTACHMENTS):
              isql_thread = Thread(target=isql_job, args=[act, b, lock, result_list])
              threads.append(isql_thread)
              isql_thread.start()
         b.wait()
         time.sleep(WAIT_FOR_ALL_CONNECTIONS_START_JOB)
         with act.connect_server() as srv:
              # Move database to shutdown with ability to run after it validation (prp_sm_single)
              srv.database.shutdown(database=act.db.db_path, mode=ShutdownMode.SINGLE,
                                    method=ShutdownMethod.FORCED, timeout=0)
              # get firebird.log _before_ validation
              srv.info.get_log()
              log_before = srv.readlines()
              # At this point no further I/O should be inside database, including internal engine actions
              # that relate to backouts. This mean that we *must* have ability to run DB validation in
              # _exclusive_ mode, like gfix -v -full does.
              #
              # Run validation that requires exclusive database access.
              # This process normally should produce NO output at all, it is "silent".
              # If database currently is in use by engine or some attachments than it shoudl fail
              # with message "database <db_file> shutdown."
    
              try:
                  srv.database.repair(database=act.db.db_path,
                                       flags=SrvRepairFlag.FULL | SrvRepairFlag.VALIDATE_DB)
              except Exception as exc:
                  # Prevent from 'fail-alarm' related to WARNINGS found during validation.
                  # We are interesting only about real errors:
                  p_validation_problem_msg = re.compile('number of .* errors', re.IGNORECASE)
                  if p_validation_problem_msg.search(exc.__str__().lower()):
                      print(f'Database validation failed: {exc}')
    
              # get firebird.log _after_ validation
>             srv.info.get_log()

tests/bugs/core_4236_test.py:143: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <firebird.driver.core.ServerInfoProvider pytest object at [hex]>
callback = None

    def get_log(self, callback: CB_OUTPUT_LINE=None) -> None:
        """Request content of Firebird Server log. **(ASYNC service)**
    
        Arguments:
            callback: Function to call back with each output line.
        """
        assert self._srv()._svc is not None
        self._srv()._reset_output()
>       self._srv()._svc.start(bytes([ServerAction.GET_FB_LOG]))

../lib/python3.11/site-packages/firebird/driver/core.py:4150: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <firebird.driver.interfaces.iService_v3 pytest object at [hex]>
spb = b'\x0c'

    def start(self, spb: bytes) -> None:
        "Start utility in services manager. Replaces `isc_service_start()`."
        self.vtable.start(self, self.status, len(spb), spb)
>       self._check()

../lib/python3.11/site-packages/firebird/driver/interfaces.py:1262: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <firebird.driver.interfaces.iService_v3 pytest object at [hex]>

    def _check(self) -> None:
        state = self.status.get_state()
        if StateFlag.ERRORS in state:
>           raise self.__report(DatabaseError, self.status.get_errors())
E           firebird.driver.types.DatabaseError: Service is currently busy: Get Log File

../lib/python3.11/site-packages/firebird/driver/interfaces.py:113: DatabaseError
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 11284 12045 2025.06.26 09:23:08.920 2025.06.26 09:23:20.204 2025.06.26 08:40:04.676 2025.06.26 08:40:16.721
2 3.0.13.33813 2025.06.14 222a9 P P 11355 12111 2025.06.20 03:41:58.030 2025.06.20 03:42:09.385 2025.06.20 02:58:47.251 2025.06.20 02:58:59.362
3 3.0.13.33811 2025.05.07 16491 P P 11437 12116 2025.06.14 10:10:24.204 2025.06.14 10:10:35.641 2025.06.14 09:26:41.641 2025.06.14 09:26:53.757
4 3.0.13.33810 2025.05.06 02b1d P P 11582 12257 2025.05.07 08:35:53.390 2025.05.07 08:36:04.972 2025.05.07 07:45:47.036 2025.05.07 07:45:59.293
5 3.0.13.33809 2025.05.05 4ec6d P P 11537 12212 2025.05.06 08:42:07.959 2025.05.06 08:42:19.496 2025.05.06 07:51:45.432 2025.05.06 07:51:57.644
6 3.0.13.33808 2025.04.18 bf513 P P 11796 12235 2025.05.04 22:30:52.627 2025.05.04 22:31:04.423 2025.05.04 21:32:36.563 2025.05.04 21:32:48.798
7 3.0.13.33807 2025.04.14 73e94 P P 11604 12226 2025.04.18 08:34:57.691 2025.04.18 08:35:09.295 2025.04.18 07:44:20.039 2025.04.18 07:44:32.265
8 3.0.13.33806 2025.03.26 b6cfe P P 11429 12186 2025.04.14 07:29:12.847 2025.04.14 07:29:24.276 2025.04.14 06:43:09.572 2025.04.14 06:43:21.758
9 3.0.13.33805 2025.03.17 98320 P P 11595 12119 2025.03.25 04:54:10.437 2025.03.25 04:54:22.032 2025.03.25 04:09:04.520 2025.03.25 04:09:16.639
10 3.0.13.33804 2025.02.25 1439d P P 759 474 2025.03.17 05:03:08.095 2025.03.17 05:03:08.854 2025.03.17 04:12:18.706 2025.03.17 04:12:19.180
11 3.0.13.33803 2025.01.29 f1848 P P 746 449 2025.02.25 07:42:50.051 2025.02.25 07:42:50.797 2025.02.25 06:53:57.076 2025.02.25 06:53:57.525
12 3.0.13.33802 2025.01.28 650bd P P 703 462 2025.01.29 22:28:45.311 2025.01.29 22:28:46.014 2025.01.29 21:31:31.541 2025.01.29 21:31:32.003
13 3.0.13.33800 2025.01.20 f20ab P P 792 477 2025.01.28 07:58:56.266 2025.01.28 07:58:57.058 2025.01.28 07:07:58.420 2025.01.28 07:07:58.897
14 3.0.13.33798 2025.01.16 0c3bb P P 766 489 2025.01.20 07:31:21.560 2025.01.20 07:31:22.326 2025.01.20 06:41:02.242 2025.01.20 06:41:02.731
15 3.0.13.33795 2024.12.23 1bf0b P P 785 424 2025.01.16 07:28:18.960 2025.01.16 07:28:19.745 2025.01.16 06:39:12.564 2025.01.16 06:39:12.988
16 3.0.13.33794 2024.10.23 e2a6b P P 611 338 2024.12.23 01:15:14.691 2024.12.23 01:15:15.302 2024.12.23 00:36:51.570 2024.12.23 00:36:51.908
17 3.0.13.33793 2024.09.02 3e627 P P 719 427 2024.10.23 07:19:58.900 2024.10.23 07:19:59.619 2024.10.23 06:37:08.569 2024.10.23 06:37:08.996
18 3.0.13.33792 2024.08.30 d9f38 P P 2383 644 2024.09.02 10:37:24.000 2024.09.02 10:37:26.383 2024.09.02 09:11:07.320 2024.09.02 09:11:07.964
19 3.0.13.33791 2024.08.21 c8a36 P P 2055 695 2024.08.30 10:14:43.529 2024.08.30 10:14:45.584 2024.08.30 08:54:02.921 2024.08.30 08:54:03.616
20 3.0.13.33790 2024.08.20 3bf52 P P 1432 748 2024.08.21 09:44:45.814 2024.08.21 09:44:47.246 2024.08.21 08:31:13.191 2024.08.21 08:31:13.939
21 3.0.13.33789 2024.08.09 7933a P P 909 560 2024.08.19 06:08:52.035 2024.08.19 06:08:52.944 2024.08.19 05:17:35.289 2024.08.19 05:17:35.849
22 3.0.12.33787 2024.08.06 bf180 F P 976 493 2024.08.09 05:56:00.609 2024.08.09 05:56:01.585 2024.08.09 05:05:05.512 2024.08.09 05:05:06.005
23 3.0.12.33784 2024.08.01 cd857 P P 642 357 2024.08.06 04:56:18.371 2024.08.06 04:56:19.013 2024.08.06 04:13:16.011 2024.08.06 04:13:16.368
24 3.0.12.33779 2024.07.31 ae35d P P 666 332 2024.08.01 04:54:46.568 2024.08.01 04:54:47.234 2024.08.01 04:11:53.681 2024.08.01 04:11:54.013
25 3.0.12.33778 2024.07.21 4680d P P 595 368 2024.07.30 04:51:53.264 2024.07.30 04:51:53.859 2024.07.30 04:09:00.636 2024.07.30 04:09:01.004
26 3.0.12.33777 2024.07.19 8e912 P P 668 310 2024.07.21 04:53:52.504 2024.07.21 04:53:53.172 2024.07.21 04:11:09.799 2024.07.21 04:11:10.109
27 3.0.12.33766 2024.07.13 b5086 P P 566 317 2024.07.19 04:46:29.001 2024.07.19 04:46:29.567 2024.07.19 04:04:02.147 2024.07.19 04:04:02.464
28 3.0.12.33765 2024.07.10 06f2a P P 542 320 2024.07.13 04:49:24.515 2024.07.13 04:49:25.057 2024.07.13 04:06:11.605 2024.07.13 04:06:11.925
29 3.0.12.33764 2024.06.18 4d0c0 P P 563 365 2024.07.10 04:38:37.728 2024.07.10 04:38:38.291 2024.07.10 03:57:18.297 2024.07.10 03:57:18.662
30 3.0.12.33761 2024.06.17 b259d P P 635 304 2024.06.18 04:39:48.993 2024.06.18 04:39:49.628 2024.06.18 03:58:02.117 2024.06.18 03:58:02.421
31 3.0.12.33758 2024.06.14 4f9bc P P 644 369 2024.06.17 04:35:19.518 2024.06.17 04:35:20.162 2024.06.17 03:52:07.004 2024.06.17 03:52:07.373
32 3.0.12.33757 2024.06.13 c7a1c P P 603 260 2024.06.14 04:50:38.785 2024.06.14 04:50:39.388 2024.06.14 04:13:39.341 2024.06.14 04:13:39.601
33 3.0.12.33744 2024.04.19 ecf36 P P 529 280 2024.05.08 15:30:28.824 2024.05.08 15:30:29.353 2024.05.08 14:53:20.754 2024.05.08 14:53:21.034

Elapsed time, ms. Chart for last 33 runs:

Last commits information (all timestamps in UTC):