Log date and time accurately with batch file

Question

I have a batch file that backups my files and works nicely, however I wanted to be able to log the exact time each task starts, but it is not working as I expected.

@echo off
> C:\log\%date:~3,2%-%date:~0,2%.log (
echo %time% - Backing up first part
... some logic
echo %time% - Backing up second part
... 
)

The problem is that I get the exact same time for both instances of %time%, instead of displaying the exact time as I wanted.

I assume it has something to do with delayed expansion, maybe DOS assigns a value to time the first time around and keeps that value througout the whole file.

What should I do to be able to reflect the time at which the echo is actually called?

Answer 1

Classic delayed expansion issue.

Your problem is that %time% expansion occurs when the statement is parsed, and the entire parenthesized block is parsed at the same time, before any commands are executed.

There are three possible solutions:

1) Use TIME /T instead

This avoids the whole issue of expansion timing. But the format is different, and there is a newline after the time, so you can't add a label to the end.

time /t
echo Backing up first part

If you want the label on the same line, then you could reverse the order and use SET /P

<nul set /p "Backing up first part - "
time /t

Or you can capture the output with a FOR /F loop and put everything on one line

for /f "delims=" %%T in ('time /t') do echo %%T - Backing up first part:

2) Use CALL and doubled percents to get an extra round of parsing

call echo %%time%% - Backing up first part:

See How does the Windows Command Interpreter (CMD.EXE) parse scripts? for an understanding of why this works. Phases 1 and 6 are relevant here. But be forewarned - it is a lot of very dense material that will take time to digest.

3) Use delayed expansion

This is the technique that I prefer to use.

This is much faster than the CALL hack. It requires SETLOCAL to enable delayed expansion, and use of ! instead of % to expand the variable:

setlocal enableDelayedExpansion
> C:\log\%date:~3,2%-%date:~0,2%.log (
  echo !time! - Backing up first part
  ... some logic
  echo !time! - Backing up second part
  ... 
)