microsoft / PowerPlatform-DataverseServiceClient

Code Replica for Microsoft.PowerPlatform.Dataverse.Client and supporting nuget packages.
MIT License
285 stars 52 forks source link

Unable to cast object of type 'generatedProxy_2' #48

Closed smfpride closed 4 years ago

smfpride commented 4 years ago

I'm getting an odd error occasionally that just started happening in the last couple of weeks. I'm using version 0.2.16-Alpha in an Azure Function (v3.0.9 SDK, runtime version 3.0.14287.0). I have a watchDirectory (Azure Function host.json setting) set, and have a function that updates a file in that directory to restart the Azure Function, the restart works, but after the Azure Function finishes restarting I receive the follow errors whenever attempting to connect to my CDS environment:

"InnerException": { "ClassName": "System.InvalidCastException", "Message": "Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.Xrm.Sdk.IOrganizationService'.", "Data": null, "InnerException": null, "HelpURL": null, "StackTraceString": " at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.InitCdsService()", "RemoteStackTraceString": null, "RemoteStackIndex": 0, "ExceptionMethod": null, "HResult": -2147467262, "Source": "System.Reflection.DispatchProxy", "WatsonBuckets": null },

"StackTraceString": " at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)\r\n at System.Threading.Tasks.Task1.GetResultCore(Boolean waitCompletionNotification)\r\n at System.Threading.Tasks.Task1.get_Result()\r\n at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.GetCachedCDSService(CdsConnectionService& ConnectionObject)\r\n at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.IntilizeService(CdsConnectionService& ConnectionObject)\r\n at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.CreateCdsServiceConnection(Object externalOrgServiceProxy, AuthenticationType requestedAuthType, String hostName, String port, String orgName, NetworkCredential credential, String userId, SecureString password, String domain, String Geo, String claimsHomeRealm, Boolean useSsl, Boolean useUniqueInstance, OrganizationDetail orgDetail, UserIdentifier user, String clientId, Uri redirectUri, PromptBehavior promptBehavior, String tokenCachePath, OrganizationWebProxyClient externalOrgWebProxyClient, String certificateThumbPrint, StoreName certificateStoreName, X509Certificate2 certificate, Uri instanceUrl, Boolean isCloned, Boolean useDefaultCreds)", "RemoteStackTraceString": null, "RemoteStackIndex": 0, "ExceptionMethod": null, "HResult": -2146233088, "Source": "System.Private.CoreLib",

"StackTraceString": " at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.CreateCdsServiceConnection(Object externalOrgServiceProxy, AuthenticationType requestedAuthType, String hostName, String port, String orgName, NetworkCredential credential, String userId, SecureString password, String domain, String Geo, String claimsHomeRealm, Boolean useSsl, Boolean useUniqueInstance, OrganizationDetail orgDetail, UserIdentifier user, String clientId, Uri redirectUri, PromptBehavior promptBehavior, String tokenCachePath, OrganizationWebProxyClient externalOrgWebProxyClient, String certificateThumbPrint, StoreName certificateStoreName, X509Certificate2 certificate, Uri instanceUrl, Boolean isCloned, Boolean useDefaultCreds)\r\n at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.ConnectToCdsService(String cdsConnectionString)\r\n at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient..ctor(String cdsConnectionString)\r\n at ....", "RemoteStackTraceString": null, "RemoteStackIndex": 0, "ExceptionMethod": null, "HResult": -2146233088, "Source": "Microsoft.PowerPlatform.Cds.Client",

If I stop the Azure Function, wait a few moments, start the Azure Function, the connection works fine.

Any thoughts on this? Another thing to note is that no code changes have occurred with these Azure Functions in about a month (prior to about 2 weeks ago, they were working wonderfully).

EDITED: Updated to latest versions.

MattB-msft commented 4 years ago

That's being triggered by the cache behavior, where its trying to pull the copy of the connection it cached in local memory to support folk's who try to rapid fire create connections to the same instance.

