Synchronization service startup sequence

As with all services, ciSync is started and stopped by the Service Control Manager, which is a part of the operating system. When the executable file, referred to as the ImagePath, is launched it receives the 'Onstart' system event. The first thing that happens after this is the creation of the main log file; ciSync.log and the ciSync_Proxy.log.

Creating a log file means that some standard information is put into the file from scratch. The logfile in its entirety can be seen here.

2011-10-17 15:07:27:914 - Application    : CapaInstaller Synchronization Service, version 4.2.3168.0, File date: 14-10-2011 13:19:51
2011-10-17 15:07:27:918 - Computer       : DEVTBS.capasystems.com
2011-10-17 15:07:27:996 - Operating sys  : Microsoft Windows 7 Enterprise, version 6.1.7601.65536 (64 bit)
2011-10-17 15:07:28:063 - User Account   : Nt Authority\System
2011-10-17 15:07:28:064 - Process ID     : 9696
2011-10-17 15:07:28:065 - Free memory    : Physical: 2.280 of 12.286 MB (18,6%). Virtual: 8.388.061 of 8.388.608 MB (100,0%)
2011-10-17 15:07:28:102 - Network state  : Connected

This information is vital. It describes the service name, the service version, and the creation date of the executable. The Fully Qualified Domain Name of the server is given as well as the operating system. The scope that the service runs in and the process ID is also part of the log header and can often help to determine the causes of error. The amount of free physical and virtual memory available at startup is a definite nice-element in case of other issues on the server interfering with the service. At last, the network state is displayed. It is of course essential to a service that synchronizes data between servers for a living, that the server is actually connected to the network. Initializing the log file is very important since it covers everything that the service does and because it is the primary source of information in the event that an error should occur.

2011-10-29 19:24:38:374 - Settings       : Loading C:\Program Files\CapaInstaller\Services\Synchronization\ciSync Settings.xml
2011-10-29 19:24:38:386 - Command line   : /runschedules
2011-10-29 19:24:38:389 - Debug mode     : False

The CiSync Settings.xml settings file is then loaded. It contains information about how the service should connect to the database, such as authentication methods and encrypted credentials. If any command-line parameters were supplied, they are listed next. In this case, the service is instructed to run every synchronization job found in the SQL database regardless of the planned time for each schedule. Whether or not the service was told to run in debug mode is also stated. The debug mode does not in itself change any functionality, but is sometimes requested by the CapaInstaller Support team in the case of errors.

2011-10-29 19:24:40:451 - SQL server     : srvsql.capasystems.com\dev
2011-10-29 19:24:40:454 -   Database     : cms_TBS
2011-10-29 19:24:40:454 -   Auth.        : WCF
2011-10-29 19:24:40:454 -   Internal url : http://devtbs.CapaSystems.com:8036
2011-10-29 19:24:40:456 -   Public url   : https://devtbs.CapaSystems.com:8037
2011-10-29 19:24:43:219 -   Connected    : http://devtbs.CapaSystems.com:8036/dalwcf

Connecting to the SQL server is another critical step in actually getting some data synchronized since the service needs to find itself in the database to justify its own existence. First, the SQL server is shown and indented the database name and the authentication method. There are three possibilities

• SQL - This means that the service will connect to the SQL server with supplied SQL credentials. The password is encrypted.
• WINDOWS - The computer is already granted access because there exists an SQL account for the server.
• WCF - Connection to the SQL server is done via the Data Connection Service (DCS) which supplies HTTP/HTTPS access to the SQL server inside the firewall.

Per definition the ciSync service does know where it is located or where the DCS is located, so if there is more that one URL to the DCS they are tried on a turn basis, starting with the one that can be reached directly the Internal URL. A connection was made on the internal URL.

2011-10-29 19:24:43:399 - Service ID     : 8
2011-10-29 19:24:43:421 - Service GUID   : 3796af0b-c034-495d-94ad-8b36e2588df8
2011-10-29 19:24:43:491 - Server role    : f5e33bd7-39a0-4f6b-8a51-150dcd28fef4: CMS Server (devtbs)

Now that an sql connection is established, there are a few facts to get straight. The first thing is to track down the service id. This is important because synchronization jobs are listed per server ID. This means that ciSync services scan the Synccom and SyncJob table frequently and filter the data on the service id (The SYNCSERVICEID column in the SYNCJOB table).
The service GUID and the server role are mostly shown for convenience for the log viewer.

2011-10-30 08:44:25:141 - Firewall ports : http port 8036, https port 8037
2011-10-30 08:44:25:372 -   Public       : Port 8036 is now open and enabled
2011-10-30 08:44:25:591 -   Domain       : Port 8036 is now open and enabled
2011-10-30 08:44:25:826 -   Private      : Port 8036 is open and now enabled
2011-10-30 08:44:26:054 -   Public       : Port 8037 is open and now enabled
2011-10-30 08:44:26:207 -   Domain       : Port 8037 is open and enabled
2011-10-30 08:44:26:359 -   Private      : Port 8037 is open and enabled

