Bug #2022: Step Skipping a large buffer results of TVH starting from beginning of buffered stream - Tvheadend

Bug #2022

Step Skipping a large buffer results of TVH starting from beginning of buffered stream

Added by Dani Louca over 10 years ago. Updated over 10 years ago.

Status:

Invalid

Priority:

Normal

Assignee:

Adam Sutton

Category:

Timeshift

Target version:

Start date:

2014-03-25

Due date:

% Done:

Estimated time:

Found in version:

master

Affected Versions:

Description

This issue was seen using the latest TVH built from master and latest TVH xbmc addon.

Steps to reproduce:
Enable Timeshift and play a channel for around 50 minutes
Hit ; to step back 30 seconds
XBMC passes the correct absolute time since stream has started to the TVH addon which multiplies it by 1000 and sends it to the TVH server.
Looks like TVH server is overflowing and ending up with a negative causing the returned point to switch all the way back to the beginning of the stream.

Useful Logs showing the issue:

XBMC/TVH Addon Logs:

22:55:31 T:2766129984 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux seek 3107451
22:55:31 T:2766129984 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - sending message [subscriptionSeek : 28]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - received response [28]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [timeshiftStatus]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - timeshiftStatus:
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - full : 0
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - start : 166822
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - end : -1155980363
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - shift : 0
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [subscriptionSkip]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [muxpkt]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux pkt idx 1:0 type I pts 166833.000000 len 42812
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [subscriptionSpeed]
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - recv speed 100
22:55:31 T:2809297728 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [timeshiftStatus]
22:55:31 T:2766129984 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux seek startpts = 166833.000000
22:55:31 T:2766129984 DEBUG: demuxer seek to: 3107451, success

TVH Server Showing the above request:
2014-03-24 22:55:31.362 timeshift: ts 12 skip -1187516288 requested -106876466
2014-03-24 22:55:31.362 timeshift: ts 12 skip last_time 38224492784 pts_delta 35085077846
2014-03-24 22:55:31.362 timeshift: ts 12 skip to 33897561558 from 38224492784
2014-03-24 22:55:31.362 timeshift: ts 12 skip found pkt @ 35085244679
2014-03-24 22:55:31.378 timeshift: ts 12 skip to 15015 ok
2014-03-24 22:55:31.378 htsp: 127.0.0.1 [ xbmc | XBMC Media Center ] - subscription skip
2014-03-24 22:55:31.378 timeshift: ts 12 sob speed 100

I'm in the process of debugging it, but if I couldn't point the code responsible for this behavior, I will request Adam to review.

History

Updated by Dani Louca over 10 years ago

Now I am not 100% sure where the overflow is coming from.
I ran it through the debugger and set the breakpoints on htsp_server.c > htsp_method_skip,
exactly at the else if:
if(!htsmsg_get_s64(in, "time", &s64)) {
skip.type = abs ? SMT_SKIP_ABS_TIME : SMT_SKIP_REL_TIME;
skip.time = hs>hs_90khz ? s64 : ts_rescale_i(s64, 1000000);
} else if (!htsmsg_get_s64(in, "size", &s64)) {

and you can see the negative value is assigned to s64, the only place this would be coming from is htsmsg_get_s64, unless I missed something in the addon.
Adam, any suggestion?

Variables values:

Name : s64
Details:-1228991296
Default:-1228991296
Decimal:-1228991296
Hex:0xffffffffb6bf14c0
Binary:1111111111111111111111111111111110110110101111110001010011000000
Octal:01777777777766657612300

Name : time
Details:-110609216
Default:-110609216
Decimal:-110609216
Hex:0xfffffffff9683cc0
Binary:1111111111111111111111111111111111111001011010000011110011000000
Octal:01777777777777132036300