dispatchIncomingCommands warning

KevinB
KevinB
edited December 2012 in Native
Hi,

I am running a bunch of client to stress test the server. and for some clients I am getting a bunch of warning messages like these:

WARNING EnetPeer.cpp dispatchIncomingCommands() line: 306 - do not dispatch if that command is not the very next one available (this is reliable)

what exactly does this mean? and what causes this?

Thanks
K

Comments

  • This means, that from several reliable commands, that are on the way to that client, it has received one, that has been send later, before at least one other reliable command in the same channcel that has been sent earlier. The client lib will hold this command back and not pass it to the according callback, until the one that has been sent earlier, has successfully been received. This guarentees, that the order of reliable commands in the same channel stays intact, so that your logic can rely on it.
    If you see several of these warnings in a very small amount of time, then that can indicate an instable connection, which is about the only reason while this is a warning. If you only get this warning rarely or your game has no better option for bad connections than to live with them, then you can safely ignore the warning.
  • Thanks Kaiserludi,

    This is useful. Is there a document that covers errors or warnings from the photon core? I have seens a couple of other warnings/infos message from the core, and would like to know more details about them.

    for example, here's one
    INFO EnetPeer.cpp dispatchIncomingCommands() line: 314 - skipped dispatching of old command
    what causes this?

    and here's another one
    INFO EnetPeer.cpp sendOutgoingCommands() line: 175 - going to resend pCommand: time: 304 = 300 sentCount: 1, original sentTime: 0
    does it mean it resend the packet because client didn't get a response? what exactly is time: 304 = 300 and original sentTime?

    Thanks,
    K
  • Sorry, I am afraid that debug out is not currently documented.

    The first message means, that the client has already received that command before and has now received it a second time. This can happen, when a reliable command need unusally long to get acknowledged as either the command itself or the acknowledgement has gotten stuck somewhere on the net. It can also happen when the acknoledgement got lost completely. In both cases the sender does not get an ack in a reasonable amount of time in relation to the latency and then resends the command, as it has to assume, that the command got lost. If the retr got lost, another retry-attempt happens and so on until the max retry time or the maxretry amount has been reached for that command. Now if not the command itself but the ack got lost or if the original command has just needed an unusual long time to arrive, but did not get lost, then the receiver will get the same command two times and in that case it print that debugout message.

    The second message is related, but happens on the sender's side: the time limit waiting for an ack for a sent command until it is resent, has been passed, so the sender resends the command, so you have guessed it correctly. First number is the current serverTime, second number is the point in time, when the comannd has been timed out, which is always <= the first time, but rarely equal, as the timeoutchecks will only be made every sendOutgoingCommands call. The last time is the sentTime of the command. For the first try the timeout is sentTime + current roundTripTime, for every retry the timeout gets greater.
    However your nuber look interesting: sendTime 0, roundTripTime 300, both variables have had initialization values, when the original attept to send has been made. Thats strange. When the peer is not connected yet, it should not even try to send.
  • Thanks a lot!

    here's one more, not sure what it means
    WARNING EnetPeer.cpp removeSentReliableCommand() line: 1009 - ACK w/o command! ackReceivedReliableSequenceNumber=42 ackReceivedChannel=255

    on the other hand, in the SERVER log, I have seen log that looks like this
    2012-12-12 04:52:38,367 [35] WARN Photon.SocketServer.PeerBase [(null)] - Disconnecting peer 2140: Unexpected data received
    It sounds like the data is corrupted when it arrived at the server end. Is that what it means? and peer 2140 is the peer connection id from the server point of view. is this connection id available on the client side? I don't seem to be able to find this on the client code.

    K
  • That means, that the clients has received an acknowledgement from the server for a command, that it has never sent. However out of my head I can#t tell, what could cause this.

    Yes, the warning from the server log means, that is has received some illiegal data. This could happen, when for example a client already can handle some datatypes, that have not been implemnted in the server version, that you are using. Aside from that scenario it should only happen, when testing a not yet working client side implemention for some new datatype support, as normally the client will already refuse sending data, thats not supported.

    Please do not rely on the peerID. Its deprecated and only available in the logs, because we have not found the time yet to remove it.
  • Kaiserludi wrote:
    Yes, the warning from the server log means, that is has received some illiegal data. This could happen, when for example a client already can handle some datatypes, that have not been implemnted in the server version, that you are using. Aside from that scenario it should only happen, when testing a not yet working client side implemention for some new datatype support, as normally the client will already refuse sending data, thats not supported.
    interesting... it only happens for us during stress test with approximately 1000 clients. Does Photon's IP layer ensures data packet isn't corrupted before passing to Peerbase?

    here's the corresponding log from the server:
    looks like it happens during decryption of the Authentication request
    [code2=xml]2012-12-13 19:02:50,783 [16] DEBUG OperationData [(null)] - OnReceive - ConnID=3280, data=(106 bytes) F3-06-00-00-01-01-78-00-00-00-5F-8E-39-29-AF-CC-C5-F8-3B-FB-20-54-F3-69-2B-BA-6B-CD-2F-45-CF-B4-62-04-C2-1D-6B-DD-BC-7F-3A-45-21-76-39-DF-7C-1B-82-23-9A-74-3C-E8-09-E2-66-76-51-3A-14-6C-9A-04-08-B8-F1-3D-9F-26-A3-7F-2A-F5-09-2A-10-A1-D5-CD-EB-C4-9E-65-3B-C5-F9-96-C0-6F-73-C7-6D-83-8D-32-6C-99-8B-5F-CE-26-6E-5D-01-81
    2012-12-13 19:02:51,158 [124] DEBUG Photon.SocketServer.PeerBase [(null)] - InitializeEncryption: conId=3280, HashMode=SHA256, Paddin=PKCS7
    2012-12-13 19:02:51,158 [124] DEBUG OperationData [(null)] - SentOpResponse: ConnID=3280, opCode=0, return=0, ChannelId=0, result=Ok, data=(110 bytes) F3-07-00-00-00-2A-00-01-01-78-00-00-00-60-3E-7B-29-84-A6-67-3F-8E-2F-39-5F-0C-FF-DA-E2-C8-6D-D8-F2-C8-91-82-B9-B2-10-DD-F9-A0-1D-42-80-2C-C0-7A-FC-B0-00-CD-01-F9-E3-02-0B-22-16-C8-E0-86-D9-36-A8-8F-7D-9E-27-2F-AA-E3-B9-07-63-40-CC-25-1A-7D-B3-60-C6-72-7D-CE-25-9E-C5-4F-A3-E7-68-54-57-B4-9B-29-81-53-72-36-94-0B-FD-B6-55-9A-79-A8
    2012-12-13 19:02:52,281 [4] DEBUG OperationData [(null)] - OnReceive - ConnID=3280, data=(50 bytes) F3-82-4A-43-0D-54-E4-78-25-E7-09-47-B7-39-6E-39-4B-71-D1-F5-77-D3-35-3A-4B-76-20-13-92-B1-47-FB-C7-8C-F1-A3-31-E8-3B-64-17-F4-0E-D4-CF-43-2C-29-63-CD
    2012-12-13 19:02:53,482 [129] DEBUG Photon.SocketServer.Security.RijndaelCryptoProvider [(null)] - Failed to decrypt data: msg=Padding is invalid and cannot be removed., offset=2, count=48, padding=PKCS7, key=A6-08-8F-8F-07-E8-13-DF-87-73-8E-56-E7-6E-CF-76-CE-15-B4-70-1C-7A-5F-6D-8E-35-41-E3-C5-9C-F2-15, data=F3-82-4A-43-0D-54-E4-78-25-E7-09-47-B7-39-6E-39-4B-71-D1-F5-77-D3-35-3A-4B-76-20-13-92-B1-47-FB-C7-8C-F1-A3-31-E8-3B-64-17-F4-0E-D4-CF-43-2C-29-63-CD
    2012-12-13 19:02:53,482 [129] DEBUG Photon.SocketServer.PeerBase [(null)] - Failed to parse operation request for peer with connection id 3280.
    2012-12-13 19:02:53,482 [129] WARN Photon.SocketServer.PeerBase [(null)] - Disconnecting peer 3280: Unexpected data received[/code2]

    is there a way to enable more debug log of the photon core in c++ client code? Thanks.

    K
  • You can set the debug level with PhotonPeer::setDebugOutputLevel().