EPG does not updates after initial load from server. about android-tvheadend HOT 22 CLOSED

The following entries in the Tvheadend log seem to equate to when the failure occurs:

2016-12-13 14:01:17.483 htsp: 192.168.10.53 [ tvh | android-tvheadend (epg) ]: Write error -- Resource temporarily unavailable
2016-12-13 14:01:17.483 htsp: 192.168.10.53 [ tvh | android-tvheadend (epg) ]: Disconnected

from android-tvheadend.

It looks like, sometimes the android-tv-headend client does not reconnect after a disconnection (e.g. tvheadend restart). Is your client or server sometine offline (poweroff client device, etc.)?

from android-tvheadend.

Yeah thats what I presumed to. The shield goes to sleep when I turn off my TV so that could be it. It uses HDMI-CEC. I will turn it off HDMI-CEC and let the shield go to sleep on its own after a quite time. But I have multiple times made sure the shield has stayed on for hours in a row while periodically looking at the logs and I can see the EpgSyncTask going again. A few lines of the update log would be:
12-13 14:42:49.358 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2339072
12-13 14:42:49.368 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2339072
12-13 14:42:49.369 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2339070
12-13 14:42:49.378 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2339070
12-13 14:42:49.379 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098191
12-13 14:42:49.390 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2098191
12-13 14:42:49.391 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098189
12-13 14:42:49.405 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2098189
12-13 14:42:49.406 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098187
12-13 14:42:49.418 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2098187
12-13 14:42:49.419 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098185
12-13 14:42:49.431 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2098185
12-13 14:42:49.433 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098183
12-13 14:42:49.447 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Update program 2098183
12-13 14:42:49.448 2983-4337/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Handling event message for ID: 2098181

However my EPG will not completely update. Sometimes it will fill in sections alright but I will still have pretty big gaps dotted through out it.

from android-tvheadend.

I think this Log extract might have something to do with my EPG issues. The initial issue seems to be a call to mMessageQueue.poll() on line 453 of Connection.java. It might have something to do with it, it might not. But its the only exception I have found in and around the EPG code.

29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Storing logo for content://android.media.tv/channel/1728 01-02 15:48:02.277 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Successfully stored logo to content://android.media.tv/channel/1728/logo 01-02 15:48:02.278 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Prepping fileCloseRequest 01-02 15:48:02.278 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Sending fileCloseRequest 01-02 15:48:02.278 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Sending HtspMessage: {digest=null, seq=445, method=fileClose, username=null, id=94} 01-02 15:48:02.278 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Storing logo for content://android.media.tv/channel/1730 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Successfully stored logo to content://android.media.tv/channel/1730/logo 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Prepping fileReadRequest 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Sending fileReadRequest 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Sending HtspMessage: {digest=null, seq=446, method=fileRead, size=10240, username=null, id=95, offset=20480} 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Prepping fileReadRequest 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Sending fileReadRequest 01-02 15:48:02.289 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Sending HtspMessage: {digest=null, seq=447, method=fileRead, size=10240, username=null, id=96, offset=20480} 01-02 15:48:02.290 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Prepping fileCloseRequest 01-02 15:48:02.290 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Sending fileCloseRequest 01-02 15:48:02.290 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Sending HtspMessage: {digest=null, seq=448, method=fileClose, username=null, id=98} 01-02 15:48:02.290 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Storing logo for content://android.media.tv/channel/1734 01-02 15:48:02.290 29202-29229/ie.macinnes.tvheadend E/ie.macinnes.htsp.Connection: Something failed - shutting down java.util.NoSuchElementException at java.util.LinkedList.removeFirstImpl(LinkedList.java:689) at java.util.LinkedList.removeFirst(LinkedList.java:676) at java.util.LinkedList.poll(LinkedList.java:895) at ie.macinnes.htsp.Connection.processWritableSelectionKey(Connection.java:453) at ie.macinnes.htsp.Connection.run(Connection.java:153) at java.lang.Thread.run(Thread.java:818) 01-02 15:48:02.290 29202-29229/ie.macinnes.tvheadend I/ie.macinnes.htsp.Connection: Closing HTSP Connection, End State: 6 01-02 15:48:02.290 29202-29229/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Transition to state 5 from 4 01-02 15:48:02.290 29202-29229/ie.macinnes.tvheadend I/ie.macinnes.htsp.Connection: Calling SocketChannel close 01-02 15:48:02.291 29202-29229/ie.macinnes.tvheadend W/ie.macinnes.htsp.Connection: Calling Selector close 01-02 15:48:02.291 29202-29229/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Transition to state 6 from 5 01-02 15:48:02.313 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.tvheadend.sync.EpgSyncTask: Successfully stored logo to content://android.media.tv/channel/1734/logo 01-02 15:48:02.313 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Prepping fileCloseRequest 01-02 15:48:02.313 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.tasks.GetFileTask: Sending fileCloseRequest 01-02 15:48:02.313 29202-29226/ie.macinnes.tvheadend D/ie.macinnes.htsp.Connection: Sending HtspMessage: {digest=null, seq=449, method=fileClose, username=null, id=99} 01-02 15:48:02.313 29202-29226/ie.macinnes.tvheadend E/AndroidRuntime: FATAL EXCEPTION: EpgSyncService Handler Thread Process: ie.macinnes.tvheadend, PID: 29202 java.lang.NullPointerException: Attempt to invoke virtual method 'java.nio.channels.SelectionKey java.nio.channels.SocketChannel.register(java.nio.channels.Selector, int)' on a null object reference at ie.macinnes.htsp.Connection.sendMessage(Connection.java:330) at ie.macinnes.htsp.Connection.sendMessage(Connection.java:341) at ie.macinnes.htsp.tasks.GetFileTask.sendFileClose(GetFileTask.java:164) at ie.macinnes.htsp.tasks.GetFileTask.onMessage(GetFileTask.java:108) at ie.macinnes.htsp.Connection$3.run(Connection.java:437) at android.os.Handler.handleCallback(Handler.java:742) at android.os.Handler.dispatchMessage(Handler.java:97) at android.os.Looper.loop(Looper.java:148) at android.os.HandlerThread.run(HandlerThread.java:61) 01-02 15:50:00.502 29202-29260/ie.macinnes.tvheadend W/nvblit: GPU blit stalled for 4.10 ms

from android-tvheadend.

@brickquinn aha, it's possible. Only a few hours ago I pushed what I hope is a fix for that exception - Could you give this build a go? It has that change http://jenkins.macinnes.ie/job/android-tvheadend/130/artifact/app/build/outputs/apk/ie.macinnes.tvheadend_v0.2.61-27-gd321e63-release.apk

from android-tvheadend.

And, Nope. That commit causes other issues. Ignore.

from android-tvheadend.

@brickquinn any chance the gaps are duplicate channels?

When a channel exists twice in TV Headend (That is, 2 channels with the same number and name) - we'll only import 1 of the channels data. That could explain the gaps?

from android-tvheadend.

@kiall No, its not duplicate channels. There is something weird between Insert/Update and delete events/programs during an update and I cant quite figure it out....I have a theory that "maybe" its something to do with IDs being re-used or something. Because i have even seen entries in the EPG that were present during the initial load just disappear a few hours later.

I did some messing about with a build and forced the last update time to always be ZERO. This as far as I can gather will force all entries from now to be returned. And I appear to be having some better results. So basically I think by returning everything again its is sidestepping the ID issue. As I said just a theory and all unproven at present. Not even sure how to validate it.

BTW my experiment with last update time of ZERO is only going about 12 hours, so I cant even be 100% certain it is performing better ye, as its probably a little early in the test.

from android-tvheadend.

BTW my only other theory is that the HTSP connection gets broken and never reconnects, and thus it never updates which is why I thought mMessageQueue.poll() exception which gets followed up with a SocketChannel exception might be the cause. But again all just theory and conjecture.

from android-tvheadend.

What version of TVheadend are you using? It's possible theres a bug re last update time..

Re never reconnects - it should reconnect after that specific exception, but there are other cases where the service will be stopped, and won't get restarted until the TV app is opened again or the device is rebooted

from android-tvheadend.

TVHeadend version; HTS Tvheadend 4.1-1429~ge29df17~jessie

from android-tvheadend.

Followed the log a little more, added to what I am seeing with my patched build I think it is a combination of both issues discussed above. When requesting EPG update with last update time of ZERO, I no longer get gaps in the EPG, however at weird times it does stop updating as in at 5 o'clock in the morning my EPG might run out of entries. If I use the DEBUG app to restart the EPG service, then things will begin updating again for a certain period of time until the service dies again. While looking at the log I think I actually caught it happening, and it is indeed the connection being dropped and the EPGService crashing.

`

E/ie.macinnes.htsp.Connection: Something failed - shutting down java.util.NoSuchElementException at java.util.LinkedList.removeFirstImpl(LinkedList.java:689) at java.util.LinkedList.removeFirst(LinkedList.java:676) at java.util.LinkedList.poll(LinkedList.java:895) at
E/ie.macinnes.htsp.Connection(13905): at ie.macinnes.htsp.Connection.processWritableSelectionKey(Connection.java:453)
E/ie.macinnes.htsp.Connection(13905): at ie.macinnes.htsp.Connection.run(Connection.java:153)
E/AndroidRuntime(13905): Process: ie.macinnes.tvheadend, PID: 13905
E/AndroidRuntime(13905): at ie.macinnes.htsp.Connection.sendMessage(Connection.java:330)
E/AndroidRuntime(13905): at ie.macinnes.htsp.Connection.sendMessage(Connection.java:341)
E/AndroidRuntime(13905): at ie.macinnes.htsp.tasks.GetFileTask.sendFileClose(GetFileTask.java:164)
E/AndroidRuntime(13905): at ie.macinnes.htsp.tasks.GetFileTask.onMessage(GetFileTask.java:108)
E/AndroidRuntime(13905): at ie.macinnes.htsp.Connection$3.run(Connection.java:437)
I/ActivityManager(669): Process ie.macinnes.tvheadend (pid 13905) has died
W/ActivityManager(669): Service crashed 2 times, stopping: ServiceRecord{9775193 u0 ie.macinnes.tvheadend/.sync.EpgSyncService}

`

So if I am reading this log correctly, then it looks like the exception being thrown during poll() is possibly killing the connection which eventually takes down the EPG Service. Android restarts it (I did see android system log entries that restarted the service but I have somehow managed to lose the full log file, so you'll have to take my word for it ;) ). But you can see in the last log entry, after the second crash Android appears to give up on the service and stop it. Therefore I guess the EPG service is dead until I restart the device or else manually kick it off again.

I might be reading the log file wrong and/or jumping to conclusions but I think this may explain my non-updating EPG issue.

I still have no explanation for the gaps I was seeing, but with the last update time of zero the gaps are gone. Maybe we could make a config option to have efficient vs full epg updates, because unless I am very unlucky I am surely not the only one seeing this.....then again with my luck maybe I am only one effected :)

from android-tvheadend.

So, The NoSuchElementException is know, I attempted to fix it with 5d4cb8b - but that actually just made things MUCH worse.

According to the JavaDoc's - That exception shouldn't be possible, yet somehow it's being raised.

I've currently no clue why that one is happening.

Re the epg-last-update - I don't have any data on it, but I suspect it's a tvheadend bug.. We could add a preference to disable the use of it..

from android-tvheadend.

PR #106 might be a fix for the NoSuchElementException, it happens so rarely (for me!) that it's hard to know for sure if it's fixed..

from android-tvheadend.

I will do a build and deploy once I get a chance. Will let you know how I get on.

from android-tvheadend.

@stquinn any luck seeing if that change resolved this issue? or that change combined with a last update time of 0?

from android-tvheadend.

I have been running with the last update time of 0 for about a week. And your concurrent list change since the day after it went in. Anecdotally it is behaving much better, I have not noticed the gaps and it seems to be keeping up with now + 24 hours worth of epg I have not gone through logs in any great detail for this issue though.

from android-tvheadend.

Okay, I'll add a preference to disable the epg last update time piece, and hopefully that'll close out this issue :)

from android-tvheadend.

Yeah we can always reopen or create a new one if something else comes to light. Thanks

from android-tvheadend.

From the standard (non debug) app which is available from Play Store, is it possible to access the Preferences panel without going through initial setup?

If not and many new features become configurable then it might be a nice future enhancement to provide access.

from android-tvheadend.

Right now, no. I've been meaning to make it easier though!

from android-tvheadend.

Cool thanks for all the hard work!

from android-tvheadend.