Bug #5782
httpc stuck and 100% cpu, when connecting to http2 server
Status:
Fixed
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
Updated by Pablo R. about 5 years ago
Updated by Could you try https://tvheadend.org/projects/tvheadend/wiki/Debugging#Mutex-profiling
It could give more information on where the problem is.
Updated by Jaroslav Kysela about 5 years ago
Updated by Error -22 means -EINVAL - something wrong in the header parser code probably.
Updated by Flole Systems about 5 years ago
Updated by 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).
Updated by Laurent H. about 5 years ago
Updated by 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.
Updated by Laurent H. about 5 years 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.
Updated by Flole Systems about 5 years 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.