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