Diagnosing a Windows Azure Website Github integration error

Yesterday I experienced an issue when trying to integrate a Windows Azure Website with Github. Specifically, my code would deploy from the master branch, but if I chose a specific other branch called ‘prototype’ I received a fetch error in the Windows Azure Management Portal:

This error has been reported to the team and I’m sure will be rectified so nobody else will run into it, but at Cory Fowler’s (@syntaxC4) prompting I wanted to document the steps I took to debug this as these steps may be useful to anyone struggling to debug a Windows Azure Website integration.

Scenario

In my scenario I had a project with a series of subfolders in my github repo. The project has progressed from a prototype to a full build but we were required to persist the prototype for design reference. We could have created ‘prototype’ without changing the solution structure, but as in all real world scenarios the requirement to leave the prototype available emerged only when we removed it and had changed the URL structure. We were only happy to continue working on new code if we could label the prototype or somehow leave it in a static state while the codebase moved on. This requirement is easily tackled by Windows Azure Websites and its Github integration; we changed the solution structure to have subfolders, created a new branch ‘prototype’ and continued our main work in ‘master’. Our ‘master’ branch has the additional benefit of having the prototype available for reference and quick applications of code change if we want to pivot our approach.

We then created two Windows Azure Websites (for free, wow!). In order to allow Windows Azure Websites to deploy the correct code for each, we created a .deployment file in each repository. In this .deployment file we inform Windows Azure Websites (through its Kudu deployment mechanism) that it should perform a custom deployment.

For the ‘master’ branch we want to deploy the /client folder, which involves a simple .deployment file containing

[config]
project = client

For the ‘prototype’ branch we want to deploy the /prototype folder, which involves a simple .deployment file containing

[config]
project = prototype

As you can see, these two branches then can evolve independently (although the prototype should be static).

Problems Start

The problems began when I tried to create a Windows Azure Website and integrate it with Github for the ‘prototype’ branch. No matter what I did, I couldn’t get the Github fetch to work:

At this point I stuck an email to some guy and David Ebbo (@davidebbo) prompted me to stop being lazy and look for some deployment logs. Powershell is your friend when it comes to debugging Windows Azure Websites, so I started there.

The first thing to do is to get the Logs using ‘Save-AzureWebsitesLog’:

PS C:\> Save-AzureWebsiteLog -Name partyr
Save-AzureWebsiteLog : Access to the path 'C:\logs.zip' is denied.
At line:1 char:1
+ Save-AzureWebsiteLog -Name partyr
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 + CategoryInfo : CloseError: (:) [Save-AzureWebsiteLog], UnauthorizedAccessException
 + FullyQualifiedErrorId : Microsoft.WindowsAzure.Management.Websites.SaveAzureWebsiteLogCommand

Oops, helps if pwd is something writable to the current user…

PS C:\> cd temp
PS C:\temp> Save-AzureWebsiteLog -Name myWebsite
PS C:\temp> ls
 Directory: C:\temp
Mode LastWriteTime Length Name
---- ------------- ------ ----
-a--- 23/09/2013 18:48 24406 logs.zip

Ok great. We have some Logs. Lets take a look!

Inside the zip at the location: /deployments/temp-59fd85ea/ are two files, log.xml and status.xml. These didn’t prove very useful :-)

Log.xml:

 <?xml version="1.0" encoding="utf-8"?>
 <entries>
 <entry time="2013-09-23T17:45:38.0768333Z" id="e7f9db74-a9e5-4738-93ee-028d051b6fd6" type="0">
 <message>Fetching changes.</message>
 </entry>
 </entries>

Status.xml:

 <?xml version="1.0" encoding="utf-8"?>
 <deployment>
 <id>temp-59fd85ea</id>
 <author>N/A</author>
 <deployer>GitHub</deployer>
 <authorEmail>N/A</authorEmail>
 <message>Fetch from git@github.com:elastacloud/asosmyWebsite.git</message>
 <progress></progress>
 <status>Failed</status>
 <statusText></statusText>
 <lastSuccessEndTime />
 <receivedTime>2013-09-23T17:45:37.9987137Z</receivedTime>
 <startTime>2013-09-23T17:45:37.9987137Z</startTime>
 <endTime>2013-09-23T17:45:40.8578955Z</endTime>
 <complete>True</complete>
 <is_temp>True</is_temp>
 <is_readonly>False</is_readonly>
 </deployment>

In the zip file at the location /LogFiles/Git/trace is a file that has much more useful information.

