Cannot add witness to my mirroring setup

Question

I'm trying to set up mirroring with a witness using my 3 dedicated servers running SQL Server 2008 R2. I've set up everything as described at this blog post

Mirroring seems to work fine between the principal and secondary server. But when I run the very last command to add the witness

alter database citec_vc_prod set witness = 'TCP://witness_address:witness_port';

I get the following error after a few seconds:

Msg 1456, Level 16, State 3, Line 1 The ALTER DATABASE command could not be sent to the remote server instance 'TCP://witness_address:witness_port'. The database mirroring configuration was not changed. Verify that the server is connected, and try again.

Also, the event log on the principal shows the following error:

The ALTER DATABASE command could not be sent to the remote server instance 'TCP://witness_address:witness_port'. The database mirroring configuration was not changed. Verify that the server is connected, and try again.

I've already shut down the firewall on the witness, and I've successfully telnetted from the principal into the mirroring endpoint of the witness server to make sure there is no connectivity problem. Yet, I still get this error.

My setup is as follows:

Principal: SQL Server 2008 R2 Standard 10.50.1617
Mirror: SQL Server 2008 R2 Standard 10.50.1617
Witness: SQL Server 2008 R2 Express 10.50.2500

Each of the servers is in a different workgroup.

Please help me SQL server gurus, you're my only hope!

Edit: Here's a complete log of the T-SQL commands I used to set up mirroring. Once the first attempt failed with the problem described above, I deleted everything and started from scratch. The same problem reoccurred though.

-- PRINCIPAL
create master key encryption by password = 'mypassword';
GO
create certificate "server1.ourdomain.com_cert" with subject = 'server1.ourdomain.com certificate', start_date = '2007/11/01', expiry_date = '2020/11/01';
GO 

Create endpoint endpoint_mirroring state = started
as tcp(listener_port = 5022, listener_ip = all)
for database_mirroring (authentication = certificate "server1.ourdomain.com_cert", encryption = disabled,  role = all);
GO
Backup certificate "server1.ourdomain.com_cert" to file = 'f:\cert\server1.ourdomain.com_cert.cer';
GO 

-- MIRROR
create master key encryption by password = 'mypassword';
GO
create certificate "server2.ourdomain.com_cert" with subject = 'server2.ourdomain.com certificate', start_date = '2007/11/01', expiry_date = '2020/11/01';
GO
Create endpoint endpoint_mirroring state = started
as tcp(listener_port = 5022, listener_ip = all)
for database_mirroring (authentication = certificate "server2.ourdomain.com_cert", encryption = disabled,  role = all);
GO
Backup certificate "server2.ourdomain.com_cert" to file = 'f:\cert\server2.ourdomain.com_cert.cer';
GO 

-- WITNESS
create master key encryption by password = 'mypassword';
GO
create certificate "witness.ourdomain.com_cert" with subject = 'witness.ourdomain.com certificate', start_date = '2007/11/01', expiry_date = '2020/11/01';
GO
Create endpoint endpoint_mirroring state = started
as tcp(listener_port = 5022, listener_ip = all)
for database_mirroring (authentication = certificate "witness.ourdomain.com_cert", encryption = disabled,role = witness);
GO
Backup certificate "witness.ourdomain.com_cert" to file = 'd:\cert\witness.ourdomain.com_cert.cer';
GO 

-- PRINCIPAL again
create login "server2.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "server2.ourdomain.com_user" from login "server2.ourdomain.com_login";
GO
select * from sys.certificates
Create certificate "server2.ourdomain.com_cert"
Authorization "server2.ourdomain.com_user"
From file = 'f:\cert\server2.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::endpoint_mirroring to [server2.ourdomain.com_login];
GO
------
create login "witness.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "witness.ourdomain.com_user" from login "witness.ourdomain.com_login";
GO
Create certificate "witness.ourdomain.com_cert"
Authorization "witness.ourdomain.com_user"
From file = 'f:\cert\witness.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::endpoint_mirroring to [witness.ourdomain.com_login];
GO 

-- MIRROR again
create login "server1.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "server1.ourdomain.com_user" from login "server1.ourdomain.com_login";
GO
Create certificate "server1.ourdomain.com_cert"
Authorization "server1.ourdomain.com_user"
From file = 'f:\cert\server1.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::Endpoint_mirroring to [server1.ourdomain.com_login];
GO
-------
create login "witness.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "witness.ourdomain.com_user" from login "witness.ourdomain.com_login";
GO
Create certificate "witness.ourdomain.com_cert"
Authorization "witness.ourdomain.com_user"
From file = 'f:\cert\witness.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::Endpoint_mirroring to [witness.ourdomain.com_login];
GO 