This is the second issue reported in this area... I am going to add in a speculative change here to see if we can get this locked down.

smfpride commented 4 years ago

Thanks for the quick reply, is there anything I set on the constructor, app settings, or elsewhere to prevent the caching in the interim (I can at least test the performance to see if there is a noticeable difference)?

MattB-msft commented 4 years ago

Set RequireNewInstance to true in the constructor. that will cause it to skip this logic.

smfpride commented 4 years ago

I set that, however the issue is still occurring. My connection string: "AuthType=ClientSecret;url={0};ClientId={1};ClientSecret={2};SkipDiscovery=true;RequireNewInstance=true;"

I added a line to check the Memory cache where the CDS Connections are being cached (System.Runtime.Caching.MemoryCache.Default) and make sure it was being reset when the function was restarting. The Memory cache is completely empty, but I'm still getting the exception.

I turned on App Insights and it looks like i'm getting a 401 from the WCF Org Service (I thought I would be connecting to the WebAPI using this SDK)

smfpride commented 4 years ago

Updated to the latest version, .0.2.17-Alpha, and still having the issue.

MattB-msft commented 4 years ago

The 401 is expected when connecting initially as that is part of the challenge response system for determine correct connection info. This client uses both webAPI and orgAPI depending on what its doing.

Are you running in Linux Functions host? or windows?

smfpride commented 4 years ago

Windows

MattB-msft commented 4 years ago

Going to give a few things to add here.. . Please add a class like this:

--> CdsTraceLogWriter.cs using System; using System.Diagnostics; using Microsoft.Extensions.Logging; namespace cds.FunctionExamples { // Log writter for working with Azure Functions for the Xrm.Tooling.Connector public class CdsTraceLogEventSink : TraceListener { public bool WriteToWindow = false; public ILogger log;

    public CdsTraceLogEventSink(string name , ILogger logger) : base(name)
    {
        log = logger; 
    }

    public override void Write(string message)
    {
    }

    public override void WriteLine(string message)
    {
        if ( log != null)
        {
            log.LogInformation($"FROMTRACE: {message}");
        }
    }
}

}

and then before you create the connection,, add the following:

// Set up trace provider. Microsoft.PowerPlatform.Cds.Client.TraceControlSettings.TraceLevel = SourceLevels.Verbose; Microsoft.PowerPlatform.Cds.Client.TraceControlSettings.AddTraceListener(new CdsTraceLogEventSink("Microsoft.Powerplatform.Cds.Client.CdsServiceClient", log));

and in a finally for your function add // Clean up listener. Microsoft.PowerPlatform.Cds.Client.TraceControlSettings.CloseListeners();

That will cause the system to capture detailed tracing from inside the CdsClient and emit it to your log. can you capture that and post that log here? everything from CDS should be prefixed with FROMTRACE:

smfpride commented 4 years ago

Here you are (I sanitized identifying information with <> tags):

