[JIRA] (JENKINS-56981) VM failed to provision when use Pool Retention Strategy

10 views
Skip to first unread message

diwangchina@gmail.com (JIRA)

unread,
Apr 11, 2019, 11:59:03 AM4/11/19
to jenkinsc...@googlegroups.com
di wang created an issue
 
Jenkins / Bug JENKINS-56981
VM failed to provision when use Pool Retention Strategy
Issue Type: Bug Bug
Assignee: Azure DevOps
Components: azure-vm-agents-plugin
Created: 2019-04-11 15:58
Environment: Jenkins 2.150.1
Azure VM Agents 0.9.0

[root@pkrvmv9zkwan3x3 centos]# cat /etc/*release
CentOS Linux release 7.6.1810 (Core)
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"

CentOS Linux release 7.6.1810 (Core)
CentOS Linux release 7.6.1810 (Core)
Priority: Major Major
Reporter: di wang

When use pool retention strategy, most times VMs are failed to provision.

If use the same template settings, only change retention strategy to Idle retention strategy, then all vms can provisioned successfully(100%). 

Retention time in hour: 24

Pool Size: 1

Only a few times, VMs can be provisioned successfully with pool retention strategy.

Node ProvisioningActivity for Azure-Test/jenkins-…

java.lang.Exception: Node ProvisioningActivity for Azure-Test/jenkins-test/null (229415501) has lost. Mark as failure at com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask.cleanCloudStatistics(AzureVMAgentCleanUpTask.java:604) at com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask.clean(AzureVMAgentCleanUpTask.java:622) at com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask.access$200(AzureVMAgentCleanUpTask.java:73) at com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask$3.call(AzureVMAgentCleanUpTask.java:632) at com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask$3.call(AzureVMAgentCleanUpTask.java:629) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

vscjenkins@microsoft.com (JIRA)

unread,
Apr 11, 2019, 9:16:01 PM4/11/19
to jenkinsc...@googlegroups.com
Azure DevOps assigned an issue to Jie Shen
Change By: Azure DevOps
Assignee: Azure DevOps Jie Shen

vscjenkins@microsoft.com (JIRA)

unread,
Apr 11, 2019, 9:16:02 PM4/11/19
to jenkinsc...@googlegroups.com
Azure DevOps started work on Bug JENKINS-56981
 
Change By: Azure DevOps
Status: Open In Progress

jieshe@microsoft.com (JIRA)

unread,
Apr 11, 2019, 11:13:01 PM4/11/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981
 
Re: VM failed to provision when use Pool Retention Strategy

Hi di wang, do you mean no VM could be created successfully with your settings? I just check it in my environment, it seems to work well for me. Your log is just for clean up action, could you please provide the reason for its failed deployment?

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 10:54:02 AM4/12/19
to jenkinsc...@googlegroups.com
di wang updated an issue
 
Change By: di wang
Attachment: pic1.png
Attachment: pic2.png
Attachment: pic3.png
Attachment: pic4.png
Attachment: pic5.png
Attachment: pic6.png

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 10:54:02 AM4/12/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981
 
Re: VM failed to provision when use Pool Retention Strategy

The VM can not be created when use pool retention strategy as you can see in pic1. All of them failed with the same error as posted in the ticket above.

 

I also attached my settings pic2 to pic5. With this setting("idle retention strategy" in pic3), all VMs can created successfully triggered by label "m1".

 

However, if I change retention strategy to "pool retention strategy" (pic6), then it starts failed to create VMs. 

 

Please let me know if you need any additional data, or please suggest any instructions on how to troubleshoot.

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:03:02 AM4/12/19
to jenkinsc...@googlegroups.com
di wang updated an issue
Change By: di wang
Attachment: pic7.png
Attachment: pic8.png

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:03:02 AM4/12/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981
 
Re: VM failed to provision when use Pool Retention Strategy

