Distributed: ONetworkProtocolBinary

[nethertek]

We've run into a strange where records do not replicate in distributed mode. The only hint that something is wrong is when we see WARNI Cannot serialize record: 1 [ONetworkProtocolBinary] in the logs.

Trying to debug the problem, I've come across the following values:

2015-10-17 15:44:58:564 INFO /127.0.0.1:47358 - Read 100 bytes: 1com.orientechnologies.orient.core.sql.OCommandSQL'UPDATE #18:0 SET last_seen = 1445096698 [OChannelBinaryServer]
2015-10-17 15:44:58:635 INFO /127.0.0.1:47358 - Writing byte (1 byte): 0 [OChannelBinaryServer]
2015-10-17 15:44:58:635 INFO /127.0.0.1:47358 - Writing int (4 bytes): 2 [OChannelBinaryServer]
2015-10-17 15:44:58:635 INFO /127.0.0.1:47358 - Writing byte (1 byte): 108 [OChannelBinaryServer]
2015-10-17 15:44:58:635 INFO /127.0.0.1:47358 - Writing int (4 bytes): 1 [OChannelBinaryServer]
2015-10-17 15:44:58:636 WARNI Cannot serialize record: 1 [ONetworkProtocolBinary]
2015-10-17 15:44:58:636 INFO /127.0.0.1:47358 - Writing short (2 bytes): -2 [OChannelBinaryServer]
2015-10-17 15:44:58:636 INFO /127.0.0.1:47358 - Flush [OChannelBinaryServer]
2015-10-17 15:44:58:636 INFO /127.0.0.1:47358 - Reading byte (1 byte)... [OChannelBinaryServer]
2015-10-17 15:44:58:637 INFO /127.0.0.1:47358 - Read byte: 5 [OChannelBinaryServer]
2015-10-17 15:44:58:637 INFO /127.0.0.1:47358 - Reading int (4 bytes)... [OChannelBinaryServer]
2015-10-17 15:44:58:639 INFO /127.0.0.1:47358 - Read int: 2 [OChannelBinaryServer]
2015-10-17 15:44:58:639 INFO /127.0.0.1:47358 - Reading byte (1 byte)... [OChannelBinaryServer]
2015-10-17 15:44:58:639 INFO /127.0.0.1:47358 - Flush [OChannelBinaryServer]
2015-10-17 15:44:58:639 INFO /127.0.0.1:47358 - Closing socket... [OChannelBinaryServer]

The same query as comparison in single mode:
2015-10-17 15:58:02:749 INFO /127.0.0.1:47523 - Read 100 bytes: 1com.orientechnologies.orient.core.sql.OCommandSQL'UPDATE #18:0 SET last_seen = 1445097482 [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Writing byte (1 byte): 0 [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Writing int (4 bytes): 5 [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Writing byte (1 byte): 97 [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Writing string (4+1=5 bytes): 1 [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Flush [OChannelBinaryServer]
2015-10-17 15:58:02:751 INFO /127.0.0.1:47523 - Reading byte (1 byte)... [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Read byte: 5 [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Reading int (4 bytes)... [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Read int: 5 [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Reading byte (1 byte)... [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Flush [OChannelBinaryServer]
2015-10-17 15:58:02:752 INFO /127.0.0.1:47523 - Closing socket... [OChannelBinaryServer]

I am unable to pinpoint the problem. We've seen these errors arise since version 2.1.x, including the latest 2.1.4

[nethertek]

I dug around a little more and found more helpful information (Both versions were the same prior to executing the UPDATE):

2015-10-17 17:59:11:412 WARNI Cannot serialize record: 1 [ONetworkProtocolBinary]
2015-10-17 17:59:11:412 FINE Disconnecting connection with id=9 [OClientConnectionManager]
2015-10-17 17:59:11:412 FINE Disconnected connection with id=9 but are present other active channels [OClientConnectionManager]
2015-10-17 17:59:11:413 FINE Disconnecting connection OClientConnection [id=9, source=?, since=1445104751099]... [OClientConnectionManager]
2015-10-17 17:59:11:413 FINE Disconnected connection OClientConnection [id=9, source=?, since=1445104751099] found 0 channels [OClientConnectionManager]
2015-10-17 17:59:11:989 FINE [server1]->[[server2]] sending request id=146 from=server1 task=record_update(#32:0 v.10) [OHazelcastDistributedDatabase]
2015-10-17 17:59:12:221 FINE [server1]->[[server2]] sent request id=146 from=server1 task=record_update(#32:0 v.10) [OHazelcastDistributedDatabase]
2015-10-17 17:59:12:351 FINE [server1]<-[server2] received response 'com.orientechnologies.orient.core.exception.OConcurrentModificationException: Cannot UPDATE the record #32:0 because the version is not the latest. Probably you are updating an old record or it has been modified by another user (db=v9 your=v10)' for request (id=146 from=server1 task=record_update(#32:0 v.10)) (receivedCurrentNode=false receivedResponses=1 expectedSynchronousResponses=1 quorum=1) [ODistributedResponseManager]
2015-10-17 17:59:16:256 FINE [OClientConnectionManager] found and removed pending closed channel 8 (null) [OClientConnectionManager]

[lvca]

OConcurrentModificationException exception is normal and must be managed by your application. Look at: http://orientdb.com/docs/last/Concurrency.html

[nethertek]

Whilst this error does not appear after reimporting the databases, it is not a concurrent modification by our application. According to the logs, it is clearly a replication issue inside OrientDB.

I will update this issue when the problem reappears.

[lvca]

Do you have any news?

[nethertek]

This is related to #5249.