Roku Developer Program

[greubel]

Every once in a while I get streaming interrupts from a UDP socket that is listening for posts from my server.
The server sends in data about every 20 seconds. The problem usually occurs after or during a movie but I've seen it when the app is just idle. I am getting the receive event and then the skt.isReadable() would fail. This would continue for a while and then clear up. I thought by deleting the socket and then reallocating the socket, the problem would clear up. But it didn't help.

Anyone have any idea how to stop this ?

Log File Data

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

[greubel]

Any ideas ? Anyone ?

[destruk]

Ask Chaneru?

[gonzotek]

"destruk" wrote:
Ask Chaneru?

He's the Chaneru dev.

[greubel]

Yes, need help from Roku !

[RokuJoel]

Here's the response from Roku Engineering:

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).

- Joel

[greubel]

The application has two UDP sockets, one for UPnP broadcasts and one to my server. The purpose of the one to my server is because Join() and DLNA doesn't work.
The server does a join() and periodically sends the devices that IT finds to the app. I had to do this because I am unable to receive any responses from a M-SEARCH. The only thing that comes back is sometimes a NOTIFY.
I have this running on a Roku, Roku-HD and a Roku2. It fails on both sockets and all boxes.
The problem is totally random. Sometimes it just gets one error and other times it will last several seconds and then it starts working again.

I’d be curious which notify*() calls he has made on the problematic socket.

m.UPnPa.notifyReadable(true) <- joined socket
m.UPnPb.notifyReadable(true) < my server
m.UPnPb.setReuseAddr(true) < my server

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.

I tried to delete and reallocate the socket, thinking that might clear it up. But from the trace log you can see that they are still coming in BUT to the released socket.
Before the delete and reallocate all the errors came in on the prime socket. You can see from the log that the reallocation worked because it is still able to receive data.

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.

I put code in to the read() the socket anyway on the error but that didn't have any effect

Try automatically closing/deleting/recreating the socket if the weirdness count exceeds a few dozen.

This was done on the first error, to no effect.

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'm pretty sure the server isn't sending in zero bytes but also note that this is occurring on the "239.255.255.250:1900" broadcast receive socket.

Thanks ... Jim