Project

General

Profile

Bug #5782

httpc stuck and 100% cpu, when connecting to http2 server

Added by Laurent H. 24 days ago. Updated 14 days ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
IPTV
Target version:
-
Start date:
2019-11-19
Due date:
% Done:

0%

Estimated time:
Found in version:
4.3-1855~gd453f5bef
Affected Versions:

Description

Hello,

When downloading iptv m3u file from an apache 2.4 with http2 module enabled,
httpc get stuck using 100% cpu.

It seems httpc does not like apache response with upgrade header.

I'm using Tvheadend version 4.3-1855~gd453f5bef on Debian Buster

  • tvheadend.log when apache2 http2 module is enable :
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: Connected to tv.xxxxxxxxx.com:443
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: sending HTTP/1.1 cmd
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 47 45 54 20 2F 66 72 65 65 2E 6D 33 75 20 48 54 GET /free.m3u HT
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 54 50 2F 31 2E 31 0D 0A 48 6F 73 74 3A 20 74 76 TP/1.1..Host: tv
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 2E 78 78 78 78 78 78 78 78 78 2E 63 6F 6D 0D 0A .xxxxxxxxx.com..
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 55 73 65 72 2D 41 67 65 6E 74 3A 20 4B 6F 64 69 User-Agent: Kodi
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 2F 31 38 2E 31 20 28 58 31 31 3B 20 4C 69 6E 75 /18.1 (X11; Linu
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 78 20 78 38 36 5F 36 34 29 20 44 65 62 69 61 6E x x86_64) Debian
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 20 47 4E 55 2F 4C 69 6E 75 78 20 41 70 70 5F 42  GNU/Linux App_B
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 69 74 6E 65 73 73 2F 36 34 20 56 65 72 73 69 6F itness/64 Versio
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6E 2F 31 38 2E 31 0D 0A 43 6F 6E 6E 65 63 74 69 n/18.1..Connecti
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6F 6E 3A 20 63 6C 6F 73 65 0D 0A 0D 0A          on: close....   
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: add poll for input (1)
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: client flush 0
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: HTTP/1.1 answer 'HTTP/1.1 200 OK' (rcseq: 0)
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 00 HTTP/1.1 200 OK.
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0A 64 61 74 65 3A 20 54 75 65 2C 20 31 39 20 4E .date: Tue, 19 N
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6F 76 20 32 30 31 39 20 31 36 3A 30 37 3A 35 37 ov 2019 16:07:57
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 20 47 4D 54 0D 0A 73 65 72 76 65 72 3A 20 41 70  GMT..server: Ap
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 61 63 68 65 0D 0A 75 70 67 72 61 64 65 3A 20 68 ache..upgrade: h
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 32 2C 68 32 63 0D 0A 63 6F 6E 6E 65 63 74 69 6F 2,h2c..connectio
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6E 3A 20 55 70 67 72 61 64 65 0D 0A 6C 61 73 74 n: Upgrade..last
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 2D 6D 6F 64 69 66 69 65 64 3A 20 57 65 64 2C 20 -modified: Wed, 
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 31 33 20 4E 6F 76 20 32 30 31 39 20 31 34 3A 33 13 Nov 2019 14:3
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 37 3A 35 35 20 47 4D 54 0D 0A 65 74 61 67 3A 20 7:55 GMT..etag: 
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 22 31 34 39 35 2D 35 39 37 33 62 34 66 37 31 30 "1495-5973b4f710
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 31 63 31 22 0D 0A 61 63 63 65 70 74 2D 72 61 6E 1c1"..accept-ran
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 67 65 73 3A 20 62 79 74 65 73 0D 0A 63 6F 6E 74 ges: bytes..cont
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 65 6E 74 2D 6C 65 6E 67 74 68 3A 20 35 32 36 39 ent-length: 5269
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0D 0A 63 6F 6E 74 65 6E 74 2D 74 79 70 65 3A 20 ..content-type: 
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 61 75 64 69 6F 2F 78 2D 6D 70 65 67 75 72 6C 0D audio/x-mpegurl.
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0A 73 74 72 69 63 74 2D 74 72 61 6E 73 70 6F 72 .strict-transpor
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 74 2D 73 65 63 75 72 69 74 79 3A 20 6D 61 78 2D t-security: max-
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 61 67 65 3D 33 31 35 33 36 30 30 30 3B 20 69 6E age=31536000; in
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 63 6C 75 64 65 53 75 62 44 6F 6D 61 69 6E 73 3B cludeSubDomains;
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 20 70 72 65 6C 6F 61 64 3B 0D 0A 78 2D 66 72 61  preload;..x-fra
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6D 65 2D 6F 70 74 69 6F 6E 73 3A 20 53 41 4D 45 me-options: SAME
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 4F 52 49 47 49 4E 0D 0A 78 2D 78 73 73 2D 70 72 ORIGIN..x-xss-pr
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6F 74 65 63 74 69 6F 6E 3A 20 31 3B 20 6D 6F 64 otection: 1; mod
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 65 3D 62 6C 6F 63 6B 0D 0A 78 2D 63 6F 6E 74 65 e=block..x-conte
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 6E 74 2D 74 79 70 65 2D 6F 70 74 69 6F 6E 73 3A nt-type-options:
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 20 6E 6F 73 6E 69 66 66 0D 0A 78 2D 72 6F 62 6F  nosniff..x-robo
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 74 73 2D 74 61 67 3A 20 6E 6F 6E 65 00 0A 0D 0A ts-tag: none....
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: client flush -22
Nov 19 17:07:57 nas tvheadend[63262]: httpc: 0000: shutdown

