Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FBSVCMGR can produce broken log when restoring database with enabled 'verbose' and 'res_stat tdrw' [CORE4897] #5190

Closed
firebird-issue-importer opened this issue Aug 2, 2015 · 9 comments

Comments

@firebird-issue-importer
Copy link

firebird-issue-importer commented Aug 2, 2015

Submitted by: @pavel-zotov

Attachments:
fbsvcmgr30-restore-broken-logs.zip

When trivial database (see its .fbk in attach) is restored by FBSVCMGR 'verbose' and option for show statistics ('res_stat tdrw' -- see issues in CORE1999 by hvlad) one may to get broken log. Lines in it can look like this:
. . .
gbak: 2.106 0.000 0 0 restoring privilege for user SYSDBA
gbak: 2.107 0.000 0 3 restoring privilege for user SYSDBA
gbak: 2.107 0.000 0 0 restori
ng privilege for user SYSDBA
gbak: 2.123 0.016 0 0 restoring privilege for user SYSDBA
gbak: 2.124 0.000 0 0 restoring privilege for user SYSDBA
gbak: 2.124 0.000 0 0 restoring privilege for user SYSDBA
. . .

This prevent to make any parsing of such log with analysis of restoring performance.

I'm using following batch which can detect such broken logs based on comparison with 'proper' size of log that has no broken lines (46817 bytes):
=== begin of 'rtest.bat' ===
@echo off
setlocal enabledelayedexpansion enableextensions

set fbhome=C:\1INSTALL\FIREBIRD\fb30sS
set fbhost=localhost
set fbport=3333
set bkname=C:\FBTESTING\qa\fbt-repo\tmp\e30.fbk
set dbrest=C:\FBTESTING\qa\fbt-repo\tmp\e30.fdz

set k=1
set log=fbsvcmgr30-restore.log
set lsz=0
set broken=0
:m1
@Rem del C:\FBTESTING\qa\fbt-repo\tmp\e30.fdz 2>nul
echo|set /p=%time% start iter=!k!. . .

%fbhome%\fbsvcmgr ^
%fbhost%/%fbport%:service_mgr user SYSDBA password masterkey ^
action_restore ^
bkp_file %bkname% ^
dbname %dbrest% ^
res_replace verbose ^
res_stat tdrw 1>%log% 2>&1

for /f "usebackq" %%A in ('%log%') do set lsz=%%~zA
if .%lsz%.==.. set lsz=0
if .!lsz!.==.46817. (
echo - restore log size=!lsz! -- OK
) else (
echo - restore log is broken, size=!lsz!, perform its copy to %log%.broken_!k!
copy %log% %log%.broken_!k! 1>nul
)
set /a k=!k!+1
goto m1
=== end of 'rtest.bat' ===

Correct settings in this batch to yours, extract .fbk from attached file and run. After sevral iterations (in my case - no more than 2-3) you will see messages:

C:\FBTESTING\qa\fbt-repo\tmp>rtest.bat | mtee rtest.bat.log
23:19:29.43 start iter=1. . . - restore log size=46817 -- OK
23:19:39.15 start iter=2. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_2
23:19:54.25 start iter=3. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_3
23:20:08.62 start iter=4. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_4
23:20:23.81 start iter=5. . . - restore log size=46817 -- OK
23:20:33.87 start iter=6. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_6
23:20:45.18 start iter=7. . . - restore log size=46817 -- OK
23:20:56.51 start iter=8. . . - restore log size=46817 -- OK
23:21:08.75 start iter=9. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_9
23:21:17.09 start iter=10. . . - restore log size=46817 -- OK
23:21:29.34 start iter=11. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_11
23:21:41.42 start iter=12. . . - restore log size=46817 -- OK
23:21:52.46 start iter=13. . . - restore log size=46817 -- OK
23:22:02.62 start iter=14. . . - restore log size=46817 -- OK
23:22:14.40 start iter=15. . . - restore log is broken, size=46819, perform its copy to fbsvcmgr30-restore.log.broken_15
23:22:25.59 start iter=16. . . - restore log size=46817 -- OK
. . .

All broken logs (which have size <> etalone, 46817) will be stored in separate files with pattern: fbsvcmgr30-restore.log.broken_NN (NN = number of iteration).
Most of these files have one broken line, some of them - two.

I'm not sure is this bug of FBSVCMGR or windows pipe system, but I didn`t see any similar before.

Commits: e64c510 69cc0b7 FirebirdSQL/fbt-repository@4fea1a4 FirebirdSQL/fbt-repository@0e4fe0e

====== Test Details ======

Check again 25.08.2015. Result: all OK, logs are identical on each iteration of batch.
Test not needed, see test for CORE1999: if output will be broken again then one may see this in failed result of core_1999.fbt

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 2, 2015

Modified by: @pavel-zotov

Attachment: fbsvcmgr30-restore-broken-logs.zip [ 12791 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 12, 2015

Modified by: @AlexPeshkoff

assignee: Alexander Peshkov [ alexpeshkoff ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 12, 2015

Commented by: @AlexPeshkoff

Confirm, reproduced on linux using:

for i in `seq 100`; do echo $i; ./fbsvcmgr localhost:service_mgr user SYSDBA password masterkey action_restore bkp_file tests/4897/e30.fbk dbname /tmp/0.fdb res_replace verbose res_stat tdrw >log.$i; done

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 14, 2015

Commented by: @AlexPeshkoff

The problem comes from the historical fact that traditional interbase SS always used to remove \n character from the end of line when sending data to user line by line, assuming that the portion of information it returns is always exactly one line. On the other hand, it never had a check that when data is requested by user it always has \n in the end, i.e. that line is complete. Therefore it was always possible to have lines half-divided in the logs, use of new switch just made that possibility higher and therefore (what a luck!) well reproducible.

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 14, 2015

Modified by: @AlexPeshkoff

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 3.0 RC 1 [ 10584 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 25, 2015

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

Test Details: Test not needed, see test for CORE1999: if output will be broken again then one may see this in failed result of core_1999.fbt

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 25, 2015

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

Test Details: Test not needed, see test for CORE1999: if output will be broken again then one may see this in failed result of core_1999.fbt => Check again 25.08.2015. Result: all OK, logs are identical on each iteration of batch.
Test not needed, see test for CORE1999: if output will be broken again then one may see this in failed result of core_1999.fbt

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Aug 25, 2015

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Closed [ 6 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 20, 2015

Modified by: @pavel-zotov

status: Closed [ 6 ] => Closed [ 6 ]

QA Status: No test => Cannot be tested

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants