App freezes when network unplugged

Rek · March 24, 2015, 3:43pm

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 · March 24, 2015, 4:07pm

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 · March 24, 2015, 4:11pm

“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 · March 24, 2015, 5:04pm

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 · March 24, 2015, 5:29pm

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 · March 24, 2015, 5:58pm

“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 · March 24, 2015, 6:04pm

“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 · March 24, 2015, 6:07pm

“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 · March 24, 2015, 6:29pm

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 · March 24, 2015, 6:38pm

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.

Rek · March 24, 2015, 7:06pm

“belltown” wrote:
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.

Ah, okay. I’ve confirmed that this is the same behaviour I’m seeing. So as long as the logs are stripped from production, and the user isn’t connected through telnet it’ll stay responsive. Cheers!

belltown · March 24, 2015, 7:44pm

“Rek” wrote:
Ah, okay. I’ve confirmed that this is the same behaviour I’m seeing. So as long as the logs are stripped from production, and the user isn’t connected through telnet it’ll stay responsive. Cheers!
Someone correct me if I’m wrong, but … The Print statements only do anything in a side-loaded development channel. Once you’re done with testing and have uploaded the channel to the Channel Store (even if as a Private Channel), then the Print statements aren’t actually logging anything anywhere, so there’s no real need to strip them out in a production version.

Rek · March 24, 2015, 7:55pm

“belltown” wrote:

“Rek” wrote:
Ah, okay. I’ve confirmed that this is the same behaviour I’m seeing. So as long as the logs are stripped from production, and the user isn’t connected through telnet it’ll stay responsive. Cheers!
Someone correct me if I’m wrong, but … The Print statements only do anything in a side-loaded development channel. Once you’re done with testing and have uploaded the channel to the Channel Store (even if as a Private Channel), then the Print statements aren’t actually logging anything anywhere, so there’s no real need to strip them out in a production version.

We strip them because we have a lot of logging, and it often has work associated with it:


' Several function calls here. getDebugString() builds a string with an int, so it's not very quick.
' Plus there's an extra intToStr and string concat in the message itself.
' By stripping this line entirely, we save a lot of execution, even if the final `print` wouldn't 
' have done anything anyways.
log_e(m.getDebugString(), "The value is: "+extValueToStr(x))

Komag · March 25, 2015, 5:00am

I have noticed that heavy printing really slows down some operations, sometimes a LOT, but I don’t know if that translates to a completed channel (private or public) - I always assumed it would.

Romans_I_XVI · March 25, 2015, 9:15am

Same here komag. I think “Roku probably ignores print in a .BRS”, but just for safekeeping I comment out all my print statements anyway before I publish.

Better safe than slow.

TheEndless · March 26, 2015, 3:48am

“Romans_I_XVI” wrote:
Same here komag. I think “Roku probably ignores print in a .BRS”, but just for safekeeping I comment out all my print statements anyway before I publish.

Better safe than slow.
Actually, I don’t think this is the case. I’m 99% sure the published version of the channel is identical to the side-loaded version, and I’ve actually had crashes in published channels that were the result of invalid objects in a “print” statement. You probably should, as a best practice, always reduce the debug output before publishing a channel.

Komag · March 26, 2015, 1:20pm

In another mod I did, I used to have ALL my print commands actually call another print function:
Instead of

PRINT("Printing some test feedback text")

I would have something like

doPrint("Printing some test feedback text", sy)

and have the following:

FUNCTION doPrint(text, sy) ' sy stands for "system associative array" with important keys/values
IF sy.printOn THEN PRINT(text)
END FUNCTION

Then just before release you can simply set sy.printOn to FALSE

renojim · March 26, 2015, 2:54pm

I’ve never removed prints from any of my channels. No adverse effects. Trying to print an invalid object will cause a crash, but I’ve never seen any other problem. A slew of prints may have an impact on speed in a published channel, but I haven’t done any measurements and I’ve never had a need for that many prints.

-JT

TheEndless · March 26, 2015, 9:29pm

“renojim” wrote:
I’ve never removed prints from any of my channels. No adverse effects. Trying to print an invalid object will cause a crash, but I’ve never seen any other problem. A slew of prints may have an impact on speed in a published channel, but I haven’t done any measurements and I’ve never had a need for that many prints.

-JT
It tends to have a more significant impact when using the 2D API when higher framerate is important.

EnTerr · May 5, 2015, 5:10pm

“belltown” wrote:
Someone correct me if I’m wrong, but … The Print statements only do anything in a side-loaded development channel. Once you’re done with testing and have uploaded the channel to the Channel Store (even if as a Private Channel), then the Print statements aren’t actually logging anything anywhere, so there’s no real need to strip them out in a production version.
I suspect prints in non-side-loaded app get redirected to log file, which gets uploaded to Roku heavens asynchronously. Dog forbid that being done synchronously, it would cause freezes like the described on buffer full and network down. That latter theory should be easy to check with network sniffer.

Topic		Replies	Views
Roku locking up / freezing Archived roku-developer-program	29	0	November 26, 2023
2 problems when switching networks Archived roku-developer-program	3	0	January 20, 2016
ECP (port 8060) not working Archived roku-developer-program	21	6	June 3, 2023
Roku custom app stops after 2 hours Archived roku-developer-program	0	0	November 1, 2021
API fragmentation? Archived roku-developer-program	16	0	January 17, 2014

App freezes when network unplugged

Related topics