Part way down this encoded xml file is the error:

 <step title="Error occurred" date="09/23 17:16:12" type="error" text="fatal: ambiguous argument 'prototype': both revision and filename&#xA;Use '--' to separate filenames from revisions&#xA;&#xD;&#xA;D:\Program Files (x86)\Git\bin\git.exe log -n 1 prototype" stackTrace=" at Kudu.Core.Infrastructure.Executable.Execute(ITracer tracer, String arguments, Object[] args)&#xD;&#xA; at Kudu.Core.SourceControl.Git.GitExeRepository.GetChangeSet(String id)&#xD;&#xA; at Kudu.Services.FetchHandler.&lt;PerformDeployment&gt;d__c.MoveNext()&#xD;&#xA;--- End of stack trace from previous location where exception was thrown ---&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)&#xD;&#xA; at Kudu.Services.FetchHandler.&lt;&gt;c__DisplayClass1.&lt;&lt;ProcessRequestAsync&gt;b__0&gt;d__3.MoveNext()&#xD;&#xA;--- End of stack trace from previous location where exception was thrown ---&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)&#xD;&#xA; at Kudu.Contracts.Infrastructure.LockExtensions.&lt;TryLockOperationAsync&gt;d__0.MoveNext()&#xD;&#xA;--- End of stack trace from previous location where exception was thrown ---&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)&#xD;&#xA; at Kudu.Services.FetchHandler.&lt;ProcessRequestAsync&gt;d__6.MoveNext()&#xD;&#xA;--- End of stack trace from previous location where exception was thrown ---&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)&#xD;&#xA; at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)&#xD;&#xA; at System.Web.TaskAsyncHelper.EndTask(IAsyncResult ar)&#xD;&#xA; at System.Web.HttpTaskAsyncHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult result)&#xD;&#xA; at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()&#xD;&#xA; at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean&amp; completedSynchronously)" elapsed="0" />
 <step title="Outgoing response" date="09/23 17:16:12" type="response" statusCode="500" statusText="Internal Server Error" Cache-Control="private" X-AspNet-Version="4.0.30319" Content-Type="text/html; charset=utf-8" elapsed="0" />
 </step>

I missed this at first amongst all the the noise in this file. What I did instead is give up on notepad and xml and run a different powershell command: Get-AzureWebsiteLog -name myWebsite -Tail, which connects powershell to a real time stream of the Website log. Really really neat.

Clicking the sync button in Deployments of Windows Azure Websites Management Portal immediately showed activities in the Powershell console:

PS C:\temp> Get-AzureWebsiteLog -Name myWebsite -Tail
 2013-09-23T17:51:01 Welcome, you are now connected to log-streaming service.
 2013-09-23T17:51:02 Error occurred, type: error, text: fatal: ambiguous argument 'prototype': both revision and file
 name
 Use '--' to separate filenames from revisions
D:\Program Files (x86)\Git\bin\git.exe log -n 1 prototype, stackTrace: at Kudu.Core.Infrastructure.Executable.Execut
 e(ITracer tracer, String arguments, Object[] args)
 at Kudu.Core.SourceControl.Git.GitExeRepository.GetChangeSet(String id)
 at Kudu.Services.FetchHandler.<PerformDeployment>d__c.MoveNext()
 --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at Kudu.Services.FetchHandler.<>c__DisplayClass1.<<ProcessRequestAsync>b__0>d__3.MoveNext()
 --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at Kudu.Contracts.Infrastructure.LockExtensions.<TryLockOperationAsync>d__0.MoveNext()
 --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at Kudu.Services.FetchHandler.<ProcessRequestAsync>d__6.MoveNext()
 --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at System.Web.TaskAsyncHelper.EndTask(IAsyncResult ar)
 at System.Web.HttpTaskAsyncHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult result)
 at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
 at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
 2013-09-23T17:51:02 Outgoing response, type: response, statusCode: 500, statusText: Internal Server Error, Cache-Con
 trol: private, X-AspNet-Version: 4.0.30319, Content-Type: text/html; charset=utf-8

Fantastic! There’s our error, and with less noise than the xml file that I was earlier confused by.

So that’s my problem, ambiguous argument ‘prototype’: both revision and file
name
Use ‘–’ to separate filenames from revisions

This means my branch in Github is called ‘prototype’ and I have a file (folder technically) called ‘prototype’ in the system and this is ambiguous to the deployment system.

Now I can’t use — to separate filenames from revisions – I don’t have that level of control over the deployment process. But what I do have control over is the branch name and the folder name. I chose to rename the prototype folder:

Then I change my .deployment file to deploy the /proto folder:

[config]
project = proto

Pushing these changes immediately solved my issue. As shown by by the continuing Get-AzureWebsiteLog -Name MyWebsite -Tail

