[mythtv-users] writeStringList error no data written on writeBlock

Mon Sep 2 04:53:38 UTC 2013

Hi all, I might have had this issue occur for me again. Running version
0.27. Frontend appeared to lose contact with the Backend. This time did not
fix itself after 5-10min. Checked the Backend log and found a slightly
different message but this might be just the difference between fixes/0.26
(when it first occurred for me) and 0.27 (now). Error was
"MythSocketThread(81) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(9124f98:-1): WriteStringList: Error, called with unconnected
socket".

Or it might be completely unrelated, I don't really know.

On a hunch I tried to restart the logserver but this made no difference
(couldn't think of anything else to try). I waited until I was confident
that any in-progress recordings would have finished then rebooted.
Everything then came back up fine and all in-progress recordings did indeed
complete successfully.

If anyone is able to point me in the right direction to troubleshoot this it
would be greatly appreciated.

Snippet of mythbackend.log file details next:

Aug 30 19:32:36 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest ringbuffer.cpp:1097 (WaitForAvail)
RingBuf(/media/fs1/recordings/1024_20130830093357.mpg): Waited 0.2 seconds
for data #012#011#011#011to become available... 70732 < 229376

Aug 30 19:32:36 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest ringbuffer.cpp:1097 (WaitForAvail)
RingBuf(/media/fs1/recordings/1024_20130830093357.mpg): Waited 0.2 seconds
for data #012#011#011#011to become available... 155676 < 229376

Aug 30 19:32:37 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
Scheduler scheduler.cpp:2644 (HandleRecordingStatusChange) Tuning recording:
"Doctor Who":"Voyage of the Damned": channel 1022 on cardid 13, sourceid 1

Aug 30 19:32:37 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
CoreContext scheduler.cpp:704 (UpdateRecStatus) Updating status for "Doctor
Who":"Voyage of the Damned" on cardid 13 (Tuning => Recording)

Aug 30 19:32:37 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 3 min

Aug 30 19:32:38 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest ringbuffer.cpp:1097 (WaitForAvail)
RingBuf(/media/fs1/recordings/1024_20130830093357.mpg): Waited 0.2 seconds
for data #012#011#011#011to become available... 173212 < 229376

Aug 30 19:32:38 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I DVBRead
tv_rec.cpp:3393 (RingBufferChanged) TVRec[15]: RingBufferChanged()

Aug 30 19:32:38 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I DVBRead
tv_rec.cpp:832 (FinishedRecording) TVRec[15]:
FinishedRecording(1024_2013-08-30T09:33:57Z) damaged recq:<RecordingQuality
overall_score="0" key="1024_2013-08-30T09:33:57Z"
countinuity_error_count="0" packet_count="9494253">#012    <Gap
start="2013-08-30T09:30:00Z" end="2013-08-30T09:33:58Z" duration="238"
/>#012</RecordingQuality>

Aug 30 19:32:39 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest ringbuffer.cpp:1097 (WaitForAvail)
RingBuf(/media/fs1/recordings/1024_20130830093357.mpg): Waited 0.2 seconds
for data #012#011#011#011to become available... 192700 < 229376

Aug 30 19:32:39 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest ringbuffer.cpp:1097 (WaitForAvail)
RingBuf(/media/fs1/recordings/1024_20130830093357.mpg): Waited 0.5 seconds
for data #012#011#011#011to become available... 192700 < 229376

Aug 30 19:35:39 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
TVRecEvent tv_rec.cpp:1048 (HandleStateChange) TVRec[15]: Changing from
WatchingLiveTV to None

Aug 30 19:35:39 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
TVRecEvent tv_rec.cpp:832 (FinishedRecording) TVRec[15]:
FinishedRecording(1024_2013-08-30T10:02:37Z) damaged recq:<RecordingQuality
overall_score="0" key="1024_2013-08-30T10:02:37Z"
countinuity_error_count="0" packet_count="928912">#012    <Gap
start="2013-08-30T10:00:00Z" end="2013-08-30T10:02:38Z" duration="158"
/>#012    <Gap start="2013-08-30T10:05:38Z" end="2013-08-30T10:30:00Z"
duration="1461" />#012</RecordingQuality>

Aug 30 19:36:57 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: N
CoreContext autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max
required Free Space: 3.0 GB w/freq: 4 min

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 4 min

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(81) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(9124f98:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(82) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(919b668:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(81) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a4c98:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(110) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a2dd0:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(108) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a2438:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(104) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a7558:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(86) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a9900:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(86) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a51b0:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(106) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a7e98:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(95) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a93c8:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(82) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(919c9c8:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(85) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91a4fe0:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding: mark-P5K-Deluxe
as a client (events: 0)

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(102) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(91900c0:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(97) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(919bc50:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:36:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: E
MythSocketThread(83) mythsocket.cpp:663 (WriteStringListReal)
MythSocket(919e0b8:-1): WriteStringList: Error, called with unconnected
socket.

Aug 30 19:37:23 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:37:23 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding: mark-P5K-Deluxe
as a client (events: 0)

Aug 30 19:38:01 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:38:01 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding: mark-P5K-Deluxe
as a client (events: 0)

Aug 30 19:38:58 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I SSDP
mythdbcon.cpp:409 (PurgeIdleConnections) New DB connection, total: 23

Aug 30 19:38:59 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:38:59 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding:
myth-lounge-desktop as a client (events: 0)

Aug 30 19:39:00 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:39:00 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding:
myth-lounge-desktop as a client (events: 1)

Aug 30 19:39:04 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:39:04 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding: mark-P5K-Deluxe
as a client (events: 0)

Aug 30 19:39:04 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Monitor

Aug 30 19:39:04 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding: mark-P5K-Deluxe
as a client (events: 1)

Aug 30 19:39:12 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1430 (HandleAnnounce) MainServer::ANN Playback

Aug 30 19:39:12 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
ProcessRequest mainserver.cpp:1432 (HandleAnnounce) adding:
myth-lounge-desktop as a client (events: 0)

Aug 30 19:39:12 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
TVRecEvent tv_rec.cpp:1048 (HandleStateChange) TVRec[15]: Changing from None
to WatchingLiveTV

Aug 30 19:39:12 mark-P5K-Deluxe mythlogserver: mythbackend[3010]: I
TVRecEvent tv_rec.cpp:3597 (TuningCheckForHWChange) TVRec[15]: HW Tuner:
15->15

Also in case a mythbackend.log with a wider timeframe is useful I have put a
larger segment onto dropbox
https://www.dropbox.com/s/4qenejkkh7pssn4/Mythbackend.log.

Any assistance would be greatly appreciated.

Mark.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.mythtv.org/pipermail/mythtv-users/attachments/20130902/3068e545/attachment-0001.html>