-- WITNESS again
create login "server1.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "server1.ourdomain.com_user" from login "server1.ourdomain.com_login";
GO
Create certificate "server1.ourdomain.com_cert"
Authorization "server1.ourdomain.com_user"
From file = 'd:\cert\server1.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::Endpoint_mirroring to [server1.ourdomain.com_login];
GO
-------
create login "server2.ourdomain.com_login" with PASSWORD = 'mypassword';
GO
create user "server2.ourdomain.com_user" from login "server2.ourdomain.com_login";
GO
Create certificate "server2.ourdomain.com_cert"
Authorization "server2.ourdomain.com_user"
From file = 'd:\cert\server2.ourdomain.com_cert.cer';
GO
Grant CONNECT ON Endpoint::endpoint_mirroring to [server2.ourdomain.com_login];
GO 

-- MIRROR again
alter database MyDBName set partner OFF
alter database MyDBName set partner = 'TCP://server1.ourdomain.com:5022';
GO 

-- PRINCIPAL again
alter database MyDBName set partner OFF
alter database MyDBName set partner = 'TCP://server2.ourdomain.com:5022';
GO
alter database MyDBName set witness OFF
alter database MyDBName set witness = 'TCP://witness.ourdomain.com:5022';
GO

Edit 2: As requested by Remus, I have attached a profiler to my three server instances while trying to add the witness. I looked for :

Database Mirroring State Change
Broker:Connection Event

I could not monitor "Audit Database Mirroring Login" since I could not find this in the "Events List" in the profiler. It's not in the "Security Audit" section, is it?

Anyway, I could not monitor any such events on the witness or the mirror. I tried, but there were simply no events. There were some of these events on the principal:

  Database Mirroring Connection                 32  2011-12-09 20:04:07.983 1       39796   2 - Connected   c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://<MyWitnessIP>:5022    principal.mytopleveldomain.com,3809                                             
    Audit Database Mirroring Login                  30  2011-12-09 20:04:08.133 1       39797   1 - Login Success               1   0X01        tcp://<MyWitnessIP>:5022    principal.mytopleveldomain.com,3809                 1   witness.mytopleveldomain.com_login      CERTIFICATE Microsoft Unified Security Protocol Provider    Initiator       
    Database Mirroring State Change DBM: Synchronized Principal without Witness -> DBM: Synchronizing Principal             27  2011-12-09 20:04:27.980 9       39798               2   1   0X01            principal.mytopleveldomain.com,3809         Zeiterfassung-Staging   0   13                          
    Database Mirroring State Change DBM: Synchronizing Principal -> DBM: Synchronized Principal without Witness             27  2011-12-09 20:04:28.237 9       39799               13  1   0X01            principal.mytopleveldomain.com,3809         Zeiterfassung-Staging   0   2                           
    Database Mirroring Connection   An error occurred while receiving data: '64(failed to retrieve text for this error. Reason: 15105)'.                30  2011-12-09 20:05:42.530 1       39803   4 - Closing c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://<MyWitnessIP>:5022    principal.mytopleveldomain.com,3809                                             
    Database Mirroring Connection                   30  2011-12-09 20:05:42.533 1       39804   5 - Closed  c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://<MyWitnessIP>:5022    principal.mytopleveldomain.com,3809                                             


Database Mirroring Connection                   32  2011-12-09 20:04:07.983 1       39796   2 - Connected   c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://85.214.251.151:5022   srv1.logmytime.de,3809                                              
Audit Database Mirroring Login                  30  2011-12-09 20:04:08.133 1       39797   1 - Login Success               1   0X01        tcp://85.214.251.151:5022   srv1.logmytime.de,3809                  1   wtn.logmytime.de_login      CERTIFICATE Microsoft Unified Security Protocol Provider    Initiator       
Database Mirroring State Change DBM: Synchronized Principal without Witness -> DBM: Synchronizing Principal             27  2011-12-09 20:04:27.980 9       39798               2   1   0X01            srv1.logmytime.de,3809          Zeiterfassung-Staging   0   13                          
Database Mirroring State Change DBM: Synchronizing Principal -> DBM: Synchronized Principal without Witness             27  2011-12-09 20:04:28.237 9       39799               13  1   0X01            srv1.logmytime.de,3809          Zeiterfassung-Staging   0   2                           
Database Mirroring Connection   An error occurred while receiving data: '64(failed to retrieve text for this error. Reason: 15105)'.                30  2011-12-09 20:05:42.530 1       39803   4 - Closing c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://85.214.251.151:5022   srv1.logmytime.de,3809                                              
Database Mirroring Connection                   30  2011-12-09 20:05:42.533 1       39804   5 - Closed  c6b6054d-56c0-4589-922a-29a40fdd9d96            1   0X01        tcp://85.214.251.151:5022   srv1.logmytime.de,3809  

I'll gladly mirror other events as well, but please let me know which event section I can find them in when adjusting the profiler.

Edit 3: I had another attempt at profiling the witness, this time with almost every event type there is. And I finally got some data:

