SilverKnight Posted May 18, 2018 Report Share Posted May 18, 2018 Client/Server Version: 7.0.16.2123 We have had several instances of the client hanging when attempting to contact the Plastic Server, and in looking at the logs, I've noticed every connection attempt from every user appears to be logging to the plastic.errors.log.txt file, even though some requests actually function without hanging. Most of the "errors" appear like this 2018-05-18 10:05:44,738 ERROR Channel - conn 27. AuthenticateConnection 15 ms 2018-05-18 10:05:45,310 ERROR Channel - conn 28. AuthenticateConnection 0 ms 2018-05-18 10:08:42,999 ERROR Channel - conn 30. AuthenticateConnection 0 ms I wouldn't expect the error log to continuously grow with errors like this while presenting the client fully functional and no indication of a problem. It seems like this may be due to the new plastic protocol switch that happened in the 7.0 branch becoming the default communications layer. Has anyone else noticed this odd behavior with logging enabled on the server end? Is it possible the clients are attempting the old protocol first, failing, then switching to the new one where it succeeds, thus the client doesn't report a problem, but the server logs the invalid first attempt? Link to comment Share on other sites More sharing options...
psantosl Posted May 18, 2018 Report Share Posted May 18, 2018 Hi @SilverKnight If I'm not mistaken, the new plasticprotocol started being default in 6.0. Now, the old remoting protocol is only the default if your clients are too old, or if they have a plasticpipeprotocol.conf file, which I doubt. Check the debug log to see more info of these errors, let's see if we find out what is going on. pablo Link to comment Share on other sites More sharing options...
SilverKnight Posted May 18, 2018 Author Report Share Posted May 18, 2018 I think when I had 6 installed, I configured it to try out the new protocol (when it wasn't default), my workstation had the plasticpipeprotocol.conf - but I deleted that when I upgraded to a client that was supposed to default to using it. The baffling thing is, there isn't any more detail in the error log file - this is the last line in that log - and they show up in relations to machines that never had the plasticpipeprotocol.conf on them. 2018-05-18 13:08:43,840 ERROR Channel - conn 50. AuthenticateConnection 0 ms The corresponding entry from plastic.channelcall.log.txt 2018-05-18 13:08:43,901 INFO ChannelCall - conn: 50 protocol:plasticproto recb: 449|rect: 62|sentb: 356|sendt: 0|queuedt: 0|prt: 15|th: 36|dest: 0|mt: 0|sert: 0|zip: 0|cpu: 0| 10.1.2.1|user::S-1-5-21-3872667650-2442655954-3868439105-1147|GetLiceseData Similar data in the plastic.realtime.requests.log.txt 2018-05-18 13:08:43,837 Enqueued new work. Enqueued: 1 Worker threads: 3 (3 free) 2018-05-18 13:08:43,837 There are 3 free threads - not starting a new one. Enqueued: 1 2018-05-18 13:08:43,838 Request dequeued. It was waiting for 00:00:00.0010010. Queued requests: 0. Id: 36 2018-05-18 13:08:43,901 conn: 50 protocol:plasticproto recb: 449|rect: 62|sentb: 356|sendt: 0|queuedt: 0|prt: 15|th: 36|dest: 0|mt: 0|sert: 0|zip: 0|cpu: 0| 10.1.2.1|user::S-1-5-21-3872667650-2442655954-3868439105-1147|GetLiceseData Here is the corresponding time from the plastic.debug.log.txt - which seems to indicate everything is functioning just fine - 2018-05-18 13:08:43,829 S-16 DEBUG Channel - conn 50 - [protocol ssl:// port 8088] - accepted 2018-05-18 13:08:43,830 S-16 DEBUG Channel - conn 50. ReceiveAsync 2018-05-18 13:08:43,830 S-16 DEBUG Channel - [protocol ssl:// port 8088] - Waiting to accept connection 2018-05-18 13:08:43,837 A-29 DEBUG Channel - conn 50. awaked. total 1 2018-05-18 13:08:43,837 A-29 DEBUG WorkerThreadPool - Enqueued new work. Enqueued: 1 Worker threads: 3 (3 free) 2018-05-18 13:08:43,837 A-29 DEBUG WorkerThreadPool - There are 3 free threads - not starting a new one. Enqueued: 1 2018-05-18 13:08:43,838 W-36 DEBUG WorkerThreadPool - Request dequeued. It was waiting for 00:00:00.0010010. Queued requests: 0. Id: 36 2018-05-18 13:08:43,838 W-36 DEBUG WorkerThread - WorkerThread.Run: Work retrieved. Id: 36. 2999057 ms 2018-05-18 13:08:43,840 W-36 ERROR Channel - conn 50. AuthenticateConnection 0 ms 2018-05-18 13:08:43,891 W-36 DEBUG Channel - conn 50. Will be handled by PlasticProto 2018-05-18 13:08:43,899 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.UserCredentials.Mode ADWorkingMode 2018-05-18 13:08:43,899 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.UserCredentials.User.Data S-1-5-21-3872667650-2442655954-3868439105-1147 2018-05-18 13:08:43,899 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.Organization 2018-05-18 13:08:43,899 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.MachineName RELLIMK 2018-05-18 13:08:43,900 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.SecurityCtx ctxNormal 2018-05-18 13:08:43,900 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.CurrentTransaction 00000000-0000-0000-0000-000000000000 2018-05-18 13:08:43,900 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG PlasticProto.ConnectionFromClient - conn 50. mInitialCmCallContext.Version 5.4.16.0 2018-05-18 13:08:43,901 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK INFO Operations - Retrieving server license data 2018-05-18 13:08:43,901 W-36 00000000-0000-0000-0000-000000000000 S-1-5-21-3872667650-2442655954-3868439105-1147 RELLIMK DEBUG Transaction - Commiting implicit transaction 2018-05-18 13:08:43,901 NetworkThread-27 DEBUG PlasticProto.ConnectionFromClient - conn 50. ReceiveAsync 2018-05-18 13:08:43,901 W-36 INFO ChannelCall - conn: 50 protocol:plasticproto recb: 449|rect: 62|sentb: 356|sendt: 0|queuedt: 0|prt: 15|th: 36|dest: 0|mt: 0|sert: 0|zip: 0|cpu: 0| 10.1.2.1|user::S-1-5-21-3872667650-2442655954-3868439105-1147|GetLiceseData 2018-05-18 13:08:43,902 W-36 DEBUG WorkerThread - WorkerThread.Run: Going to GetWork. Id: 36 The question is, why is it dumping that line to the error log - when there doesn't appear to actually be a problem - of if there is actually a problem, what do I need to do to resolve it? My co-worker had a newer version of the client installed - to resolve the hang, he completely uninstalled the client, deleted the %appdata% plastic file stuff for preferences, then re-installed. The new installed instance no longer hangs -- he didn't have an older 6.x client version installed - he started with the 7.0.16.x version - so no possibility of having had the plasticpipeprotocol.conf file on that machine. However, when using the client, it still logs these events to the error log as if there is still some sort of problem. We are using the SSL / 8088 connection type - and I think we did end up having the Plastic server generate a new certificate than we had been using during our last upgrade - could this have something to do with the certificates? (They were accepted and stored on the end point, and we don't get a prompt when connecting or giving any indication there is a cert problem) Link to comment Share on other sites More sharing options...
psantosl Posted May 21, 2018 Report Share Posted May 21, 2018 We'll double check, but it can be simply a log issue, I believe. Link to comment Share on other sites More sharing options...
Recommended Posts
Archived
This topic is now archived and is closed to further replies.