attached new errors that I just tried today. 

 

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:05:01 AM4/12/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
attached new the errors that I just tried today. As mentioned above, no VMs can be created after switch to pool retention strategy.  

 

  

 !pic7.png!

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:06:01 AM4/12/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
attached the errors that I just tried today. As mentioned above, no VMs can be created after switch to pool retention strategy. 

 

 

!pic7.png!

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:06:03 AM4/12/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
The VM can not be created when use pool retention strategy as you can see in pic1. All of them failed with the same error as posted in the ticket above.

 

I also attached my settings pic2 to pic5. With this setting("idle retention strategy" in pic3), all VMs can created successfully triggered by label "m1".

 

However, if I change retention strategy to "pool retention strategy" (pic6), then it starts failed to create VMs. 

 

Please let me know if you need any additional data, or please suggest any instructions on how to troubleshoot. !pic1.png!  

 

diwangchina@gmail.com (JIRA)

unread,
Apr 12, 2019, 11:25:03 AM4/12/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
attached the errors that I just tried today. As mentioned


Observe it for an hour now. It looks like it created VM first, but shut it down after 1 or 2 minutes. I don't know why it shut the new VM down as it suppose to keep the new VM to maintain the pool. Maybe because of above error? 

Anyway , eventually no VMs can be created after switch to pool retention strategy. 

 

jieshe@microsoft.com (JIRA)

unread,
Apr 15, 2019, 4:33:02 AM4/15/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981

Even though I can use pool retention strategy to provision an agent and successfully run a job. But its behavior is not what I excepted. It cannot maintain a healthy pool of agents for my further jobs. Need more investigation on this strategy. 

diwangchina@gmail.com (JIRA)

unread,
Apr 18, 2019, 10:23:02 AM4/18/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981

Jie Shen do you have any update on this issue?

jieshe@microsoft.com (JIRA)

unread,
Apr 19, 2019, 3:15:02 AM4/19/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981

I have made a  PR  to fix one bug for pool retention strategy. But the your issue seems not related with it. I am afraid the advanced configuration parameters caused the provisioned agents into improper status. And this leads the clean up task to delete them.

diwangchina@gmail.com (JIRA)

unread,
Apr 24, 2019, 2:53:01 PM4/24/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981

Are you able to reproduce the issue? Do you need any other information?

jieshe@microsoft.com (JIRA)

unread,
Apr 26, 2019, 4:37:01 AM4/26/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981

