Brekeke SIP Proxy Server Version 3- major bug

Izzyg · Post by **Izzyg** » Wed Jul 08, 2015 5:21 am

1. Brekeke Product Name and Version:
server-product Brekeke SIP Server
server-ver 3.4.6.3/411

2. Java version:
java-ver 1.6.0_45

3. OS type and the version:
os-name Windows Server 2008 R2
os-ver 6.1

4. UA (phone), gateway or other hardware/software involved:

5. Your problem:

several times thru out the day my brekeke SIP Server will stop responding to a OPTIONS message for about 15 seconds, no other SIP messaging is processed during that time

this is something that started happening after updating to Version 3

can anyone recommend where i should start looking for causes?

snuyzm · Post by **snuyzm** » Wed Jul 08, 2015 10:05 am

It seems the issue happen with your configuration or network routing.

Who did send OPTIONS?
Does the OPTIONS's request-URI point the SIP Server's IP address or FQDN?

Izzyg · Post by **Izzyg** » Wed Jul 08, 2015 10:10 am

i get OPTIONS all day long from several monitor servers, i doubt that would cause it

where would you recommend i check on the network? when i was running Version 2 it was perfect, and it actually still is
only Version 3 has the bug

on the same hardware we see a different when Version 2 runs or when version 3 runs

snuyzm · Post by **snuyzm** » Wed Jul 08, 2015 10:41 am

Does the OPTIONS's request-URI point the SIP Server's IP address or FQDN?

Izzyg · Post by **Izzyg** » Wed Jul 08, 2015 11:26 am

most of them are pointed to the IP Address, it might be there are some doing it based on FQDN

snuyzm · Post by **snuyzm** » Wed Jul 08, 2015 12:24 pm

Does the IP address in OPTIONS's request-URI match the SIP Server's interface IP address shown in the [Status] page?

Does the FQDN point to the SIP Server's interface IP address?

Izzyg · Post by **Izzyg** » Wed Jul 15, 2015 11:59 am

i updated to the latest version 3.4.7.0 and its still happening

the IP Address in the request URI matches the interface IP

and the FQDN points to this server

the problem is with 2 version 3.4.7.0 servers,,,

but with version 2.4.8.6 it does not happen

snuyzm · Post by **snuyzm** » Wed Jul 15, 2015 4:45 pm

Do you have dialplan rule for OPTIONS?
Is it sent over TCP? or UDP?

Can you paste an OPTIONS packet here?

Izzyg · Post by **Izzyg** » Wed Jul 15, 2015 8:52 pm

Dial Plan History Details
No. 75064
Session ID n/a
Rule _OPTIONS
Time (received) 07/15/15 23:45:35.416
Time (Dial Plan IN) 07/15/15 23:45:35.416 (0ms)
Time (Dial Plan OUT) 12/31/69 19:00:00.000 (-1437018335416ms)
Source IP 69.200.100.12:5060 (UDP)
Destination IP n/a
Action 200
Incoming Packet OPTIONS sip:74.206.239.197 SIP/2.0
Via: SIP/2.0/UDP 69.200.100.12:5060;branch=z9hG4bK0180aeca;rport=5060
From: "SPB.a.1.4" <sip:SPB.a.1.4@ips1>;tag=as5087bf1f
To: <sip:74.200.100.11>
Contact: <sip:SPB.a.1.4@69.42.161.12>
Call-ID: 4dc29ea534ef66355a2b8d980fa86242@ips1
CSeq: 102 OPTIONS
User-Agent: IPS.12A
Max-Forwards: 70
Date: Thu, 16 Jul 2015 01:43:34 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0

snuyzm · Post by **snuyzm** » Wed Jul 15, 2015 10:58 pm

Are there any errors around at that time?

You can check errors in Error Logs page.

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 5:11 am

i have MANY OPTIONS messages a minute, and so does all my other servers

so i doubt its related to the OPTIONS being sent, why do you suspect it is ?

i dont see anything in the error logs, what should i search for ?

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 9:40 am

Does the SIP server stop responding to other SIP messages if an OPTIONS causes a delay?

Can you post the DialPlan rule "_OPTIONS" ?

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 10:24 am

$request = ^OPTIONS

$auth = false
$action = 200

all SIP traffic is effected most likely, i dont know for certain how i can proov it
but int he past when i used this for all my incoming and outgoing calls, when i get an alert from my monitoring system that it didnt receive a reply for the OPTIONS, at the same time our customers would experience issues with placing and receiving calls

once i moved back to version 2.4.8.6, it works fine there, but im still getting the timeouts fromt he Version 3.4.7.0 Brekeke

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 11:06 am

Add this in the Configuration's Advanced.
net.dispatcher.max.stacked.time = 0
and restart the sip server.

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 11:32 am

Brekeke support told me to use this setting:
net.dispatcher.max.stacked.time = 86400000

and thats what ive been using, are you asking me to change it?

can you explain what this does and how will the new change effect ?

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 1:48 pm

Because you are using 3.4.7.0, net.dispatcher.max.stacked.time=0 will be better.

0 disables the stacked timer from recent Brekeke versions.

The stacked timer feature will cause the issue if your PC has a problem in system-clock.

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 2:52 pm

i had the same issue with previous version 3.4.x.x versions

how can i check on my system if the system has a system-clock issue?

this is happening on a Linux and a Windows installation

was the value of 0 for the stacked timer introduced only in 3.4.7.0?

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 5:07 pm

A system-clock issue happens if you are using a PC which has a CMOS battery problem.
Disable the NTP client in OS, and replace CMOS battery or use a better PC.

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 6:24 pm

i disabled the time clock updater, and it is still happening

its been turned off for months ever since the issue started

still i can try to set the value to 0 instead of what its now, if you beleive it may help?

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 8:29 pm

did you disable Windows Time service?

If you are using 3.4.7.0, 0 will be better than the current value.

Izzyg · Post by **Izzyg** » Thu Jul 16, 2015 8:35 pm

ill try it on my backup server, but its a linux server

on the windows machine i disable the windows time service from updating the clock automatic

snuyzm · Post by **snuyzm** » Thu Jul 16, 2015 10:58 pm

Are you sure the time service is not running?

Check the Windows Time Service's log.
https://support.microsoft.com/en-us/kb/816043

Izzyg · Post by **Izzyg** » Fri Jul 17, 2015 8:14 am

wow, i just looked and saw time sync was on

i turned it off again now, and lets see what happens

what should i look for in the log that would indicate there was an issue ?

snuyzm · Post by **snuyzm** » Fri Jul 17, 2015 11:13 am

check the time service's log to confirm it is not running.

Izzyg · Post by **Izzyg** » Fri Jul 17, 2015 11:17 am

here is the logs

