Extensions Custom Script not running

[jermth]

I believe this is related to #1269

I saw this happen today in VMs in scale sets in east us. The VM is running WALinuxAgent-2.2.31, and see this in the waagent.log

2018/10/04 14:57:14.773072 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.6] Install extension [bin/custom-script-shim install]
2018/10/04 14:57:14.855006 INFO ExtHandler Examine /proc/net/route for primary interface
2018/10/04 14:57:14.856113 INFO ExtHandler Primary interface is [eth0]
2018/10/04 14:57:15.233890 INFO ExtHandler EnvMonitor: Detected dhcp client restart. Restoring routing table.
2018/10/04 14:57:15.234521 INFO ExtHandler Configure routes
2018/10/04 14:57:15.234884 INFO ExtHandler Gateway:None
2018/10/04 14:57:15.235246 INFO ExtHandler Routes:None
2018/10/04 14:57:15.777653 WARNING [Microsoft.Azure.Extensions.CustomScript-2.0.6] [ExtensionError] Non-zero exit code: 1, bin/custom-script-shim install
2018/10/04 14:57:15.818581 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.6] Remove extension handler directory: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.0.6

And see this in /var/log/azure/custom-script/handler.log:

+ /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.0.6/bin/custom-script-extension install
/var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.0.6/bin/custom-script-shim: line 77: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.0.6/bin/custom-script-extension: Text file busy

This is an CentOS 7.4 image.

I've attached the waagaent.log

waagent.not-working.log

[dougclayton]

This is the same as #1267

[Diastro]

Seems like some other process is using the custom-script-extension executable.
@jermth can you run the following and see which process is using the file?
lsof | grep custom-script-extension

[Diastro]

@dougclayton, @vrdmr could this be a race condition while the agent is also calling chmod on the file? The extension is crashing while calling the extension executable. I'm wondering if this https://github.com/Azure/WALinuxAgent/blob/master/azurelinuxagent/ga/exthandlers.py#L779 could be the cause (mix with some weird race condition).

[dougclayton]

@Diastro I am pretty sure it is a race condition, but I don't know that it involves the chmod. I have traced back that particular error to a line in the custom script extension (bin/custom-script-shim) which executes another file (bin/custom-script-extension) which is what is apparently open, and thus gives the error. So it is likely something that opens the file for writing. Since the WALinuxAgent is what writes both those files in the first place (https://github.com/Azure/WALinuxAgent/blob/master/azurelinuxagent/ga/exthandlers.py#L771), I believe it is where the problem lies.

[cy33hc]

I'm facing the same issue with custom-script extension failing with the "text file busy" error also. To make things worst now, after the commit #1397, the WAAGENT fails at an early phase and I can't even ssh into the VM to view the failure.

[vrdmr]

Fixed by CSE - Azure/custom-script-extension-linux#153 and Azure/custom-script-extension-linux#155. As a part of the CSE v2.1.2.

Closing the issue now.