10:32:28:   -> Server trace started.
10:32:28:   -> Tracelevel set to 0.  PID is 1800
10:32:28:   -> Session ID is 7085c37739c0109
10:32:28:   -> Session time is Thu Jan 10 16:32:28 2019
10:32:28: S -> Server was compiled Aug  3 2018 06:36:02
10:32:28: S -> Server was compiled with MSVC C/C++ 1310
10:32:28: S -> Server build platform is microsoft-windows-x86
10:32:28: S -> Server: CVSNT 2.8.01 (Soolin) Build 6795
10:32:28: S -> main - SYSTEM_INITIALIZE begin
10:32:28: S -> CVS Server 'W7X64' is acting as standalone
10:32:28: S -> Build version is CVSNT 2.8.01 (Soolin) Build 6795
10:32:28: S -> User name is CVSMANAGER_USER
10:32:28: S -> Server running on "Windows 7 x64 Service Pack 1 (Build 7601) [6.1.7601] "
10:32:28: S -> /3GB is enabled, highest user address is fffeffff
10:32:28: S -> Server has      30 percent of memory in use.
10:32:28: S -> Server has 4193848 total Kbytes of physical memory*.
10:32:28: S -> Server has 2918064 free Kbytes of physical memory*.
10:32:28: S -> Server has 4193848 total Kbytes of physical memory.
10:32:28: S -> Server has 2918064 free Kbytes of physical memory.
10:32:28: S -> Server has 8385792 total Kbytes of paging file.
10:32:28: S -> Server has 6859316 free Kbytes of paging file.
10:32:28: S -> Server has 4194176 total Kbytes of virtual memory.
10:32:28: S -> Server has 4133800 free Kbytes of virtual memory.
10:32:28: S -> Server has       0 free Kbytes of extended memory.
10:32:28: S -> The custom heap has the low-fragmentation heap enabled.
10:32:28: S -> The minimum large page size is 2097152.
10:32:28: S -> Walking heap 0X014E0000...
10:32:28: S -> Region
10:32:28: S ->   90112 bytes committed
10:32:28: S ->   172032 bytes uncommitted
10:32:28: S ->   First block address: 0X014E0590
10:32:28: S ->   Last block address: 0X01520000
10:32:28: S ->   Data portion begins at: 0X014E0000
10:32:28: S ->   Size: 1416 bytes
10:32:28: S ->   Overhead: 0 bytes
10:32:28: S ->   Region index: 0
10:32:28: S -> Block
10:32:28: S ->   Data portion begins at: 0X014F4C88
10:32:28: S ->   Size: 4952 bytes
10:32:28: S ->   Overhead: 16 bytes
10:32:28: S ->   Region index: 0
10:32:28: S -> Uncommitted range
10:32:28: S ->   Data portion begins at: 0X014F6000
10:32:28: S ->   Size: 172032 bytes
10:32:28: S ->   Overhead: 0 bytes
10:32:28: S ->   Region index: 0
10:32:28: S -> Server Hardware information (Wow64): 
10:32:28: S ->   Number of processors: 2
10:32:28: S ->   Processor type: 8664
10:32:28: S ->   processor architecture: x64
10:32:28: S ->   processor type 8664/Xeon model: unknown
10:32:28: S -> Free space in C:\Windows\TEMP\ 1908363264
10:32:28: S -> Total space in C:\Windows\TEMP\ 4292866048
10:32:28: S -> Total Free space in C:\Windows\TEMP\ 1908363264
10:32:28: S -> main - SYSTEM_INITIALIZE compelted
10:32:28: S -> main - server active in C:\Windows\system32
10:32:28: S -> main - before cvsrc command: server
10:32:28: S -> Server: call the requested function preload
10:32:28: S -> Socket instantiated: -1
10:32:28: S -> Socket instantiated: -1
10:32:28: S -> Socket for preload server 436,
10:32:28: S -> Socket for preload server 424,
10:32:28: S -> Socket for preload proxy 440,
10:32:28: S -> Socket for preload proxy 444,
10:32:28: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
10:32:28: S -> Loading protocol enum as enum.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/enum.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol ext as ext.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ext.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol fork as fork.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/fork.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol gserver as gserver.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/gserver.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol pserver as pserver.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/pserver.dll
10:32:28: S -> get_interface(pserver) - shouldn't this initialise verify_only (0)?
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol server as server.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/server.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol sserver as sserver.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sserver.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol ssh as ssh.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ssh.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol sspi as sspi.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sspi.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> Loading protocol sync as sync.dll
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sync.dll
10:32:28: S -> Library reference count set to 1.
10:32:28: S -> LoadTrigger(info.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/info.dll
10:32:28: S -> LoadTrigger(audit.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/audit.dll
10:32:28: S -> Audit trigger not enabled.
10:32:28: S -> LoadTrigger(bugzilla.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/bugzilla.dll
10:32:28: S -> Defect Tracking trigger not enabled (preinit).
10:32:28: S -> LoadTrigger(checkout.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/checkout.dll
10:32:28: S -> LoadTrigger(email.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/email.dll
10:32:28: S -> LoadTrigger(make.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/make.dll
10:32:28: S -> Make trigger is not enabled (preinit fail).
10:32:28: S -> LoadTrigger(script.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/script.dll
10:32:28: S -> LoadTrigger(sync.dll)
10:32:28: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/sync.dll
10:32:28: S -> Opened Semaphore OK.
10:32:28: S -> Heap Allocated OK with size=0 serialised
10:32:28: S -> Triggers and Protocols loaded.  Waiting for connect. Interval=3000
10:32:28: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:31: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:31: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:34: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:34: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:37: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:37: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:40: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:40: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:43: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:43: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:46: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:46: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:49: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:49: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:52: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:52: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:55: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:55: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:32:58: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:32:58: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:01: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:01: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:04: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:04: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:07: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:07: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:10: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:10: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:13: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:13: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:16: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:16: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:19: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:19: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:22: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:22: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:25: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:25: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:28: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:33:28: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:33:28: S -> Select socket found 1 something(s) to connect with (timeout=3000msec)?
10:33:28: S -> Select wait for semaphore max time 3000msec
10:33:28: S -> Select semaphore signalled OK
10:33:28: S -> Select tcp socket try and WSAAccept()
10:33:28: S -> Socket instantiated: 584
10:33:28: S -> Released Semaphore OK -- means it is ready for other new connections.
10:33:28: S -> Select socket continue
10:33:28: S -> Select wait for semaphore max time 3000msec
10:33:28: S -> Select semaphore signalled OK
10:33:28: S -> Select tcp socket try and WSAAccept()
10:33:28: S -> WSAAccept() returned INVALID_SOCKET
10:33:28: S -> Released Semaphore OK -- means it is ready for other new connections.
10:33:28: S -> Select socket continue
10:33:28: S -> Select socket done
10:33:28: S -> run_preload - auth
10:33:28: S -> Session (real) time is Thu Jan 10 16:33:28 2019
10:33:28: S -> run_preload: decision point auth or no auth
10:33:28: S -> Authenticating: perform reverse DNS lookup
10:33:28: S -> Authenticating: remote JUPITER
10:33:28: S -> If nt_setuid() is called then:
10:33:28: S ->   windows privilege: SeCreateTokenPrivilege = nt_setuid will enable
10:33:28: S ->   windows privilege: SeImpersonatePrivilege = do nothing
10:33:28: S ->   windows privilege: SeCreateGlobalPrivilegev = do nothing
10:33:28: S ->   windows privilege: SeAssignPrimaryTokenPrivilege = do nothing
10:33:28: S ->   windows privilege: SeTcbPrivilege = do nothing
10:33:28: S ->   windows privilege: SeSecurityPrivilege = do nothing
10:33:28: S -> If nt_s4u() is called then:
10:33:28: S ->   windows privilege: SeCreateTokenPrivilege = do nothing
10:33:28: S ->   windows privilege: SeImpersonatePrivilege = do nothing
10:33:28: S ->   windows privilege: SeCreateGlobalPrivilegev = do nothing
10:33:28: S ->   windows privilege: SeAssignPrimaryTokenPrivilege = do nothing
10:33:28: S ->   windows privilege: SeTcbPrivilege = nt_s4u will enable
10:33:28: S ->   windows privilege: SeSecurityPrivilege = do nothing
10:33:28: S -> During win32switchtouser() do:
10:33:28: S ->   [SwitchToUserSuid] trysuid() called if trys4u() returns -1
10:33:28: S ->   [SwitchToUserToken] trytoken() called if trysuid() returns -1
10:33:28: S -> io_getline received "BEGIN SSPI".
10:33:28: S -> server_authenticate_connection: Client sent 'BEGIN SSPI'
10:33:28: S -> FindPrototocol(BEGIN SSPI)
10:33:28: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
10:33:28: S -> enum protocol library reference count set to 2.
10:33:28: S -> Checking protocol enum
10:33:28: S ->    - Not this one..
10:33:28: S -> UnloadProtocol enum
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> ext protocol library reference count set to 2.
10:33:28: S -> Checking protocol ext
10:33:28: S ->    - Not a server protocol..
10:33:28: S -> UnloadProtocol ext
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> fork protocol library reference count set to 2.
10:33:28: S -> Checking protocol fork
10:33:28: S ->    - Not a server protocol..
10:33:28: S -> UnloadProtocol fork
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> gserver protocol library reference count set to 2.
10:33:28: S -> Checking protocol gserver
10:33:28: S -> gserver_auth_protocol_connect()
10:33:28: S ->    - Not this one..
10:33:28: S -> UnloadProtocol gserver
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> pserver protocol library reference count set to 2.
10:33:28: S -> Checking protocol pserver
10:33:28: S ->    - Not this one..
10:33:28: S -> UnloadProtocol pserver
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> server protocol library reference count set to 2.
10:33:28: S -> Checking protocol server
10:33:28: S ->    - Not a server protocol..
10:33:28: S -> UnloadProtocol server
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> sserver protocol library reference count set to 2.
10:33:28: S -> Checking protocol sserver
10:33:28: S ->    - Not this one..
10:33:28: S -> UnloadProtocol sserver
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> ssh protocol library reference count set to 2.
10:33:28: S -> Checking protocol ssh
10:33:28: S ->    - Not a server protocol..
10:33:28: S -> UnloadProtocol ssh
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> sspi protocol library reference count set to 2.
10:33:28: S -> Checking protocol sspi
10:33:28: S -> SSPI:ServerAuthenticate(Negotiate) AcquireCredentialsHandle
10:33:28: S -> SSPI:ServerAuthenticate() AcquireCredentialsHandle result = OK
10:33:28: S -> SSPI:ServerAuthenticate() AcceptSecurityContext
10:33:28: S -> SSPI:ServerAuthenticate() AcceptSecurityContext
10:33:28: S -> SSPI:ServerAuthenticate() (rc<0) [80090301] The handle specified is invalid


10:33:28: S -> FindProtocol: !CVSPROTO_NOTME && !CVSPROTO_NOTIMP
10:33:28: S -> FindProtocol: Authentication protocol rejected access
10:33:28: S -> UnloadProtocol sspi
10:33:28: S -> UnloadProtocol reference count still too high
10:33:28: S -> UnloadProtocol complete
10:33:28: S -> (2)server_authenticate_connection: authenticated [badauth=false]
10:33:28: S -> (2)server_authenticate_connection: authenticated [badauth=false]
10:33:28: S -> Couldn't find a matching authentication protocol
10:33:28: S -> (2)Couldn't find a matching authentication protocol
10:33:28: S -> error_exit() - are we here due to a connection timeout?
10:33:28: S -> Unloading checkout.dll
10:33:28: S -> Unloading - about to destroy
10:33:28: S -> Unloading - destroyed
10:33:28: S -> Unloading - about to get lib
10:33:28: S -> Unloading - about to unload checkout.dll
10:33:28: S -> Unloading - unloaded
10:33:28: S -> Unloading - about to free
10:33:28: S -> Unloading - about to delete trigg
10:33:28: S -> Unloading - about to delete inf
10:33:28: S -> Unloading - complete
10:33:28: S -> Unloading email.dll
10:33:28: S -> Unloading - about to destroy
10:33:28: S -> Unloading - destroyed
10:33:28: S -> Unloading - about to get lib
10:33:28: S -> Unloading - about to unload email.dll
10:33:28: S -> Unloading - unloaded
10:33:28: S -> Unloading - about to free
10:33:28: S -> Unloading - about to delete trigg
10:33:28: S -> Unloading - about to delete inf
10:33:28: S -> Unloading - complete
10:33:28: S -> Unloading info.dll
10:33:28: S -> Unloading - about to destroy
10:33:28: S -> Unloading - destroyed
10:33:28: S -> Unloading - about to get lib
10:33:28: S -> Unloading - about to unload info.dll
10:33:28: S -> Unloading - unloaded
10:33:28: S -> Unloading - about to free
10:33:28: S -> Unloading - about to delete trigg
10:33:28: S -> Unloading - about to delete inf
10:33:28: S -> Unloading - complete
10:33:28: S -> Unloading script.dll
10:33:28: S -> Unloading - about to destroy
10:33:28: S -> Unloading - destroyed
10:33:28: S -> Unloading - about to get lib
10:33:28: S -> Unloading - about to unload script.dll
10:33:28: S -> Unloading - unloaded
10:33:28: S -> Unloading - about to free
10:33:28: S -> Unloading - about to delete trigg
10:33:28: S -> Unloading - about to delete inf
10:33:28: S -> Unloading - complete
10:33:28: S -> Unloading sync.dll
10:33:28: S -> Unloading - about to destroy
10:33:28: S -> Unloading - destroyed
10:33:28: S -> Unloading - about to get lib
10:33:28: S -> Unloading - about to unload sync.dll
10:33:28: S -> Unloading - unloaded
10:33:28: S -> Unloading - about to free
10:33:28: S -> Unloading - about to delete trigg
10:33:28: S -> Unloading - about to delete inf
10:33:28: S -> Unloading - complete
10:33:28: S -> Unloading - about to clear list
10:33:28: S -> Unloading - cleared list
10:33:28: S -> Server finishing, server_cleanup() calls UnloadProtocol(server)
10:33:28: S -> UnloadProtocol none