Skip to content

How to debug

Jump to bottom
Simon J.K. Pedersen edited this page Apr 18, 2017 · 2 revisions

How to debug

If you experience problems with the site-extension you can enable Application Logging Enable Applicatoin Logging

When Application logging has been enabled you will be able to see the logs in the Log Stream Log Stream

Or you can browse the log files in D:\home\LogFiles\SiteExtensions\letsencrypt using the Kudu portal.

A failed installation

If the installation of the certificates fail on the challenge response, the error could look like this


Connecting...
2016-03-22T19:57:24  Welcome, you are now connected to log-streaming service.
2016-03-22T19:58:03  PID[4200] Warning     unable to parse WEBSITE_OWNER_NAME ''
2016-03-22T19:58:03  PID[4200] Warning     unable to parse WEBSITE_OWNER_NAME ''
2016-03-22T19:58:03  PID[4200] Information 3/22/2016 7:58:03 PM:  - AuthenticationContext: ADAL .NET with assembly version '2.18.0.0', file version '2.18.20625.1556' and informational version 'b90841565e0ecaad0f3f73072c3d40e43223de4e' is running...
2016-03-22T19:58:03  PID[4200] Information 3/22/2016 7:58:03 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - AcquireTokenHandlerBase: === Token Acquisition started:
	Authority: https://login.windows.net/delegate.onmicrosoft.com/
	Resource: https://management.core.windows.net/
	ClientId: ce88fa0e-9f6a-4bde-afb3-796af31c430f
	CacheType: Microsoft.IdentityModel.Clients.ActiveDirectory.TokenCache (0 items)
	Authentication Target: Client
	
2016-03-22T19:58:03  PID[4200] Information 3/22/2016 7:58:03 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - TokenCache: Looking up cache for a token...
2016-03-22T19:58:03  PID[4200] Information 3/22/2016 7:58:03 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - TokenCache: No matching token was found in the cache
2016-03-22T19:58:04  PID[4200] Information 3/22/2016 7:58:04 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - TokenCache: Storing token in the cache...
2016-03-22T19:58:04  PID[4200] Information 3/22/2016 7:58:04 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - TokenCache: An item was stored in the cache
2016-03-22T19:58:04  PID[4200] Information 3/22/2016 7:58:04 PM: 6772597e-61ec-4f06-8cb8-db192e689622 - AcquireTokenHandlerBase: === Token Acquisition finished successfully. An access token was retuned:
	Access Token Hash: 6nFeNYy2D6LmMACzct9OtuulmtDRU0PgBbtS1dyVsmU=
	Refresh Token Hash: [No Refresh Token]
	Expiration Time: 3/22/2016 8:58:03 PM +00:00
	User Hash: null
	