2020-08-26T21:53:10Z   [Information]   Executing '<CDSAzureFunctionName>' (Reason='This function was programmatically called via the host APIs.', Id=520553c8-b6c9-4257-9dd3-1d2fb7d1c59e)
2020-08-26T21:53:10Z   [Information]   C# HTTP trigger function processed a request.
2020-08-26T21:53:11Z   [Information]   FROMTRACE: Initialize CDS connection Started - AuthType: ClientSecret
2020-08-26T21:53:11Z   [Information]   FROMTRACE: Direct Login Process Started
2020-08-26T21:53:11Z   [Information]   FROMTRACE: Attempting to Connect to Uri https://<orgurl>.crm.dynamics.com/XRMServices/2011/Organization.svc
2020-08-26T21:53:11Z   [Information]   FROMTRACE: BuildOrgConnectUri CoreClass ()
2020-08-26T21:53:11Z   [Information]   FROMTRACE: DiscoveryServer indicated organization service location = https://<orgurl>.crm.dynamics.com/XRMServices/2011/Organization.svc
2020-08-26T21:53:11Z   [Information]   FROMTRACE: BuildOrgConnectUri CoreClass ()
2020-08-26T21:53:11Z   [Information]   FROMTRACE: Organization Service URI is = https://<orgurl>.crm.dynamics.com/XRMServices/2011/Organization.svc
2020-08-26T21:53:11Z   [Information]   FROMTRACE: ConnectAndInitCdsOrgService - Initializing Organization Service Object
2020-08-26T21:53:11Z   [Information]   FROMTRACE: ConnectAndInitCdsOrgService - Requesting connection to Organization with CDS Version: No organization data available
2020-08-26T21:53:11Z   [Information]   FROMTRACE: GetAuthorityFromTargetService - ADAL Version : 5.2.0.0
2020-08-26T21:53:11Z   [Information]   FROMTRACE: AuthenticateService - found authority with name https://login.microsoftonline.com/8726277b-9b4e-4709-ae9a-a232124ad416/
2020-08-26T21:53:11Z   [Information]   FROMTRACE: AuthenticateService - found resource with name https://<orgurl>.crm.dynamics.com/
2020-08-26T21:53:11Z   [Information]   FROMTRACE: ObtainAccessToken - Client Secret
2020-08-26T21:53:12Z   [Information]   FROMTRACE: Added WebClient Header Hooks to the Request object.
2020-08-26T21:53:12Z   [Information]   FROMTRACE: Unable to connect to CDS: Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.Xrm.Sdk.IOrganizationService'.
Source  : System.Reflection.DispatchProxy
Method  : Create
Date    : 8/26/2020
Time    : 9:53:11 PM
Error   : Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.Xrm.Sdk.IOrganizationService'.
Stack Trace : at System.Reflection.DispatchProxy.Create[T,TProxy]()
   at System.ServiceModel.Channels.ServiceChannelProxy.CreateProxy[TChannel](MessageDirection direction, ServiceChannel serviceChannel)
   at System.ServiceModel.Channels.ServiceChannelFactory.CreateProxy[TChannel](MessageDirection direction, ServiceChannel serviceChannel)
   at System.ServiceModel.Channels.ServiceChannelFactory.CreateChannel[TChannel](EndpointAddress address, Uri via)
   at System.ServiceModel.ChannelFactory`1.CreateChannel(EndpointAddress address, Uri via)
   at System.ServiceModel.ClientBase`1.get_Channel()
   at System.ServiceModel.ClientBase`1.get_InnerChannel()
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.ConnectAndInitCdsOrgService(OrganizationDetail orgdata, Boolean IsOnPrem, Uri homeRealmUri)
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.DoDirectLogin()
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.InitCdsService()
======================================================================================================================
2020-08-26T21:53:12Z   [Error]   Microsoft.PowerPlatform.Cds.Client.Utils.CdsClientConnectionException: Failed to connect to Common Data Service
 ---> System.AggregateException: One or more errors occurred. (Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.Xrm.Sdk.IOrganizationService'.)
 ---> System.InvalidCastException: Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.Xrm.Sdk.IOrganizationService'.
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.InitCdsService()
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at System.Threading.Tasks.Task`1.get_Result()
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.GetCachedCDSService(CdsConnectionService& ConnectionObject)
   at Microsoft.PowerPlatform.Cds.Client.CdsConnectionService.IntilizeService(CdsConnectionService& ConnectionObject)
   at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.CreateCdsServiceConnection(Object externalOrgServiceProxy, AuthenticationType requestedAuthType, String hostName, String port, String orgName, NetworkCredential credential, String userId, SecureString password, String domain, String Geo, String claimsHomeRealm, Boolean useSsl, Boolean useUniqueInstance, OrganizationDetail orgDetail, UserIdentifier user, String clientId, Uri redirectUri, PromptBehavior promptBehavior, String tokenCachePath, OrganizationWebProxyClient externalOrgWebProxyClient, String certificateThumbPrint, StoreName certificateStoreName, X509Certificate2 certificate, Uri instanceUrl, Boolean isCloned, Boolean useDefaultCreds)
   --- End of inner exception stack trace ---
   at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.CreateCdsServiceConnection(Object externalOrgServiceProxy, AuthenticationType requestedAuthType, String hostName, String port, String orgName, NetworkCredential credential, String userId, SecureString password, String domain, String Geo, String claimsHomeRealm, Boolean useSsl, Boolean useUniqueInstance, OrganizationDetail orgDetail, UserIdentifier user, String clientId, Uri redirectUri, PromptBehavior promptBehavior, String tokenCachePath, OrganizationWebProxyClient externalOrgWebProxyClient, String certificateThumbPrint, StoreName certificateStoreName, X509Certificate2 certificate, Uri instanceUrl, Boolean isCloned, Boolean useDefaultCreds)
   at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient.ConnectToCdsService(String cdsConnectionString)
   at Microsoft.PowerPlatform.Cds.Client.CdsServiceClient..ctor(String cdsConnectionString)
   at ....<My code>
2020-08-26T21:53:12Z   [Information]   Executed '<CDSAzureFunctionName>' (Succeeded, Id=520553c8-b6c9-4257-9dd3-1d2fb7d1c59e, Duration=2018ms)

Thanks for all the help @MattB-msft

MattB-msft commented 4 years ago

Ok that helps... thanks ! Looking into this now...

MattB-msft commented 4 years ago

can you tell us what .netcore version your targeting with your project?

smfpride commented 4 years ago

.NET Core 3.1

MattB-msft commented 4 years ago

@smfpride Can you reach out to me at mbarbour @ microsoft.com to discuss this? we are not able to reproduce this and would like to see if we an have a look at your function code and setup.

thanks

smfpride commented 4 years ago

@MattB-msft traced it back to an issue with an Azure Function watchDirectories setting in the host.json. To quote him on the intended use of watchDirectories, and why they are the issue:

Apparently this is intended to support updating Assemblies on the fly and forcing a reload which is causing the locally loaded types to be reset. Thus it cant find types because the assemblies it needs to do the type mapping have been forced unloaded.

I resolved this by changing the file type that was was modifying to .dll which forces the host to shutdown (which was the intended behavior for my code). The next request starts the host back up and all is fine.

Thanks for all the help @MattB-msft !

Guilhermeslucas commented 4 years ago

@MattB-msft Thanks for all the context, helps a lot! Question: When you say:

and in a finally for your function add // Clean up listener. Microsoft.PowerPlatform.Cds.Client.TraceControlSettings.CloseListeners();

I didn't undertood where it should be placed? Constructor maybe? Run method? Thanks a lot!

MoranShusheng commented 2 years ago

Based on the code block you mentioned above that the system captures detailed traces from within CdsClient and sends it to your logs, we are getting static ServiceClient in the code, then we should put the code block that collects logs where appropriate Location? Here is our example:

` public static class NoTargetedIncentiveForImei { private static string dataverseConStr = Environment.GetEnvironmentVariable("DataverseConnection"); private static ServiceClient serviceClient = new ServiceClient(dataverseConStr);

    [FunctionName("NoTargetedIncentiveForImei")]
    public static async Task Run([ServiceBusTrigger("%NoTargetQueueName%", Connection = "ServiceBusConnection", IsSessionsEnabled = true)] 
        Message message, ILogger log)
    {
        log.LogInformation("Message is {0}", JsonConvert.SerializeObject(message));
        if (serviceClient.IsReady)
            serviceClient.EnableAffinityCookie = false;
        else
        {
            serviceClient = new ServiceClient(dataverseConStr) ?? throw new ArgumentNullException(nameof(dataverseConStr));
        }
    }

}`