Roku Developer Program

[Rek]

Hi all, I think we may have stumbled upon a firmware bug. I have my Roku 3 connected via ethernet. It appears that if I unplug the ethernet cable while my app is running, it stops receiving CPU time. Please consider the following:

function main()
        t = 0
	timer = createobject("roTimespan")
	while true
		log_e("main", "iteration: "+extValueToStr(t))
		t = t + 1
	end while
	log_e("main", "Total Loop: "+extValueToStr(timer.totalMilliseconds()))
end function

When that code is run it just spits out a log messages with a counter over and over again. When I unplug the network cable the logs just stop until I plug it back in. The timestamps reflect the lapse in time (~12 seconds), but the counter only increases by 1. This indicates to me that my app has stopped running for the interim.

Output:

11:28:21.415 [ERROR] [main] iteration: 402464
11:28:21.415 [ERROR] [main] iteration: 402465
11:28:21.415 [ERROR] [main] iteration: 402466
11:28:21.416 [ERROR] [main] iteration: 402467
11:28:21.416 [ERROR] [main] iteration: 402468
11:28:21.416 [ERROR] [main] iteration: 402469
11:28:21.417 [ERROR] [main] iteration: 402470
11:28:21.417 [ERROR] [main] iteration: 402471
11:28:21.417 [ERROR] [main] iteration: 402472
11:28:21.418 [ERROR] [main] iteration: 402473
11:28:21.418 [ERROR] [main] iteration: 402474
11:28:21.418 [ERROR] [main] iteration: 402475 
11:28:34.618 [ERROR] [main] iteration: 402476 <----- Note the jump in time from the previous line
11:28:34.619 [ERROR] [main] iteration: 402477
11:28:34.619 [ERROR] [main] iteration: 402478
11:28:34.619 [ERROR] [main] iteration: 402479
11:28:34.620 [ERROR] [main] iteration: 402480
11:28:34.620 [ERROR] [main] iteration: 402481
11:28:34.621 [ERROR] [main] iteration: 402482
11:28:34.621 [ERROR] [main] iteration: 402483
11:28:34.621 [ERROR] [main] iteration: 402484
11:28:34.622 [ERROR] [main] iteration: 402485
11:28:34.622 [ERROR] [main] iteration: 402486
11:28:34.622 [ERROR] [main] iteration: 402487

Can anyone explain why this is happening, and if there is anything my app can do to stay responsive in this scenario?

On a side note: It appears that roTimespan objects do not 'detect' the lapse in execution time. My log timestamps are based on roDateTime and clearly illustrate the gap in time, but when log the value of the timer on each iteration, it does not appear jump when the app freezes...

function main() as Void
	t = 0
	timer = createobject("roTimespan")
	while true
		log_e("main", "iteration: "+extValueToStr(t)+", timeSinceLastIteration: "+extValueToStr(timer.totalMilliseconds())+"ms")
		t = t + 1
		timer.mark()
	end while
	log_e("main", "Total Loop: "+extValueToStr(timer.totalMilliseconds()))
end function

Output:

11:41:14.742 [ERROR] [main] iteration: 23340, timeSinceLastIteration: 0ms
11:41:14.742 [ERROR] [main] iteration: 23341, timeSinceLastIteration: 0ms
11:41:14.743 [ERROR] [main] iteration: 23342, timeSinceLastIteration: 0ms
11:41:14.743 [ERROR] [main] iteration: 23343, timeSinceLastIteration: 0ms
11:41:14.743 [ERROR] [main] iteration: 23344, timeSinceLastIteration: 0ms
11:41:27.938 [ERROR] [main] iteration: 23345, timeSinceLastIteration: 0ms  <-- Note: There is a 13 second gap here, but the timer indicates 0ms have elapsed
11:41:27.939 [ERROR] [main] iteration: 23346, timeSinceLastIteration: 0ms
11:41:27.939 [ERROR] [main] iteration: 23347, timeSinceLastIteration: 0ms
11:41:27.940 [ERROR] [main] iteration: 23348, timeSinceLastIteration: 0ms
11:41:27.940 [ERROR] [main] iteration: 23349, timeSinceLastIteration: 0ms

This suggests that the roTimespan does not accurately reflect the real amount of time which has elapsed.

[renojim]

No significant time is ever going to elapse between your mark() and your log. Basically, if you unroll that loop you have:

timer.mark()
log/print timer.totalMilliseconds()

Without knowing what's in log_e, I suspect it's blocking on a URLtransfer that can't complete when you unplug the cable and that's why it looks like your app stops responding.

-JT

[Rek]

"renojim" wrote:
No significant time is ever going to elapse between your mark() and your log. Basically, if you unroll that loop you have:

timer.mark()
log/print timer.totalMilliseconds()

Without knowing what's in log_e, I suspect it's blocking on a URLtransfer that can't complete when you unplug the cable and that's why it looks like your app stops responding.

-JT

I realise that no significant time will ever elapse between mark() and the log -- that's the purpose of the test. If there is ever a long delay in execution, then there WILL be a significant amount of time elapsed. And no, there is no url transfer or any other long running operation in my logging function; it simply creates a roDateTime and prints the given string with the current log level and timestamp.

[Romans_I_XVI]

Umm... is the log you're referring to just the output you're receiving via telnet? Or are you writing it to a file or something and then reading it later?

