Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Login Failed for user during Migrate() on Azure. Error number: 18456 #15644

Closed
programista25 opened this issue May 7, 2019 · 9 comments · Fixed by #25832
Closed

Login Failed for user during Migrate() on Azure. Error number: 18456 #15644

programista25 opened this issue May 7, 2019 · 9 comments · Fixed by #25832
Labels
area-sqlserver closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported punted-for-3.0 type-bug
Milestone

Comments

@programista25
Copy link

Cannot perform migration on Azure SQL Database using EF Core randomly due to following exception:

**Exception message**: System.Data.SqlClient.SqlException (0x80131904): Login failed for user 'admin'.
**Error Number**: 18456
**State**: 1
**Class**: 14
**Stack trace**: at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, Boolean applyTransientFaultHandling, String accessToken)
2019-05-07T09:18:18.1797251Z    at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1797779Z    at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1798222Z    at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
2019-05-07T09:18:18.1798546Z    at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
2019-05-07T09:18:18.1799015Z    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
2019-05-07T09:18:18.1799424Z    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
2019-05-07T09:18:18.1799897Z    at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
2019-05-07T09:18:18.1800863Z    at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1802601Z    at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
2019-05-07T09:18:18.1802906Z    at System.Data.SqlClient.SqlConnection.Open()
2019-05-07T09:18:18.1803225Z    at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenDbConnection(Boolean errorsExpected)
2019-05-07T09:18:18.1803519Z    at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.Open(Boolean errorsExpected)
2019-05-07T09:18:18.1803814Z    at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerDatabaseCreator.<>c__DisplayClass18_0.<Exists>b__0(DateTime giveUp)
2019-05-07T09:18:18.1804141Z    at Microsoft.EntityFrameworkCore.ExecutionStrategyExtensions.<>c__DisplayClass12_0`2.<Execute>b__0(DbContext c, TState s)
2019-05-07T09:18:18.1804455Z    at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.ExecuteImplementation[TState,TResult](Func`3 operation, Func`3 verifySucceeded, TState state)
2019-05-07T09:18:18.1804761Z    at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
2019-05-07T09:18:18.1805084Z    at Microsoft.EntityFrameworkCore.ExecutionStrategyExtensions.Execute[TState,TResult](IExecutionStrategy strategy, Func`2 operation, Func`2 verifySucceeded, TState state)
2019-05-07T09:18:18.1805378Z    at Microsoft.EntityFrameworkCore.Migrations.HistoryRepository.Exists()
2019-05-07T09:18:18.1805690Z    at Microsoft.EntityFrameworkCore.Migrations.Internal.Migrator.Migrate(String targetMigration)
2019-05-07T09:18:18.1805993Z    at Apport.Application.Migrator.Program.MigrateDatabase[TDbContext](IServiceProvider serviceProvider)

Steps to reproduce

I performed following code against Azure SQL database:

var migrator = dbContext.GetService<IMigrator>();
migrator.Migrate();

This code also causes an exception:

dbContext.Database.Migrate();

Further technical details

EF Core version: 2.2.2
Database Provider: Microsoft.EntityFrameworkCore.SqlServer
Operating system: Windows 10
IDE: Visual Studio 2017 15.4

My investigations

In file SqlServerDatabaseCreator following method does not contains error number 18456:

// Login failed is thrown when database does not exist (See Issue #776)
// Unable to attach database file is thrown when file does not exist (See Issue #2810)
// Unable to open the physical file is thrown when file does not exist (See Issue #2810)
private static bool IsDoesNotExist(SqlException exception) =>
    exception.Number == 4060 || exception.Number == 1832 || exception.Number == 5120;

As well as in this method:

private bool RetryOnExistsFailure(SqlException exception)
{           
      if (exception.Number == 233
           || exception.Number == -2
           || exception.Number == 4060
           || exception.Number == 1832
           || exception.Number == 5120)
       {
           ClearPool();
           return true;
       }

       return false;
}

But it can be some wrong error number returned from Azure

@ErikEJ
Copy link
Contributor

ErikEJ commented May 7, 2019

@programista25
Copy link
Author

programista25 commented May 7, 2019

Credentials are ok - I'm sure of it. The problem is that bug occurs randomly. I can connect to master db using same connection string. Notice, that I'm using Azure SQL Server. If the credentials will be invalid, State in the exception will has number higher than 1.

@ajcvickers
Copy link
Contributor

@programista25 This looks like an issue with the underlying SqlClient ADO.NET provider, since that is the component that is connecting to the database. I'll move it to the corefx repo unless there is any reason to think this is EF-specific.

@programista25
Copy link
Author

I did a little bit more investigation using this class: EFCore.Relational/Migrations/Internal/Migrator.cs.

I've added CustomMigrate method which is refactored from the original one:

public virtual void Migrate(string targetMigration = null)
{
    _logger.MigrateUsingConnection(this, _connection);

    if (!_historyRepository.Exists())
    {
         if (!_databaseCreator.Exists())
         {
             _databaseCreator.Create();
         }

         var command = _rawSqlCommandBuilder.Build(_historyRepository.GetCreateScript());
         command.ExecuteNonQuery(_connection);
    }

    var commandLists = GetMigrationCommandLists(_historyRepository.GetAppliedMigrations(), targetMigration);
    foreach (var commandList in commandLists)
    {
         _migrationCommandExecutor.ExecuteNonQuery(commandList(), _connection);
    }
}

I think, that _databaseCreator.Exists() method is doing the check in wrong way. Shouldn't it use connection to master db and check whether db exists and if not create it with this SQL?:

IF NOT EXISTS (SELECT * FROM sys.databases WHERE name = 'database')
BEGIN
    CREATE DATABASE database
END"

I've refactored it and my CustomMigrate method looks like following:

public virtual void CustomMigrate(DbContext masterDbContext, ConnectionConfiguration connection)
{
	//connection param contains connection string to db which we want to migrate
    var database = connection.InitialCatalog;

    var createSql = $@"IF NOT EXISTS (SELECT * FROM sys.databases WHERE name = '{database}')
                     BEGIN
                        CREATE DATABASE {database}
                     END";
    masterDbContext.Database.ExecuteSqlCommand(new RawSqlString(createSql));
	//Everything above is working fine

    //Problem starts below, in PerformCommand method, in connection.Open()
    PerformCommand(_historyRepository.GetCreateIfNotExistsScript(), connection.ConnectionString);

    var commandLists = GetMigrationCommandLists(_historyRepository.GetAppliedMigrations(), null);

    foreach (var commandList in commandLists)
    {
        var commands = commandList();

        foreach (var command in commands)
        {
            Console.WriteLine($"Migration SQL: {command.CommandText.Substring(0, command.CommandText.Length <= 100 ? command.CommandText.Length : 100)}");
            PerformCommand(command.CommandText, connection.ConnectionString);
        }
    }
}

public void PerformCommand(string sql, string connectionString)
{
	using (var connection = new SqlConnection(connectionString))
	{
		connection.Open(); 
		//Above call fails randomly right after db on azure is created. SqlException Login failed for user 'admin', number 18456
		//If it not fails after CREATE DATABASE, everything works fine.
		
		var command = new SqlCommand(sql, connection)
		command.ExecuteNonQuery();
		connection.Close();
	}
}                

After Azure database is created using CREATE DATABASE, connection.Open() fails from time to time. I suppose, that there is needed a time gap after everything is done on Azure site (I don't know, meybe some configuration is performing in the background). If I add Thread.Sleep(2 * 60 * 1000) right after masterDbContext.Database.ExecuteSqlCommand(new RawSqlString(createSql)) no issue occures.

Please remember, that we are talking about connection to Azure SQL Server.

Here is my connectionString:
Server=tcp:myazuredbserver.database.windows.net,1433;Initial Catalog=myDatabase;Persist Security Info=False;User ID=myUserId;Password=myPassword;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=240;

@ajcvickers
Copy link
Contributor

Note for triage: looks like we need to review which error numbers can indicate that the database doesn't exist. We could also expose the amount of time to wait until Exists returns true.

@ajcvickers
Copy link
Contributor

Note from triage: we are still following up with the SQL Server folks on this.

@ajcvickers ajcvickers added this to the Backlog milestone Jun 28, 2019
@divega divega removed their assignment Sep 18, 2019
@Arcanst
Copy link

Arcanst commented Jan 23, 2020

Hey, is there a real possibility that this will be implemented anytime soon? I'm another developer on this project and we're about to switch to core3.0 - I'm just wondering if our custom migrators should be removed or they are still necessary.

@AndriySvyryd
Copy link
Member

@Arcanst It's still not clear what is the right fix for this

@AndriySvyryd
Copy link
Member

We got confirmation that retrying on 18456 in RetryOnExistsFailure is the correct fix.

@AndriySvyryd AndriySvyryd added the closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. label Sep 1, 2021
@AndriySvyryd AndriySvyryd removed their assignment Sep 1, 2021
AndriySvyryd added a commit that referenced this issue Sep 1, 2021
AndriySvyryd added a commit that referenced this issue Sep 1, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-sqlserver closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported punted-for-3.0 type-bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants