Connection timeout issue

[sajid2045]

On 2.1.1,
I can see occasional errors on orient server logs.
2015-09-02 17:51:50:482 FINE Found unknown session 146, shutdown current connection [ONetworkProtocolBinary]Error during closing of output stream
java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at java.io.DataOutputStream.flush(DataOutputStream.java:123)
at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinary.close(OChannelBinary.java:406)
at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.shutdown(OBinaryNetworkProtocolAbstract.java:114)
at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.shutdown(ONetworkProtocolBinary.java:148)
at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.sendError(ONetworkProtocolBinary.java:879)
at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:216)
at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:77)
Suppressed: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
at java.io.FilterOutputStream.close(FilterOutputStream.java:159)

[tglman]

Hi @sajid2045,

This is normal if there is some client terminate without a proper shutdown or if there's some connection problem, it's not an issue is standard logging in this cases.

If this happen a lot, i would suggest to check the network infrastructure.

[sajid2045]

Hi @tglman ,

All the operation are running within same Virtual LAN and possibility of packet loss is very low. After running all night, I can see the error is happening for every request, looks like the connection is being reset every time. And it looks like the error is coming from the client side. The error goes away on a client restart and stays ok for a while. Again, this has become very very critical and we need to resolve this as soon as possible. Also, because the connections needs to be reset, the response time increase to the factor of 100.

[2015-09-03 10:02:01,119] [get testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Caught I/O errors from Not connected (local socket=?), trying to reconnec
t (error: java.io.IOException: Channel is closed)
[2015-09-03 10:02:01,428] [get testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Connection re-acquired transparently after 235ms and 1 retries to server
'fsasydgrhdb01.foxsports.com.au:2424/subscription-service': no errors will be thrown at application level
[2015-09-03 10:02:01,680] [get testabcd] [INFO] [au.com.foxsports.subscription.service.SubscriptionServiceImpl:1142] [findVertexByProperty] [serviceName:SubscriptionService]=> [--: load(Device) v(Device)[#43:282]
took: 698 ms
[2015-09-03 10:02:10,642] [get testabcd] [DEBUG] [au.com.foxsports.subscription.service.SubscriptionServiceImpl:177] [getByUniqueDocumentId] [serviceName:SubscriptionService]=> Loaded: testabcd -> #62:58
[2015-09-03 10:02:10,676] [get testabcd] [DEBUG] [au.com.foxsports.subscription.service.SubscriptionServiceImpl:159] [get] [serviceName:SubscriptionService]=> [eventType:GET_BY_SUBSCRIPTION_ID] [subscriptionId:test
abcd] [time:9695]
[2015-09-03 10:02:13,689] [update testabcd] [INFO] [au.com.foxsports.subscription.api.Subscriptions:72] [logStash] [serviceName:SubscriptionService]=> [event:UPDATE] [subscriptionId=testabcd] [subscriptionType=android] [uniqueUserId=testabcd] [subscriptions=[Subscription [topic=/test/sports/league/series/1/teams/55017, events=[gamedue, score, closegame, video, news]], Subscription [topic=/test/sports/league/series/18/teams/55017, events=[gamedue, score, closegame, video, news]], Subscription [topic=/test/sports/league/series/23/teams/55011, events=[gamedue, score, closegame, video]], Subscription [topic=/test/sports/cricket/series/34/teams/60003, events=[gamedue, wicket, century, fulltime, closegame, video]], Subscription [topic=/test/sports/league/series/23/teams/55017, events=[gamedue, score, closegame, video, news]], Subscription [topic=/test/sports/league/series/1/teams/55008, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]], Subscription [topic=/test/sports/rugby/series/7/teams/50053, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]], Subscription [topic=/test/sports/league/series/1/teams/55011, events=[gamedue, score, closegame, video]], Subscription [topic=/test/sports/league/series/23/teams/55010, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]], Subscription [topic=/test/sports/cricket/series/8/teams/60003, events=[gamedue, wicket, century, fulltime, closegame, video]], Subscription [topic=/test/sports/afl/series/2/teams/20001, events=[lineups, gamedue, goal, 1quarter, halftime, 3quarter, fulltime, closegame, video, news]], Subscription [topic=/test/sports/league/series/1/teams/55010, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]], Subscription [topic=/test/sports/afl/series/1/teams/20001, events=[lineups, gamedue, goal, 1quarter, halftime, 3quarter, fulltime, closegame, video, news]], Subscription [topic=/test/sports/cricket/series/25/teams/60003, events=[gamedue, wicket, century, fulltime, closegame, video]], Subscription [topic=/test/sports/rugby/series/7/teams/50063, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]], Subscription [topic=/test/sports/football/series/30/teams/60247, events=[gamedue, goal, shootout, closegame, video]], Subscription [topic=/test/sports/football/series/22/teams/60247, events=[gamedue, goal, shootout, closegame, video]], Subscription [topic=/test/sports/cricket/series/26/teams/60003, events=[gamedue, wicket, century, fulltime, closegame, video]], Subscription [topic=/test/sports/league/series/23/teams/55008, events=[lineups, gamedue, score, halftime, fulltime, extratime, closegame, video, news]]]] [ignores=[Subscription [topic=/test/sports/afl/series/1/matches/afl20120105, events=[]], Subscription [topic=/test/sports/football/series/6/matches/epl2014-151602chehul, events=[]]]]
[2015-09-03 10:02:13,807] [update testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Caught I/O errors from Not connected (local socket=?), trying to reconnect (error: java.io.IOException: Channel is closed)

[2015-09-03 10:02:14,029] [update testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Connection re-acquired transparently after 169ms and 1 retries to server 'fsasydgrhdb01.foxsports.com.au:2424/subscription-service': no errors will be thrown at application level
[2015-09-03 10:02:14,343] [update testabcd] [INFO] [au.com.foxsports.subscription.service.SubscriptionServiceImpl:395] [update] [serviceName:SubscriptionService]=> [event:UPDATE_SUB_DOC] [time:652]
[2015-09-03 10:02:14,343] [update testabcd] [DEBUG] [org.mule.api.processor.LoggerMessageProcessor$LogLevel$4:188] [log] [serviceName:SubscriptionService]=> #62:58
[2015-09-03 10:02:14,514] [GraphConnectionLogger] [INFO] [au.com.foxsports.subscription.utils.GraphConnectionPool$1:82] [run] [serviceName:SubscriptionService]=> [event:CONNECTION_STAT] [created:111] [free:101]
[2015-09-03 10:02:17,473] [get testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Caught I/O errors from Not connected (local socket=?), trying to reconnect (error: java.io.IOException: Channel is closed)
[2015-09-03 10:02:17,717] [get testabcd] [WARN] [com.orientechnologies.common.log.OLogManager:140] [log] [serviceName:SubscriptionService]=> Connection re-acquired transparently after 169ms and 1 retries to server 'fsasydgrhdb01.foxsports.com.au:2424/subscription-service': no errors will be thrown at application level
[2015-09-03 10:02:17,870] [get testabcd] [INFO] [au.com.foxsports.subscription.service.SubscriptionServiceImpl:1142] [findVertexByProperty] [serviceName:SubscriptionService]=> [--: load(Device) v(Device)[#43:282] took: 494 ms

[sajid2045]

PS: also note, I ran a separate client instance pointing to the same server and it ran without any problem.

[gChurchel]

For what it's worth: I was getting the same error and resolved it by updating the server. I had version 2.1.3 installed as the server and 2.2.7 installed on the client. After installing 2.2.7 on the server the problem went away.