di wang are you able to build a SNAP-SHOOT version with the above PR checked in? If so, please verify it in your Jenkins. If not, you can install the 0.7.5 (https://repo.jenkins-ci.org/releases/org/jenkins-ci/plugins/azure-vm-agents/0.7.5/) version which does not contain the bug. Instruction at https://jenkins.io/doc/book/managing/plugins/#advanced-installation . The ProvisioningActivity error log seems to only affect cloud statics, so it will not prevent provisioning VMs.

jieshe@microsoft.com (JIRA)

unread,
Apr 26, 2019, 5:24:03 AM4/26/19
to jenkinsc...@googlegroups.com
Jie Shen edited a comment on Bug JENKINS-56981
[~diwang] are you able to build a SNAP-SHOOT SNAPSHOT version with the above PR checked in? If so, please verify it in your Jenkins. If not, you can install the 0.7.5 ([https://repo.jenkins-ci.org/releases/org/jenkins-ci/plugins/azure-vm-agents/0.7.5/]) version which does not contain the bug. Instruction at [https://jenkins.io/doc/book/managing/plugins/#advanced-installation] . The ProvisioningActivity error log seems to only affect cloud statics, so it will not prevent provisioning VMs.

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:31:01 PM4/30/19
to jenkinsc...@googlegroups.com
di wang updated an issue
Change By: di wang
Attachment: Screen Shot 2019-04-30 at 4.20.06 PM.png

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:32:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang updated an issue
Change By: di wang
Attachment: Screen Shot 2019-04-30 at 4.24.13 PM.png

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:33:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981
 
Re: VM failed to provision when use Pool Retention Strategy

Built a snapshot plugin based on https://github.com/jenkinsci/azure-vm-agents-plugin/commit/82829b83854244c8e203e67fff7689056a8fd515

Upload the azure-vm-agents.hpi, then restart Jenkins. Check the new pic I uploaded. 

It is the same error. See new attached pic. 

From jenkins log, it looks like it thinks it provisioned successfully, but it actually didn't. Check attached new pic.

 

Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentApr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Initializing deployment for agentTemplate test-vmApr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Creating a new deployment test-vm0430161709407 with VM base name test-vm40794Apr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Use embedded deployment template (with managed) /referenceImageIDTemplateWithManagedDisk.jsonApr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask$DeploymentRegistrar registerDeploymentINFO: AzureVMAgentCleanUpTask: registerDeployment: Registering deployment test-vm0430161709407 in cardinal-jenkins-testApr 30, 2019 4:17:13 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Waiting for deployment test-vm0430161709407 to be completedApr 30, 2019 4:17:43 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 90fe5df5-b8e3-403c-b4c8-5ad1e8b43a32] Instance discovery was successfulApr 30, 2019 4:17:43 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?Apr 30, 2019 4:18:07 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Deployment test-vm0430161709407 not yet finished (Running): Microsoft.Compute/virtualMachines:test-vm407940 - waited 30 secondsApr 30, 2019 4:18:37 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 22087788-162d-4386-b453-f33292ef2516] Instance discovery was successfulApr 30, 2019 4:18:38 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?Apr 30, 2019 4:18:48 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: VM available: test-vm407940Apr 30, 2019 4:18:49 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate parseResponseINFO: AzureVMManagementServiceDelegate: parseDeploymentResponse: found agent test-vm407940 OS type Linux number of executors 1Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: The Azure agent doesn't have a public IP. Will use the private IPApr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: Azure agent details:nodeNametest-vm407940adminUserName=azure-jenkinsshutdownOnIdle=falseretentionTimeInMin=0labels=packerApr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloud$3 callINFO: Azure Cloud: provision: Adding agent test-vm407940 to Jenkins nodesApr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMAgent createComputerINFO: AzureVMAgent: createComputer: start for agent test-vm407940Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloudPoolRetentionStrategy startINFO: AzureVMCloudRetensionStrategy: start: azureComputer name test-vm407940Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launch method called for agent test-vm407940Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate isVMAliveOrHealthyINFO: AzureVMManagementServiceDelegate: isVMAliveOrHealthy: status PowerState/runningApr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: startApr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: getting remote session for user jenkins to host 10.10.0.42:22Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: Got remote session for user jenkins to host 10.10.0.42:22Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: Got remote connectionApr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: checking for java runtimeApr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: starting java fullversionApr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: executed successfullyApr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: java runtime present, copying slave.jar to remoteApr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: Initiating file transfer to slave.jarApr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: copied file Successfully to slave.jarApr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launching agent: java  -jar slave.jarApr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: Connected successfullyApr 30, 2019 4:19:13 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launched agent successfullyApr 30, 2019 4:23:36 PM com.microsoft.rest.interceptors.LoggingInterceptor logINFO: <- HTTP FAILED: java.net.SocketException: Connection resetApr 30, 2019 4:23:36 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?

 

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:33:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang updated an issue
Change By: di wang
Attachment: Screen Shot 2019-04-30 at 4.31.45 PM.png

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:37:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
Built a snapshot plugin based on [https://github.com/jenkinsci/azure-vm-agents-plugin/commit/82829b83854244c8e203e67fff7689056a8fd515]

Upload the azure-vm-agents.hpi, then restart Jenkins. Check the new pic I uploaded. 

It is the same error. See new attached pic. 

From jenkins log, it looks like it thinks it provisioned successfully, but it actually didn't. Check attached new pic.

 
{quote}Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentApr createDeployment

Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Initializing deployment for agentTemplate test- vmApr vm

Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Creating a new deployment test-vm0430161709407 with VM base name test- vm40794Apr vm40794

Apr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Use embedded deployment template (with managed) /referenceImageIDTemplateWithManagedDisk. jsonApr json

Apr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask$DeploymentRegistrar registerDeploymentINFO: AzureVMAgentCleanUpTask: registerDeployment: Registering deployment test-vm0430161709407 in cardinal-jenkins- testApr test

Apr 30, 2019 4:17:13 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Waiting for deployment test-vm0430161709407 to be completedApr completed

Apr 30, 2019 4:17:43 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 90fe5df5-b8e3-403c-b4c8-5ad1e8b43a32] Instance discovery was successfulApr successful

Apr 30, 2019 4:17:43 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?

Apr 30, 2019 4:18:07 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Deployment test-vm0430161709407 not yet finished (Running): Microsoft.Compute/virtualMachines:test-vm407940 - waited 30 secondsApr seconds

Apr 30, 2019 4:18:37 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 22087788-162d-4386-b453-f33292ef2516] Instance discovery was successfulApr successful