For any communication to work, the relevant ports must be opened. Natively ciSync communicates on HTTP but can additionally communicate on HTTPS. In this case, the ports 8036 and 8037 are used. The default values are HTTP port 80 and HTTPS port 443. When working with firewall ports it becomes clear that you can open the same port on different networks (profiles). Workgroup servers have a Public Profile and a Private Profile. Servers that are part of a domain also sports the Domain Profile. Each port on each profile is then checked to be opened or opened and checked to be enabled or enabled. In the log file, there is a difference in checking a port to be open and opening a port. When the log says; 'is open' then the port was already open. When it says; 'is now open' then it means that the port was initially closed, but the service opened the port. The same goes for 'enabled' and 'now enabled'. Firewall ports can be altered from many places. Therefore the ciSync service checks and ensures throughput on a regular basis via the Synchronization service idle check.

2011-10-30 08:44:26:395 - Certificate
2011-10-30 08:44:26:396 -   Name         : *.capasystems.com
2011-10-30 08:44:26:398 -   Store        : Personal
2011-10-30 08:44:26:399 -   Thumbprint   : D34bec93f092c728643435b1655bb99ad58ab4d8
2011-10-30 08:44:26:509 -   Binding      : Certificate already bound to port 8037

If HTTPS communication is set up there will need to be a certificate installed on the parent server. In this case its a star certificate located in the Personal Store.

The certificates are identified by their thumbprint since certificate names are ununique. For the certificate to work, it must be bound to the HTTPS port. The service checks that it is, and binds it if it's not already bound.

2011-10-30 08:44:26:510 - Servicehosts
2011-10-30 08:44:26:546 -   Opened       : http://devtbs.capasystems.com:8036/general
2011-10-30 08:44:26:553 -   Opened       : http://devtbs.capasystems.com:8036/transfer
2011-10-30 08:44:26:563 -   Opened       : https://devtbs.capasystems.com:8037/general
2011-10-30 08:44:26:567 -   Opened       : https://devtbs.capasystems.com:8037/transfer

In order to communicate with child servers, the ciSync service must establish service-hosts containing endpoints to do so. Two endpoints are needed per protocol. The general endpoint handles all communication/negotiation between parent and child, and when it comes to the actual data transfer it is streamed on the transfer endpoint.

2011-10-30 08:44:26:589 - Loopback test  
2011-10-30 08:44:26:644 -   Http url     : Succeded: http://devtbs.capasystems.com:8036
2011-10-30 08:44:26:679 -   Https url    : Succeded: https://devtbs.capasystems.com:8037
2011-10-30 08:44:28:706 -   Public url   : Failed: https://devtbs2.capasystems.com:8037 (It is not uncommon that a public url is inaccessible from the inside of the firewall)

To test that the service-hosts and endpoints are actually working, the service performs a loop-back test on each protocol, and if configured for the server, the Public URL is tried as well. In case of an error, it is always nice to be able to out rule half of the equation, and by testing the server part, any bug-tracking can concentrate on the client part. The public URL test is a bit tricky because this means that the service must access itself by entering the firewall from the outside. In many cases, the ability to do this has been revoked by the systems administrator, and therefore this test is only partly useful.

2011-10-30 08:44:29:015 - Parent server  
2011-10-30 08:44:29:060 -   Connecting   : http://ws09.capasystems.com:8036 (Internal url)
2011-10-30 08:44:32:086 -     Connected  : http://ws09.capasystems.com:8036/general
2011-10-30 08:44:32:091 -     Connected  : http://ws09.capasystems.com:8036/transfer

Now that the service is running, is connected to the SQL server, and has established a service-host, it is time to connect to the parent server. The SQL server identifies the parent server from the Service ID and Service Role. If the server is both a management server and an OS server, the OS server ranks higher. When a synchronization job, with this server as the target server, is running, then the source server is automatically deemed the parent server. The parent server can be contacted on the internal URL as well as via the public URL, and in both cases, HTTP and HTTPS can be selected. With more that one choice, the server alternated between them, starting with the internal URL for speed. In this case, the internal URL worked just fine, and two clients were hooked up to the equivalent endpoints, general and transfer.

2011-10-30 08:44:32:298 - Auto update    
2011-10-30 08:44:32:310 -   Equal        : ciSync on ws09.capasystems.com is equal to current version

Once connected, the parent server is queried for a file version of the service. If the parent service is newer, then the parent service is requested to 'zip' itself and hand over the goods. When received, the zip file is decompressed, and the ciSync service calls the self-update utility, which will in turn stops the service, replaces the executables with the new ones, and then starts the service. In this example, the parent service version was found to be of equal version.

2011-10-30 08:44:32:334 - Timers         
2011-10-30 08:44:32:335 -   Cleanup      : 24 hours
2011-10-30 08:44:32:336 -   Schedule     : 10 seconds
2011-10-30 08:44:32:337 -   SyncCom      : 1 minute
2011-10-30 08:44:32:339 -   System       : 1 minute
2011-10-30 08:44:32:340 -   Parent       : 10 seconds
2011-10-30 08:44:32:341 -   Heartbeat    : 10 seconds

The last initialization act is to start the various timers. Their job is listed below;

2011-10-30 08:44:32:399 - Initialized    
2011-10-30 08:44:32:400

The service is now up and running. Ready to receive orders from the sql server.