Friday, 3 September 2010

Forefront Identity Manager Service fails to start after reboot

Update [28/09/2010]: Spence recently released a follow-up article to the Rational Guide… in which he discusses an additional change for those of us using SQL Server aliases. Check out the section entitled "Using a SQL Server Named Instance" and scoot down to the local DTC configuration steps. I haven't tried this yet myself but it sounds promising.

Update [27/10/2010]: I see Spence has updated the above-mentioned article to include a section about this problem which validates the solution presented here.

After following Spence Harbar's Rational Guide to implementing SharePoint Server 2010 User Profile Synchronization, I was able to not only get the UPS service started but I was also able to run a sync on my first attempt. I probably got lucky ;-)

The one small hiccup I had along the way was getting the Forefront Identity Manager Service to start following a reboot; the service simply refused to start automatically despite being configured by SharePoint/FIM to do so. Interestingly, both the User Profile Service and the User Profile Synchronization Service items listed in Central Admin's Services on Server page listed the services as running. Starting the FIM Service manually from the Windows Services snapin succeeded (I didn't try directly through CA) but felt hacky and annoying.

What to do? Since the Synchronization Service was starting successfully and I could manually start the service after logging in, I assume this has to be some kind of dependency issue between the services themselves or SQL Server (some of the event log error message listed below definitely take issue with SQL).

Update 29/09/2010: After examining the sequence of event log entries relating to MSSQLSERVER and FIM, I can clearly see SQL is NOT ready to accept client connections by the time the FIM services kick in. I should point out my test environment is running as a single-server farm (AD, SQL, IIS, SharePoint, etc) so I'd definitely pay attention to Spence's follow-up article I note above in the 28/09 update.

My solution was to therefore set both services to start automatically at boot time after a delay by reconfiguring the startup type of BOTH services and Automatic (Delayed Start) in the Windows Services snapin:

FIM-Delayed-Start

Interestingly, I found the FIM Service starts before the FIM Sync Service, fwiw. I also still have one error remaining stating The Forefront Identity Manager Service cannot connect to the SQL Database Server but it doesn't prevent the services from starting or a sync from running.

So is this an inappropriate change to make? I can't say, especially with everyone and their dog saying "let SharePoint manage these services, don't start 'em manually!" In a single-server environment, I'll suggest it is acceptable. I know for certain both services now start automatically after a minute or so (once all other services set to just Automatic have started) and I can still run a profile sync; the following errors are also no longer present:

Log Name:      Application
Source:        Forefront Identity Manager
Date:          3/09/2010 12:37:17 PM
Event ID:      3
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
.Net SqlClient Data Provider: System.Data.SqlClient.SqlException: Cannot open database "Sync DB" requested by the login. The login failed.
Login failed for user 'DEV\SVC_SPFARM'.
   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlInternalConnectionTds.CompleteLogin(Boolean enlistOK)
   at System.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(ServerInfo serverInfo, String newPassword, Boolean ignoreSniOpenTimeout, Int64 timerExpire, SqlConnection owningObject)
   at System.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(String host, String newPassword, Boolean redirectedUserInstance, SqlConnection owningObject, SqlConnectionString connectionOptions, Int64 timerStart)
   at System.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(SqlConnection owningObject, SqlConnectionString connectionOptions, String newPassword, Boolean redirectedUserInstance)
   at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, Object providerInfo, String newPassword, SqlConnection owningObject, Boolean redirectedUserInstance)
   at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection)
   at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnection owningConnection, DbConnectionPool pool, DbConnectionOptions options)
   at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject)
   at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject)
   at System.Data.ProviderBase.DbConnectionPool.GetConnection(DbConnection owningObject)
   at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)
   at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
   at System.Data.SqlClient.SqlConnection.Open()
   at Microsoft.ResourceManagement.Data.DatabaseConnection.Open(SqlConnection connection)

Log Name:      Application
Source:        Forefront Identity Manager
Date:          3/09/2010 12:37:17 PM
Event ID:      3
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
.Net SqlClient Data Provider: System.Data.SqlClient.SqlException: Cannot open database "Sync DB" requested by the login. The login failed.
Login failed for user 'DEV\SVC_SPFARM'.
   at Microsoft.ResourceManagement.Data.Exception.DataAccessExceptionManager.ThrowException(SqlException innerException)
   at Microsoft.ResourceManagement.Data.DatabaseConnection.Open(SqlConnection connection)
   at Microsoft.ResourceManagement.Data.DatabaseConnection.Open(DataStore store)

Log Name:      Application
Source:        Microsoft.ResourceManagement.ServiceHealthSource
Date:          3/09/2010 12:37:17 PM
Event ID:      26
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
The Forefront Identity Manager Service was not able to initialize a timer necessary for supporting the execution of workflows.

Upon startup, the Forefront Identity Manager Service must initialize and set a timer to support workflow execution.  If this timer fails to get created, workflows will not run successfully and there is no recovery other than to stop and start the Forefront Identity Manager Service.

Restart the Forefront Identity Manager Service.