httpc get stuck using 100% cpu until i stop tvheadend
  • log without http2 module :
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: Connected to tv.xxxxxxxxx.com:443
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: sending HTTP/1.1 cmd
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 47 45 54 20 2F 66 72 65 65 2E 6D 33 75 20 48 54 GET /free.m3u HT
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 54 50 2F 31 2E 31 0D 0A 48 6F 73 74 3A 20 74 76 TP/1.1..Host: tv
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 2E 78 78 78 78 78 78 78 78 78 2E 63 6F 6D 0D 0A .xxxxxxxxx.com..
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 55 73 65 72 2D 41 67 65 6E 74 3A 20 4B 6F 64 69 User-Agent: Kodi
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 2F 31 38 2E 31 20 28 58 31 31 3B 20 4C 69 6E 75 /18.1 (X11; Linu
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 78 20 78 38 36 5F 36 34 29 20 44 65 62 69 61 6E x x86_64) Debian
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 20 47 4E 55 2F 4C 69 6E 75 78 20 41 70 70 5F 42  GNU/Linux App_B
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 69 74 6E 65 73 73 2F 36 34 20 56 65 72 73 69 6F itness/64 Versio
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6E 2F 31 38 2E 31 0D 0A 43 6F 6E 6E 65 63 74 69 n/18.1..Connecti
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6F 6E 3A 20 63 6C 6F 73 65 0D 0A 0D 0A          on: close....   
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: add poll for input and output (2)
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: add poll for input (1)
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: client flush 0
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: HTTP/1.1 answer 'HTTP/1.1 200 OK' (rcseq: 0)
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 00 HTTP/1.1 200 OK.
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0A 64 61 74 65 3A 20 54 75 65 2C 20 31 39 20 4E .date: Tue, 19 N
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6F 76 20 32 30 31 39 20 31 36 3A 31 30 3A 31 36 ov 2019 16:10:16
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 20 47 4D 54 0D 0A 73 65 72 76 65 72 3A 20 41 70  GMT..server: Ap
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 61 63 68 65 0D 0A 6C 61 73 74 2D 6D 6F 64 69 66 ache..last-modif
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 69 65 64 3A 20 57 65 64 2C 20 31 33 20 4E 6F 76 ied: Wed, 13 Nov
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 20 32 30 31 39 20 31 34 3A 33 37 3A 35 35 20 47  2019 14:37:55 G
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 4D 54 0D 0A 65 74 61 67 3A 20 22 31 34 39 35 2D MT..etag: "1495-
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 35 39 37 33 62 34 66 37 31 30 31 63 31 22 0D 0A 5973b4f7101c1"..
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 61 63 63 65 70 74 2D 72 61 6E 67 65 73 3A 20 62 accept-ranges: b
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 79 74 65 73 0D 0A 63 6F 6E 74 65 6E 74 2D 6C 65 ytes..content-le
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6E 67 74 68 3A 20 35 32 36 39 0D 0A 63 6F 6E 74 ngth: 5269..cont
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 65 6E 74 2D 74 79 70 65 3A 20 61 75 64 69 6F 2F ent-type: audio/
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 78 2D 6D 70 65 67 75 72 6C 0D 0A 73 74 72 69 63 x-mpegurl..stric
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 74 2D 74 72 61 6E 73 70 6F 72 74 2D 73 65 63 75 t-transport-secu
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 72 69 74 79 3A 20 6D 61 78 2D 61 67 65 3D 33 31 rity: max-age=31
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 35 33 36 30 30 30 3B 20 69 6E 63 6C 75 64 65 53 536000; includeS
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 75 62 44 6F 6D 61 69 6E 73 3B 20 70 72 65 6C 6F ubDomains; prelo
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 61 64 3B 0D 0A 78 2D 66 72 61 6D 65 2D 6F 70 74 ad;..x-frame-opt
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 69 6F 6E 73 3A 20 53 41 4D 45 4F 52 49 47 49 4E ions: SAMEORIGIN
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0D 0A 78 2D 78 73 73 2D 70 72 6F 74 65 63 74 69 ..x-xss-protecti
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6F 6E 3A 20 31 3B 20 6D 6F 64 65 3D 62 6C 6F 63 on: 1; mode=bloc
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6B 0D 0A 78 2D 63 6F 6E 74 65 6E 74 2D 74 79 70 k..x-content-typ
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 65 2D 6F 70 74 69 6F 6E 73 3A 20 6E 6F 73 6E 69 e-options: nosni
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 66 66 0D 0A 78 2D 72 6F 62 6F 74 73 2D 74 61 67 ff..x-robots-tag
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 3A 20 6E 6F 6E 65 0D 0A 63 6F 6E 6E 65 63 74 69 : none..connecti
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 6F 6E 3A 20 63 6C 6F 73 65 00 0A 0D 0A          on: close....   
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: data complete, finishing
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: finishing
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: shutdown
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: add poll for input (0)
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: shutdown
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: client flush 0
    Nov 19 17:10:16 nas tvheadend[63568]: httpc: 0000: Closed
    

