Project

General

Profile

Bug #5782

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

Added by Laurent H. 5 months ago. Updated 4 months 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. 4 months 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 4 months ago

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

#3

Updated by Flole Systems 4 months 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. 4 months 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. 4 months 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 4 months ago

PR is created

#7

Updated by Flole Systems 4 months 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. 4 months ago

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

Also available in: Atom PDF