2013-09-23T17:54:53 Fetching changes.
2013-09-23T17:54:58 Updating submodules.
2013-09-23T17:55:00 Preparing deployment for commit id '7331a9c9c3'.
2013-09-23T17:55:01 Generating deployment script.
2013-09-23T17:55:01 Using the following command to generate deployment script: 'azure site deploymentscript -y --no-
dot-deployment -r "C:\DWASFiles\Sites\partyr\VirtualDirectory0\site\repository" -o "C:\DWASFiles\Sites\partyr\VirtualDi
rectory0\site\deployments\tools" --basic --sitePath "C:\DWASFiles\Sites\partyr\VirtualDirectory0\site\repository\proto"
'.
2013-09-23T17:55:01 The site directory path: .\proto
2013-09-23T17:55:01 Generating deployment script for Web Site
2013-09-23T17:55:01 Generated deployment script files
2013-09-23T17:55:01 Running deployment command...
2013-09-23T17:55:01 Command: C:\DWASFiles\Sites\partyr\VirtualDirectory0\site\deployments\tools\deploy.cmd
2013-09-23T17:55:01 Handling Basic Web Site deployment.
2013-09-23T17:55:01 KuduSync.NET from: 'C:\DWASFiles\Sites\partyr\VirtualDirectory0\site\repository\proto' to: 'C:\D
WASFiles\Sites\partyr\VirtualDirectory0\site\wwwroot'
2013-09-23T17:55:02 Deleting file: 'hubEventListener.js'
2013-09-23T17:55:02 Deleting file: 'hubEventListener.js.map'
2013-09-23T17:55:02 Deleting file: 'hubEventListener.ts'
2013-09-23T17:55:02 Deleting file: 'readme.txt'
2013-09-23T17:55:02 Copying file: 'index.html'
2013-09-23T17:55:02 Copying file: 'signalr.html'
2013-09-23T17:55:02 Deleting file: 'css\readme.txt'
2013-09-23T17:55:02 Copying file: 'css\bootstrap.min.css'
2013-09-23T17:55:02 Copying file: 'css\foundation.css'
2013-09-23T17:55:02 Copying file: 'css\foundation.min.css'
2013-09-23T17:55:02 Copying file: 'css\normalize.css'
2013-09-23T17:55:02 Copying file: 'css\party.css'
2013-09-23T17:55:02 Copying file: 'css\partyr.css'
2013-09-23T17:55:02 Copying file: 'css\ticker-style.css'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.abide.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.alerts.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.clearing.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.cookie.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.dropdown.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.forms.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.interchange.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.joyride.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.magellan.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.orbit.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.placeholder.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.reveal.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.section.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.tooltips.js'
2013-09-23T17:55:02 Copying file: 'foundation\foundation.topbar.js'
2013-09-23T17:55:02 Deleting file: 'img\readme.txt'
2013-09-23T17:55:02 Copying file: 'img\asos.png'
2013-09-23T17:55:02 Copying file: 'img\bg.gif'
2013-09-23T17:55:02 Copying file: 'img\draggable.jpg'
2013-09-23T17:55:02 Copying file: 'img\facebook_icon.jpg'
2013-09-23T17:55:02 Copying file: 'img\google_plus_logo.jpg'
2013-09-23T17:55:02 Copying file: 'img\rand1.jpeg'
2013-09-23T17:55:02 Copying file: 'img\rand2.jpeg'
2013-09-23T17:55:02 Copying file: 'img\rand3.jpeg'
2013-09-23T17:55:02 Copying file: 'img\rand4.jpeg'
2013-09-23T17:55:02 Copying file: 'img\rand5.jpg'
2013-09-23T17:55:02 Copying file: 'img\rand6.jpg'
2013-09-23T17:55:02 Copying file: 'img\rand7.jpg'
2013-09-23T17:55:02 Copying file: 'img\rand8.jpg'
2013-09-23T17:55:02 Copying file: 'img\twitter-bird-light-bgs.png'
2013-09-23T17:55:02 Copying file: 'img\voted.png'
2013-09-23T17:55:02 Copying file: 'jasmine\SpecRunner.html'
2013-09-23T17:55:02 Copying file: 'jasmine\lib\jasmine-1.3.1\jasmine-html.js'
2013-09-23T17:55:02 Copying file: 'jasmine\lib\jasmine-1.3.1\jasmine.css'
2013-09-23T17:55:02 Omitting next output lines...
2013-09-23T17:55:03 Finished successfully.
2013-09-23T17:55:03 Deployment successful.

The Kudu guys have already tackled the issue (https://github.com/projectkudu/kudu/issues/785) but the above diagnostics should help some of you.

Happy clouding,
Andy

Leave a Reply

Your email address will not be published. Required fields are marked *

*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>