Azure Function / Azure Website Custom Deploy Script Ending Prematurely

Question

I've got a custom batch deployment script for an Azure Function which is ending prematurely without erroring out. I'm hoping someone can help me understand what is going on.

The problematic portion appears to be in the "Pre-deployment" section of the script:

for /F %%f in ('git.exe diff --name-only %PREVIOUS_SCM_COMMIT_ID% %SCM_COMMIT_ID% ^| grep package.json') do (
    SET PACKAGEJSON=%%~f
    SET PKGFOLDER=!DEPLOYMENT_SOURCE!\!PACKAGEJSON:package.json=!
    echo "NPM Install: !PKGFOLDER!package.json"
    pushd "!PKGFOLDER!"
    npm install --production --progress=false --cache-min=432000
    npm install --save json-loader --progress=false --cache-min=432000
    IF !ERRORLEVEL! NEQ 0 goto error
    popd
)

If a package.json has not been modified between the last two commits, the script skips this section as expected and continues to executing the "Deployment" section.

If a package.json HAS been modified, the code works as expected at first and it runs the npm installs. Afterwards, however, it ends without an error and does not continue on to the deployment section. There is no additional output from the script after the last npm install runs.

Can anyone help me understand what is wrong? This looks correct to me.

The full script is below, and it is a portion of the following project: https://github.com/securityvoid/.deploy

@if "%SCM_TRACE_LEVEL%" NEQ "4" @echo off
@echo Started: %date% %time%

:: ----------------------
:: KUDU Deployment Script
:: Version: 1.0.12
:: ----------------------

:: Prerequisites
:: -------------

:: Verify node.js installed
where node 2>nul >nul
IF %ERRORLEVEL% NEQ 0 (
  echo Missing node.js executable, please install node.js, if already installed make sure it can be reached from current environment.
  goto error
)

:: Setup
:: -----

setlocal enabledelayedexpansion

SET ARTIFACTS=%~dp0%..\artifacts

IF NOT DEFINED DEPLOYMENT_SOURCE (
  SET DEPLOYMENT_SOURCE=%~dp0%.
)
echo "Deployment Source: %DEPLOYMENT_SOURCE%"

IF NOT DEFINED DEPLOYMENT_DIST (
    SET DEPLOYMENT_DIST=%DEPLOYMENT_SOURCE%\dist
) ELSE (
    ECHO "Deployement Dist already set"
)
echo "Deployment Dist: %DEPLOYMENT_DIST%"

IF NOT DEFINED DEPLOYMENT_TARGET (
  SET DEPLOYMENT_TARGET=%ARTIFACTS%\wwwroot
)
echo "Deployment Target: %DEPLOYMENT_TARGET%"

IF NOT DEFINED NEXT_MANIFEST_PATH (
  SET NEXT_MANIFEST_PATH=%ARTIFACTS%\manifest

  IF NOT DEFINED PREVIOUS_MANIFEST_PATH (
    SET PREVIOUS_MANIFEST_PATH=%ARTIFACTS%\manifest
  )
)

IF NOT DEFINED KUDU_SYNC_CMD (
  :: Install kudu sync
  echo Installing Kudu Sync
  call npm install kudusync -g --silent
  IF !ERRORLEVEL! NEQ 0 goto error

  :: Locally just running "kuduSync" would also work
  SET KUDU_SYNC_CMD=%appdata%\npm\kuduSync.cmd
)

for /F "tokens=5 delims=.\" %%a in ("%PREVIOUS_MANIFEST_PATH%") do SET PREVIOUS_SCM_COMMIT_ID=%%a

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: Pre-Deployment
:: ----------
@echo "Initiating Pre-Deployment: %date% %time%"
@echo "Previous Commit: %PREVIOUS_SCM_COMMIT_ID%  Current Commit: %SCM_COMMIT_ID%"
for /F %%f in ('git.exe diff --name-only %PREVIOUS_SCM_COMMIT_ID% %SCM_COMMIT_ID% ^| grep package.json') do (
    SET PACKAGEJSON=%%~f
    SET PKGFOLDER=!DEPLOYMENT_SOURCE!\!PACKAGEJSON:package.json=!
    echo "NPM Install: !PKGFOLDER!package.json"
    pushd "!PKGFOLDER!"
    npm install --production --progress=false --cache-min=432000
    npm install --save json-loader --progress=false --cache-min=432000
    IF !ERRORLEVEL! NEQ 0 goto error
    popd
)


