Jump to content

Server Errors Log ERROR Channel


SilverKnight

Recommended Posts

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

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

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

Archived

This topic is now archived and is closed to further replies.

×
×
  • Create New...