How can I prepend information to streamed output and capture %ERRORLEVEL%?

Question

I have two scripts, foo and bar. Foo calls bar. I need to print the lines of bar's output with pre-pended time, and capture the %ERRORLEVEL% from bar. I can't seem to figure out how to do both. I further can't figure out how to accurately display the time bar's lines were executed, only the time bar finished executing and transferred control back to foo.

foo.cmd

echo off
for /f "delims=" %%a in ('bar') do (call :log "%%a")
echo after loop error level: %ERRORLEVEL%
goto :eof

:log
echo during loop error level: %ERRORLEVEL%
echo [%time%]: %~1
goto :eof

bar.cmd

echo this is log output line 1
timeout /t 2 /nobreak > NUL
echo this is log output line 2
EXIT /B 3

My output from this run is:

>foo
>echo off
during loop error level: 0
during loop error level: 0
[13:24:22.21]: this is log output line 1
during loop error level: 0
during loop error level: 0
during loop error level: 0
[13:24:22.23]: this is log output line 2
during loop error level: 0
after loop error level: 0

My desired from this run is:

>foo
>echo off
during loop error level: 0
during loop error level: 0
[13:24:20.21]: this is log output line 1
during loop error level: 0
during loop error level: 0
during loop error level: 0
[13:24:22.23]: this is log output line 2 <------- this is 2 seconds later
during loop error level: 0
after loop error level: 3 <------ I got %ERRORLEVEL%

Any help is appreciated!

I think you may need to redirect the output of `bar` to a temporary file, check its `errorlevel` and then loop through the temporary file adding the timestamp. By the way, your output doesn't seem to be from the code you show (your code doesn't output timestamps). — DodgyCodeException, Apr 20 '18 at 14:57
Thank you for the idea! I'll give it a shot. And sorry I missed on the appending of time. I had added it while making this example but forgot to update the already typed question. — Aaron, Apr 20 '18 at 15:02
I tried the proposal and it works except for one thing. The timestamp prepended is not from when the original command was processing, but from when the temp logfile was appended. — Aaron, Apr 20 '18 at 15:23
@Aaron, it would help potential responders were you to [edit your question](https://stackoverflow.com/posts/49944333/edit) to include your updated code, output and expected output. — Compo, Apr 20 '18 at 16:04
So you want errorlevel and time on the same line each time it runs? — Gerhard, Apr 20 '18 at 16:29
I will see if it will let me edit the question to show the additional requirement of accurate time in the expected output. — Aaron, Apr 20 '18 at 18:23
Are you expecting that the `FOR` loop is going to execute and process `bar.cmd` one line at a time? Because that is not how it works. The loop will call `bar.cmd` which will run entirely and then the output is returned to the loop. — aphoria, Apr 20 '18 at 19:05
@aphoria: to be exact: the *output* of `bar.cmd` is processed one line at a time. — Stephan, Apr 20 '18 at 19:40
@Stephan Correct. But, I think that @Aaron is thinking that each line of `bar.cmd` will execute _and_ be processed by the loop _before_ the next line of `bar.cmd` is executed. — aphoria, Apr 20 '18 at 19:48
That is what I would like to happen, but I understand now it is not how FOR /F works. I can't use stdout redirection (>>) I can't prepend to it on the way through. Another thought is stdout redirection to another routine (|), but I am not sure if this will have the same issue as the FOR /F, executing bar entirely and then redirecting the resulting output afterwards. — Aaron, Apr 20 '18 at 20:41

michael_heath · Answer 1 · 2018-04-23T07:03:05.077

main.cmd:

@echo off
setlocal

call bar 2> stderr.txt > stdout.txt
set "errorsaved=%errorlevel%"

for /f "delims=" %%A in (stdout.txt) do echo [%time%]: %%A

if %errorsaved% gtr 0 (
    echo [%time%]: ERRORLEVEL: %errorsaved%
    for /f "delims=" %%A in (stderr.txt) do echo [%time%]: ERRORINFO: %%A
)

del stderr.txt stdout.txt

bar.cmd:

@echo off
setlocal

echo some output
echo more output
>&2 echo %~nx0 failed to continue
exit /b 1

A command in a for loop does not want to set the errorlevel. An option is to save stdout and stderr to files and save errorlevel to a variable for post processing.

main.cmd calls bar.cmd and redirects the streams to files. Value of %errorlevel% is saved to %errorsaved%. The file stdout.txt is read and echoed. If bar.cmd set errorlevel greater than 0, then %errorsaved% is echoed and the file stderr.txt is read and echoed. Finally the files are deleted.

Tested output:

[ 0:08:34.46]: some output
[ 0:08:34.46]: more output
[ 0:08:34.46]: ERRORLEVEL: 1
[ 0:08:34.46]: ERRORINFO: bar.cmd failed to continue

Due concern about timings not being realtime with a file method. Here is test code similar to the question using a for loop.

main2.cmd:

@echo off
setlocal

for /f "delims=" %%A in ('bar2.cmd') do call :log "%%~A"

:log
echo [%time%]: %~1
goto :eof

bar2.cmd:

@echo off
setlocal enabledelayedexpansion

echo start
for /l %%A in (2 2 10) do (
    >nul timeout /nobreak /t 2
    echo %%A secs [!time!]
)

Output:

[16:37:48.10]: start
[16:37:48.11]: 2 secs [16:37:40.14]
[16:37:48.11]: 4 secs [16:37:42.16]
[16:37:48.11]: 6 secs [16:37:44.17]
[16:37:48.11]: 8 secs [16:37:46.19]
[16:37:48.11]: 10 secs [16:37:48.10]
[16:37:48.11]:

Each echo should be roughly 2 secs a part.

As can be seen by the output, a for loop does not return stdout in realtime. Rather it seems to wait for the process to finish, similar to how piping does.

Running just bar2.cmd as a main script does echo in realtime so no trickery is being done to influence main2.cmd with it's output.

Unfortunately this won't print the correct timestamp. The OP wants the timestamp to reflect the time that each individual line was output by bar.cmd - not the time at which the stdout.txt file was read by main.cmd. — Klitos Kyriacou, Apr 22 '18 at 19:36
@Klitos, added to the answer about timestamp concern. Thanks for the interest. — michael_heath, Apr 23 '18 at 07:09
Regarding your edit - "... similar to how piping does" - that's not similar to piping. With a pipe, the process on the right-hand side reads the output of the first process in real time, as can be seen if you do `bar2.cmd | findstr /n "^"`. Unfortunately, plain batch can't read from a piped STDIN so you have to use a helper utility such as VBScript or PowerShell, or download GNU Awk. — Klitos Kyriacou, Apr 23 '18 at 08:23

score 0 · Answer 2 · answered Apr 23 '18 at 10:35

Using ideas from michael_heath's answer and Klitos Kyriacou's comments, here's an answer to the first part of the question:

@echo off
for /f "delims=" %%a in ('bar^|powershell -noprofile -command "ForEach ($line in $Input) {Write-Output \"[$(Get-Date -Format hh:mm:ss.ff^)]: $line\"}"') do (call :log "%%a")
echo after loop error level: %ERRORLEVEL%
goto :eof

:log
echo during loop error level: %ERRORLEVEL%
echo %~1
goto :eof

I've moved the timestamping from the :log subroutine to a process to which the output of bar is piped. This just echoes the output of bar prepended by a timestamp.

This leaves the second part of the question: how do you get the errorlevel. This is a very complicated problem, but fortunately it's been solved by dbenham in another StackOverflow post.

How can I prepend information to streamed output and capture %ERRORLEVEL%?

2 Answers2