Deploying Java Azure Function using azure-maven-plugin giving timeout error

Question

I am trying to deploy Java Azure function via Maven plugin and getting a Channel Response timeout during deployment.

I am using azure-function-maven-plugin version: 1.27.0 and also 1.28.0 . Below are my setups and problem logs below that.

Maven pom.xml plugin setup:

<plugin>
	<groupId>com.microsoft.azure</groupId>
	<artifactId>azure-functions-maven-plugin</artifactId>
	<version>1.28.0</version>
	<configuration>
		<appName>my</appName>
		<resourceGroup>${param.functionAppResourceGroup}</resourceGroup>
		<appServicePlanName>${param.functionAppServicePlan}</appServicePlanName>
		<subscriptionId>{param.subscriptionId}</subscriptionId>
		<region>australiaeast</region>
		<pricingTier>EP2</pricingTier>
		<runtime>
			<os>linux</os>
			<javaVersion>11</javaVersion>
		</runtime>
		<appSettings></appSettings>
		<auth>
			<type>azure_cli</type>
		</auth>
	</configuration>
	<executions>
		<execution>
			<id>package-functions</id>
			<goals>
				<goal>package</goal>
			</goals>
		</execution>
	</executions>
</plugin>

Maven command being run:

mvn clean package azure-functions:deploy \
 -Dparam.functionAppResourceGroup=xxx \
 -Dparam.functionAppServicePlan=xxx \
 -Dparam.subscriptionId=

Where the problem happens

The log output (ran looks like below where deployment initiates and gets stuck after this line:

[INFO] Starting deployment...

I can see Channel response timed out issue happening repeatedly every 60s after which Maven retries the same operation (unable to make out what that is from logs) before I have to kill it.

[DEBUG] Compressing '/agent/_work/1/a/staging/sample-az-fns-java/target/azure-functions/my-az-function-name' into '/tmp/azure-functions1565839957208350650.zip'.
[DEBUG] Copying '/tmp/azure-functions1565839957202353651.zip' to '/tmp/zt-zip-tmp13860731593857892672.zip' and removing paths [local.settings.json].
[DEBUG] [sites:my-az-function-name]:getRemote()
[DEBUG] Creating a new [http] client pool [PoolFactory{evictionInterval=PT0S, leasingStrategy=fifo, maxConnections=500, maxIdleTime=-1, maxLifeTime=-1, metricsEnabled=false, pendingAcquireMaxCount=1000, pendingAcquireTimeout=45000}] for [my-az-function-name.scm.azurewebsites.net:443]
[DEBUG] [c1108a10] Created a new pooled channel, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
[DEBUG] [c1108a10] SSL enabled using engine io.netty.handler.ssl.OpenSslEngine@28892bcb and SNI my-az-function-name.scm.azurewebsites.net:443
[DEBUG] [c1108a10] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[DEBUG] [c1108a10] Connecting to [my-az-function-name.scm.azurewebsites.net/<redacted>:443].
[DEBUG] [my-az-function-name]:fireStatusChangedEvent()
[DEBUG] [c1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Registering pool release on close event for channel
[DEBUG] [c1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Channel connected, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
[DEBUG] [id: 0xc1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[DEBUG] [c1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] onStateChange(PooledConnection{channel=[id: 0xc1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443]}, [connected])
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] onStateChange(GET{uri=null, connection=PooledConnection{channel=[id: 0xc1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443]}}, [configured])
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Handler is being applied: {uri=https://my-az-function-name.scm.azurewebsites.net/api/settings, method=GET}
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] onStateChange(GET{uri=/api/settings, connection=PooledConnection{channel=[id: 0xc1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443]}}, [request_prepared])
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Added decoder [azureWriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureWriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Non Removed handler: azureRequestProgressHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (azureWriteTimeoutHandler = com.azure.core.http.netty.implementation.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] onStateChange(GET{uri=/api/settings, connection=PooledConnection{channel=[id: 0xc1108a10, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443]}}, [request_sent])
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Non Removed handler: azureRequestProgressHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (azureWriteTimeoutHandler = com.azure.core.http.netty.implementation.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Removed handler: azureWriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[DEBUG] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Added decoder [azureResponseTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureResponseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
[WARNING] [c1108a10-1, L:/10.<redacted>:55700 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] The connection observed an error
java.util.concurrent.TimeoutException: Channel response timed out after 60000 milliseconds.
    at com.azure.core.http.netty.implementation.ResponseTimeoutHandler.responseTimedOut (ResponseTimeoutHandler.java:58)
    at com.azure.core.http.netty.implementation.ResponseTimeoutHandler.lambda$handlerAdded$0 (ResponseTimeoutHandler.java:45)
    at io.netty.util.concurrent.PromiseTask.runTask (PromiseTask.java:98)
    at io.netty.util.concurrent.ScheduledFutureTask.run (ScheduledFutureTask.java:153)
    at io.netty.util.concurrent.AbstractEventExecutor.runTask (AbstractEventExecutor.java:174)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute (AbstractEventExecutor.java:167)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks (SingleThreadEventExecutor.java:470)
    at io.netty.channel.epoll.EpollEventLoop.run (EpollEventLoop.java:406)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run (SingleThreadEventExecutor.java:997)
    at io.netty.util.internal.ThreadExecutorMap$2.run (ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run (FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run (Thread.java:829)

I can Also see a 503 Service Unavaiable for this endpoint after several interations of the above 60000ms timeout exception.

2023-10-05T23:56:25.5091532Z [DEBUG] [f788d0cf-1, L:/<redacted>:50402 - R:my-az-function-name.scm.azurewebsites.net/<redacted>:443] Handler is being applied: {uri=https://my-az-function-name.scm.azurewebsites.net/api/settings, method=GET}


... 

2023-10-05T23:57:21.5441643Z HTTP/1.1 503 Service Unavailable
2023-10-05T23:57:21.5442483Z Date: <filtered>
2023-10-05T23:57:21.5443241Z Set-Cookie: <filtered>
2023-10-05T23:57:21.5443494Z Set-Cookie: <filtered>
2023-10-05T23:57:21.5443757Z Transfer-Encoding: <filtered>

Would appreciate any pointers whats gone wrong. Thanks.

Answer 1

@Ali Imtiaz Thanks for your patience! From the logs I see that deployment fails due to connectivity issues with storage account.

Azure Function requires access to the storage account for the Docker container for both the main site and Kudu to start up.

Please verify kudu service status, If the Kudu service is not running, deployments will not be possible. So, both your main site and Kudu need to be running and have access to the storage account for the Docker container for successful deployment of your Azure Function.
You might need to check your access permissions or network configurations that could be preventing Kudu from starting up or accessing the necessary resources.

Storage account you need to look at is the one in the app setting WEBSITE_CONTENTAZUREFILECONNECTIONSTRING for connectivity. 

let me know incase of further queries, I would be happy to assist you.