milo: fix step duration

appengine/cmd/milo/swarming/testdata/build-patch-failure

+@@@CURRENT_TIMESTAMP@1457949601@@@
 Running: gclient root
 Running: gclient config --spec 'solutions = [
   {
     "url": "https://chromium.googlesource.com/infra/infra.git",
     "managed": False,
     "name": "infra",
     "deps_file": ".DEPS.git",
   },
 ]
 '
 Running: gclient sync
 Running: git submodule foreach 'git config -f $toplevel/.git/config submodule.$name.ignore all'
 Running: git config --add remote.origin.fetch '+refs/tags/*:refs/tags/*'
 Running: git config diff.ignoreSubmodules all
 @@@SET_BUILD_PROPERTY@recipe@infra/infra_repo_trybot@@@
 @@@SET_BUILD_PROPERTY@buildername@Infra Linux Trusty 64 Tester@@@
 @@@SET_BUILD_PROPERTY@recipe@infra/infra_repo_trybot@@@
 @@@SET_BUILD_PROPERTY@mastername@tryserver.infra@@@
 @@@SET_BUILD_PROPERTY@buildnumber@1@@@
 @@@SET_BUILD_PROPERTY@slavename@fakeslave@@@
 @@@SET_BUILD_PROPERTY@patchset@1@@@
 @@@SET_BUILD_PROPERTY@issue@1431683003@@@
 @@@SET_BUILD_PROPERTY@patch_project@infra@@@
 @@@SET_BUILD_PROPERTY@revision@HEAD@@@
 
 @@@SEED_STEP update_scripts@@@
 
 @@@STEP_CURSOR update_scripts@@@
 
+@@@CURRENT_TIMESTAMP@1457949602@@@
 @@@STEP_STARTED@@@
 
 /tmp/runguSO1v/b/build/../depot_tools/gclient sync --force --verbose --output-json /tmp/tmptiMDN5/tmpf8q84i
 in dir /tmp/runguSO1v/b/build:
  cmd: ['/tmp/runguSO1v/b/build/../depot_tools/gclient', 'sync', '--force', '--verbose', '--output-json', '/tmp/tmptiMDN5/tmpf8q84i']
  cwd: /tmp/runguSO1v/b/build
  name: update_scripts
 full environment:
  ADDRFAM: inet
  BOTO_CONFIG: /home/chrome-bot/.boto
@@ skipping 1378 matching lines @@
 @@@STEP_LOG_END@gclient_json@@@
 
 @@@STEP_TEXT@git - 1fb19c56e954ada4c990ed04cf8a004e16def555@@@
 
 @@@SET_BUILD_PROPERTY@build_scm@"git"@@@
 
 @@@SET_BUILD_PROPERTY@build_revision@"1fb19c56e954ada4c990ed04cf8a004e16def555"@@@
 
 @@@STEP_CURSOR update_scripts@@@
 
+@@@CURRENT_TIMESTAMP@1457949603@@@
 @@@STEP_CLOSED@@@
 Cloning into '/tmp/runguSO1v/b/build/scripts/slave/.recipe_deps/recipe_engine'...
 
 @@@HONOR_ZERO_RETURN_CODE@@@
 
 @@@SEED_STEP setup_build@@@
 
 @@@STEP_CURSOR setup_build@@@
 
+@@@CURRENT_TIMESTAMP@1457949604@@@
 @@@STEP_STARTED@@@
 
 @@@STEP_LOG_LINE@run_recipe@To repro this locally, run the following line from a build checkout:@@@
 
 @@@STEP_LOG_LINE@run_recipe@@@@
 
 @@@STEP_LOG_LINE@run_recipe@./scripts/tools/run_recipe.py infra/infra_repo_trybot --properties-file - <<EOF@@@
 
 @@@STEP_LOG_LINE@run_recipe@{u'buildername': u'Infra Linux Trusty 64 Tester', u'recipe': 'infra/infra_repo_trybot', u'mastername': u'tryserver.infra', u'buildnumber': 1, u'slavename': u'fakeslave', u'patchset': 1, u'issue': 1431683003, u'patch_project': u'infra', u'revision': u'HEAD'}@@@
 
 @@@STEP_LOG_LINE@run_recipe@EOF@@@
 
 @@@STEP_LOG_LINE@run_recipe@@@@
 
 @@@STEP_LOG_LINE@run_recipe@To run on Windows, you can put the JSON in a file and redirect the@@@
 
 @@@STEP_LOG_LINE@run_recipe@contents of the file into run_recipe.py, with the < operator.@@@
 
 @@@STEP_LOG_END@run_recipe@@@
 
 Running recipe with {u'buildername': u'Infra Linux Trusty 64 Tester', u'recipe': 'infra/infra_repo_trybot', u'mastername': u'tryserver.infra', u'buildnumber': 1, u'slavename': u'fakeslave', u'patchset': 1, u'issue': 1431683003, u'patch_project': u'infra', u'revision': u'HEAD'}
 
 @@@STEP_TEXT@<br/>running recipe: "infra/infra_repo_trybot"@@@
 
 @@@STEP_CURSOR setup_build@@@
 
+@@@CURRENT_TIMESTAMP@1457949605@@@
 @@@STEP_CLOSED@@@
 
 @@@SEED_STEP bot_update@@@
 
 @@@STEP_CURSOR bot_update@@@
 