Apr 30, 2019 4:18:38 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?

Apr 30, 2019 4:18:48 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: VM available: test- vm407940Apr vm407940

Apr 30, 2019 4:18:49 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate parseResponseINFO: AzureVMManagementServiceDelegate: parseDeploymentResponse: found agent test-vm407940 OS type Linux number of executors 1Apr 1

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: The Azure agent doesn't have a public IP. Will use the private IPApr IP

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: Azure agent details:nodeNametest-vm407940adminUserName=azure-jenkinsshutdownOnIdle=falseretentionTimeInMin=0labels= packerApr packer

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloud$3 callINFO: Azure Cloud: provision: Adding agent test-vm407940 to Jenkins nodesApr nodes

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMAgent createComputerINFO: AzureVMAgent: createComputer: start for agent test- vm407940Apr vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloudPoolRetentionStrategy startINFO: AzureVMCloudRetensionStrategy: start: azureComputer name test- vm407940Apr vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launch method called for agent test- vm407940Apr vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate isVMAliveOrHealthyINFO: AzureVMManagementServiceDelegate: isVMAliveOrHealthy: status PowerState/ runningApr running

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: startApr start

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: getting remote session for user jenkins to host 10.10.0.42: 22Apr 22

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: Got remote session for user jenkins to host 10.10.0.42: 22Apr 22

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: Got remote connectionApr connection

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: checking for java runtimeApr runtime

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: starting java -fullversionApr fullversion

Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: executed successfullyApr successfully

Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: java runtime present, copying slave.jar to remoteApr remote

Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: Initiating file transfer to slave. jarApr jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: copied file Successfully to slave. jarApr jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launching agent: java  -jar slave. jarApr jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: Connected successfullyApr successfully

Apr 30, 2019 4:19:13 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launched agent successfullyApr successfully

Apr 30, 2019 4:23:36 PM com.microsoft.rest.interceptors.LoggingInterceptor logINFO: - <-- HTTP FAILED: java.net.SocketException: Connection resetApr reset

Apr 30, 2019 4:23:36 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?
{quote}
h6.  

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:39:03 PM4/30/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
Built a snapshot plugin based on [https://github.com/jenkinsci/azure-vm-agents-plugin/commit/82829b83854244c8e203e67fff7689056a8fd515]

Upload the azure-vm-agents.hpi, then restart Jenkins. Check the new pic I uploaded. 

It is the same error. See new attached pic. 

From jenkins log, it looks like it thinks it provisioned successfully, but it actually didn't. The latest provision failed but no more attempts after it.  Check attached new pic.

 
{quote}Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeployment


Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Initializing deployment for agentTemplate test-vm

Apr 30, 2019 4:17:09 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Creating a new deployment test-vm0430161709407 with VM base name test-vm40794

Apr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate createDeploymentINFO: AzureVMManagementServiceDelegate: createDeployment: Use embedded deployment template (with managed) /referenceImageIDTemplateWithManagedDisk.json

Apr 30, 2019 4:17:10 PM com.microsoft.azure.vmagent.AzureVMAgentCleanUpTask$DeploymentRegistrar registerDeploymentINFO: AzureVMAgentCleanUpTask: registerDeployment: Registering deployment test-vm0430161709407 in cardinal-jenkins-test

Apr 30, 2019 4:17:13 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Waiting for deployment test-vm0430161709407 to be completed

Apr 30, 2019 4:17:43 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 90fe5df5-b8e3-403c-b4c8-5ad1e8b43a32] Instance discovery was successful


