10:01:10:   -> Server trace started.
10:01:10:   -> Tracelevel set to 0.  PID is 2996
10:01:10:   -> Session ID is bb4508970566163
10:01:10:   -> Session time is Thu Oct 25 17:01:10 2012
10:01:10: S -> Server was compiled Jul 17 2012 10:40:37
10:01:10: S -> Server was compiled with MSVC C/C++ 1310
10:01:10: S -> Server build platform is microsoft-windows-x86
10:01:10: S -> Server: CVSNT 2.8.01 (Soolin) Build 4588
10:01:10: S -> main - SYSTEM_INITIALIZE begin
10:01:11: S -> CVS Server is acting as standalone
10:01:11: S -> Build version is CVSNT 2.8.01 (Soolin) Build 4588
10:01:11: S -> User name is CVSMANAGER_USER
10:01:11: S -> Server running on "Windows 7 x64 Service Pack 1 (Build 7601) [6.1.7601] (Service Pack 1)"
10:01:11: S -> /3GB is enabled, highest user address is fffeffff
10:01:11: S -> Server has      28 percent of memory in use.
10:01:11: S -> Server has 2096696 total Kbytes of physical memory*.
10:01:11: S -> Server has 1501284 free Kbytes of physical memory*.
10:01:11: S -> Server has 2096696 total Kbytes of physical memory.
10:01:11: S -> Server has 1501284 free Kbytes of physical memory.
10:01:11: S -> Server has 4193392 total Kbytes of paging file.
10:01:11: S -> Server has 3374940 free Kbytes of paging file.
10:01:11: S -> Server has 4194176 total Kbytes of virtual memory.
10:01:11: S -> Server has 4134212 free Kbytes of virtual memory.
10:01:11: S -> Server has       0 free Kbytes of extended memory.
10:01:11: S -> The custom heap has the low-fragmentation heap enabled.
10:01:11: S -> The minimum large page size is 2097152.
10:01:11: S -> Walking heap 0X012B0000...
10:01:11: S -> Region
10:01:11: S ->   49152 bytes committed
10:01:11: S ->   212992 bytes uncommitted
10:01:11: S ->   First block address: 0X012B0598
10:01:11: S ->   Last block address: 0X012F0000
10:01:11: S ->   Data portion begins at: 0X012B0000
10:01:11: S ->   Size: 1416 bytes
10:01:11: S ->   Overhead: 0 bytes
10:01:11: S ->   Region index: 0
10:01:11: S -> Block
10:01:11: S ->   Data portion begins at: 0X012BB040
10:01:11: S ->   Size: 4000 bytes
10:01:11: S ->   Overhead: 16 bytes
10:01:11: S ->   Region index: 0
10:01:11: S -> Uncommitted range
10:01:11: S ->   Data portion begins at: 0X012BC000
10:01:11: S ->   Size: 212992 bytes
10:01:11: S ->   Overhead: 0 bytes
10:01:11: S ->   Region index: 0
10:01:11: S -> Server Hardware information (Wow64): 
10:01:11: S ->   Number of processors: 1
10:01:11: S ->   Processor type: 8664
10:01:11: S ->   processor architecture: x64
10:01:11: S ->   processor type 8664/Xeon model: unknown
10:01:11: S -> Free space in C:\test 1823571968
10:01:11: S -> Total space in C:\test 4292866048
10:01:11: S -> Total Free space in C:\test 1823571968
10:01:11: S -> main - SYSTEM_INITIALIZE compelted
10:01:11: S -> main - server active in C:\Windows\system32
10:01:11: S -> main - before cvsrc command: server
10:01:11: S -> Server: call the requested function preload
10:01:11: S -> Socket instantiated: -1
10:01:11: S -> Socket instantiated: -1
10:01:11: S -> Socket for preload server 400,
10:01:11: S -> Socket for preload server 404,
10:01:11: S -> Socket for preload proxy 408,
10:01:11: S -> Socket for preload proxy 412,
10:01:11: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
10:01:11: S -> Loading protocol enum as enum.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/enum.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol ext as ext.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ext.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol fork as fork.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/fork.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol gserver as gserver.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/gserver.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol pserver as pserver.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/pserver.dll
10:01:11: S -> get_interface(pserver) - shouldn't this initialise verify_only (0)?
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol server as server.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/server.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol sserver as sserver.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sserver.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol ssh as ssh.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ssh.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol sspi as sspi.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sspi.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> Loading protocol sync as sync.dll
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sync.dll
10:01:11: S -> Library reference count set to 1.
10:01:11: S -> LoadTrigger(info.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/info.dll
10:01:11: S -> LoadTrigger(audit.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/audit.dll
10:01:11: S -> Audit trigger not enabled.
10:01:11: S -> LoadTrigger(bugzilla.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/bugzilla.dll
10:01:11: S -> Defect Tracking trigger not enabled.

10:01:11: S -> LoadTrigger(checkout.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/checkout.dll
10:01:11: S -> LoadTrigger(email.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/email.dll
10:01:11: S -> LoadTrigger(make.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/make.dll
10:01:11: S -> LoadTrigger(script.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/script.dll
10:01:11: S -> LoadTrigger(sync.dll)
10:01:11: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/sync.dll
10:01:11: S -> Opened Semaphore OK.
10:01:11: S -> Heap Allocated OK with size=0 serialised
10:01:11: S -> Triggers and Protocols loaded.  Waiting for connect. Interval=3000
10:01:11: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:01:14: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:01:14: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:01:17: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
10:01:17: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
10:01:18: S -> Select socket found 1 something(s) to connect with (timeout=3000msec)?
10:01:18: S -> Select wait for semaphore max time 3000msec
10:01:18: S -> Select semaphore signalled OK
10:01:18: S -> Select tcp socket try and WSAAccept()
10:01:18: S -> Socket instantiated: 524
10:01:18: S -> Released Semaphore OK -- means it is ready for other new connections.
10:01:18: S -> Select socket continue
10:01:18: S -> Select wait for semaphore max time 3000msec
10:01:18: S -> Select semaphore signalled OK
10:01:18: S -> Select tcp socket try and WSAAccept()
10:01:18: S -> WSAAccept() returned INVALID_SOCKET
10:01:18: S -> Released Semaphore OK -- means it is ready for other new connections.
10:01:18: S -> Select socket continue
10:01:18: S -> Select socket done
10:01:18: S -> run_preload - auth
10:01:18: S -> Session (real) time is Thu Oct 25 17:01:18 2012
10:01:18: S -> run_preload: decision point auth or no auth
10:01:18: S -> Authenticating: perform reverse DNS lookup
10:01:18: S -> Authenticating: remote EUROPA
10:01:18: S -> io_getline received "BEGIN SSL AUTH REQUEST".
10:01:18: S -> server_authenticate_connection: Client sent 'BEGIN SSL AUTH REQUEST'
10:01:18: S -> FindPrototocol(BEGIN SSL AUTH REQUEST)
10:01:18: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
10:01:18: S -> enum protocol library reference count set to 2.
10:01:18: S -> Checking protocol enum
10:01:18: S ->    - Not this one..
10:01:18: S -> UnloadProtocol enum
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> ext protocol library reference count set to 2.
10:01:18: S -> Checking protocol ext
10:01:18: S ->    - Not a server protocol..
10:01:18: S -> UnloadProtocol ext
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> fork protocol library reference count set to 2.
10:01:18: S -> Checking protocol fork
10:01:18: S ->    - Not a server protocol..
10:01:18: S -> UnloadProtocol fork
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> gserver protocol library reference count set to 2.
10:01:18: S -> Checking protocol gserver
10:01:18: S -> gserver_auth_protocol_connect()
10:01:18: S ->    - Not this one..
10:01:18: S -> UnloadProtocol gserver
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> pserver protocol library reference count set to 2.
10:01:18: S -> Checking protocol pserver
10:01:18: S ->    - Not this one..
10:01:18: S -> UnloadProtocol pserver
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> server protocol library reference count set to 2.
10:01:18: S -> Checking protocol server
10:01:18: S ->    - Not a server protocol..
10:01:18: S -> UnloadProtocol server
10:01:18: S -> UnloadProtocol reference count still too high
10:01:18: S -> UnloadProtocol complete
10:01:18: S -> sserver protocol library reference count set to 2.
10:01:18: S -> Checking protocol sserver
10:01:18: S -> SSERVER:auth_protocol_connect() certs="C:\PROGRA~2\CVSSUI~1\CVSNT/ca.pem" auth_string="BEGIN SSL AUTH REQUEST"
10:01:18: S -> SSERVER:auth_protocol_connect() Unable to set auth sserver socket to non-blocking.
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_library_init()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_load_error_strings()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_new()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_set_options()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_load_verify_locations()
10:01:18: S -> SSERVER:auth_protocol_connect() -- ERR_get_error() -- Clear error stack
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_use_certificate_file()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_use_PrivateKey_file()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_check_private_key()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_set_verify()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_new()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_set_rfd()
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_set_wfd()
10:01:18: S -> SSERVER:auth_protocol_connect() -- set_encrypted_channel(1)
10:01:18: S -> SSERVER:auth_protocol_connect() -- SSL_accept()
10:01:19: S -> SSERVER:auth_protocol_connect() -- SSL_get_verify_result()
10:01:19: S -> SSERVER:auth_protocol_connect() -- SSL_get_peer_certificate()
10:01:19: S -> SSERVER:auth_protocol_connect() user="Glen Starrett" password="A******"
10:01:19: S -> FindProtocol: Correctly authenticated [badauth=false]
10:01:19: S -> (2)server_authenticate_connection: authenticated [badauth=false]
10:01:19: S -> (2)server_authenticate_connection: authenticated [badauth=false]
10:01:19: S -> server_authenticate_connection: xfree (tmp)
10:01:19: S -> (2)server_authenticate_connection: xfree (tmp)
10:01:19: S -> server_authenticate_connection: temp_protocol = NULL
10:01:19: S -> (2)server_authenticate_connection: temp_protocol = NULL
10:01:19: S -> Authentication protocol :sserver: returned user Glen Starrett
10:01:19: S -> (2)Authentication protocol returned user(Glen Starrett)
10:01:19: S -> win32_sanitize_username(Glen Starrett)
10:01:19: S -> check_password(Glen Starrett,password,C:/PROGRA~3/MARCHH~1/myrepo)
10:01:19: S -> check_repository_password(Glen Starrett,password,C:/PROGRA~3/MARCHH~1/myrepo)
10:01:19: S -> Checking password using passwd/shadow files
10:01:19: S -> win32getpwnam(Glen Starrett)
10:01:19: S -> Find netapi32.dll with the symbol DsGetDcNameW
10:01:19: S -> Call GetComputerNameW
10:01:19: S -> Authenticating server: (local)
10:01:19: S -> NetUserGetInfo returned NERR_UserNotFound - failing
10:01:19: S -> Host user not set - login fail
10:01:19: S -> I HATE YOU
10:01:19: S -> error_exit() - are we here due to a connection timeout?
10:01:19: S -> Unloading checkout.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading email.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading info.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading make.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading script.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading sync.dll
10:01:19: S -> Unloading - about to destroy
10:01:19: S -> Unloading - destroyed
10:01:19: S -> Unloading - about to get lib
10:01:19: S -> Unloading - about to unload
10:01:19: S -> Unloading - unloaded
10:01:19: S -> Unloading - about to free
10:01:19: S -> Unloading - about to delete trigg
10:01:19: S -> Unloading - about to delete inf
10:01:19: S -> Unloading - complete
10:01:19: S -> Unloading - about to clear list
10:01:19: S -> Unloading - cleared list
10:01:19: S -> SSERVER:auth_protocol_connect() Unable to set sserver socket to non-blocking on shutdown.
10:01:19: S -> Server finishing, server_cleanup() calls UnloadProtocol(server)
10:01:19: S -> UnloadProtocol sserver
10:01:19: S -> UnloadProtocol reference count still too high
10:01:19: S -> UnloadProtocol complete