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-05-12 19:15:50.748
2024-05-12 19:15:50.753 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-12 19:15:50.758 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-12 19:15:50.766
2024-05-12 19:15:50.772 @pytest.mark.version('>=3.0')
2024-05-12 19:15:50.780 def test_1(act: Action, capsys):
2024-05-12 19:15:50.787 PLANNED_DML_ATTACHMENTS = 20
2024-05-12 19:15:50.795 WAIT_FOR_ALL_CONNECTIONS_START_JOB = 10
2024-05-12 19:15:50.802 lock = Lock()
2024-05-12 19:15:50.807 threads = []
2024-05-12 19:15:50.813 result_list = []
2024-05-12 19:15:50.818 # Start multiple ISQL instances with heavy DML job
2024-05-12 19:15:50.823 b = Barrier(PLANNED_DML_ATTACHMENTS + 1)
2024-05-12 19:15:50.828 for i in range(PLANNED_DML_ATTACHMENTS):
2024-05-12 19:15:50.833 isql_thread = Thread(target=isql_job, args=[act, b, lock, result_list])
2024-05-12 19:15:50.839 threads.append(isql_thread)
2024-05-12 19:15:50.844 isql_thread.start()
2024-05-12 19:15:50.850 b.wait()
2024-05-12 19:15:50.855 time.sleep(WAIT_FOR_ALL_CONNECTIONS_START_JOB)
2024-05-12 19:15:50.860 with act.connect_server() as srv:
2024-05-12 19:15:50.864 # Move database to shutdown with ability to run after it validation (prp_sm_single)
2024-05-12 19:15:50.869 srv.database.shutdown(database=act.db.db_path, mode=ShutdownMode.SINGLE,
2024-05-12 19:15:50.874 method=ShutdownMethod.FORCED, timeout=0)
2024-05-12 19:15:50.879 # get firebird.log _before_ validation
2024-05-12 19:15:50.884 srv.info.get_log()
2024-05-12 19:15:50.888 log_before = srv.readlines()
2024-05-12 19:15:50.893 # At this point no further I/O should be inside database, including internal engine actions
2024-05-12 19:15:50.898 # that relate to backouts. This mean that we *must* have ability to run DB validation in
2024-05-12 19:15:50.903 # _exclusive_ mode, like gfix -v -full does.
2024-05-12 19:15:50.908 #
2024-05-12 19:15:50.912 # Run validation that requires exclusive database access.
2024-05-12 19:15:50.917 # This process normally should produce NO output at all, it is "silent".
2024-05-12 19:15:50.922 # If database currently is in use by engine or some attachments than it shoudl fail
2024-05-12 19:15:50.927 # with message "database <db_file> shutdown."
2024-05-12 19:15:50.931
2024-05-12 19:15:50.936 try:
2024-05-12 19:15:50.941 srv.database.repair(database=act.db.db_path,
2024-05-12 19:15:50.945 flags=SrvRepairFlag.FULL | SrvRepairFlag.VALIDATE_DB)
2024-05-12 19:15:50.950 except Exception as exc:
2024-05-12 19:15:50.955 # Prevent from 'fail-alarm' related to WARNINGS found during validation.
2024-05-12 19:15:50.960 # We are interesting only about real errors:
2024-05-12 19:15:50.964 p_validation_problem_msg = re.compile('number of .* errors', re.IGNORECASE)
2024-05-12 19:15:50.969 if p_validation_problem_msg.search(exc.__str__().lower()):
2024-05-12 19:15:50.975 print(f'Database validation failed: {exc}')
2024-05-12 19:15:50.980
2024-05-12 19:15:50.984 # get firebird.log _after_ validation
2024-05-12 19:15:50.989 >             srv.info.get_log()
2024-05-12 19:15:50.994
2024-05-12 19:15:50.999 tests/bugs/core_4236_test.py:143:
2024-05-12 19:15:51.003 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-05-12 19:15:51.008
2024-05-12 19:15:51.013 self = <firebird.driver.core.ServerInfoProvider object at [hex]>
2024-05-12 19:15:51.018 callback = None
2024-05-12 19:15:51.022
2024-05-12 19:15:51.028 def get_log(self, callback: CB_OUTPUT_LINE=None) -> None:
2024-05-12 19:15:51.032 """Request content of Firebird Server log. **(ASYNC service)**
2024-05-12 19:15:51.037
2024-05-12 19:15:51.042 Arguments:
2024-05-12 19:15:51.046 callback: Function to call back with each output line.
2024-05-12 19:15:51.051 """
2024-05-12 19:15:51.056 assert self._srv()._svc is not None
2024-05-12 19:15:51.061 self._srv()._reset_output()
2024-05-12 19:15:51.066 >       self._srv()._svc.start(bytes([ServerAction.GET_FB_LOG]))
2024-05-12 19:15:51.071
2024-05-12 19:15:51.077 ../lib/python3.11/site-packages/firebird/driver/core.py:4150:
2024-05-12 19:15:51.082 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-05-12 19:15:51.087
2024-05-12 19:15:51.092 self = <firebird.driver.interfaces.iService_v3 object at [hex]>
2024-05-12 19:15:51.097 spb = b'\x0c'
2024-05-12 19:15:51.102
2024-05-12 19:15:51.107 def start(self, spb: bytes) -> None:
2024-05-12 19:15:51.112 "Start utility in services manager. Replaces `isc_service_start()`."
2024-05-12 19:15:51.117 self.vtable.start(self, self.status, len(spb), spb)
2024-05-12 19:15:51.122 >       self._check()
2024-05-12 19:15:51.127
2024-05-12 19:15:51.132 ../lib/python3.11/site-packages/firebird/driver/interfaces.py:1262:
2024-05-12 19:15:51.137 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2024-05-12 19:15:51.142
2024-05-12 19:15:51.146 self = <firebird.driver.interfaces.iService_v3 object at [hex]>
2024-05-12 19:15:51.151
2024-05-12 19:15:51.156 def _check(self) -> None:
2024-05-12 19:15:51.161 state = self.status.get_state()
2024-05-12 19:15:51.165 if StateFlag.ERRORS in state:
2024-05-12 19:15:51.170 >           raise self.__report(DatabaseError, self.status.get_errors())
2024-05-12 19:15:51.175 E           firebird.driver.types.DatabaseError: Service is currently busy: Get Log File
2024-05-12 19:15:51.180
2024-05-12 19:15:51.185 ../lib/python3.11/site-packages/firebird/driver/interfaces.py:113: DatabaseError
2024-05-12 19:15:51.190 ---------------------------- Captured stdout setup -----------------------------
2024-05-12 19:15:51.196 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.33809 2025.05.06 28ad0 P P 11864 12157 2025.06.30 14:40:14.081 2025.06.30 14:40:25.945 2025.06.30 13:52:38.926 2025.06.30 13:52:51.083
2 3.0.13.33808 2025.04.25 28426 P P 12053 12255 2025.05.06 13:38:29.428 2025.05.06 13:38:41.481 2025.05.06 12:42:22.248 2025.05.06 12:42:34.503
3 3.0.13.33803 2025.02.25 08ebd P P 12068 12192 2025.04.25 16:53:27.410 2025.04.25 16:53:39.478 2025.04.25 15:57:48.767 2025.04.25 15:58:00.959
4 3.0.13.33796 2025.01.29 0ab85 P P 933 515 2025.02.25 15:26:14.224 2025.02.25 15:26:15.157 2025.02.25 14:30:53.258 2025.02.25 14:30:53.773
5 3.0.13.33796 2025.01.14 99b3b P P 1070 506 2025.01.28 17:39:57.051 2025.01.28 17:39:58.121 2025.01.28 16:43:23.084 2025.01.28 16:43:23.590
6 3.0.13.33795 2024.11.24 b8847 P P 976 471 2025.01.13 15:17:42.923 2025.01.13 15:17:43.899 2025.01.13 14:21:46.205 2025.01.13 14:21:46.676
7 3.0.13.33794 2024.10.15 abe09 P P 728 376 2024.11.23 06:26:26.609 2024.11.23 06:26:27.337 2024.11.23 05:44:04.186 2024.11.23 05:44:04.562
8 3.0.13.33793 2024.10.04 82ccc P P 954 406 2024.10.14 04:21:49.153 2024.10.14 04:21:50.107 2024.10.14 03:35:26.859 2024.10.14 03:35:27.265
9 3.0.13.33792 2024.08.31 d8791 P P 1099 455 2024.10.03 09:27:57.436 2024.10.03 09:27:58.535 2024.10.03 08:38:25.786 2024.10.03 08:38:26.241
10 3.0.13.33787 2024.08.17 2e0d6 P P 2406 1345 2024.08.25 15:08:17.700 2024.08.25 15:08:20.106 2024.08.25 13:20:13.368 2024.08.25 13:20:14.713
11 3.0.13.33787 2024.08.09 df740 P P 1144 571 2024.08.16 12:42:19.927 2024.08.16 12:42:21.071 2024.08.16 11:46:34.369 2024.08.16 11:46:34.940
12 3.0.12.33746 2024.07.15 11dd4 P P 1434 576 2024.08.09 12:39:15.132 2024.08.09 12:39:16.566 2024.08.09 11:41:32.518 2024.08.09 11:41:33.094
13 3.0.12.33746 2024.06.11 8a5eb P P 848 363 2024.07.15 10:31:00.407 2024.07.15 10:31:01.255 2024.07.15 09:43:31.067 2024.07.15 09:43:31.430
14 3.0.12.33744 2024.05.09 9cf37 F P 751 265 2024.05.12 15:38:58.881 2024.05.12 15:38:59.632 2024.05.12 14:55:39.226 2024.05.12 14:55:39.491
15 3.0.12.33744 2024.04.20 af6b2 P P 732 283 2024.05.08 16:54:36.282 2024.05.08 16:54:37.014 2024.05.08 16:13:39.037 2024.05.08 16:13:39.320

Elapsed time, ms. Chart for last 15 runs:

Last commits information (all timestamps in UTC):