Apr 30, 2019 4:17:43 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?

Apr 30, 2019 4:18:07 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: Deployment test-vm0430161709407 not yet finished (Running): Microsoft.Compute/virtualMachines:test-vm407940 - waited 30 seconds

Apr 30, 2019 4:18:37 PM com.microsoft.aad.adal4j.AuthenticationAuthority doInstanceDiscoveryINFO: [Correlation ID: 22087788-162d-4386-b453-f33292ef2516] Instance discovery was successful


Apr 30, 2019 4:18:38 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?

Apr 30, 2019 4:18:48 PM com.microsoft.azure.vmagent.AzureVMCloud createProvisionedAgentINFO: AzureVMCloud: createProvisionedAgent: VM available: test-vm407940

Apr 30, 2019 4:18:49 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate parseResponseINFO: AzureVMManagementServiceDelegate: parseDeploymentResponse: found agent test-vm407940 OS type Linux number of executors 1

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: The Azure agent doesn't have a public IP. Will use the private IP


Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate setVirtualMachineDetailsINFO: Azure agent details:nodeNametest-vm407940adminUserName=azure-jenkinsshutdownOnIdle=falseretentionTimeInMin=0labels=packer

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloud$3 callINFO: Azure Cloud: provision: Adding agent test-vm407940 to Jenkins nodes


Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMAgent createComputerINFO: AzureVMAgent: createComputer: start for agent test-vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMCloudPoolRetentionStrategy startINFO: AzureVMCloudRetensionStrategy: start: azureComputer name test-vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launch method called for agent test-vm407940

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.AzureVMManagementServiceDelegate isVMAliveOrHealthyINFO: AzureVMManagementServiceDelegate: isVMAliveOrHealthy: status PowerState/running

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: start

Apr 30, 2019 4:18:51 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: getting remote session for user jenkins to host 10.10.0.42:22

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher getRemoteSessionINFO: AzureVMAgentSSHLauncher: getRemoteSession: Got remote session for user jenkins to host 10.10.0.42:22

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher connectToSshINFO: AzureVMAgentSSHLauncher: connectToSsh: Got remote connection

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: checking for java runtime

Apr 30, 2019 4:18:52 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: starting java fullversion

Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher executeRemoteCommandINFO: AzureVMAgentSSHLauncher: executeRemoteCommand: executed successfully

Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: java runtime present, copying slave.jar to remote


Apr 30, 2019 4:18:54 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: Initiating file transfer to slave.jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher copyFileToRemoteINFO: AzureVMAgentSSHLauncher: copyFileToRemote: copied file Successfully to slave.jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launching agent: java  -jar slave.jar

Apr 30, 2019 4:19:04 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: Connected successfully

Apr 30, 2019 4:19:13 PM com.microsoft.azure.vmagent.remote.AzureVMAgentSSHLauncher launchINFO: AzureVMAgentSSHLauncher: launch: launched agent successfully

Apr 30, 2019 4:23:36 PM com.microsoft.rest.interceptors.LoggingInterceptor logINFO: -<-- HTTP FAILED: java.net.SocketException: Connection reset


Apr 30, 2019 4:23:36 PM okhttp3.internal.platform.Platform logINFO: ALPN callback dropped: HTTP/2 is disabled. Is alpn-boot on the boot class path?
{quote}
h6.  

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:43:01 PM4/30/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981

