Chaneru Log Data for Monday November 26, 2012
16:57:34.660 * Chaneru start vers 2.0
.. Removed log entries
16:57:43.745 1273 roSocketEvent UDP Chaneru
16:57:43.758 Received Chaneru message: ???.???.???.???:??? <- No from address ???????
NOTIFY * HTTP/1.1
.. Removed log entries
16:58:05.739 10912 roSocketEvent UDP Chaneru
16:58:05.775 Received Chaneru message: 192.168.1.11:55388
NOTIFY * HTTP/1.1
.. Removed log entries
16:58:24.131 29300 roSocketEvent UDP Chaneru
16:58:24.159 Received Chaneru message: 192.168.1.11:54780
NOTIFY * HTTP/1.1
.. Removed log entries
16:58:46.558 4161 roSocketEvent UDP Chaneru
16:58:46.602 Received Chaneru message: 192.168.1.11:63371
NOTIFY * HTTP/1.1
.. Removed log entries
16:58:46.885 4481 roSocketEvent UDP Chaneru
16:58:46.922 ********************************************
16:58:46.944 ********** MSG isReadable() failed *********
16:58:46.995 ********************************************
* Here I did a socket.close() and reinitialized a new one with same port
* The following shows that the events were queued to the old socket because I couldn't find the socket ID
16:58:47.032 4629 roSocketEvent Unknown ?
16:58:47.049 4647 roSocketEvent Unknown ?
16:58:47.067 4671 roSocketEvent Unknown ?
16:58:47.083 4687 roSocketEvent Unknown ?
*
* Removed 800 duplicate lines
*
16:59:16.418 34021 roSocketEvent Unknown ?
16:59:16.433 34037 roSocketEvent Unknown ?
16:59:16.444 34048 roSocketEvent Unknown ?
16:59:16.456 34059 roSocketEvent Unknown ?
* This continued for over 20 seconds
* Before reallocating the socket, I would get the isReadable() failure.
.. Removed log entries
* This shows that the socket reallocation worked !
16:59:20.885 38479 roSocketEvent UDP Chaneru
16:59:20.908 Received Chaneru message: ???.???.???.???:??? <- No from address ???????
NOTIFY * HTTP/1.1
.. Removed log entries
16:59:23.750 41353 roSocketEvent UDP Chaneru
16:59:23.769 Received Chaneru message: 192.168.1.11:56778
NOTIFY * HTTP/1.1
.. Removed log entries
16:59:43.777 61378 roSocketEvent UDP Chaneru
16:59:43.799 Received Chaneru message: 192.168.1.11:60090
NOTIFY * HTTP/1.1
"destruk" wrote:He's the Chaneru dev.
Ask Chaneru?
I haven’t seen a problem like this. Just from this developer’s self-logging and comments, I can only guess at potential problems and workarounds. In particular I don’t have any good guess as to whether this is a script or firmware bug. It might even be both.
I’d be curious which notify*() calls he has made on the problematic socket.
It seems like sometimes the socket that is the subject of the message flood has been removed from the developer’s map of active sockets, but hasn’t been completely deleted.
One possibility is that he has removed the socket from his own map but still has a reference to it somewhere, so it really is still around and remains readable when he returns to the wait loop, so it interrupts again. Of course this doesn’t explain why isReadable() would return false.
Of course it’s also quite possible there is just a bug in the roSockets code or even lower in the firmware.
This sounds a little like the normal operation of a connected socket that is closed on the other end: to become readable with a 0 byte count which must actually be read, or the socket might stay readable. This developer reports using UDP, so this is not likely the direct issue here, but it may provide a hint as to a firmware bug.
Some potential diagnostics/workarounds to try:
Keep all the obsolete sockets in a separate map and check them, too, when a socket fails to be found in the active map. One interesting thing to note might be whether an obsolete socket id matches an active socket id. That could potentially explain isReadable() on the active socket returning false when it’s actually the (supposedly) inactive socket that’s generating the message. Duplicate socket IDs would indicate a firmware bug, but one for which there is probably a reasonable defensive strategy for the script.
Log the weirdness, like receiving a message indicating activity on a socket where the socket’s isReadable() nevertheless returns false, and try a read() of 0 (or maybe 1) bytes anyway.
Try automatically closing/deleting/recreating the socket if the weirdness count exceeds a few dozen.
Is it possible that the server really is sending a zero byte UDP message? If this even flies with UDP, it would still indicate a firmware bug in not handling it correctly, but there could be workarounds on both the server (don’t send 0 byte messages) and the client (read regardless of isReadable() when a message is received).
I’d be curious which notify*() calls he has made on the problematic socket.
It seems like sometimes the socket that is the subject of the message flood has been removed from the developer’s map of active sockets, but hasn’t been completely deleted.
Log the weirdness, like receiving a message indicating activity on a socket where the socket’s isReadable() nevertheless returns false, and try a read() of 0 (or maybe 1) bytes anyway.
Try automatically closing/deleting/recreating the socket if the weirdness count exceeds a few dozen.
Is it possible that the server really is sending a zero byte UDP message? If this even flies with UDP, it would still indicate a firmware bug in not handling it correctly, but there could be workarounds on both the server (don’t send 0 byte messages) and the client (read regardless of isReadable() when a message is received).