Bug #5899
SIGSEGV on FreeBSD in tvh:dvr-inotify
0%
Description
On FreeBSD while removing recordings I have hit this:
2020-05-15 12:34:45.980 [ INFO] dvr: delete entry 376f4ed4153f0f11acf5b7146d6fd0f2 "Události za okamžik a počasí" on "CT1 CZ" start time 2020-05-12 18:54:30, scheduled for recording by "192.168.0.38", retention "On file removal" removal "3 days"
Thread 24 "tvh:dvr-inotify" received signal SIGSEGV, Segmentation fault.
[Switching to LWP 102251 of process 50314]
_dvr_inotify_thread (p=<optimized out>
at src/dvr/dvr_inotify.c:400
400 i += EVENT_SIZE + ev->len;
(gdb) bt
#0 _dvr_inotify_thread (p=<optimized out> at src/dvr/dvr_inotify.c:400
#1 0x000000000033b69d in thread_wrapper (p=0x801b9c510) at src/tvh_thread.c:91
#2 0x000000080095c736 in ?? () from /lib/libthr.so.3
#3 0x0000000000000000 in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffdd3e8000
(gdb) generate-core-file
Saved corefile core.50314
(gdb) p i
$1 = -1458412714
(gdb) p EVENT_SIZE
No symbol "EVENT_SIZE" in current context.
(gdb) p ev
$2 = (struct inotify_event *) 0x7fff8650e126
(gdb) p *ev
Cannot access memory at address 0x7fff8650e126
(gdb) p p
$3 = <optimized out>
(gdb) p len
$4 = 335
Hopefully I am able to reproduce it. Let me know if you need more info.
Thank you.
Files
History
Updated by Flole Systems over 4 years ago
Updated by As you already figured out, ev is pointing to something that doesn't exist. As i seems to be negative you need to figure out why that happened. That can only happen if ev->len was negative before or if there is an overflow. When you can reproduce this reliably you can always just break there, single step and then watch why it gets negative.
Updated by Martin Rehak over 4 years ago
Updated by I am lost in what messages in the buffer mean and their meaning. This is the output after dvr-inotify tracing was enabled:
2020-05-15 15:20:22.719 [ TRACE]:dvr-inotify: i=0 len=294 name=Říše stříbra-Prima Zoom CZ2020-05-1220-55.ts
2020-05-15 15:20:22.719 [ TRACE]:dvr-inotify: i=66 len=294 from=Říše stříbra-Prima Zoom CZ2020-05-1220-55.ts cookie=15089
2020-05-15 15:20:22.720 [ TRACE]:dvr-inotify: i=66 len=294 name=.íše stříbra-Prima Zoom CZ2020-05-1220-55.ts.removing
2020-05-15 15:20:22.720 [ TRACE]:dvr-inotify: i=141 len=294 to_cookie=15089 from_cookie=15089 cookie_prev=0
2020-05-15 15:20:22.720 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/Říše stříbra-Prima Zoom CZ2020-05-1220-55.ts" to: ".íše stříbra-Prima Zoom CZ2020-05-1220-55.ts.removing" to_fd: 1
2020-05-15 15:20:22.742 [ TRACE]:dvr-inotify: i=141 len=294 name=Teorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts
2020-05-15 15:20:22.742 [ TRACE]:dvr-inotify: i=213 len=294 from=Teorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts cookie=15088
2020-05-15 15:20:22.742 [ TRACE]:dvr-inotify: i=213 len=294 name=.eorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts.removing
2020-05-15 15:20:22.742 [ TRACE]:dvr-inotify: i=294 len=294 to_cookie=15088 from_cookie=15088 cookie_prev=0
2020-05-15 15:20:22.742 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/Teorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts" to: ".eorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts.removing" to_fd: 1
2020-05-15 15:20:22.766 [ TRACE]:dvr-inotify: i=0 len=335 name=.eorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts.removing
2020-05-15 15:20:22.766 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/.eorie velkého třesku-Prima Cool CZ2020-05-1220-45.ts.removing" to: "<none>" to_fd: -1
2020-05-15 15:20:22.794 [ TRACE]:dvr-inotify: i=81 len=335 name=Letní hokej-CT2 CZ2020-05-1221-00.ts
2020-05-15 15:20:22.794 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/Letní hokej-CT2 CZ2020-05-1221-00.ts" to: "<none>" to_fd: -1
2020-05-15 15:20:22.817 [ TRACE]:dvr-inotify: i=135 len=335 name=Říše stříbra-Prima Zoom CZ2020-05-1220-55-1.ts
2020-05-15 15:20:22.817 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/Říše stříbra-Prima Zoom CZ2020-05-1220-55-1.ts" to: "<none>" to_fd: -1
2020-05-15 15:20:22.841 [ TRACE]:dvr-inotify: i=203 len=335 name=Letní hokej-CT2 CZ2020-05-1221-00-2.ts
2020-05-15 15:20:22.842 [ TRACE]:dvr-inotify: i=259 len=335 from=Letní hokej-CT2 CZ2020-05-1221-00-2.ts cookie=15119
2020-05-15 15:20:22.842 [ TRACE]:dvr-inotify: i=259 len=335 name=.etní hokej-CT2 CZ2020-05-1221-00-2.ts.removing
2020-05-15 15:20:22.842 [ TRACE]:dvr-inotify: i=324 len=335 to_cookie=15119 from_cookie=15119 cookie_prev=0
2020-05-15 15:20:22.842 [ DEBUG]:dvr: inotify: moved from_fd: 1 path: "/tv/live/Letní hokej-CT2 CZ2020-05-1221-00-2.ts" to: ".etní hokej-CT2 CZ2020-05-1221-00-2.ts.removing" to_fd: 1
Do you see the issue from this or should I continue with debugging, please?
Updated by Martin Rehak over 4 years ago
Okay, so I have hit it during gdb session but I am lost in what happened there. Could you look into it, please? Session attached.
Updated by Flole Systems over 4 years ago
You need to figure out what happened to the inotify_event at 0x7fffdd3e7e60. Either something overwrote it or it was indeed read like this. Maybe the check that would issue a break should also check for negative values, I need to think about that again. It shouldn't become negative in the first place though, that check seems to be a detection for broken values though (as otherwise it would never match).... You can try to see if that helps though, so make it
if (i > len || i < 0)
Updated by Martin Rehak over 4 years ago
I have tried to remove 100 files, no crash. The question is whether it is a fix or rather a workaround. 
Anyway, thank you very much indeed.
Updated by Flole Systems over 4 years ago
It could even be that the len attribute of the event before had an invalid length and then caused parsing of the following event to get invalid data. That would need more investigation to prevent issues in the future, it would be great if you could look into that a little more (check what exactly is *ev right before the iteration that causes the crash).