Log Name:      Application
Source:        Microsoft.ResourceManagement.ServiceHealthSource
Date:          3/09/2010 12:37:17 PM
Event ID:      2
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
The Forefront Identity Manager Service could not bind to its endpoints.  This failure prevents clients from communicating with the Web services.

A most likely cause for the failure is another service, possibly another instance of Forefront Identity Manager Service, has already bound to the endpoint.  Another, less likely cause, is that the account under which the service runs does not have permission to bind to endpoints.

Ensure that no other processes have bound to that endpoint and that the service account has permission to bind endpoints.  Further, check the application configuration file to ensure the Forefront Identity Manager Service is binding to the correct endpoints.

Log Name:      Application
Source:        Forefront Identity Manager
Date:          3/09/2010 12:37:17 PM
Event ID:      3
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
.Net SqlClient Data Provider: System.Data.SqlClient.SqlException: Cannot open database "Sync DB" requested by the login. The login failed.
Login failed for user 'DEV\SVC_SPFARM'.
   at Microsoft.ResourceManagement.Data.Exception.DataAccessExceptionManager.ThrowException(SqlException innerException)
   at Microsoft.ResourceManagement.Data.DatabaseConnection.Open(SqlConnection connection)
   at Microsoft.ResourceManagement.Data.DatabaseConnection.Open(DataStore store)
   at Microsoft.ResourceManagement.Data.TransactionAndConnectionScope..ctor(Boolean createTransaction, IsolationLevel isolationLevel, DataStore dataStore)
   at Microsoft.ResourceManagement.Data.TransactionAndConnectionScope..ctor(Boolean createTransaction)
   at Microsoft.ResourceManagement.Data.DataAccess.RegisterService(String hostName)
   at Microsoft.ResourceManagement.Workflow.Hosting.HostActivator.RegisterService(String hostName)
   at Microsoft.ResourceManagement.Workflow.Hosting.HostActivator.Initialize()
   at Microsoft.ResourceManagement.WebServices.ResourceManagementServiceHostFactory.CreateServiceHost(String constructorString, Uri[] baseAddresses)
   at Microsoft.ResourceManagement.WindowsHostService.OnStart(String[] args)

Log Name:      Application
Source:        Microsoft Resource Management Service
Date:          3/09/2010 12:37:17 PM
Event ID:      0
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      dev-sps2010-01.dev.mediawhole.com
Description:
Service cannot be started. System.Data.SqlClient.SqlException: Cannot open database "Sync DB" requested by the login. The login failed.
Login failed for user 'DEV\SVC_SPFARM'.
   at Microsoft.ResourceManagement.WindowsHostService.OnStart(String[] args)
   at System.ServiceProcess.ServiceBase.ServiceQueuedMainCallback(Object state)

If you found this post helpful, please support my advertisers.

4 comments:

  1. Thanks a lot for this! I have had the exact same issues. I'm testing SP2010 in farm mode on a single virtual machine, so it's also running AD & SQL.

    I also followed Harbar's instructions up to the point where you wait 5-10 minutes for the provisioning. Then I reboot, and both FIM services start and everything looks good. (The farm account is still local admin.) I can even create a Sychronization connection.

    But if I reboot once more, then I start receiving the same error messages that you posted above, saying that suddenly the farm account can't access the Sync database. But nothing has changed, and the farm account is still an administrator.

    I followed your advice and I set both FIM-services to delayed start, and now everything works! :) It seems obvious now though, as I can see in the event log that FIM is trying to access the SyncDB *before* SQL Server has started that database, see the error messages and the times below.

    Maybe I get the errors because my virtual machine isn't fast enough? Setting the FIM services to delayed start doesn't feel like a perfect solution, but it's probably acceptable - and it definitely works. I also still get a single event ID 22 saying "The Forefront Identity Manager Service cannot connect to the SQL Database Server." but it doesn't seem to be true. As far as I know. ;)

    Thanks again!

    ---
    Log Name: Application
    Source: Forefront Identity Manager
    Date: 2010-09-10 13:39:14
    Event ID: 3
    Task Category: None
    Level: Error
    Keywords: Classic
    User: N/A
    Computer: win2008a.sp.int
    Description:
    .Net SqlClient Data Provider: System.Data.SqlClient.SqlException: Cannot open database "Sync DB" requested by the login. The login failed.
    Login failed for user 'SP\FarmAccount'.


    Log Name: Application
    Source: MSSQLSERVER
    Date: 2010-09-10 13:39:32
    Event ID: 17137
    Task Category: Server
    Level: Information
    Keywords: Classic
    User: N/A
    Computer: win2008a.sp.int
    Description:
    Starting up database 'Sync DB'.
    ---

    ReplyDelete
  2. Thanks Michael for this hint!
    Setting the services to 'automatic (delayed)' and granting the Network Service permissions to the
    'C:\Program Files\Microsoft Office Servers\14.0\*' directory fixed the problem for me.

    Greetings from Germany,
    Chris

    ReplyDelete
  3. I've wrote your hint at my blog, linking to this blog! Nice post, thanks!

    http://otak-otak-it.blogspot.com/2012/02/forefront-identity-manager-service.html

    ReplyDelete
  4. Good Catch. I didn't consider the timing factors with SQl & FIM

    ReplyDelete