History

#1

Updated by Pablo R. 21 days ago

Could you try https://tvheadend.org/projects/tvheadend/wiki/Debugging#Mutex-profiling

It could give more information on where the problem is.

#2

Updated by Jaroslav Kysela 21 days ago

Error -22 means -EINVAL - something wrong in the header parser code probably.

#3

Updated by Flole Systems 21 days ago

The -EINVAL is at httpc.c:1099, try to change line 1096 to

if (strcasecmp(p, "close") == 0 || strcasecmp(p, "upgrade") == 0)

After you verified this I can provide a PR for that (we should add a comment to why this was necessary).

#4

Updated by Laurent H. 20 days ago

Pablo R. wrote:

Could you try https://tvheadend.org/projects/tvheadend/wiki/Debugging#Mutex-profiling

It could give more information on where the problem is.

nc -lu -p 7777
thread: mutex 0x56552f6bdca0 at src/main.c:1224 took 184ms
thread: mutex 0x56552f6bdca0 at src/input/mpegts/linuxdvb/linuxdvb_adapter.c:606 took 1615ms

but nothing more.

#5

Updated by Laurent H. 20 days ago

Flole Systems wrote:

The -EINVAL is at httpc.c:1099, try to change line 1096 to

[...]

After you verified this I can provide a PR for that (we should add a comment to why this was necessary).

With your patch :

diff --git a/src/httpc.c b/src/httpc.c
index 6cb4798cc..178ecbe72 100644
--- a/src/httpc.c
+++ b/src/httpc.c
@@ -1093,7 +1093,7 @@ header:
   }
   p = http_arg_get(&hc->hc_args, "Connection");
   if (p && ver != RTSP_VERSION_1_0) {
-    if (strcasecmp(p, "close") == 0)
+    if (strcasecmp(p, "close") == 0 || strcasecmp(p, "upgrade") == 0)
       hc->hc_keepalive = 0;
     else if (strcasecmp(p, "keep-alive")) /* no change for keep-alive */
       return http_client_flush(hc, -EINVAL);

I can confirm, it works with that patch, iptv m3u are downloaded and parsed ok.

#6

Updated by Flole Systems 20 days ago

PR is created

#7

Updated by Flole Systems 14 days ago

PR is merged. Now we still need to figure out why an invalid value causes high CPU usage but your initial problem should be fixed.

#8

Updated by Laurent H. 14 days ago

Thanks, let me know if you need me to do some tests.

Also available in: Atom PDF