2016-03-22T19:58:04  PID[4200] Information Loading Signer from D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\Signer
2016-03-22T19:58:05  PID[4200] Information 
Getting AcmeServerDirectory
2016-03-22T19:58:05  PID[4200] Information Loading Registration from D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\Registration
2016-03-22T19:58:05  PID[4200] Information Authorizing Identifier letsencrypt2.sjkp.dk Using Challenge Type http-01
2016-03-22T19:58:11  PID[4200] Information Writing challenge answer to D:\home\site\wwwroot\.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4
2016-03-22T19:58:11  PID[4200] Information Answer should now be browsable at http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4
2016-03-22T19:58:11  PID[4200] Information Submitting answer
2016-03-22T19:58:11  PID[4200] Information Refreshing authorization attempt1
2016-03-22T19:58:22  PID[4200] Information Auth Result invalid
2016-03-22T19:58:22  PID[4200] Error       Authorization Failed invalid
2016-03-22T19:58:22  PID[4200] Information Full Error Details {"IdentifierPart":{"Type":"dns","Value":"letsencrypt2.sjkp.dk"},"IdentifierType":"dns","Identifier":"letsencrypt2.sjkp.dk","Uri":"https://acme-staging.api.letsencrypt.org/acme/authz/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0","Status":"invalid","Expires":"2016-03-29T19:58:06Z","Challenges":[{"ChallengePart":{"Type":"dns-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977050","Token":"8IxtVU4fFM8tXzLAJ6w6j3UAkGAp27zGQG2naRMhqZA","Status":"pending","Validated":null,"Error":null},"Challenge":null,"Type":"dns-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977050","Token":"8IxtVU4fFM8tXzLAJ6w6j3UAkGAp27zGQG2naRMhqZA","Status":"pending","OldChallengeAnswer":{"Key":null,"Value":null},"ChallengeAnswerMessage":null,"HandlerName":null,"HandlerHandleDate":null,"HandlerCleanUpDate":null,"SubmitDate":null,"SubmitResponse":null},{"ChallengePart":{"Type":"http-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977051","Token":"RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4","Status":"invalid","Validated":null,"Error":{"type":"urn:acme:error:unauthorized","detail":"Invalid response from http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4 [13.75.89.224]: 404"},"keyAuthorization":"RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4.3tUz3o6-ZSFvWB50_m-BQ26XlHvoVv5KieCpFy98o5s","validationRecord":[{"url":"http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4","hostname":"letsencrypt2.sjkp.dk","port":"80","addressesResolved":["13.75.89.224"],"addressUsed":"13.75.89.224"},{"url":"http://letsencrypt2.sjkp.dk/login.aspx?ReturnUrl=%2f.well-known%2facme-challenge%2fRsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4","hostname":"letsencrypt2.sjkp.dk","port":"80","addressesResolved":["13.75.89.224"],"addressUsed":"13.75.89.224"}]},"Challenge":null,"Type":"http-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977051","Token":"RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4","Status":"invalid","OldChallengeAnswer":{"Key":null,"Value":null},"ChallengeAnswerMessage":null,"HandlerName":null,"HandlerHandleDate":null,"HandlerCleanUpDate":null,"SubmitDate":null,"SubmitResponse":null},{"ChallengePart":{"Type":"tls-sni-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977052","Token":"gqPNNrpK3UM1NLkre7fcaCpPy690vkvXFsLjz93lz3s","Status":"pending","Validated":null,"Error":null},"Challenge":null,"Type":"tls-sni-01","Uri":"https://acme-staging.api.letsencrypt.org/acme/challenge/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0/1977052","Token":"gqPNNrpK3UM1NLkre7fcaCpPy690vkvXFsLjz93lz3s","Status":"pending","OldChallengeAnswer":{"Key":null,"Value":null},"ChallengeAnswerMessage":null,"HandlerName":null,"HandlerHandleDate":null,"HandlerCleanUpDate":null,"SubmitDate":null,"SubmitResponse":null}],"Combinations":[[0],[1],[2]]}
2016-03-22T19:58:22  PID[4200] Error       Unable to reach http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4
2016-03-22T19:58:22  PID[4200] Error       System.Exception: The Lets Encrypt ACME server was probably unable to reach http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/RsGZ7YTzsAaiUf2QwUDLX3kIDbrc02Sc2MFWkH3sgJ4 view error report from Lets Encrypt at https://acme-staging.api.letsencrypt.org/acme/authz/UG0esYff2sDcZUEYRvFt5dhil_TJsfkm1AcQOAgOti0 for more information
   at LetsEncrypt.SiteExtension.Core.CertificateManager.Authorize(Target target) in c:\Projects\LetsEncrypt-SiteExtension\LetsEncrypt-SiteExtension\LetsEncrypt.SiteExtension.Core\CertificateManager.cs:line 553
   at LetsEncrypt.SiteExtension.Core.CertificateManager.Auto(Target binding) in c:\Projects\LetsEncrypt-SiteExtension\LetsEncrypt-SiteExtension\LetsEncrypt.SiteExtension.Core\CertificateManager.cs:line 437
   at LetsEncrypt.SiteExtension.Core.CertificateManager.RequestAndInstallInternal(Target target) in c:\Projects\LetsEncrypt-SiteExtension\LetsEncrypt-SiteExtension\LetsEncrypt.SiteExtension.Core\CertificateManager.cs:line 222

Successful installation

A successful installation could look like this

