14:42:30:   -> Server trace started.
14:42:30:   -> Tracelevel set to 0.  PID is 732
14:42:30:   -> Session ID is 2dc596e64a67489
14:42:30:   -> Session time is Tue Jul 18 19:42:30 2017
14:42:30: S -> Server was compiled May 31 2017 06:12:55
14:42:30: S -> Server was compiled with MSVC C/C++ 1310
14:42:30: S -> Server build platform is microsoft-windows-x86
14:42:30: S -> Server: CVSNT 2.8.01 (Soolin) Build 6332
14:42:30: S -> main - SYSTEM_INITIALIZE begin
14:42:30: S -> Domain found: DELTA
14:42:30: S -> CVS Server 'D-W2012X64-M' is acting as member of domain 'DELTA' (D-w2012x64-M.delta.starrettlab.net)
14:42:30: S -> Build version is CVSNT 2.8.01 (Soolin) Build 6332
14:42:30: S -> User name is SYSTEM
14:42:30: S -> Server running on "Windows Server 2012 x64 Server 4.0  (Build 9200) [6.2.9200] "
14:42:30: S -> /3GB is enabled, highest user address is fffeffff
14:42:30: S -> Server has      31 percent of memory in use.
14:42:30: S -> Server has 2096628 total Kbytes of physical memory*.
14:42:30: S -> Server has 1445176 free Kbytes of physical memory*.
14:42:30: S -> Server has 2096628 total Kbytes of physical memory.
14:42:30: S -> Server has 1445176 free Kbytes of physical memory.
14:42:30: S -> Server has 2489844 total Kbytes of paging file.
14:42:30: S -> Server has 1890372 free Kbytes of paging file.
14:42:30: S -> Server has 4194176 total Kbytes of virtual memory.
14:42:30: S -> Server has 4135176 free Kbytes of virtual memory.
14:42:30: S -> Server has       0 free Kbytes of extended memory.
14:42:30: S -> The custom heap has the low-fragmentation heap enabled.
14:42:30: S -> The minimum large page size is 2097152.
14:42:30: S -> Walking heap 0X00CE0000...
14:42:30: S -> Region
14:42:30: S ->   4096 bytes committed
14:42:30: S ->   258048 bytes uncommitted
14:42:30: S ->   First block address: 0X00CE04A0
14:42:30: S ->   Last block address: 0X00D1F000
14:42:30: S ->   Data portion begins at: 0X00CE0000
14:42:30: S ->   Size: 1176 bytes
14:42:30: S ->   Overhead: 0 bytes
14:42:30: S ->   Region index: 0
14:42:30: S -> Block
14:42:30: S ->   Data portion begins at: 0X00CE05B0
14:42:30: S ->   Size: 2608 bytes
14:42:30: S ->   Overhead: 16 bytes
14:42:30: S ->   Region index: 0
14:42:30: S -> Uncommitted range
14:42:30: S ->   Data portion begins at: 0X00CE1000
14:42:30: S ->   Size: 253952 bytes
14:42:30: S ->   Overhead: 0 bytes
14:42:30: S ->   Region index: 0
14:42:30: S -> Server Hardware information (Wow64): 
14:42:30: S ->   Number of processors: 2
14:42:30: S ->   Processor type: 8664
14:42:30: S ->   processor architecture: x64
14:42:30: S ->   processor type 8664/Xeon model: unknown
14:42:30: S -> Free space in C:\CVSTEMP 2998198272
14:42:30: S -> Total space in C:\CVSTEMP 4292866048
14:42:30: S -> Total Free space in C:\CVSTEMP 2998198272
14:42:30: S -> main - SYSTEM_INITIALIZE compelted
14:42:30: S -> main - server active in C:\Windows\system32
14:42:30: S -> main - before cvsrc command: server
14:42:30: S -> Server: call the requested function preload
14:42:30: S -> Socket instantiated: -1
14:42:30: S -> Socket instantiated: -1
14:42:30: S -> Socket for preload server 548,
14:42:30: S -> Socket for preload server 560,
14:42:30: S -> Socket for preload proxy 564,
14:42:30: S -> Socket for preload proxy 568,
14:42:30: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
14:42:30: S -> Loading protocol enum as enum.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/enum.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol ext as ext.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ext.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol fork as fork.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/fork.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol gserver as gserver.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/gserver.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol pserver as pserver.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/pserver.dll
14:42:30: S -> get_interface(pserver) - shouldn't this initialise verify_only (0)?
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol server as server.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/server.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol sserver as sserver.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sserver.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol ssh as ssh.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/ssh.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol sspi as sspi.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sspi.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> Loading protocol sync as sync.dll
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/protocols/sync.dll
14:42:30: S -> Library reference count set to 1.
14:42:30: S -> LoadTrigger(info.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/info.dll
14:42:30: S -> LoadTrigger(audit.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/audit.dll
14:42:30: S -> Audit trigger not enabled.
14:42:30: S -> LoadTrigger(bugzilla.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/bugzilla.dll
14:42:30: S -> Defect Tracking trigger not enabled (preinit).
14:42:30: S -> LoadTrigger(checkout.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/checkout.dll
14:42:30: S -> LoadTrigger(email.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/email.dll
14:42:30: S -> LoadTrigger(make.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/make.dll
14:42:30: S -> Make trigger is not enabled (preinit fail).
14:42:30: S -> LoadTrigger(script.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/script.dll
14:42:30: S -> LoadTrigger(sync.dll)
14:42:30: S -> CLibraryAccess::Load loading C:\PROGRA~2\CVSSUI~1\CVSNT/triggers/sync.dll
14:42:30: S -> Opened Semaphore OK.
14:42:30: S -> Heap Allocated OK with size=0 serialised
14:42:30: S -> Triggers and Protocols loaded.  Waiting for connect. Interval=3000
14:42:30: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:33: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:33: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:36: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:36: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:39: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:39: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:42: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:42: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:45: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:45: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:48: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:48: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:51: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:51: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:54: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:54: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:42:57: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:42:57: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:00: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:00: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:03: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:03: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:06: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:06: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:09: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:09: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:12: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:12: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:15: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:15: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:18: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:18: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:21: S -> Select socket done found zero (0) something(s) to connect with (timeout=3000msec)?
14:43:21: S -> wait for 2|2 socket(s) timeout=3000msec using WIN32 method!
14:43:24: S -> Select socket found 1 something(s) to connect with (timeout=3000msec)?
14:43:24: S -> Select wait for semaphore max time 3000msec
14:43:24: S -> Select semaphore signalled OK
14:43:24: S -> Select tcp socket try and WSAAccept()
14:43:24: S -> Socket instantiated: 488
14:43:24: S -> Released Semaphore OK -- means it is ready for other new connections.
14:43:24: S -> Select socket continue
14:43:24: S -> Select wait for semaphore max time 3000msec
14:43:24: S -> Select semaphore signalled OK
14:43:24: S -> Select tcp socket try and WSAAccept()
14:43:24: S -> WSAAccept() returned INVALID_SOCKET
14:43:24: S -> Released Semaphore OK -- means it is ready for other new connections.
14:43:24: S -> Select socket continue
14:43:24: S -> Select socket done
14:43:24: S -> run_preload - auth
14:43:24: S -> Session (real) time is Tue Jul 18 19:43:24 2017
14:43:24: S -> run_preload: decision point auth or no auth
14:43:24: S -> Authenticating: perform reverse DNS lookup
14:43:28: S -> Authenticating: remote 192.168.248.203
14:43:28: S -> If nt_setuid() is called then:
14:43:28: S ->   windows privilege: SeCreateTokenPrivilege = nt_setuid will enable
14:43:28: S ->   windows privilege: SeImpersonatePrivilege = do nothing
14:43:28: S ->   windows privilege: SeCreateGlobalPrivilegev = do nothing
14:43:28: S ->   windows privilege: SeAssignPrimaryTokenPrivilege = do nothing
14:43:28: S ->   windows privilege: SeTcbPrivilege = do nothing
14:43:28: S ->   windows privilege: SeSecurityPrivilege = do nothing
14:43:28: S -> If nt_s4u() is called then:
14:43:28: S ->   windows privilege: SeCreateTokenPrivilege = do nothing
14:43:28: S ->   windows privilege: SeImpersonatePrivilege = do nothing
14:43:28: S ->   windows privilege: SeCreateGlobalPrivilegev = do nothing
14:43:28: S ->   windows privilege: SeAssignPrimaryTokenPrivilege = do nothing
14:43:28: S ->   windows privilege: SeTcbPrivilege = nt_s4u will enable
14:43:28: S ->   windows privilege: SeSecurityPrivilege = do nothing
14:43:28: S -> During win32switchtouser() do:
14:43:28: S ->   [SwitchToUserSuid] trysuid() called if trys4u() returns -1
14:43:28: S ->   [SwitchToUserToken] trytoken() called if trysuid() returns -1
14:43:28: S -> io_getline received "BEGIN SSL VERIFICATION REQUEST".
14:43:28: S -> server_authenticate_connection: Client sent 'BEGIN SSL VERIFICATION REQUEST'
14:43:28: S -> FindPrototocol(BEGIN SSL VERIFICATION REQUEST)
14:43:28: S -> EnumerateProtocols: C:\PROGRA~2\CVSSUI~1\CVSNT/protocols
14:43:28: S -> enum protocol library reference count set to 2.
14:43:28: S -> Checking protocol enum
14:43:28: S ->    - Not this one..
14:43:28: S -> UnloadProtocol enum
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> ext protocol library reference count set to 2.
14:43:28: S -> Checking protocol ext
14:43:28: S ->    - Not a server protocol..
14:43:28: S -> UnloadProtocol ext
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> fork protocol library reference count set to 2.
14:43:28: S -> Checking protocol fork
14:43:28: S ->    - Not a server protocol..
14:43:28: S -> UnloadProtocol fork
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> gserver protocol library reference count set to 2.
14:43:28: S -> Checking protocol gserver
14:43:28: S -> gserver_auth_protocol_connect()
14:43:28: S ->    - Not this one..
14:43:28: S -> UnloadProtocol gserver
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> pserver protocol library reference count set to 2.
14:43:28: S -> Checking protocol pserver
14:43:28: S ->    - Not this one..
14:43:28: S -> UnloadProtocol pserver
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> server protocol library reference count set to 2.
14:43:28: S -> Checking protocol server
14:43:28: S ->    - Not a server protocol..
14:43:28: S -> UnloadProtocol server
14:43:28: S -> UnloadProtocol reference count still too high
14:43:28: S -> UnloadProtocol complete
14:43:28: S -> sserver protocol library reference count set to 2.
14:43:28: S -> Checking protocol sserver
14:43:28: S -> SSERVER:auth_protocol_connect() certs="C:\PROGRA~2\CVSSUI~1\CVSNT/ca.pem" auth_string="BEGIN SSL VERIFICATION REQUEST"
14:43:28: S -> SSERVER:auth_protocol_connect() Unable to set auth sserver socket to non-blocking.
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_library_init()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSLeay_version()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSLeay_version() "OpenSSL 1.1.0b  26 Sep 2016".
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_load_error_strings()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_new()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_set_options()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_load_verify_locations()
14:43:28: S -> SSERVER:auth_protocol_connect() -- ERR_get_error() -- Clear error stack
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_use_certificate_file()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_use_PrivateKey_file()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_check_private_key()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_set_verify()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_CTX_set_cipher_list() ciphers="HIGH:!EXPORT"
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_new()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_set_rfd()
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_set_wfd()
14:43:28: S -> SSERVER:auth_protocol_connect() -- set_encrypted_channel(1)
14:43:28: S -> SSERVER:auth_protocol_connect() -- SSL_accept()
14:43:29: S -> SSERVER:auth_protocol_connect() -- SSL_get_verify_result()
14:43:29: S -> SSERVER:auth_protocol_connect() -- SSL_get_peer_certificate()
14:43:29: S -> SSERVER:auth_protocol_connect() -- SSL_get_current_cipher()
14:43:29: S -> SSERVER:auth_protocol_connect() -- SSL_get_current_cipher() name="AES256-SHA" 256/0 bits "SSLv3".
14:43:29: S -> SSERVER:auth_protocol_connect() -- SSL_get_current_cipher() description="AES256-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(256)  Mac=SHA1
".
14:43:29: S -> SSERVER:auth_protocol_connect() user="D-W2012X64-M\muser2" password="A******"
14:43:29: S -> FindProtocol: Correctly authenticated [badauth=false]
14:43:29: S -> (2)server_authenticate_connection: authenticated [badauth=false]
14:43:29: S -> (2)server_authenticate_connection: authenticated [badauth=false]
14:43:29: S -> server_authenticate_connection: xfree (tmp)
14:43:29: S -> (2)server_authenticate_connection: xfree (tmp)
14:43:29: S -> server_authenticate_connection: temp_protocol = NULL
14:43:29: S -> (2)server_authenticate_connection: temp_protocol = NULL
14:43:29: S -> Authentication protocol :sserver: returned user D-W2012X64-M\muser2
14:43:29: S -> (2)Authentication protocol returned user(D-W2012X64-M\muser2)
14:43:29: S -> win32_sanitize_username(D-W2012X64-M\muser2)
14:43:29: S -> win32_sanitize_username(done)=D-W2012X64-M\muser2
14:43:29: S -> wnt_fopen('C:/PROGRA~3/MARCHH~1/myrepo/CVSROOT/config','r')
14:43:29: S -> wnt_fopen('C:/PROGRA~3/MARCHH~1/myrepo/CVSROOT/config','r') returns 7c3ab6b8
14:43:29: S -> check_password(D-W2012X64-M\muser2,password,C:/PROGRA~3/MARCHH~1/myrepo)
14:43:29: S -> check_repository_password(D-W2012X64-M\muser2,password,C:/PROGRA~3/MARCHH~1/myrepo)
14:43:29: S -> wnt_fopen('C:/PROGRA~3/MARCHH~1/myrepo/CVSROOT/passwd','r')
14:43:29: S -> wnt_fopen('C:/PROGRA~3/MARCHH~1/myrepo/CVSROOT/passwd','r') returns 7c3ab6b8
14:43:29: S -> check_repository_password - found : non-system user, with bad password
14:43:29: S -> LogonUser() general error 0000052e
14:43:29: S ->  : The user name or password is incorrect.


14:43:29: S -> User in CVSROOT/passwd, but password incorect
14:43:29: S -> Host user not set - login fail
14:43:29: S -> I HATE YOU
14:43:29: S -> error_exit() - are we here due to a connection timeout?
14:43:29: S -> Unloading checkout.dll
14:43:29: S -> Unloading - about to destroy
14:43:29: S -> Unloading - destroyed
14:43:29: S -> Unloading - about to get lib
14:43:29: S -> Unloading - about to unload checkout.dll
14:43:29: S -> Unloading - unloaded
14:43:29: S -> Unloading - about to free
14:43:29: S -> Unloading - about to delete trigg
14:43:29: S -> Unloading - about to delete inf
14:43:29: S -> Unloading - complete
14:43:29: S -> Unloading email.dll
14:43:29: S -> Unloading - about to destroy
14:43:29: S -> Unloading - destroyed
14:43:29: S -> Unloading - about to get lib
14:43:29: S -> Unloading - about to unload email.dll
14:43:29: S -> Unloading - unloaded
14:43:29: S -> Unloading - about to free
14:43:29: S -> Unloading - about to delete trigg
14:43:29: S -> Unloading - about to delete inf
14:43:29: S -> Unloading - complete
14:43:29: S -> Unloading info.dll
14:43:29: S -> Unloading - about to destroy
14:43:29: S -> Unloading - destroyed
14:43:29: S -> Unloading - about to get lib
14:43:29: S -> Unloading - about to unload info.dll
14:43:29: S -> Unloading - unloaded
14:43:29: S -> Unloading - about to free
14:43:29: S -> Unloading - about to delete trigg
14:43:29: S -> Unloading - about to delete inf
14:43:29: S -> Unloading - complete
14:43:29: S -> Unloading script.dll
14:43:29: S -> Unloading - about to destroy
14:43:29: S -> Unloading - destroyed
14:43:29: S -> Unloading - about to get lib
14:43:29: S -> Unloading - about to unload script.dll
14:43:29: S -> Unloading - unloaded
14:43:29: S -> Unloading - about to free
14:43:29: S -> Unloading - about to delete trigg
14:43:29: S -> Unloading - about to delete inf
14:43:29: S -> Unloading - complete
14:43:29: S -> Unloading sync.dll
14:43:29: S -> Unloading - about to destroy
14:43:29: S -> Unloading - destroyed
14:43:29: S -> Unloading - about to get lib
14:43:29: S -> Unloading - about to unload sync.dll
14:43:29: S -> Unloading - unloaded
14:43:29: S -> Unloading - about to free
14:43:29: S -> Unloading - about to delete trigg
14:43:29: S -> Unloading - about to delete inf
14:43:29: S -> Unloading - complete
14:43:29: S -> Unloading - about to clear list
14:43:29: S -> Unloading - cleared list
14:43:29: S -> SSERVER:auth_protocol_connect() Unable to set sserver socket to non-blocking on shutdown.
14:43:29: S -> Server finishing, server_cleanup() calls UnloadProtocol(server)
14:43:29: S -> UnloadProtocol sserver
14:43:29: S -> UnloadProtocol reference count still too high
14:43:29: S -> UnloadProtocol complete