If we're just talking about the output to your telnet terminal obviously you won't receive any messages when you unplug the ethernet cable, even if you're Roku is connected to Wi-FI, your Wi-Fi IP will be different than your ethernet IP. So maybe everything IS running fine while the ethernet cable is unplugged, and that it is properly printing the message log, you just aren't receiving it because your telnet is disconnected.

edit: Nevermind, the iteration count doesn't go up and it should, didn't pay attention to that at first. IDK 😛

edit again: Maybe print for some reason hangs if it's disconnected from the network... would be silly but I've never tested it. And you're not Mark()ing the timestamp somewhere else in the code? I know these are all basic and obvious thoughts, but just throwing stuff out there.

[RokuMarkn]

Can you post your log_e function? It seems that that function must be hanging when you unplug the cable. In that case your roDateTime is working as it should, since there's no significant time between the mark and the print; the delay is outside that area.

--Mark

[Rek]

"RokuMarkn" wrote:
Can you post your log_e function? It seems that that function must be hanging when you unplug the cable. In that case your roDateTime is working as it should, since there's no significant time between the mark and the print; the delay is outside that area.

--Mark

The roDateTime is working as expected. It's the roTimespan that's not giving the actual iteration time.

I've extracted all the relevant code into the following self-contained example:

function main() as Void
   t = 0
   timer = createobject("roTimespan")
   while true
      log_e("main", "iteration: "+extIntToStr(t)+", timeSinceLastIteration: "+extIntToStr(timer.totalMilliseconds())+"ms")
      t = t + 1
      timer.mark()
   end while
   log_e("main", "Total Loop: "+extIntToStr(timer.totalMilliseconds()))
end function

function log_e(tag as String, msg as String) as Void
	level = "ERROR"

	dt = createObject("roDateTime")
	dt.toLocalTime()

	hours  = dt.getHours()
	mins   = dt.getMinutes()
	secs   = dt.getSeconds()
	millis = dt.getMilliseconds()

	hours  = extIntToStr(hours, 2)
	mins   = extIntToStr(mins, 2)
	secs   = extIntToStr(secs, 2)
	millis = extIntToStr(millis, 3)

	?hours;":";mins;":";secs;".";millis;" [";level;"] [";tag;"] ";msg
end function

function extIntToStr(int as Integer, numDigits = 0 as Integer) as String
	result = box(int).toStr()

	if numDigits > 0
		while len(result) < numDigits
			result = "0" + result
		end while
	end if

	return result
end function

[renojim]

"Rek" wrote:
If there is ever a long delay in execution, then there WILL be a significant amount of time elapsed.

Nope, your test is fundamentally flawed. You do a mark() and immediately use the value of totalMilliseconds in the call to log_e. It will ALWAYS show 0ms has elapsed. You're "logging" the amount of time it takes to get from the mark() at the bottom of the loop to where you pass timer.totalMilliseconds() to log_e at the top of the loop.

What I think you want to measure is the time log_e is taking and that's not what you're doing. Try this:

while true
   timer.mark()
   log_e(...)
   print timer.totalMilliseconds()
end while

-JT

[Rek]

"renojim" wrote:

"Rek" wrote:
If there is ever a long delay in execution, then there WILL be a significant amount of time elapsed.

Nope, your test is fundamentally flawed. You do a mark() and immediately use the value of totalMilliseconds in the call to log_e. It will ALWAYS show 0ms has elapsed. You're "logging" the amount of time it takes to get from the mark() at the bottom of the loop to where you pass timer.totalMilliseconds() to log_e at the top of the loop.

What I think you want to measure is the time log_e is taking and that's not what you're doing. Try this:

while true
   timer.mark()
   log_e(...)
   print timer.totalMilliseconds()
end while

-JT

No, I don't care about the log function. This happens whether I'm logging or not; it will still "eat" all my input events until the network is reconnected, then it plays them all back as fast as they can come out of the message port. The log function is only there to illustrate the problem by providing useful information (iteration count, elapsed time for iteration).

Has anyone been able to reproduce this? I've seen it on at least two Roku 3's... Will try with a Roku 2 shortly.

[RokuMarkn]

As far as I can see, roTimeSpan is working as expected. Since you never pause between the mark and the print, roTimeSpan always shows 0 or 1 ms elapsed. The hang is, I'm pretty sure, happening in the print statement. Normally any print output that occurs while the network is down will be buffered and printed when the network reconnects. In your case, you're printing so much data that the buffer fills up and at that point the the next print causes the to app hang until the network is reconnected and it can print out the buffered output.

--Mark

[belltown]

Does your channel continue to work when you unplug your ethernet cable if you remove the Print statements?

Does your channel continue to work when you unplug your ethernet cable if you have not previously opened port 8085 to view the console log?

Once you open port 8085, e.g. using Telnet, to examine your log activity, the Roku appears to open a port for transmitting log messages to your Telnet client. If the communication link between the Roku and the Telnet client terminates, it seems that after a while (perhaps when the internal console buffer fills), the channel hangs. When the connection to the Telnet client restarts, the channel resumes, all the logs that were being held in the console buffer are sent to the Telnet client, followed by any new log entries. The log timestamps will show the delay while the channel was hung.

I've seen this behavior a lot when debugging a channel from my laptop. When I put the laptop to sleep (thus severing the network connection between the Roku and the Telnet client), the channel continues to run for a little while then hangs. After I resume my laptop the console log spews forth a bunch of stored log messages then the channel continues. I don't get this behavior if I exit from Telnet before putting the laptop to sleep.

I just read RokuMarkn's comment. I think he's saying the same thing.