2016-03-22T19:59:24  No new trace in the past 1 min(s).
2016-03-22T20:00:22  PID[4200] Warning     unable to parse WEBSITE_OWNER_NAME ''
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - AcquireTokenHandlerBase: === Token Acquisition started:
	Authority: https://login.windows.net/delegate.onmicrosoft.com/
	Resource: https://management.core.windows.net/
	ClientId: ce88fa0e-9f6a-4bde-afb3-796af31c430f
	CacheType: Microsoft.IdentityModel.Clients.ActiveDirectory.TokenCache (1 items)
	Authentication Target: Client
	
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - TokenCache: Looking up cache for a token...
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - TokenCache: An item matching the requested resource was found in the cache
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - TokenCache: 57.680644005 minutes left until token in cache expires
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - TokenCache: A matching item (access token or refresh token or both) was found in the cache
2016-03-22T20:00:22  PID[4200] Information 3/22/2016 8:00:22 PM: a82f21d9-bbb8-4520-9185-13108f227816 - AcquireTokenHandlerBase: === Token Acquisition finished successfully. An access token was retuned:
	Access Token Hash: 6nFeNYy2D6LmMACzct9OtuulmtDRU0PgBbtS1dyVsmU=
	Refresh Token Hash: [No Refresh Token]
	Expiration Time: 3/22/2016 8:58:03 PM +00:00
	User Hash: null
	