Oops, please ignore my last comment. Even the same error appears, but the vm provisioned successfully this time. I saw it in the jenkins agent list.

However, Cloud Statistics report it failed and no further report of it(test-vm407940), like "Operation time" and etc. 

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:52:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981

With more testing, I config the max vm nunmber is 4 which the pool size is 1.

I submit a branch of requests to trigger it. As it thinks test-vm407940 was failed, then it provisioned another 4 vm. So total is 5 now, more than the max vm number I configured.

diwangchina@gmail.com (JIRA)

unread,
Apr 30, 2019, 4:52:02 PM4/30/19
to jenkinsc...@googlegroups.com
di wang updated an issue
Change By: di wang
Attachment: Screen Shot 2019-04-30 at 4.50.40 PM.png

diwangchina@gmail.com (JIRA)

unread,
May 9, 2019, 10:17:03 AM5/9/19
to jenkinsc...@googlegroups.com
di wang commented on Bug JENKINS-56981

diwangchina@gmail.com (JIRA)

unread,
May 9, 2019, 10:17:03 AM5/9/19
to jenkinsc...@googlegroups.com
di wang edited a comment on Bug JENKINS-56981
Jie, do we have a fix for this?   [~jieshe]

jieshe@microsoft.com (JIRA)

unread,
May 10, 2019, 2:05:03 AM5/10/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981

di wang I have tested with vnet configuration(delete and provision several times), but I still get no luck to reproduce your error. I use the latest version on the dev branch for the configuration as code work done on the branch and it is should be a stable one with some fixes. And below is my configuration:

- azureVM:
azureCredentialsId: "imds"
cloudName: "jsdev"
configurationStatus: "pass"
deploymentTimeout: 1200
existingResourceGroupName: "Testing"
maxVirtualMachinesLimit: 10
newResourceGroupName: "jieshe-dev-agents"
resourceGroupReferenceType: "new"
vmTemplates:
- agentLaunchMethod: "SSH"
availabilityType:
availabilitySet: "avset"
builtInImage: "Windows Server 2016"
credentialsId: "agent_admin_account"
diskType: "managed"
doNotUseMachineIfInitFails: true
enableMSI: false
executeInitScriptAsRoot: true
existingStorageAccountName: "fsxvergehbetgzsvfg"
imageReference:
offer: "UbuntuServer"
publisher: "Canonical"
sku: "16.04-LTS"
version: "latest"
imageTopLevelType: "advanced"
initScript: "sudo add-apt-repository ppa:openjdk-r/ppa -y\nsudo apt-get -y\
\ update\nsudo apt-get install openjdk-8-jre openjdk-8-jre-headless openjdk-8-jdk\
\ -y"
installDocker: false
installGit: false
installMaven: false
labels: "advanced"
location: "East US"
newStorageAccountName: "asdfwefwef"
noOfParallelJobs: 1
osDiskSize: 0
osType: "Linux"
preInstallSsh: true
retentionStrategy:
azureVMCloudPool:
poolSize: 1
retentionInHours: 24
shutdownOnIdle: false
storageAccountNameReferenceType: "new"
storageAccountType: "Standard_LRS"
subnetName: "jenkins"
templateDisabled: false
templateName: "advanced"
usageMode: "Use this node as much as possible"
usePrivateIP: true
virtualMachineSize: "Standard_F2s"
virtualNetworkName: "jenkins-vnet"
virtualNetworkResourceGroupName: "jieshe-jenkins"

Do I miss anything in the configuration that make me unable to reproduce the error on my side?
 

jieshe@microsoft.com (JIRA)

unread,
May 10, 2019, 2:12:02 AM5/10/19
to jenkinsc...@googlegroups.com
Jie Shen commented on Bug JENKINS-56981

For provisioning more nodes than the limits, it is an existing issue JENKINS-56972 caused by bad concurrency control. I will try to fix this later.
Reply all
Reply to author
Forward
0 new messages