Trace Start                     2011-12-10 01:24:08.180                                                                                             
ErrorLog    2011-12-10 01:24:40.40 Logon       Database Mirroring Login succeeded for user 'principal.ourdomain.com_login'. Authentication mode: CERTIFICATE.  [CLIENT: <principalip>]
                29  2011-12-10 01:24:40.400 1   28046   1428                    1   0X01        witness.ourdomain.com,3809          master  0       sa                          
EventLog    Database Mirroring Login succeeded for user 'principal.ourdomain.com_login'. Authentication mode: CERTIFICATE.  [CLIENT: <principalip>]             29  2011-12-10 01:24:40.400 1   28046   1429                    1   0X01        witness.ourdomain.com,3809          master  0       sa  

Next, I did the same on the mirror, but I got only these two rather unimportant events:

ErrorLog    2011-12-10 01:38:02.14 spid29s     Database mirroring is inactive for database 'DatabaseName'. This is an informational message only. No user action is required.
            sa                      29  2011-12-10 01:38:02.143         
EventLog    Database mirroring is inactive for database 'DatabaseName'. This is an informational message only. No user action is required.          sa                      29  2011-12-10 01:38:02.143     0XA20500000A0000000F000000570049004E003600360036004800520054004B003700540032004800000000000000  
ErrorLog    2011-12-10 01:38:22.40 spid29s     Database mirroring is active with database 'DatabaseName' as the mirror copy. This is an informational message only. No user action is required.
            sa                      29  2011-12-10 01:38:22.407         
EventLog    Database mirroring is active with database 'DatabaseName' as the mirror copy. This is an informational message only. No user action is required.            sa                      29  2011-12-10 01:38:22.407     0XA10500000A0000000F000000570049004E003600360036004800520054004B003700540032004800000000000000  

I still don't see any information on why adding the witness fails though.

Solution

Can you attach the SQL Profiler to all three instances involved and monitor for these events:

• Audit Database Mirroring Login
• Database Mirroring State Change
• Broker:Connection Event

Then attempt again to establish the mirroring session. Make sure you select all columns when adding the events. Start from a blank template.

2011-12-09 20:04:07.983  Database Mirroring Connection    Connected   
2011-12-09 20:04:08.133  Audit Database Mirroring Login   Login Success
2011-12-09 20:04:27.980  Database Mirroring State Change DBM: 
  Synchronized Principal without Witness -> 
  DBM: Synchronizing Principal             
2011-12-09 20:04:28.237  Database Mirroring State Change DBM: 
  Synchronizing Principal -> 
  DBM: Synchronized Principal without Witness
2011-12-09 20:05:42.530  Database Mirroring Connection   An error occurred... 

Here is the explanation for what happens:

• at 20:04:07 the principal connect with the witness
• at 20:04:08 the principal and witness finish a successful handshage (audit login succes)
• at 20:04:27 DBM changes the state from synchronized w/o witness to synchronized
• at 20:04:28 DBM changes the state back from syncronized to synchronized w/o witness
• at 20:05:42 the connection with the witness times out due to inactivity and closes

This sequence of events indicates that the connectivity between principal and witness is functional. The request to add the witness fails, and there could be multiple reasons. Similar events must occur on the mirror and on the witness as well, is not clear why you say that you could only capture them on the principal.

Comments

[Ben Thul]

That it's waiting a few seconds suggests to me that it's not able to get there for whatever reason. I have never done a mirroring setup, but does your firewall setup allow traffic from any port to your witness port on both sides of all involved firewalls? That is, you altered the firewall on the witness side, but there could be one on your server that is disallowing. Might be time for wireshark or a similar tool.

[Adrian Grigore]

@Ben: I had the same thoughts, but as already mentioned the firewall is currently switched off on the witness. And there are no outgoing port restrictions on the principal server.

[Ben Thul]

Firewalls can exist on the network. They don't have to be Windows firewall on the server.

[Adrian Grigore]

@Ben: I successfully telnetted from the principal into the witness on the port of the mirroring endpoint. There is obviously no firewall problem.

[Adrian Grigore]

Yes, the witness endpoint is started. I am not using windows domains at all, but certificate-based authentication. Please see my OP for details.

[Adrian Grigore]

It's a name and I have triple-checked all three names can be resolved properly (via DNS) from all three hosts.

[Adrian Grigore]

I think the reason I did not get any monitoring data from the witness is that it raises less events than the principal and the event types are different as well. Please see my edit 3 above.

[Adrian Grigore]

I think you are confusing this with the "alter database <dbname> set partner <hostname>" command. That one has to be executed on the mirror first, then on the principle. "Set witness" is only initiated on the principal - if you try to run it on the mirror, you get the following error: "Msg 1470, Level 16, State 2, Line 1 The alter database for this partner config values may only be initiated on the current principal server for database MYDBNAME"

[Adrian Grigore]

The next line after the one you quoted restarts the mirroring session.