2016-03-22T20:00:22  PID[4200] Information Loading Signer from D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\Signer
2016-03-22T20:00:23  PID[4200] Information 
Getting AcmeServerDirectory
2016-03-22T20:00:23  PID[4200] Information Loading Registration from D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\Registration
2016-03-22T20:00:23  PID[4200] Information Authorizing Identifier letsencrypt2.sjkp.dk Using Challenge Type http-01
2016-03-22T20:00:24  PID[4200] Information Writing challenge answer to D:\home\site\wwwroot\.well-known/acme-challenge/hoVlz1YfWSKnjGEatsG4wNSFDupbS_UmC_CN-rkgVVE
2016-03-22T20:00:24  PID[4200] Information Answer should now be browsable at http://letsencrypt2.sjkp.dk/.well-known/acme-challenge/hoVlz1YfWSKnjGEatsG4wNSFDupbS_UmC_CN-rkgVVE
2016-03-22T20:00:24  PID[4200] Information Submitting answer
2016-03-22T20:00:25  PID[4200] Information Refreshing authorization attempt1
2016-03-22T20:00:35  PID[4200] Information Auth Result valid
2016-03-22T20:00:35  PID[4200] Information Deleting answer
2016-03-22T20:00:35  PID[4200] Information Authorizing Identifier letsencrypt.sjkp.dk Using Challenge Type http-01
2016-03-22T20:00:36  PID[4200] Information Writing challenge answer to D:\home\site\wwwroot\.well-known/acme-challenge/sWOJsD5gu1j9l3Alfr0bYcv2JH4ueCYRvPsKzTqSw44
2016-03-22T20:00:36  PID[4200] Information Answer should now be browsable at http://letsencrypt.sjkp.dk/.well-known/acme-challenge/sWOJsD5gu1j9l3Alfr0bYcv2JH4ueCYRvPsKzTqSw44
2016-03-22T20:00:36  PID[4200] Information Submitting answer
2016-03-22T20:00:37  PID[4200] Information Refreshing authorization attempt1
2016-03-22T20:00:47  PID[4200] Information Auth Result valid
2016-03-22T20:00:47  PID[4200] Information Deleting answer
2016-03-22T20:00:47  PID[4200] Information RSAKeyBits: 2048
2016-03-22T20:00:48  PID[4200] Information Requesting Certificate
2016-03-22T20:00:49  PID[4200] Information certRequ ACMESharp.CertificateRequest
2016-03-22T20:00:49  PID[4200] Information Request Status: Created
2016-03-22T20:00:49  PID[4200] Information Saving Certificate to D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\letsencrypt2.sjkp.dk-crt.der
2016-03-22T20:00:49  PID[4200] Information Saving Issuer Certificate to D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\ca-009CF1912EA8D50908-crt.pem
2016-03-22T20:00:49  PID[4200] Information Saving Certificate to D:\home\siteextensions\letsencrypt\config\httpsacme-staging.api.letsencrypt.org\letsencrypt2.sjkp.dk-all.pfx
2016-03-22T20:00:59 sandboxproc.exe C:\DWASFiles\Sites\#1webAppcfmv5fy7lcq7o\Temp\applicationhost.config
2016-03-22T20:00:59 env XPROC_TYPENAME=Microsoft.Web.Hosting.Transformers.ApplicationHost.SiteExtensionHelper, Microsoft.Web.Hosting, Version=7.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
2016-03-22T20:00:59 env XPROC_METHODNAME=Transform
2016-03-22T20:00:59 sandboxproc.exe C:\DWASFiles\Sites\webAppcfmv5fy7lcq7o\Temp\applicationhost.config
2016-03-22T20:00:59 env XPROC_TYPENAME=Microsoft.Web.Hosting.Transformers.ApplicationHost.SiteExtensionHelper, Microsoft.Web.Hosting, Version=7.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
2016-03-22T20:00:59 Start 'letsencrypt' site extension transform
2016-03-22T20:00:59 :(6,10), No element in the source document matches '/configuration/system.applicationHost/sites/site[@name='~1webAppcfmv5fy7lcq7o']/application[@path='/letsencrypt']'
2016-03-22T20:00:59 env XPROC_METHODNAME=Transform
2016-03-22T20:00:59 Start 'letsencrypt' site extension transform
2016-03-22T20:01:00 :(6,10), No element in the source document matches '/configuration/system.applicationHost/sites/site[@name='~1webAppcfmv5fy7lcq7o']/application[@path='/letsencrypt']'
2016-03-22T20:01:00 Not executing Remove (transform line 6, 68)
2016-03-22T20:00:59 Not executing Remove (transform line 6, 68)
2016-03-22T20:00:59 StartSection Executing Insert (transform line 7, 64)
2016-03-22T20:01:00 on /configuration/system.applicationHost/sites/site[@name='~1webAppcfmv5fy7lcq7o']/application
2016-03-22T20:01:00 Applying to 'site' element (no source line info)
2016-03-22T20:01:00 Inserted 'application' element
2016-03-22T20:01:00 EndSection Done executing Insert
2016-03-22T20:01:00 Successful 'D:\home\SiteExtensions\letsencrypt\applicationHost.xdt' site extension transform
2016-03-22T20:01:00 StartSection Executing Insert (transform line 7, 64)
2016-03-22T20:01:00 on /configuration/system.applicationHost/sites/site[@name='~1webAppcfmv5fy7lcq7o']/application
2016-03-22T20:01:00 Applying to 'site' element (no source line info)
2016-03-22T20:01:00 Inserted 'application' element
2016-03-22T20:01:00 EndSection Done executing Insert
2016-03-22T20:01:00 Successful 'D:\home\SiteExtensions\letsencrypt\applicationHost.xdt' site extension transform
2016-03-22T20:01:00 sandboxproc.exe complete successfully. Ellapsed = 989.00 ms
2016-03-22T20:01:00 sandboxproc.exe complete successfully. Ellapsed = 1065.00 ms
2016-03-22T20:01:01  PID[4200] Warning     unable to parse WEBSITE_OWNER_NAME ''
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - AcquireTokenHandlerBase: === Token Acquisition started:
	Authority: https://login.windows.net/delegate.onmicrosoft.com/
	Resource: https://management.core.windows.net/
	ClientId: ce88fa0e-9f6a-4bde-afb3-796af31c430f
	CacheType: Microsoft.IdentityModel.Clients.ActiveDirectory.TokenCache (1 items)
	Authentication Target: Client
	
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - TokenCache: Looking up cache for a token...
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - TokenCache: An item matching the requested resource was found in the cache
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - TokenCache: 57.022747165 minutes left until token in cache expires
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - TokenCache: A matching item (access token or refresh token or both) was found in the cache
2016-03-22T20:01:01  PID[4200] Information 3/22/2016 8:01:01 PM: 0c91d11e-8382-4c4f-a555-d4bd318bd7de - AcquireTokenHandlerBase: === Token Acquisition finished successfully. An access token was retuned:
	Access Token Hash: 6nFeNYy2D6LmMACzct9OtuulmtDRU0PgBbtS1dyVsmU=
	Refresh Token Hash: [No Refresh Token]
	Expiration Time: 3/22/2016 8:58:03 PM +00:00
	User Hash: null
Clone this wiki locally