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
|