Dotnet: .NET 4.7.2 (and Windows 10 1803) upgrade - SqlClient timeout exception

[divega]

_From @rossmhk on May 15, 2018 8:29_

After upgrading to .NET 4.7.2, a number of Entity Framework queries are now failing against Azure SQL DB. This is confirmed to be not happening on .NET 4.7.1.

System.Data.SqlClient.SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception: The wait operation timed out
   --- End of inner exception stack trace ---
   at System.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__180_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.<ExecuteStoreCommandsAsync>d__c.MoveNext()
   --- End of inner exception stack trace ---
   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.<ExecuteStoreCommandsAsync>d__c.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Data.Entity.Core.Objects.Internal.ObjectQueryExecutionPlan.<ExecuteAsync>d__0`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---

Steps to reproduce

Seems to be a pattern where there a 3 of more tables involved and the EF LINQ expression has an Include statement. For example, one of the simpler examples:

string username = "john";
var user = _context.Users.Include("User_UserRoles.UserRole").Where(u => u.UserName == username).FirstOrDefault();

Further technical details

Operating system: Windows 10 1803 / .NET 4.7.2
IDE: Visual Studio 2017 15.7 / 15.8.0 (Preview 1.1)

_Copied from original issue: aspnet/EntityFramework6#538_

[divega]

_From @ajcvickers on May 15, 2018 19:36_

/cc @divega

[divega]

@rossmhk Thanks a lot of reporting this. I am going to be moving this issue to a different repository, where issues for SqlClient on .NET Framework are tracked.

Once there, it would be great if you could provide a repro project for the SqlClient team to investigate.

[geleems]

@rossmhk
Can you provide sample project that we can run quickly?

[geleems]

Here is a code that I wrote for repro. And I do not see any error.

• OS: Windows 10 v1709 (OSBuild 16299.431)
• Target Framework: .NET Framework 4.7.2
• Targeting DB: localDb

using System;
using System.Collections.Generic;
using System.Data.Entity;
using System.Linq;
using System.Threading.Tasks;

namespace EFRepro
{
    public class Student
    {
        public int StudentID { get; set; }
        public string StudentName { get; set; }
        public decimal Height { get; set; }
        public float Weight { get; set; }
        public Grade Grade { get; set; }
        public Major Major { get; set; }
    }

    public class Grade
    {
        public int GradeId { get; set; }
        public string GradeName { get; set; }
        public string Section { get; set; }
        public ICollection<Student> Students { get; set; }
    }

    public class Major
    {
        public int MajorId { get; set; }
        public string MajorName { get; set; }
        public ICollection<Student> Students { get; set; }
    }

    public class SchoolContext : DbContext
    {
        public SchoolContext() : base() { }
        public DbSet<Student> Students { get; set; }
        public DbSet<Grade> Grades { get; set; }
        public DbSet<Major> Majors { get; set; }
    }

    class Program
    {
        private static void SetupEnv()
        {
            using (SchoolContext context = new SchoolContext())
            {
                Major major_math = new Major() { MajorName = "Math", };
                context.Majors.Add(major_math);
                Major major_earthScience = new Major() { MajorName = "EarthScience", };
                context.Majors.Add(major_earthScience);

                Grade grade1a01 = new Grade() { GradeName = "Grade1", Section = "A01" };
                context.Grades.Add(grade1a01);
                Grade grade1a02 = new Grade() { GradeName = "Grade1", Section = "A02" };
                context.Grades.Add(grade1a02);
                Grade grade2a01 = new Grade() { GradeName = "Grade2", Section = "A01" };
                context.Grades.Add(grade2a01);
                Grade grade2a02 = new Grade() { GradeName = "Grade2", Section = "A02" };
                context.Grades.Add(grade2a02);

                Major[] majors = new Major[] { major_math, major_earthScience };
                Grade[] grades = new Grade[] { grade1a01, grade1a02, grade2a01, grade2a02 };
                string[] names = new string[]
                {
                    "Oliver", "Jake", "Noah", "James",
                    "Jack", "Connor", "Liam", "John",
                    "Harry", "Callum", "Mason", "Robert",
                    "Jacob", "Jacob", "Jacob", "Michael",
                    "Charlie", "Kyle", "William",
                    "Thomas", "Joe", "Ethan", "David",
                    "George", "Reece", "Michael", "Richard",
                    "Oscar", "Rhys", "Alexander", "Joseph",
                    "James", "Charles", "Damian", "Daniel",
                };

                Random random = new Random();
                for (int i = 0; i < 10; ++i)
                {
                    Student student = new Student()
                    {
                        StudentName = names[random.Next(0, names.Length)],
                        Weight = (float)random.Next(100, 150),
                        Height = random.Next(150, 200),
                        Major = majors[random.Next(0, majors.Length)],
                        Grade = grades[random.Next(0, grades.Length)],
                    };
                    context.Students.Add(student);
                }

                context.SaveChanges();
            }
        }

        private static void Run()
        {
            using (SchoolContext context = new SchoolContext())
            {
                Student s = context.Students.Include(a => a.Major).Include(a => a.Grade)
                    .Where(u => u.Major.MajorName == "Math")
                    .Where(u => u.Grade.Section == "A02").FirstOrDefault();
                Console.WriteLine(s.StudentName);
                Console.WriteLine(s.Major.MajorName);
                Console.WriteLine(s.Grade.GradeName);
                Console.WriteLine(s.Grade.Section);
            }
        }

        private static async void RunAsync()
        {
            using (SchoolContext context = new SchoolContext())
            {
                Task<Student> t = context.Students.Include(a => a.Major).Include(a => a.Grade)
                    .Where(u => u.Major.MajorName == "EarthScience")
                    .Where(u => u.Grade.Section == "A01").FirstOrDefaultAsync();
                Student s = await t;
                Console.WriteLine(s.StudentName);
                Console.WriteLine(s.Major.MajorName);
                Console.WriteLine(s.Grade.GradeName);
                Console.WriteLine(s.Grade.Section);
            }
        }

        public static void Main(string[] args)
        {
            SetupEnv();
            Run();
            RunAsync();
            Console.ReadLine();
        }
    }
}

@rossmhk
Do you still get the error?

[geleems]

@rossmhk
My code creates entity tables in localDb by default.
Do you use specific SQL Server with your code, or just use localDb?
Is your db environment Azure?

[rossmhk]

@geleems Thanks for the help. It's happening against Azure SQL Database. Let me see if I can reproduce over weekend with localDb, and running your sample (or variations) against Azure SQL Db.

[dsikic]

This happens only on AzureSQL environments.

From my testing even SQL Management Studio is affected, as it cannot expand the Tables list within the navigation menu. It can query SCHEMA_INFORMATION.Tables and it can expand Views, but not tables. Just see if you're able to do that with a 17.x version of SSMS.

You'll see that local databases work fine, but any Azure db fails.

[geleems]

@rossmhk @dsikic @divega
Thank for the information.
I could confirm the SqlTimeOut occured when using 4.7.2 and targeting Azure DB.
No issue happened with the same code when using 4.7.1 with Azure DB.
Interesting thing is that it works with no error when using 4.7.2 with SQL Server or localDb.
This makes me to think that this error might be caused due to encryption (security) feature changed in 4.7.2 for Azure.

[dsikic]

@geleems How long do you expect a fix to take? I have users who will be completely locked out of my CRM software as soon as Windows Update installs 4.7.2, or the Windows 10 April Update. I'm getting a little nervous about this. If it will take a while, I may have to release a build which targets 4.5 or something like that, assuming that will work. But, I'd rather not because there would be some features lost. Thanks!

[geleems]

@dsikic The security team is working on this urgently with top priority, and targeting ETA is tomorrow Sunday (5/20) for hotfix worldwide. I will keep you updated as frequently as possible on this thread.

[dsikic]

@geleems Thank you!!

[dsikic]

Hi @geleems ,

I hate to bother you on a holiday. Is this the right place to keep an eye out for this hot fix? https://support.microsoft.com/en-ca/help/4099479

I'm worried that some of my clients' machines may have spent this long weekend upgrading themselves to 1803, in which case tomorrow will be a very eventful day!

[geleems]

@dsikic The link does not seems to be a right one for the hotfix. The hotfix is for Azure DB Server side, not client side.
It seems the hotfix was already deployed yesterday (5/20), and I could confirm the repro code worked without any error on 4.7.2 with Azure.
Can you please test it on your side, and let me know how it goes?

[geleems]

@dsikic @rossmhk
Rolling out the hotfix is still in progress in some places (especially southcentralus). Security team reported that the fix is about 60% rolled out currently. So you might still be experiencing the issue depending on your Azure server area, but it will be resolved eventually in a day or so. Which server location is your Azure on?

[rossmhk]

@geleems Thanks for the updates and the fast resolution. I can confirm that the fix has resolved the issue.

[geleems]

@rossmhk Thanks for your update!
@dsikic Have you got a chance to test in your side?

[dsikic]

I’m not near a computer right now but it wasn’t available on my machine as of 4:00pm EST. I’ll know in a few hours, and post back.

[geleems]

@dsikic ok, thanks. It will be great if you can tell me your Azure server location, and I can check with security team how the hotfix goes in the specific area.

[dsikic]

Canada Central, I believe. Toronto area and mirrored to Montreal.

[dsikic]

Nothing yet. Not sure if it's a Windows Hotfix or Azure Hotfix. But windows is up to date, and Azure SQL still cannot expand tables via SSMS 17.7.

[geleems]

@dsikic The fix was already rolled out for Canada Central completely, and I confirmed the SqlClient Timeout issue is no longer occurred on Azure in Canada Central area. My SSMS 17.7 was able to access Azure DB in Canada Central with expanding and navigating tables/views functionalities all working.
Can you check your Azure firewall ipaddress list to see your SqlClient IP is added correctly?

[dsikic]

It doesn't work. Are you using **.database.secure.windows.net ? I can expand Views node fine, so it's not a firewall issue.

[dsikic]

I sent you an email.

[geleems]

@divega I was communicating with @dsikic, and the issue was resolved. You can close this.