FBSVCMGR with `action_trace_stop` does not verify that trace log is ENTIRELY
written on disk before returning control to outer environment
-------------------------------------------------------------------------------------------------------------------------------------------
Key: CORE-4896
URL: http://tracker.firebirdsql.org/browse/CORE-4896
Project: Firebird Core
Issue Type: Bug
Components: SVCMGR
Affects Versions: 3.0 RC 1
Reporter: Pavel Zotov
Priority: Critical
It looks like very unpleasant "feature" that FBSVCMGR with action_trace_stop
can return control to outer environment (batch or fbtest) without checking that
OS really has finished writing of log.
This effect can be watched at least on Windows 32-bit, I've checked FB build
WI-V3.0.0.31948.
Consider following batch (be sure that you have standard utility for comparing
text files - 'fc.exe' on Windows):
=== start of batch `fbsvc_check.bat` ===
@echo off
setlocal enabledelayedexpansion enableextensions
cls
set fbhome=C:\1INSTALL\FIREBIRD\fb30sS
set fbhost=localhost
set fbport=3333
set dbtest=C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb
set dbbkup=C:\FBTESTING\qa\fbt-repo\tmp\e30.fbk
set fbsrun=%fbhome%\fbsvcmgr %fbhost%/%fbport%:service_mgr user SYSDBA password
masterkey
set fbscfg=%~n0.cfg.tmp
set fbslst=%~n0.lst.tmp
set fbslog=%~n0.trc.log
set ownlog=%~n0.own.log
del %fbscfg% 2>nul
del %fbslst% 2>nul
del %fbslog% 2>nul
del %ownlog% 2>nul
echo services>> %fbscfg%
echo {>> %fbscfg%
echo enabled = true>> %fbscfg%
echo log_services = true>> %fbscfg%
echo exclude_filter = "%%((List Trace Sessions)|(Start Trace Session))%%">>
%fbscfg%
echo }>> %fbscfg%
set estlog=%~n0.est.log
del %estlog% 2>nul
set actlog=%~n0.act.log
del %actlog% 2>nul
echo %dbtest% %dbbkup% >>%estlog%
echo -REPLACE_DATABASE %dbbkup% %dbtest% >>%estlog%
echo %dbtest% -SYSTEM >>%estlog%
echo %dbtest% -HEADER >>%estlog%
echo %dbtest% -WRITE ASYNC >>%estlog%
echo %dbtest% -BUFFERS 3210 >>%estlog%
echo %dbtest% -HOUSEKEEPING 33333 >>%estlog%
echo %dbtest% -SQL_DIALECT 1 >>%estlog%
echo %dbtest% -MODE READ_ONLY >>%estlog%
echo %dbtest% -MODE READ_WRITE >>%estlog%
set str=%fbsrun% action_trace_start trc_cfg %fbscfg% 1^>%fbslog% 2^>^&1
echo Starting trace session using FBSVCMGR.
echo Command: %str%
start /min cmd /c !str!
ping -n 2 127.0.0.1>nul
@rem Do some actions which should be written into trace log:
@echo --- BACKUP ---
%fbsrun% action_backup dbname %dbtest% bkp_file %dbbkup%
@echo --- RESTORE ---
%fbsrun% action_restore bkp_file %dbbkup% dbname %dbtest% res_replace
@echo --- STATISTICS of sys relations ---
%fbsrun% action_db_stats dbname %dbtest% sts_sys_relations 1>nul
@echo --- STATISTICS of header ---
%fbsrun% action_db_stats dbname %dbtest% sts_hdr_pages 1>nul
@echo --- PROPERTIES: update FW ---
%fbsrun% action_properties dbname %dbtest% prp_write_mode prp_wm_async
@echo --- PROPERTIES: update BUFFERS number ---
%fbsrun% action_properties dbname %dbtest% prp_page_buffers 3210
@echo --- PROPERTIES: update SWEEP interval ---
%fbsrun% action_properties dbname %dbtest% prp_sweep_interval 33333
@echo --- PROPERTIES: change SQL DIALECT ---
%fbsrun% action_properties dbname %dbtest% prp_set_sql_dialect 1
@echo --- PROPERTIES: make database READ-ONLY ---
%fbsrun% action_properties dbname %dbtest% prp_access_mode prp_am_readonly
@echo --- PROPERTIES: return database to READ-WRITE ---
%fbsrun% action_properties dbname %dbtest% prp_access_mode prp_am_readwrite
%fbsrun% action_trace_list 1>%fbslst% 2>&1
for /f "tokens=3" %%i in ('findstr "Session" fbsvc_check.lst.tmp') do (
echo %time% %~nx0: request to stop trace session with id = %%i 1>>%ownlog%
%fbsrun% action_trace_stop trc_id %%i 1>>%ownlog%
echo %time% %~nx0: control from FBSVCMGR returned to this batch.>>%ownlog%
copy %fbslog% copy-of-%fbslog% 1>nul
echo %time% %~nx0: copy of trace log has been created.>>%ownlog%
)
@rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1
########### ]
cls
echo Estimated to be seen in trace log (see %estlog%^):
echo --------------------------------------------------------------------
type %estlog%
echo --------------------------------------------------------------------
findstr /c:"%dbtest%" %fbslog%>%actlog%
echo.
echo Actual content of trace log (%fbslog%^) related to actions:
echo --------------------------------------------------------------------
type %actlog%
echo --------------------------------------------------------------------
echo.
echo Difference between estimated and actual content, w/o leading or trailing
spaces and tabs:
echo
-----------------------------------------------------------------------------------------
fc.exe /c /n /w %actlog% %estlog%
@rem echo %errorlevel%
echo Content of copy-of-%fbslog% related to actions:
findstr /c:"%dbtest%" copy-of-%fbslog%
=== end of batch `fbsvc_check.bat` ===
Correct following env. variables in it:
set fbhome=C:\1INSTALL\FIREBIRD\fb30sS
set fbhost=localhost
set fbport=3333
set dbtest=C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb
set dbbkup=C:\FBTESTING\qa\fbt-repo\tmp\e30.fbk
-- and run several times.
You will be able to see following messages about comparing files using fc.exe:
. . .
Comparing files fbsvc_check.act.log and FBSVC_CHECK.EST.LOG
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
7: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -HOUSEKEEPING 33333
8: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -SQL_DIALECT 1
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
8: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -SQL_DIALECT 1
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
etc.
Is is unlikely that you will see message about no difference between estimated
and actual output of trace - untill you UNCOMMENT line:
@rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1
########### ]
(and maybe you need to change number of seconds from '4' to +/- (1..2) here)
Without knowledge about this 'feature' (that one need to wait several seconds
after fbsvcmgr is stopped) it is very easy to get wrong results if analysis of
trace log starts immediately after trace finish. And if trace log is huge I
suppose that one need to wait this log to be flushed on disk much more - dozen
seconds ?
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://tracker.firebirdsql.org/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
------------------------------------------------------------------------------
Firebird-Devel mailing list, web interface at
https://lists.sourceforge.net/lists/listinfo/firebird-devel