151313 10:13:30.2664062s - ---------- Log File Opened -----------------
151313 10:13:30.2664062s - CurSpc:15625000ns BaseSpc:15625000ns SyncToCmos:Yes
151313 10:13:30.2664062s - PerfFreq:2337910c/s
151313 10:13:30.2664062s - ReadConfig: Found provider 'NtpClient':
151313 10:13:30.2664062s - ReadConfig: 'Enabled'=0x00000001
151313 10:13:30.2664062s - ReadConfig: 'DllName'='%systemroot%\system32\w32time.dll'
151313 10:13:30.2664062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:30.2664062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:30.2664062s - ReadConfig: 'InputProvider'=0x00000001
151313 10:13:30.2664062s - ReadConfig: Found provider 'NtpServer':
151313 10:13:30.2664062s - ReadConfig: 'Enabled'=0x00000000
151313 10:13:30.2664062s - ReadConfig: 'DllName'='%systemroot%\system32\w32time.dll'
151313 10:13:30.2664062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:30.2664062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:30.2673828s - ReadConfig: 'InputProvider'=0x00000000
151313 10:13:30.2673828s - ReadConfig: Found provider 'VMICTimeProvider':
151313 10:13:30.2673828s - ReadConfig: 'Enabled'=0x00000001
151313 10:13:30.2673828s - ReadConfig: 'DllName'='%SystemRoot%\System32\vmictimeprovider.dll'
151313 10:13:30.2673828s - ReadConfig: 'DllName'='C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:30.2673828s - ReadConfig: 'DllName'='C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:30.2673828s - ReadConfig: 'InputProvider'=0x00000001
151313 10:13:30.2673828s - ReadConfig: 'PhaseCorrectRate'=0x00000001 (2)
151313 10:13:30.2673828s - ReadConfig: 'UpdateInterval'=0x00057E40 (2)
151313 10:13:30.2673828s - ReadConfig: 'FrequencyCorrectRate'=0x00000004 (2)
151313 10:13:30.2673828s - ReadConfig: 'PollAdjustFactor'=0x00000005 (2)
151313 10:13:30.2673828s - ReadConfig: 'LargePhaseOffset'=0x02FAF080 (2)
151313 10:13:30.2673828s - ReadConfig: 'SpikeWatchPeriod'=0x00000384 (2)
151313 10:13:30.2673828s - ReadConfig: 'HoldPeriod'=0x00000005 (2)
151313 10:13:30.2673828s - ReadConfig: 'MinPollInterval'=0x0000000A (2)
151313 10:13:30.2673828s - ReadConfig: 'MaxPollInterval'=0x0000000F (2)
151313 10:13:30.2673828s - ReadConfig: 'AnnounceFlags'=0x0000000A (2)
151313 10:13:30.2673828s - ReadConfig: 'LocalClockDispersion'=0x0000000A (2)
151313 10:13:30.2673828s - ReadConfig: 'MaxNegPhaseCorrection'=0x0000D2F0 (2)
151313 10:13:30.2673828s - ReadConfig: 'MaxPosPhaseCorrection'=0x0000D2F0 (2)
151313 10:13:30.2673828s - ReadConfig: 'EventLogFlags'=0x00000002 (2)
151313 10:13:30.2673828s - ReadConfig: 'MaxAllowedPhaseOffset'=0x00000001 (2)
151313 10:13:30.2673828s - ReadConfig: 'TimeJumpAuditOffset'=0x00007080 (2)
151313 10:13:30.2673828s - lastClockRate=156250, clockPrecision=-6
151313 10:13:30.2673828s - SetTimeSlipNotification succeeds with 0x00000000.
151313 10:13:30.2673828s - W32TmServiceMain: RequestNetTopoChangeNotification Succeed
151313 10:13:30.2683593s - DomainHierarchy: LSA role change notification. Redetecting.
151313 10:13:30.2683593s - ClockDisciplineThread: Starting: SetUnsync: LI:3 S:0 RDl:0 RDs:0 TSF:0x0 LastUTC:117175675
151313 10:13:30.2683593s - Starting Providers.
151313 10:13:30.2683593s - Starting 'NtpClient', dll:'C:\Windows\system32\w32time.dll'
151313 10:13:30.2683593s - LoadLibrary
151313 10:13:30.2683593s - NtpTimeProvOpen("NtpClient") called.
151313 10:13:30.2683593s - StartNtpProv
151313 10:13:30.2683593s - sysPrecision=-6, systmeClockResolution=156250
151313 10:13:30.2693359s - NtpProvider: Created 2 sockets (0 listen-only): [::]:123<0x0>, 0.0.0.0:123<0x0>
151313 10:13:30.2693359s - StartListeningThread completed!
151313 10:13:30.2693359s - PeerPollingThread: waiting forever
151313 10:13:30.2693359s - StartPeerPollingThread completed!
151313 10:13:30.2693359s - ReadConfig: 'AllowNonstandardModeCombinations'=0x00000001 (2)
151313 10:13:30.2693359s - ReadConfig: 'CompatibilityFlags'=0x80000000 (2)
151313 10:13:30.2693359s - ReadConfig: 'SpecialPollInterval'=0x00093A80 (2)
151313 10:13:30.2693359s - ReadConfig: 'ResolvePeerBackoffMinutes'=0x0000000F (2)
151313 10:13:30.2693359s - ReadConfig: 'ResolvePeerBackoffMaxTimes'=0x00000007 (2)
151313 10:13:30.2693359s - ReadConfig: 'EventLogFlags'=0x00000001 (2)
151313 10:13:30.2693359s - ReadConfig: 'LargeSampleSkew'=0x00000003 (2)
151313 10:13:30.2693359s - ReadConfig: 'Type'=NTP (2)
151313 10:13:30.2693359s - ReadConfig: 'NtpServer'=time.windows.com,0x9 (2)
151313 10:13:30.2693359s - ReadConfig: 'ManualPeerList'(parsed)='time.windows.com,0x9'
151313 10:13:30.2693359s - AddNewPendingPeer: manual
151313 10:13:30.2693359s - StartListeningThread completed!
151313 10:13:30.2693359s - PeerPollingThread: waiting 0.000s
151313 10:13:30.2693359s - PeerPollingThread: WaitTimeout
151313 10:13:30.2693359s - StartPeerPollingThread completed!
151313 10:13:30.2693359s - NtpClient started.
151313 10:13:30.2693359s - Resolving manual peer: time.windows.com,0x9
151313 10:13:30.2693359s - Starting 'VMICTimeProvider', dll:'C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:30.2693359s - PeerPollingThread: PeerListUpdated
151313 10:13:30.2693359s - PeerPollingThread: waiting forever
151313 10:13:30.2703125s - LoadLibrary
151313 10:13:30.2703125s - Successfully started 2 providers.
151313 10:13:30.2703125s - /--TimeProvider: All providers started
151313 10:13:30.2703125s - | Name:NtpClient, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:30.2703125s - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:30.2703125s - >--
151313 10:13:30.2703125s - | Total:2, Input: 2, Marked: 0
151313 10:13:30.2703125s - \--
151313 10:13:30.2703125s - W32TmServiceMain: waiting i16.000s (1024.000s)
151313 10:13:30.2703125s - W32TmServiceMain: Network Topology Change
151313 10:13:30.2712890s - TimeProvCommand([NtpClient], TPC_NetTopoChange) called.
151313 10:13:30.2908203s - RPC Caller is PD-Name\Administrator (S-1-5-21-3496082489-3062377768-2907400675-500)
151313 10:13:30.2908203s - RPC Call Attribute is local=1, kernel=0, session=0, authentication=6, protocol=2, OpNum=0
151313 10:13:30.2908203s - RPC Call - ForceResync
151313 10:13:30.2908203s - W32TmServiceMain: ********** Time Slip Notification **********
151313 10:13:30.2908203s - ClockDispln TimeSlip:TimeSlip LastUTC:117175676 SetUnsync: LI:3 S:0 RDl:0 RDs:0 TSF:0x0
151313 10:13:30.2908203s - TimeProvCommand([NtpClient], TPC_TimeJumped) called.
151313 10:13:30.2908203s - W32TmServiceMain: waiting i16.000s (1024.000s)
151313 10:13:30.3601562s - Create new peer associations: #1
151313 10:13:30.3601562s - Association: (Local) 0.0.0.0:123 => 191.233.81.105:123 (Remote)
151313 10:13:30.3601562s - Created reachability group: (
151313 10:13:30.3601562s - 191.233.81.105:123,
151313 10:13:30.3601562s - )
151313 10:13:30.3601562s - PollIntervalChange(): clear: host 0 = max 17
151313 10:13:30.3601562s - PeerPollingThread: waiting 0.000s
151313 10:13:30.3601562s - NtpProvider: Network Topology Change
151313 10:13:30.3601562s - Reachability: removing peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123). LAST PEER IN GROUP!
151313 10:13:30.3601562s - Peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123) never sync'd, resync now!
151313 10:13:30.3601562s - Peers reset: p-p:0 a-p:1 a-x:0
151313 10:13:30.3601562s - NtpProvider: Created 2 sockets (0 listen-only): [::]:123<0x0>, 0.0.0.0:123<0x0>
151313 10:13:30.3601562s - StartListeningThread completed!
151313 10:13:30.3601562s - PeerPollingThread: waiting 1.500s
151313 10:13:30.3601562s - StartPeerPollingThread completed!
151313 10:13:30.3601562s - W32TmServiceMain: waiting i16.000s (1024.000s)
151313 10:13:30.3601562s - W32TmServiceMain: RequestNetTopoChangeNotification Succeed
151313 10:13:30.3601562s - PeerPollingThread: PeerListUpdated
151313 10:13:30.3601562s - Logging error: NtpClient has been configured to acquire time from one or more time sources, however none of the sources are currently accessible and no attempt to contact a source will be made for 1 minutes. NTPCLIENT HAS NO SOURCE OF ACCURATE TIME.
151313 10:13:30.3601562s - PeerPollingThread: waiting 1.500s
151313 10:13:31.8601562s - PeerPollingThread: WaitTimeout
151313 10:13:31.8601562s - Resolving manual peer: time.windows.com,0x9
151313 10:13:31.8601562s - Create new peer associations: #1
151313 10:13:31.8601562s - Association: (Local) 0.0.0.0:123 => 191.233.81.105:123 (Remote)
151313 10:13:31.8601562s - Created reachability group: (
151313 10:13:31.8601562s - 191.233.81.105:123,
151313 10:13:31.8601562s - )
151313 10:13:31.8601562s - PollIntervalChange(): clear: host 0 = max 17
151313 10:13:31.8601562s - PeerPollingThread: waiting 0.000s
151313 10:13:31.8601562s - PeerPollingThread: PeerListUpdated
151313 10:13:31.8601562s - PeerPollingThread: WaitTimeout
151313 10:13:31.8601562s - Reachability: Attempting to contact peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123).
151313 10:13:31.8601562s - Polling peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123)
151313 10:13:31.8601562s - Sending packet to time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123) in Win2K detect mode, stage 1.
151313 10:13:31.8601562s - PeerPollingThread: waiting forever
151313 10:13:31.8601562s - PollIntervalChange(time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123)): reclamp: 17 -> 10 (min=4, max=17, sys=10)
151313 10:13:31.8601562s - Peer poll: Max:604800.0000000s (special) Cur:00.0000000s
151313 10:13:31.8601562s - PeerPollingThread: waiting 604800.000s
151313 10:13:31.8611328s - ListeningThread -- DataAvailEvent set for socket 1 (0.0.0.0:123)
151313 10:13:31.8611328s - ListeningThread -- response heard from 191.233.81.105:123 <- 74.200.100.11:123
151313 10:13:31.8611328s - /-- NTP Packet:
151313 10:13:31.8611328s - | LeapIndicator: 0 - no warning; VersionNumber: 3; Mode: 4 - Server; LiVnMode: 0x1C
151313 10:13:31.8611328s - | Stratum: 2 - secondary reference (syncd by (S)NTP)
151313 10:13:31.8611328s - | Poll Interval: 17 - out of valid range; Precision: -22 - 238.419ns per tick
151313 10:13:31.8611328s - | RootDelay: 0x0000.0075s - 0.00178528s; RootDispersion: 0x0000.0375s - 0.013504s
151313 10:13:31.8611328s - | ReferenceClockIdentifier: 0x803B2730 - source IP: 128.59.39.48
151313 10:13:31.8611328s - | ReferenceTimestamp: 0xD8D765EE73DC376E - 13073479790452579000ns - 151313 10:09:50.4525790s
151313 10:13:31.8611328s - | OriginateTimestamp: 0xD8D766CBDC33325C - 13073480011860156200ns - 151313 10:13:31.8601562s
151313 10:13:31.8611328s - | ReceiveTimestamp: 0xD8D766C9D7FC1054 - 13073480009843689900ns - 151313 10:13:29.8436899s
151313 10:13:31.8611328s - | TransmitTimestamp: 0xD8D766C9D7FEF61D - 13073480009843734200ns - 151313 10:13:29.8437342s
151313 10:13:31.8611328s - >-- Non-packet info:
151313 10:13:31.8611328s - | DestinationTimestamp: 151313 10:13:31.8611328s - 0xD8D766CBDC7332FD151313 10:13:31.8611328s - - 13073480011861132800ns151313 10:13:31.8611328s - - 151313 10:13:31.8611328s
151313 10:13:31.8611328s - | RoundtripDelay: 932300ns (0s)
151313 10:13:31.8611328s - | LocalClockOffset: -2016932400ns - 0:02.016932400s
151313 10:13:31.8611328s - \--
151313 10:13:31.8611328s - ListeningThread STC:117175777
151313 10:13:31.8611328s - Peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123) is not Win2K. Setting compat flags.
151313 10:13:31.8611328s - PollIntervalChange(time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123)): peer receive: 0 -> 17
151313 10:13:31.8611328s - Peer poll: Max:604800.0000000s (special) Cur:604799.9990234s
151313 10:13:31.8611328s - Response from peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123), ofs: -02.0169324s
151313 10:13:31.8611328s - 5 Age:5 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:08.0000000s
151313 10:13:31.8611328s - 4 Age:4 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:12.0000000s
151313 10:13:31.8611328s - 3 Age:3 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:14.0000000s
151313 10:13:31.8611328s - 2 Age:2 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.0000000s
151313 10:13:31.8611328s - 1 Age:1 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.5000000s
151313 10:13:31.8611328s - 0 Age:0 Ofs:-02.0169324s Dly:+00.0312500s RDly:+00.0017853s Dsp:00.0156252s RDsp:00.0135040s Pnt:00.0000000s Dst:00.0312502s FDsp:07.7500000s
151313 10:13:31.8611328s - Reachability: peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123) is reachable.
151313 10:13:31.8611328s - Logging information: NtpClient is currently receiving valid time data from time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123).
151313 10:13:31.8611328s - W32TmServiceMain: resync req, user requested, get samples as soon as possible.
151313 10:13:31.8611328s - W32TmServiceMain: waiting i0.000s (1022.499s)
151313 10:13:31.8611328s - W32TmServiceMain: timeout
151313 10:13:31.8611328s - Sample Prepared at 130734800118611328 for peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123)
151313 10:13:31.8611328s - NtpClient returned 1 samples.
151313 10:13:31.8611328s - Sample 0 offset:-02.0169324s delay:+00.0330353s dispersion:07.7791292s
151313 10:13:31.8611328s - Intersection successful with 0 dropped samples.
151313 10:13:31.8611328s - 0: Sample:0 SyncDist:397956468 SelectDisp:0
151313 10:13:31.8611328s - Sample 0 chosen. Select Dispersion:00.0000000s STC:117175777
151313 10:13:31.8611328s - ClockDispln Update: LastUTC:117175777 SO:-20169324 KPhO:0 PhO:-20169324 uT:101Sample was within boundaries, but resync is forced SD:38895646 LI:0 S:3 RDl:330353 RDs:77891292 TSF:0x0 Unset->Hold
151313 10:13:29.8442004s - ClockDispln Discipline: *SET*TIME* - PhCR:56 KPho:-20169324
151313 10:13:29.8442004s - ClockDispln Discipline: *SKEW*TIME* - PhCRR:0 CR:156250 PhCR:56 UI:360000 phcT:101 KPhO:0
151313 10:13:29.8451769s - Logging information: The time service is now synchronizing the system time with the time source time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123).
151313 10:13:29.8451769s - TimeProvCommand([NtpClient], TPC_TimeJumped) called.
151313 10:13:29.8451769s - W32TmServiceMain: waiting 1024.000s
151313 10:13:29.8451769s - W32TmServiceMain: ********** Time Slip Notification **********
151313 10:13:29.8451769s - PeerPollingThread: PeerListUpdated
151313 10:13:29.8451769s - ClockDispln TimeSlip:TimeSlip LastUTC:117175777 SetUnsync: LI:3 S:0 RDl:330353 RDs:77891292 TSF:0x0 ReleaseClock2CMOS
151313 10:13:29.8450000s - PeerPollingThread: waiting 604800.000s
151313 10:13:29.8450000s - TimeProvCommand([NtpClient], TPC_TimeJumped) called.
151313 10:13:29.8450000s - W32TmServiceMain: waiting i16.000s (1024.000s)
151313 10:13:29.8450000s - PeerPollingThread: PeerListUpdated
151313 10:13:29.8459765s - PeerPollingThread: waiting 604800.000s
151313 10:13:29.8459765s - RPC Caller is PC-Name\Administrator (S-1-5-21-3496082489-3062377768-2907400675-500)
151313 10:13:29.8459765s - RPC Call Attribute is local=1, kernel=0, session=0, authentication=6, protocol=3, OpNum=2
151313 10:13:29.8459765s - RPC Call - Query provider status
151313 10:13:29.8459765s - TimeProvCommand([NtpClient], TPC_Query) called.
151313 10:13:29.8469531s - RPC Caller is PC-Name\Administrator (S-1-5-21-3496082489-3062377768-2907400675-500)
151313 10:13:29.8469531s - RPC Call Attribute is local=1, kernel=0, session=0, authentication=6, protocol=2, OpNum=6
151313 10:13:29.8469531s - RPC Call - Query Status
151313 10:13:29.8479296s - W32TimeHandler called: SERVICE_CONTROL_PARAMCHANGE
151313 10:13:29.8489062s - W32TmServiceMain: Param change notification
151313 10:13:29.8489062s - ReadConfig: Found provider 'NtpClient':
151313 10:13:29.8489062s - ReadConfig: 'Enabled'=0x00000001
151313 10:13:29.8489062s - ReadConfig: 'DllName'='%systemroot%\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'InputProvider'=0x00000001
151313 10:13:29.8489062s - ReadConfig: Found provider 'NtpServer':
151313 10:13:29.8489062s - ReadConfig: 'Enabled'=0x00000000
151313 10:13:29.8489062s - ReadConfig: 'DllName'='%systemroot%\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\system32\w32time.dll'
151313 10:13:29.8489062s - ReadConfig: 'InputProvider'=0x00000000
151313 10:13:29.8489062s - ReadConfig: Found provider 'VMICTimeProvider':
151313 10:13:29.8489062s - ReadConfig: 'Enabled'=0x00000001
151313 10:13:29.8489062s - ReadConfig: 'DllName'='%SystemRoot%\System32\vmictimeprovider.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:29.8489062s - ReadConfig: 'DllName'='C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:29.8489062s - ReadConfig: 'InputProvider'=0x00000001
151313 10:13:29.8489062s - ReadConfig: 'PhaseCorrectRate'=0x00000001 (2)
151313 10:13:29.8489062s - ReadConfig: 'UpdateInterval'=0x00057E40 (2)
151313 10:13:29.8489062s - ReadConfig: 'FrequencyCorrectRate'=0x00000004 (2)
151313 10:13:29.8489062s - ReadConfig: 'PollAdjustFactor'=0x00000005 (2)
151313 10:13:29.8489062s - ReadConfig: 'LargePhaseOffset'=0x02FAF080 (2)
151313 10:13:29.8489062s - ReadConfig: 'SpikeWatchPeriod'=0x00000384 (2)
151313 10:13:29.8489062s - ReadConfig: 'HoldPeriod'=0x00000005 (2)
151313 10:13:29.8489062s - ReadConfig: 'MinPollInterval'=0x0000000A (2)
151313 10:13:29.8489062s - ReadConfig: 'MaxPollInterval'=0x0000000F (2)
151313 10:13:29.8489062s - ReadConfig: 'AnnounceFlags'=0x0000000A (2)
151313 10:13:29.8489062s - ReadConfig: 'LocalClockDispersion'=0x0000000A (2)
151313 10:13:29.8489062s - ReadConfig: 'MaxNegPhaseCorrection'=0x0000D2F0 (2)
151313 10:13:29.8489062s - ReadConfig: 'MaxPosPhaseCorrection'=0x0000D2F0 (2)
151313 10:13:29.8489062s - ReadConfig: 'EventLogFlags'=0x00000002 (2)
151313 10:13:29.8489062s - ReadConfig: 'MaxAllowedPhaseOffset'=0x00000001 (2)
151313 10:13:29.8489062s - ReadConfig: 'TimeJumpAuditOffset'=0x00007080 (2)
151313 10:13:29.8489062s - No params changed for local clock.
151313 10:13:29.8489062s - /--TimeProvider: new enabled provider list
151313 10:13:29.8489062s - | Name:NtpClient, Started:0, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:29.8489062s - | Name:VMICTimeProvider, Started:0, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:29.8489062s - >--
151313 10:13:29.8489062s - | Total:2, Input: 2, Marked: 0
151313 10:13:29.8489062s - \--
151313 10:13:29.8489062s - /--TimeProvider: Parameter change before list is updated
151313 10:13:29.8489062s - | Name:NtpClient, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:29.8489062s - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:29.8489062s - >--
151313 10:13:29.8489062s - | Total:2, Input: 2, Marked: 0
151313 10:13:29.8489062s - \--
151313 10:13:29.8489062s - /--TimeProvider: new disabled provider list
151313 10:13:29.8489062s - | Name:NtpServer, Started:0, Input:0, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:29.8489062s - >--
151313 10:13:29.8489062s - | Total:1, Input: 0, Marked: 0
151313 10:13:29.8489062s - \--
151313 10:13:29.8489062s - /--TimeProvider: Parameter change before list is updated
151313 10:13:29.8489062s - | Name:NtpServer, Started:0, Input:0, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:29.8489062s - >--
151313 10:13:29.8489062s - | Total:1, Input: 0, Marked: 0
151313 10:13:29.8489062s - \--
151313 10:13:29.8489062s - TimeProvCommand([NtpClient], TPC_UpdateConfig) called.
151313 10:13:29.8489062s - ReadConfig: 'AllowNonstandardModeCombinations'=0x00000001 (2)
151313 10:13:29.8498828s - ReadConfig: 'CompatibilityFlags'=0x80000000 (2)
151313 10:13:29.8498828s - ReadConfig: 'SpecialPollInterval'=0x00093A80 (2)
151313 10:13:29.8498828s - ReadConfig: 'ResolvePeerBackoffMinutes'=0x0000000F (2)
151313 10:13:29.8498828s - ReadConfig: 'ResolvePeerBackoffMaxTimes'=0x00000007 (2)
151313 10:13:29.8498828s - ReadConfig: 'EventLogFlags'=0x00000001 (2)
151313 10:13:29.8498828s - ReadConfig: 'LargeSampleSkew'=0x00000003 (2)
151313 10:13:29.8498828s - ReadConfig: 'Type'=NTP (2)
151313 10:13:29.8498828s - ReadConfig: 'NtpServer'=time.windows.com,0x9 (2)
151313 10:13:29.8498828s - ReadConfig: 'ManualPeerList'(parsed)='time.windows.com,0x9'
151313 10:13:29.8498828s - ManualPeerListUpdate: add:0 del:0 noch:1
151313 10:13:29.8498828s - StartListeningThread completed!
151313 10:13:29.8498828s - PeerPollingThread: waiting 604799.995s
151313 10:13:29.8498828s - StartPeerPollingThread completed!
151313 10:13:29.8498828s - Provider list: 0 stopped, 0 started, 2 not changed.
151313 10:13:29.8498828s - /--TimeProvider: Parameter change after list is updated
151313 10:13:29.8498828s - | Name:NtpClient, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
151313 10:13:29.8498828s - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:29.8498828s - >--
151313 10:13:29.8498828s - | Total:2, Input: 2, Marked: 0
151313 10:13:29.8498828s - \--
151313 10:13:29.8498828s - W32TmServiceMain: waiting i15.996s (1023.996s)
151313 10:13:30.9075000s - RPC Call - Query provider status
151313 10:13:30.9075000s - TimeProvCommand([NtpClient], TPC_Query) called.
151313 10:13:30.9084765s - RPC Call - Query Status
151313 10:13:30.9094531s - RPC Call - Query provider status
151313 10:13:30.9094531s - TimeProvCommand([NtpClient], TPC_Query) called.
151313 10:13:30.9104296s - RPC Call - Query Status
151313 10:13:36.4602343s - RPC Caller is PC-Name\Administrator (S-1-5-21-3496082489-3062377768-2907400675-500)
151313 10:13:36.4602343s - RPC Call Attribute is local=1, kernel=0, session=0, authentication=6, protocol=3, OpNum=2
151313 10:13:36.4602343s - RPC Call - Query provider status
151313 10:13:36.4602343s - TimeProvCommand([NtpClient], TPC_Query) called.
151313 10:13:36.4612109s - RPC Caller is PC-Name\Administrator (S-1-5-21-3496082489-3062377768-2907400675-500)
151313 10:13:36.4612109s - RPC Call Attribute is local=1, kernel=0, session=0, authentication=6, protocol=2, OpNum=6
151313 10:13:36.4612109s - RPC Call - Query Status
151313 10:13:38.5676562s - W32TimeHandler called: SERVICE_CONTROL_STOP
151313 10:13:38.5676562s - shutdown in service control handler, w/o restart service async151313 10:13:38.5676562s - NotifyShutdown: error = 0
151313 10:13:38.5696093s - Service shutdown initiated with exit code: 0.
151313 10:13:38.5705859s - ClockDisciplineThread: hShutDownEvent signaled. Exiting.
151313 10:13:38.5709766s - RemoveProviderFromList: NtpClient
151313 10:13:38.5709766s - Stopping 'NtpClient', dll:'C:\Windows\system32\w32time.dll'
151313 10:13:38.5709766s - NtpTimeProvClose("0000000000000002") called.
151313 10:13:38.5709766s - NtpTimeProvClose([NtpClient]) called.
151313 10:13:38.5709766s - Reachability: removing peer time.windows.com,0x9 (ntp.m|0x9|0.0.0.0:123->191.233.81.105:123). LAST PEER IN GROUP!
151313 10:13:38.5709766s - StartListeningThread completed!
151313 10:13:38.5709766s - PeerPollingThread: waiting forever
151313 10:13:38.5719531s - PeerPollingThread: PeerListUpdated
151313 10:13:38.5719531s - PeerPollingThread: waiting forever
151313 10:13:38.5719531s - StartPeerPollingThread completed!
151313 10:13:38.5719531s - StopNtpProv
151313 10:13:38.5719531s - ListeningThread: StopEvent
151313 10:13:38.5719531s - PeerPollingThread: StopEvent
151313 10:13:38.5719531s - FreeLibrary dll:C:\Windows\system32\w32time.dll
151313 10:13:38.5719531s - /--TimeProvider: Provider list after the provider is actually removed
151313 10:13:38.5719531s - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:38.5719531s - >--
151313 10:13:38.5719531s - | Total:1, Input: 1, Marked: 0
151313 10:13:38.5719531s - \--
151313 10:13:38.5719531s - RemoveProviderFromList: VMICTimeProvider
151313 10:13:38.5719531s - Stopping 'VMICTimeProvider', dll:'C:\Windows\System32\vmictimeprovider.dll'
151313 10:13:38.5719531s - FreeLibrary dll:C:\Windows\System32\vmictimeprovider.dll
151313 10:13:38.5719531s - /--TimeProvider: Provider list after the provider is actually removed
151313 10:13:38.5719531s - >--
151313 10:13:38.5719531s - | Total:0, Input: 0, Marked: 0
151313 10:13:38.5719531s - \--
151313 10:13:38.5719531s - SetTimeSlipNotification succeeds with 0x00000000.
151313 10:13:38.5719531s - Exiting ServiceShutdown
151313 10:13:38.5719531s - ---------- Log File Closed -----------------