::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: Deployment
:: ----------

@echo "Initiating Deployment: %date% %time%"

:: 1. Build Script
node %DEPLOYMENT_SOURCE%\.deploy\deploy.js

:: 2. KuduSync
IF /I "%IN_PLACE_DEPLOYMENT%" NEQ "1" (
  call :ExecuteCmd "%KUDU_SYNC_CMD%" -v 50 -f "%DEPLOYMENT_DIST%" -t "%DEPLOYMENT_TARGET%" -n "%NEXT_MANIFEST_PATH%" -p "%PREVIOUS_MANIFEST_PATH%" -i ".git;.hg;.deployment;deploy.cmd"
  IF !ERRORLEVEL! NEQ 0 goto error
)

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
goto end

:: Execute command routine that will echo out when error
:ExecuteCmd
setlocal
set _CMD_=%*
call %_CMD_%
if "%ERRORLEVEL%" NEQ "0" echo Failed exitCode=%ERRORLEVEL%, command=%_CMD_%
exit /b %ERRORLEVEL%

:error
endlocal
echo An error has occurred during web site deployment.
call :exitSetErrorLevel
call :exitFromFunction 2>nul

:exitSetErrorLevel
exit /b 1

:exitFromFunction
()

:end
endlocal
echo Finished successfully.

How long does it take before ending? Is it always the same? Also, is your app in Consumption mode or App Service Plan mode? — David Ebbo, Mar 01 '17 at 18:38
Consumption mode, and its pretty quick. Takes about 60-90 seconds to run the NPM commands. It is not always the same exact time period. I've also increased SCM_COMMAND_IDLE_TIMEOUT to 900 seconds. — Doug, Mar 01 '17 at 19:04
Not sure what's going on. One thing to check for is whether the Kudu w3wp is somehow crashing. You can look at the Kudu process manager before & after to see if PID changes (for the scm one). — David Ebbo, Mar 01 '17 at 23:45
I'll check that next push. Deployment does show a check mark as if it was a success. I'd think a w3wp would generate the "Unexpected error occurred" failure, but maybe not. — Doug, Mar 02 '17 at 02:31
PID stayed constant. I don't know what is going on. I just figured I messed up the batch :-(. — Doug, Mar 03 '17 at 17:33
Is the repro as simple a git pushing your repo to a Functions App? — David Ebbo, Mar 03 '17 at 17:47
Can you test if changing `npm install ...` into `call npm install ....` makes a difference? — MC ND, Mar 17 '17 at 20:54
It worked! Please add that as the answer and I'll accept it. If you have any idea as to why it worked, I'd be very interested to know that as well! — Doug, Mar 17 '17 at 21:04
It's because npm is a batch file. Without calling it, it stops the batch context. But the cached code block can still be executed — jeb, Mar 17 '17 at 21:32

MC ND · Accepted Answer · 2017-03-18T09:23:01.613

The source of the problem is that npm is a batch file. When a batch file (your batch file) invokes another batch file, the execution flow is transferred to the called one, and once it ends its work, the execution flow does not return to the caller.

This behaviour changes if the invocation is done using the call command.

call npm ....

The execution control is transfered to the called batch file and on end the execution flow returns to the caller.

note: The exposed behaviour is a simplification of the undelaying process. Batch files are executed inside a memory "context". Without the call command, the called batch file replaces the caller "context", with the call command, a new "context" is created.

This leaves another question: if the invocation of the batch npm batch file transfer execution flow and it does not return, why the second npm command is executed?

While executing a batch file (or command lines), blocks of code (code enclosed in parenthesis) are loaded into memory and parsed as a whole. Your for command is placed in memory, and all the commands included in its do clause will continue running until the loop ends.

note: Not relevant in in this case, but once the first npm has been invoked (without call) and the caller batch "context" has been discarded (replaced by the called context), the rest of the commands in the for loop are executed (they are still in memory) in command line context and not in batch context, and as the "context" was discarded, the setlocal has been reverted and variable changes, directoy changes and delayed expansion are discarded.

Thank-you for the great explanation. This is really interesting! — Doug, Mar 18 '17 at 19:56

Azure Function / Azure Website Custom Deploy Script Ending Prematurely

1 Answers1

Linked