+@@@CURRENT_TIMESTAMP@1457949606@@@
 @@@STEP_STARTED@@@
 
 python -u /tmp/runguSO1v/b/build/scripts/slave/bot_update.py --master tryserver.infra --builder 'Infra Linux Trusty 64 Tester' --slave fakeslave --spec $'cache_dir = \'/tmp/runguSO1v/b/git_cache\'\nsolutions = [{\'deps_file\': \'.DEPS.git\', \'managed\': True, \'name\': \'infra\', \'url\': \'https://chromium.googlesource.com/infra/infra.git\'}]' --root infra --revision_mapping_file /tmp/tmpT20mYl.json --issue 1431683003 --patchset 1 --output_json /tmp/tmp49asLT.json --revision infra@HEAD --force --output_manifest
 in dir /tmp/runguSO1v/b/build/slave/bot/build:
  allow_subannotations: False
  cmd: ['python', '-u', '/tmp/runguSO1v/b/build/scripts/slave/bot_update.py', '--master', 'tryserver.infra', '--builder', 'Infra Linux Trusty 64 Tester', '--slave', 'fakeslave', '--spec', "cache_dir = '/tmp/runguSO1v/b/git_cache'\nsolutions = [{'deps_file': '.DEPS.git', 'managed': True, 'name': 'infra', 'url': 'https://chromium.googlesource.com/infra/infra.git'}]", '--root', 'infra', '--revision_mapping_file', '/tmp/tmpT20mYl.json', '--issue', '1431683003', '--patchset', '1', '--output_json', '/tmp/tmp49asLT.json', '--revision', 'infra@HEAD', '--force', '--output_manifest']
  cwd: /tmp/runguSO1v/b/build/slave/bot/build
  name: bot_update
 full environment:
  BOTO_CONFIG: /home/chrome-bot/.boto
@@ skipping 4333 matching lines @@
 @@@STEP_LOG_LINE@patch error@@@@
 
 @@@STEP_LOG_LINE@patch error@CWD=/tmp/runguSO1v/b/build/slave/bot/build@@@
 
 @@@STEP_LOG_LINE@patch error@Checkout path=/tmp/runguSO1v/b/build/slave/bot/build/infra@@@
 
 @@@STEP_LOG_END@patch error@@@
 
 @@@STEP_CURSOR bot_update@@@
 
+@@@CURRENT_TIMESTAMP@1457949607@@@
 @@@STEP_CLOSED@@@
 
 @@@SEED_STEP Patch failure@@@
 
 @@@STEP_CURSOR Patch failure@@@
 
+@@@CURRENT_TIMESTAMP@1457949608@@@
 @@@STEP_STARTED@@@
 
 python -u /tmp/tmpIUIfxt.py
 in dir /tmp/runguSO1v/b/build/slave/bot/build:
  allow_subannotations: False
  cmd: ['python', '-u', '/tmp/tmpIUIfxt.py']
  cwd: /tmp/runguSO1v/b/build/slave/bot/build
  name: Patch failure
 full environment:
  BOTO_CONFIG: /home/chrome-bot/.boto
  HOME: /home/chrome-bot
  PATH: /tmp/runguSO1v/staging/depot_tools:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
  PWD: /
  USER: chrome-bot
  USERNAME: ${USER}
 
 
 @@@STEP_CURSOR Patch failure@@@
 
 @@@STEP_TEXT@Check the bot_update step for details@@@
 
 @@@STEP_FAILURE@@@
 
 @@@STEP_CURSOR Patch failure@@@
 
+@@@CURRENT_TIMESTAMP@1457949609@@@
 @@@STEP_CLOSED@@@
 
 @@@SEED_STEP recipe failure reason@@@
 
 @@@STEP_CURSOR recipe failure reason@@@
 
+@@@CURRENT_TIMESTAMP@1457949610@@@
 @@@STEP_STARTED@@@
 
 @@@STEP_LOG_LINE@failure reason@Step('Patch failure') failed with return_code 1@@@
 
 @@@STEP_LOG_END@failure reason@@@
 
 @@@STEP_CURSOR recipe failure reason@@@
 
+@@@CURRENT_TIMESTAMP@1457949611@@@
 @@@STEP_CLOSED@@@
 Traceback (most recent call last):
   File "luci_recipe_run.py", line 81, in <module>
     sys.exit(main(sys.argv[1:]))
   File "luci_recipe_run.py", line 78, in main
     subprocess.check_call(cmd, cwd=work_dir)
   File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
     raise CalledProcessError(retcode, cmd)
 subprocess.CalledProcessError: Command '['/home/chrome-bot/infra-python/ENV/bin/python', '-u', '../../../scripts/slave/annotated_run.py', '--factory-properties-gz=eJyrVipKTc4sSFWyUlDKzEsrStQHk/FFqQX58SVFlUn5JUq1APnTDbo=', '--build-properties-gz=eJw9zsEKwjAMBuBXKT2LbmwM2U1QmOBx99HNDKtbW5J0OMR3d63OSw4/X/7kJVuvhyugUSPIUsiz6VGJizb+KWr0xLMoclEDMaDcCInQaRelDnIXZ4PgbMM4t5YDGlXga+WSE+AEuI04gHjU+LFdSkuRLgkNaoJ1o1cPiEGwTnF3I+Af1EQ+oDTP0mKfJUm2msahvUPH/+e+/06atDUhrE6Ho3x/AAlJTyU=']' returned non-zero exit status 1
+
+@@@CURRENT_TIMESTAMP@1457949612@@@