Kodi Community Forum
Timer based recoding doesn't terminate / kodi and vdr disconnect - Printable Version

+- Kodi Community Forum (https://forum.kodi.tv)
+-- Forum: Support (https://forum.kodi.tv/forumdisplay.php?fid=33)
+--- Forum: PVR & Live TV Support (https://forum.kodi.tv/forumdisplay.php?fid=167)
+---- Forum: VDR (https://forum.kodi.tv/forumdisplay.php?fid=169)
+---- Thread: Timer based recoding doesn't terminate / kodi and vdr disconnect (/showthread.php?tid=320332)

Timer based recoding doesn't terminate / kodi and vdr disconnect - Spirou - 2017-08-22

I am expereincing a strange issue now for at least the second time. I have not yet been able to reproduce the exact circumstances which triggers the issue, but I believe it is not accidental.

What happened:

Last night I set up a timer based recording for vdr. I did this in kodi by selecting the 'record' entry from the context menu of the highlighted title in the guide.

Timer created:
Code:
Sky Cinema Comedy - Taxi 22.08.2017 from 04:42 to 06:20

As you can see from the attached log vdr starts recording on schedule at 4:42.
It then stops recording at 6:11 (seemingly "due to modification of channel 131 (Sky Cinema Comedy)") and instantly resumes or rather restarts recording a second later.

There is no log entry at 6:20 when the recording was actually supposed to end according to timer settings.
In fact, recording continued until the late afternoon when I noticed it and eventually rebooted the system. Choosing "end recording" didn't give me a result and it looked as kodi was completely disconnect from vdr (system did not react to opening vdr osd from client specific settings).

The errors it threw were:
Code:
Aug 22 17:24:00 localhost vdr: [2775] ERROR: video data stream broken
Aug 22 17:24:00 localhost vdr: [2775] initiating emergency exit

Checking the recoding and the recording folder I found the recording had in fact continued for more than 12 hours:
Code:
kodi@kodi-mc:~/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec$ ls -ls
insgesamt 16762220
1877432 -rw-rw-r-- 1 vdr vdr 1922484804 Aug 22 06:11 00001.ts
8192136 -rw-rw-r-- 1 vdr vdr 8388743112 Aug 22 13:09 00002.ts
6683756 -rw-rw-r-- 1 vdr vdr 6844161432 Aug 22 17:29 00003.ts
   8892 -rw-rw-r-- 1 vdr vdr    9100832 Aug 22 17:21 index
      4 -rw-rw-r-- 1 vdr vdr        666 Aug 22 06:11 info
Although, apparently for everything after 6:11 the recoding shows only a black screen.

I am not sure if this actually a kodi/vnsi issue or if this is more inside vdr. Hence, any guidance is much appreciated.

Here is the syslog for the relevant time interval:
Code:
Aug 22 04:41:01 localhost vdr: [1106] switching device 2 to channel 131 S19.2E-133-3-8 (Sky Cinema Comedy)
Aug 22 04:41:02 localhost vdr: [1455] changing pids of channel 131 (Sky Cinema Comedy) from 1023+1023=27:1024=deu@3,1025=eng@3;1027=deu@106:0:0 to 1023+1023=27:1024=deu@3;1027=deu@106:0:0
Aug 22 04:41:02 localhost vdr: [1455] channel 131 (Sky Cinema Comedy) event Di. 22.08.2017 04:45-06:15 'Taxi' status 4
Aug 22 04:41:02 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 04:41:02 localhost vdr: [1455] changing pids of channel 128 (Sky Cinema +1) from 255+255=27:256=deu@3,257=eng@3;259=deu@106:0:0 to 255+255=27:256=deu@3;259=deu@106:0:0
Aug 22 04:41:02 localhost vdr: [1455] changing pids of channel 88 (Disney XD) from 1279+1279=27:1280=deu@3:0:0 to 1279+1279=27:1280=deu@3,1281=eng@3:0:0
Aug 22 04:41:07 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 04:41:36 localhost vdr: [2307] epg data writer thread started (pid=1106, tid=2307, prio=low)
Aug 22 04:41:36 localhost vdr: [2307] epg data writer thread ended (pid=1106, tid=2307)
Aug 22 04:42:00 localhost vdr: [1106] CAM 1/1: creating new MTD CAM slot
Aug 22 04:42:00 localhost vdr: [1106] CAM 1: assigned to device 2
Aug 22 04:42:00 localhost vdr: [1106] switching device 2 to channel 131 S19.2E-133-3-8 (Sky Cinema Comedy)
Aug 22 04:42:00 localhost vdr: [2310] device 2 receiver thread started (pid=1106, tid=2310, prio=high)
Aug 22 04:42:00 localhost vdr: [1106] timer 1 (131 0442-0620 'Taxi') start
Aug 22 04:42:00 localhost vdr: [1106] Title: 'Taxi' Subtitle: 'Actionkomödie'
Aug 22 04:42:00 localhost vdr: [1106] executing '/usr/lib/vdr/vdr-recordingaction before "/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec"'
Aug 22 04:42:00 localhost vdr: [2311] device 2 TS buffer thread started (pid=1106, tid=2311, prio=high)
Aug 22 04:42:00 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R90.custom before recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 04:42:00 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R91.custom before recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 04:42:00 localhost vdr: [1106] record /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 04:42:00 localhost vdr: [1106] creating directory /home/kodi/Aufnahmen/Taxi
Aug 22 04:42:00 localhost vdr: [1106] creating directory /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 04:42:00 localhost vdr: [1106] recording to '/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec/00001.ts'
Aug 22 04:42:00 localhost vdr: [2332] recording thread started (pid=1106, tid=2332, prio=high)
Aug 22 04:42:00 localhost vdr: [1578] VNSI: Requesting clients to reload timers
Aug 22 04:42:01 localhost vdr: [1578] VNSI: Requesting clients to reload recordings list
Aug 22 04:42:02 localhost vdr: [2332] executing '/usr/lib/vdr/vdr-recordingaction started "/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec"'
Aug 22 04:42:02 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R90.custom
Aug 22 04:42:02 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R91.custom
Aug 22 04:42:23 localhost vdr: [1582] SVDRP < 127.0.0.1:41998 client connection accepted
Aug 22 04:42:23 localhost vdr: [1582] SVDRP < 127.0.0.1:41998 server created
Aug 22 04:42:25 localhost vdr: [1582] SVDRP < 127.0.0.1:41998 connection closed
Aug 22 04:42:25 localhost vdr: [1582] SVDRP < 127.0.0.1:41998 server destroyed
Aug 22 04:51:26 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:04:27 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:05:27 localhost vdr: [1881] VNSI: Video stream change, pid: 167, width: 720, height: 576, aspect: 1,777778
Aug 22 05:17:01 localhost CRON[2444]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 05:17:27 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:25:59 localhost vdr: [1455] changing pids of channel 129 (Sky Cinema +24) from 511+511=27:512=deu@3,513=eng@3;515=deu@106:0:0 to 511+511=27:512=deu@3;515=deu@106:0:0
Aug 22 05:26:00 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:30:28 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:41:44 localhost vdr: [1106] =====================
Aug 22 05:41:44 localhost vdr: [1106] EPG bugfix statistics
Aug 22 05:41:44 localhost vdr: [1106] =====================
Aug 22 05:41:44 localhost vdr: [1106] IF SOMEBODY WHO IS IN CHARGE OF THE EPG DATA FOR ONE OF THE LISTED
Aug 22 05:41:44 localhost vdr: [1106] CHANNELS READS THIS: PLEASE TAKE A LOOK AT THE FUNCTION cEvent::FixEpgBugs()
Aug 22 05:41:44 localhost vdr: [1106] IN VDR/epg.c TO LEARN WHAT'S WRONG WITH YOUR DATA, AND FIX IT!
Aug 22 05:41:44 localhost vdr: [1106] =====================
Aug 22 05:41:44 localhost vdr: [1106] Fix Hits Channels
Aug 22 05:41:44 localhost vdr: [1106] 3   361  ANIXE HD, RTL Crime HD, Disney Junior, Goldstar TV, Heimatkanal, Sky Atlantic +1 HD, ...
Aug 22 05:41:44 localhost vdr: [1106] 4   24   NDR Info Spez., NDR Info, ARD-alpha, SWR2, BR-KLASSIK, SR 2 KulturRadio, 3sat HD, ...
Aug 22 05:41:44 localhost vdr: [1106] 6   2612 tagesschau24, arte, PHOENIX, ONE, hr-fernsehen HD, MDR Sachsen HD, rbb Berlin HD, ...
Aug 22 05:41:44 localhost vdr: [1106] 7   114  tagesschau24, tagesschau24 HD, NDR FS NDS HD, NDR FS NDS, WDR Event, Eurosport 1 HD, ...
Aug 22 05:41:44 localhost vdr: [1106] 8   1343 Romance TV, DELUXE MUSIC, ANIXE SD, TLC, SIXX, N24 DOKU, kabel eins, N24, ...
Aug 22 05:41:44 localhost vdr: [1106] 9   1343 Romance TV, DELUXE MUSIC, ANIXE SD, TLC, SIXX, N24 DOKU, kabel eins, N24, ...
Aug 22 05:41:44 localhost vdr: [1106] =====================
Aug 22 05:43:28 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:46:30 localhost vdr: [1881] VNSI: exit streamer thread
Aug 22 05:46:30 localhost vdr: [1881] cLiveStreamer stream processor thread ended (pid=1106, tid=1881)
Aug 22 05:46:30 localhost vdr: [1879] VNSI: LiveStreamer::Close - close
Aug 22 05:46:30 localhost vdr: [1879] VNSI: close video input ...
Aug 22 05:46:30 localhost vdr: [1879] VNSI: activate live receiver: 0
Aug 22 05:46:30 localhost vdr: [1879] VNSI: Dummy receiver (0x7fbba000b740) deactivated
Aug 22 05:46:30 localhost vdr: [1882] device 1 TS buffer thread ended (pid=1106, tid=1882)
Aug 22 05:46:30 localhost vdr: [1880] buffer stats: 126900 (2%) used
Aug 22 05:46:30 localhost vdr: [1880] device 1 receiver thread ended (pid=1106, tid=1880)
Aug 22 05:46:30 localhost vdr: [1879] VNSI: close video input ...
Aug 22 05:46:30 localhost vdr: [1879] VNSI: cxSocket::read(fd=21): eof, connection closed
Aug 22 05:46:30 localhost vdr: [1879] VNSI Client 5->192.168.178.15:49644 thread ended (pid=1106, tid=1879)
Aug 22 05:46:30 localhost vdr: [1578] VNSI: Client with ID 5 seems to be disconnected, removing from client list
Aug 22 05:46:34 localhost vdr: [1866] VNSI: cxSocket::read(fd=26): eof, connection closed
Aug 22 05:46:35 localhost vdr: [1866] VNSI: Stopping scan plugin not reported back and stop maybe not complete confirmed
Aug 22 05:46:35 localhost vdr: [1866] VNSI Client 2->192.168.178.15:49624 thread ended (pid=1106, tid=1866)
Aug 22 05:46:35 localhost vdr: [1578] VNSI: Client with ID 2 seems to be disconnected, removing from client list
Aug 22 05:51:21 localhost vdr: [1451] changing pids of channel 137 (Sky Arts HD) from 767+767=27:0;771=deu@106,772=eng@106:0:0 to 767+767=27:0;771=deu@106:0:0
Aug 22 05:51:21 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:52:07 localhost /usr/lib/snapd/snapd[1004]: snapmgr.go:422: No snaps to auto-refresh found
Aug 22 05:52:07 localhost snapd[1004]: 2017/08/22 05:52:07.057096 snapmgr.go:422: No snaps to auto-refresh found
Aug 22 05:53:48 localhost vdr: [1451] changing pids of channel 147 (Sky Sport 2) from 1791+1791=27:1792=qae@3,1793=qaf@3:0:32 to 1791+1791=27:1792=qae@3:0:32
Aug 22 05:53:48 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:53:48 localhost vdr: [1451] changing pids of channel 125 (Disney Cinemagic) from 3327+3327=27:3328=deu@3,3329=eng@3:0:0 to 3327+3327=27:3328=deu@3:0:0
Aug 22 05:53:48 localhost vdr: [1451] changing pids of channel 134 (Sky Cinema Hits) from 255+255=27:256=deu@3;259=deu@106:0:0 to 255+255=27:256=deu@3,257=eng@3;259=deu@106:0:0
Aug 22 05:53:53 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:54:51 localhost vdr: [1451] changing pids of channel 83 (A&E) from 1791+1791=27:1792=deu@3:0:0 to 1791+1791=27:1792=deu@3,1793=eng@3:0:0
Aug 22 05:54:51 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:55:12 localhost vdr: [1451] changing pids of channel 110 (Discovery HD) from 1023+1023=27:0;1027=deu@106,1028=eng@106:0:0 to 1023+1023=27:0;1027=deu@106:0:0
Aug 22 05:55:12 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:55:39 localhost vdr: [1455] changing pids of channel 128 (Sky Cinema +1) from 255+255=27:256=deu@3;259=deu@106:0:0 to 255+255=27:256=deu@3,257=@3;259=deu@106:0:0
Aug 22 05:55:39 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:55:40 localhost vdr: [1455] changing pids of channel 128 (Sky Cinema +1) from 255+255=27:256=deu@3,257=@3;259=deu@106:0:0 to 255+255=27:256=deu@3,257=eng@3;259=deu@106:0:0
Aug 22 05:55:44 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:55:54 localhost vdr: [1451] changing pids of channel 161 (Sky Sport 2 HD) from 1023+1023=27:0;1026=qae@106,1027=qaf@106,1028=qtz@106:0:32 to 1023+1023=27:0;1026=qae@106,1027=qaf@106:0:32
Aug 22 05:55:54 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:56:15 localhost vdr: [1451] changing pids of channel 86 (Discovery Channel) from 3327+3327=27:3328=deu@3,3329=eng@3:0:0 to 3327+3327=27:3328=deu@3:0:0
Aug 22 05:56:15 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:56:15 localhost vdr: [1451] changing pids of channel 133 (Sky Cinema Family) from 4095+4095=27:4096=deu@3,4097=eng@3;4099=deu@106:0:0 to 4095+4095=27:4096=deu@3,4097=eng@3:0:0
Aug 22 05:56:15 localhost vdr: [1451] changing pids of channel 135 (Sky Cinema Nostalgie) from 767+767=27:768=deu@3:0:0 to 767+767=27:768=deu@3,769=eng@3:0:0
Aug 22 05:56:20 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:56:29 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 05:56:36 localhost vdr: [1451] changing pids of channel 142 (Sky Cinema +24 HD) from 511+511=27:0;515=deu@106,516=eng@106:0:0 to 511+511=27:0;515=deu@106:0:0
Aug 22 05:56:36 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:57:06 localhost /usr/lib/snapd/snapd[1004]: snapmgr.go:504: DEBUG: Next refresh scheduled for 2017-08-22 14:14:23.268401218 +0200 CEST.
Aug 22 05:58:42 localhost vdr: [1451] changing pids of channel 145 (Sky Cinema Hits HD) from 767+767=27:0;771=deu@106:0:0 to 767+767=27:0;771=deu@106,772=eng@106:0:0
Aug 22 05:58:42 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 05:59:03 localhost vdr: [1451] changing pids of channel 115 (History HD) from 767+767=27:0;771=deu@106,772=eng@106:0:0 to 767+767=27:0;771=deu@106:0:0
Aug 22 05:59:03 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 06:00:10 localhost kernel: [11914.264509] [drm] Got external EDID base block and 1 extension from "edid/edid.bin" for connector "HDMI-A-2"
Aug 22 06:06:44 localhost vdr: [1451] changing pids of channel 137 (Sky Arts HD) from 767+767=27:0;771=deu@106:0:0 to 767+767=27:0;771=deu@106,772=eng@106:0:0
Aug 22 06:06:45 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 06:06:52 localhost systemd[1]: Starting Daily apt upgrade and clean activities...
Aug 22 06:06:54 localhost systemd[1]: Started Daily apt upgrade and clean activities.
Aug 22 06:09:11 localhost vdr: [1451] changing pids of channel 147 (Sky Sport 2) from 1791+1791=27:1792=qae@3:0:32 to 1791+1791=27:1792=qae@3,1793=qaf@3:0:32
Aug 22 06:09:11 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 06:09:29 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 06:10:35 localhost vdr: [1451] changing pids of channel 160 (Sky Sport 1 HD) from 767+767=27:0;770=qae@106,771=qaf@106:0:32 to 767+767=27:0;770=qae@106,771=qaf@106,772=qtz@106:0:32
Aug 22 06:10:36 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 06:10:40 localhost vdr: [1455] channel 131 (Sky Cinema Comedy) event Di. 22.08.2017 06:15-08:05 'The Singing Detective' status 2
Aug 22 06:11:10 localhost vdr: [1455] channel 131 (Sky Cinema Comedy) event Di. 22.08.2017 06:15-08:05 'The Singing Detective' status 4
Aug 22 06:11:10 localhost vdr: [1455] changing pids of channel 131 (Sky Cinema Comedy) from 1023+1023=27:1024=deu@3;1027=deu@106:0:0 to 1023+1023=27:1024=deu@3,1025=@3;1027=deu@106:0:0
Aug 22 06:11:11 localhost vdr: [1578] VNSI: Requesting clients to reload channel list
Aug 22 06:11:11 localhost vdr: [1106] stopping recording due to modification of channel 131 (Sky Cinema Comedy)
Aug 22 06:11:11 localhost vdr: [2332] recording thread ended (pid=1106, tid=2332)
Aug 22 06:11:11 localhost vdr: [1106] CAM 1: unassigned from device 2
Aug 22 06:11:11 localhost vdr: [2311] device 2 TS buffer thread ended (pid=1106, tid=2311)
Aug 22 06:11:11 localhost vdr: [1106] buffer stats: 160552 (0%) used
Aug 22 06:11:11 localhost vdr: [1106] timer 1 (131 0442-0620 'Taxi') stop
Aug 22 06:11:11 localhost vdr: [1106] executing '/usr/lib/vdr/vdr-recordingaction after "/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec"'
Aug 22 06:11:11 localhost vdr: [2310] buffer stats: 90992 (1%) used
Aug 22 06:11:11 localhost vdr: [2310] device 2 receiver thread ended (pid=1106, tid=2310)
Aug 22 06:11:11 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R90.custom after recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 06:11:11 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R91.custom after recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 06:11:11 localhost vdr: [1106] CAM 1/1: reusing MTD CAM slot
Aug 22 06:11:11 localhost vdr: [1106] CAM 1: assigned to device 1
Aug 22 06:11:11 localhost vdr: [1106] switching device 1 to channel 131 S19.2E-133-3-8 (Sky Cinema Comedy)
Aug 22 06:11:11 localhost vdr: [2752] device 1 receiver thread started (pid=1106, tid=2752, prio=high)
Aug 22 06:11:11 localhost vdr: [1106] timer 1 (131 0442-0620 'Taxi') start
Aug 22 06:11:11 localhost vdr: [1106] Title: 'Taxi' Subtitle: 'Actionkomödie'
Aug 22 06:11:11 localhost vdr: [1106] executing '/usr/lib/vdr/vdr-recordingaction before "/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec"'
Aug 22 06:11:11 localhost vdr: [2754] device 1 TS buffer thread started (pid=1106, tid=2754, prio=high)
Aug 22 06:11:11 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R90.custom before recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 06:11:11 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R91.custom before recording /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 06:11:12 localhost vdr: [1106] record /home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec
Aug 22 06:11:12 localhost vdr: [1106] recording to '/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec/00002.ts'
Aug 22 06:11:12 localhost vdr: [2775] recording thread started (pid=1106, tid=2775, prio=high)
Aug 22 06:11:14 localhost vdr: [2775] executing '/usr/lib/vdr/vdr-recordingaction started "/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec"'
Aug 22 06:11:14 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R90.custom
Aug 22 06:11:14 localhost recordingaction: executing /usr/share/vdr/recording-hooks/R91.custom
Aug 22 06:22:30 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 06:25:01 localhost CRON[2857]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Aug 22 06:35:30 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 06:36:26 localhost vdr: [1582] SVDRP < 127.0.0.1:42222 client connection accepted
Aug 22 06:36:26 localhost vdr: [1582] SVDRP < 127.0.0.1:42222 server created
Aug 22 06:36:28 localhost vdr: [1582] SVDRP < 127.0.0.1:42222 connection closed
Aug 22 06:36:28 localhost vdr: [1582] SVDRP < 127.0.0.1:42222 server destroyed
Aug 22 06:48:31 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 07:01:31 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 07:14:32 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 07:17:01 localhost CRON[3071]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 07:27:32 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 07:30:01 localhost CRON[3143]: (root) CMD (test -x /etc/init.d/anacron && /usr/sbin/invoke-rc.d anacron start >/dev/null)
Aug 22 07:30:01 localhost systemd[1]: Started Run anacron jobs.
Aug 22 07:30:01 localhost anacron[3165]: Anacron 2.3 started on 2017-08-22
Aug 22 07:30:01 localhost anacron[3165]: Normal exit (0 jobs run)
Aug 22 07:36:28 localhost vdr: [1582] SVDRP < 127.0.0.1:42308 client connection accepted
Aug 22 07:36:28 localhost vdr: [1582] SVDRP < 127.0.0.1:42308 server created
Aug 22 07:36:30 localhost vdr: [1582] SVDRP < 127.0.0.1:42308 connection closed
Aug 22 07:36:30 localhost vdr: [1582] SVDRP < 127.0.0.1:42308 server destroyed
Aug 22 07:40:33 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 07:53:33 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 08:06:34 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 08:17:01 localhost CRON[3356]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 08:19:34 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 08:32:35 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 08:36:30 localhost vdr: [1582] SVDRP < 127.0.0.1:42390 client connection accepted
Aug 22 08:36:30 localhost vdr: [1582] SVDRP < 127.0.0.1:42390 server created
Aug 22 08:36:32 localhost vdr: [1582] SVDRP < 127.0.0.1:42390 connection closed
Aug 22 08:36:32 localhost vdr: [1582] SVDRP < 127.0.0.1:42390 server destroyed
Aug 22 08:45:35 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 08:58:36 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 09:11:36 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 09:17:01 localhost CRON[3627]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 09:24:36 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 09:36:32 localhost vdr: [1582] SVDRP < 127.0.0.1:42476 client connection accepted
Aug 22 09:36:32 localhost vdr: [1582] SVDRP < 127.0.0.1:42476 server created
Aug 22 09:36:34 localhost vdr: [1582] SVDRP < 127.0.0.1:42476 connection closed
Aug 22 09:36:34 localhost vdr: [1582] SVDRP < 127.0.0.1:42476 server destroyed
Aug 22 09:37:37 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 09:50:37 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 10:03:38 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 10:16:38 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 10:17:01 localhost CRON[3887]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 10:29:39 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 10:36:34 localhost vdr: [1582] SVDRP < 127.0.0.1:42562 client connection accepted
Aug 22 10:36:34 localhost vdr: [1582] SVDRP < 127.0.0.1:42562 server created
Aug 22 10:36:36 localhost vdr: [1582] SVDRP < 127.0.0.1:42562 connection closed
Aug 22 10:36:36 localhost vdr: [1582] SVDRP < 127.0.0.1:42562 server destroyed
Aug 22 10:42:39 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 10:55:40 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 11:08:40 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 11:17:01 localhost CRON[4148]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 11:21:41 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 11:34:41 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 11:47:42 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 11:47:56 localhost vdr: [1582] SVDRP < 127.0.0.1:42668 client connection accepted
Aug 22 11:47:56 localhost vdr: [1582] SVDRP < 127.0.0.1:42668 server created
Aug 22 11:47:58 localhost vdr: [1582] SVDRP < 127.0.0.1:42668 connection closed
Aug 22 11:47:58 localhost vdr: [1582] SVDRP < 127.0.0.1:42668 server destroyed
Aug 22 12:00:42 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 12:13:43 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 12:17:01 localhost CRON[4410]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 12:26:43 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 12:28:01 localhost CRON[4471]: (root) CMD (   test -x /etc/cron.daily/popularity-contest && /etc/cron.daily/popularity-contest --crond)
Aug 22 12:39:44 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 12:40:29 localhost dhclient[1203]: DHCPREQUEST of 192.168.178.12 on eth0 to 192.168.178.13 port 67 (xid=0x235dda3d)
Aug 22 12:40:29 localhost dhclient[1203]: DHCPACK of 192.168.178.12 from 192.168.178.13
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2674]   address 192.168.178.12
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2674]   plen 24 (255.255.255.0)
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2674]   gateway 192.168.178.1
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2674]   server identifier 192.168.178.13
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2674]   lease time 86400
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2675]   hostname 'Kodi-MC'
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2675]   nameserver '192.168.178.13'
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2675]   domain name 'internal'
Aug 22 12:40:29 localhost NetworkManager[991]: <info>  [1503398429.2675] dhcp4 (eth0): state changed bound -> bound
Aug 22 12:40:29 localhost dbus[927]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Aug 22 12:40:29 localhost systemd[1]: Starting Network Manager Script Dispatcher Service...
Aug 22 12:40:29 localhost dbus[927]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 22 12:40:29 localhost systemd[1]: Started Network Manager Script Dispatcher Service.
Aug 22 12:40:29 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: new request (1 scripts)
Aug 22 12:40:29 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: start running ordered scripts...
Aug 22 12:40:29 localhost dhclient[1203]: bound to 192.168.178.12 -- renewal in 39072 seconds.
Aug 22 12:47:58 localhost vdr: [1582] SVDRP < 127.0.0.1:42754 client connection accepted
Aug 22 12:47:58 localhost vdr: [1582] SVDRP < 127.0.0.1:42754 server created
Aug 22 12:48:00 localhost vdr: [1582] SVDRP < 127.0.0.1:42754 connection closed
Aug 22 12:48:00 localhost vdr: [1582] SVDRP < 127.0.0.1:42754 server destroyed
Aug 22 12:52:44 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 13:05:45 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 13:09:16 localhost vdr: [2775] recording to '/home/kodi/Aufnahmen/Taxi/2017-08-22.04.42.131-0.rec/00003.ts'
Aug 22 13:11:46 localhost vdr: [1451] read incomplete section - len = 18, r = 846
Aug 22 13:17:01 localhost CRON[4682]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 13:18:45 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 13:22:59 localhost kernel: [38485.332345] perf interrupt took too long (2515 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
Aug 22 13:25:03 localhost vdr: [1451] read incomplete section - len = 419, r = 252
Aug 22 13:31:46 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 13:44:46 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 13:48:00 localhost vdr: [1582] SVDRP < 127.0.0.1:42832 client connection accepted
Aug 22 13:48:00 localhost vdr: [1582] SVDRP < 127.0.0.1:42832 server created
Aug 22 13:48:02 localhost vdr: [1582] SVDRP < 127.0.0.1:42832 connection closed
Aug 22 13:48:02 localhost vdr: [1582] SVDRP < 127.0.0.1:42832 server destroyed
Aug 22 13:57:47 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 14:10:47 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 14:17:01 localhost CRON[4945]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 14:17:07 localhost /usr/lib/snapd/snapd[1004]: snapmgr.go:422: No snaps to auto-refresh found
Aug 22 14:17:07 localhost snapd[1004]: 2017/08/22 14:17:07.000542 snapmgr.go:422: No snaps to auto-refresh found
Aug 22 14:22:06 localhost /usr/lib/snapd/snapd[1004]: snapmgr.go:504: DEBUG: Next refresh scheduled for 2017-08-22 19:56:49.657804097 +0200 CEST.
Aug 22 14:23:48 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 14:32:48 localhost vdr: [1455] read incomplete section - len = 811, r = 15
Aug 22 14:36:48 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 14:48:02 localhost vdr: [1582] SVDRP < 127.0.0.1:42920 client connection accepted
Aug 22 14:48:02 localhost vdr: [1582] SVDRP < 127.0.0.1:42920 server created
Aug 22 14:48:04 localhost vdr: [1582] SVDRP < 127.0.0.1:42920 connection closed
Aug 22 14:48:04 localhost vdr: [1582] SVDRP < 127.0.0.1:42920 server destroyed
Aug 22 14:49:49 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 14:59:54 localhost vdr: [1451] read incomplete section - len = 1778, r = 799
Aug 22 15:00:53 localhost vdr: [1455] read incomplete section - len = 718, r = 327
Aug 22 15:02:49 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 15:15:50 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 15:17:01 localhost CRON[5210]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 15:28:50 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 15:41:51 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 15:48:04 localhost vdr: [1582] SVDRP < 127.0.0.1:43002 client connection accepted
Aug 22 15:48:04 localhost vdr: [1582] SVDRP < 127.0.0.1:43002 server created
Aug 22 15:48:06 localhost vdr: [1582] SVDRP < 127.0.0.1:43002 connection closed
Aug 22 15:48:06 localhost vdr: [1582] SVDRP < 127.0.0.1:43002 server destroyed
Aug 22 15:54:51 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 16:07:52 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 16:17:01 localhost CRON[5466]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 16:20:52 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 16:27:55 localhost kernel: [49581.170447] [drm] Got external EDID base block and 1 extension from "edid/edid.bin" for connector "HDMI-A-2"
Aug 22 16:29:43 localhost vdr: [1463] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
Aug 22 16:29:43 localhost vdr: [1463] VNSI: Client with ID 6 connected: 127.0.0.1:37300
Aug 22 16:31:00 localhost systemd[1]: Started Session 59 of user kodi.
Aug 22 16:33:53 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 16:46:53 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 16:48:06 localhost vdr: [1582] SVDRP < 127.0.0.1:43126 client connection accepted
Aug 22 16:48:06 localhost vdr: [1582] SVDRP < 127.0.0.1:43126 server created
Aug 22 16:48:08 localhost vdr: [1582] SVDRP < 127.0.0.1:43126 connection closed
Aug 22 16:48:08 localhost vdr: [1582] SVDRP < 127.0.0.1:43126 server destroyed
Aug 22 16:59:54 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 17:12:54 localhost systemd[1]: Started CUPS Scheduler.
Aug 22 17:17:01 localhost CRON[5836]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 17:17:29 localhost systemd[1]: Started Session 63 of user kodi.


RE: Timer based recoding doesn't terminate / kodi and vdr disconnect - FernetMenta - 2017-08-23

vnsi is not involved here. did you post this issue on vdr-portal forum already?

RE: Timer based recoding doesn't terminate / kodi and vdr disconnect - Spirou - 2017-08-23

No, not yet. I was waiting for confirmation that it is not VNSI related. Will post it there as soon as possible.

Update: Posted on vdr-portal. Now waiting for feedback.