Brekeke SIP Proxy Server Version 3- major bug

29 posts · Brekeke SIP Server Forum

Izzyg 2015-07-08 12:21 UTC Original post

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 2015-07-08 17:05 UTC

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 2015-07-08 17:10 UTC

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 2015-07-08 17:41 UTC

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

Izzyg 2015-07-08 18:26 UTC

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

snuyzm 2015-07-08 19:24 UTC

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 2015-07-15 18:59 UTC

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 2015-07-15 23:45 UTC

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

Can you paste an OPTIONS packet here?

Izzyg 2015-07-16 03:52 UTC

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 2015-07-16 05:58 UTC

Are there any errors around at that time?

You can check errors in Error Logs page.

Izzyg 2015-07-16 12:11 UTC

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 2015-07-16 16:40 UTC

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

Can you post the DialPlan rule "_OPTIONS" ?

Izzyg 2015-07-16 17:24 UTC

$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 2015-07-16 18:06 UTC

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

Izzyg 2015-07-16 18:32 UTC

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 2015-07-16 20:48 UTC

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 2015-07-16 21:52 UTC

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 2015-07-17 00:07 UTC

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 2015-07-17 01:24 UTC

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 2015-07-17 03:29 UTC

did you disable Windows Time service?

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

Izzyg 2015-07-17 03:35 UTC

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 2015-07-17 05:58 UTC

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 2015-07-17 15:14 UTC

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 2015-07-17 18:13 UTC

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

Izzyg 2015-07-17 18:17 UTC

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 -----------------

snuyzm 2015-07-23 18:30 UTC

Izzyg,
do you have any updates?
does the problem still happen?

Izzyg 2015-07-23 19:43 UTC

yes it still happened, July 21 is last time it happened

snuyzm 2015-07-24 17:58 UTC

Are you using a 3rd party database? or Radius?

Izzyg 2015-07-24 18:26 UTC

this issue was happening when i was NOT using any third pparty DB or radius

and is still happening even when i use a mysql db