[mythtv] Overlapping calls to readSocket

Wed Apr 13 07:24:20 UTC 2005

Bruce Markey wrote:
> Brian Foddy wrote:
> 
>> On Tuesday 12 April 2005 09:52 pm, Buechler, Mark R wrote:
>>
>>> After 2 hours of running in gdb I received this error before the backend
>>> locked:
>>>
>>> QSocketNotifier: Multiple socket notifiers for same socket 23 and 
>>> type read
>>>
>>> The backend still didn't dump, however, it just stopped sending 
>>> packets and
>>> refused new connections.
>>>
>>> -----Original Message-----
>>> From: Buechler, Mark R [mailto:Mark_R_Buechler at bausch.com]
>>> Sent: Tuesday, April 12, 2005 7:56 PM
>>> To: 'Development of mythtv'
>>> Subject: [mythtv] Overlapping calls to readSocket
>>>
>>> Updated to todays CVS and I see there's been updates to mainserver.cpp.
>>> Since then I'm getting in the log a few "Overlapping calls to 
>>> readSocket"
>>> messages. Has anyone else seen these? Shortly after these messages 
>>> appear
>>> the backend dumps. I'm unable to get the backend to dump under gdb which
>>> points to a possible race condition. Was wondering if anyone else has 
>>> seen
>>> this as well.
>>>
>>> - Mark.
>>
>>
>>
>> I too have seen this, I took a cvs snap from last night, just before 
>> bjm's last UNKNOWN_COMMAND, but there were others just before
>> it that looked promising.  I've only run 1 day on it so I can't give a 
>> full
>> report but at least one time these messages seemed to precede a 
>> necessary restart of both master / slave backends.
> 
> 
> As I'd mentioned in another thread, the changes I've made are more
> geared to trying to recover after something has gone wrong. We still
> don't know for a fact what exactly triggered the out of sequence or
> garbled messages though some of the things Isaac did probably address
> the most likely causes. BTW, the Overlapping message is more debugging
> info than any sort of serious problem.
> 
> If you could, please do the following for the next day or so. Install
> current CVS and run:
> 
> mythbackend -v network >> /tmp/mb.log 2>&1 &
> 
> on both the master and any slaves. Later "grep Protocol /tmp/mb.log".
> If there is a match, please cut'n'paste all the messages from
> a minute before up to a minute after the "Protocol error:" message
> and grab the messages in the same time frame from the slave's log.
> 
> Thank you,
> 
> --  bjm
> _______________________________________________
> mythtv-dev mailing list
> mythtv-dev at mythtv.org
> http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-dev

, and not with absolute current CVS - About 2 hours before Isaac's "More 
locking for the sockets" checkin.

This is actually with -v all, however, I've stripped the logs, leaving 
the interesting bits. I just found out that my MBE and slave are not 
syncronised timewise. I'll fix that now.

MBE:
----------------------------------------
2005-04-13 03:03:28.621 Overlapping calls to readSocket.
2005-04-13 03:03:28.627 Reschedule requested for id 0.
2005-04-13 03:03:28.627 15      QUERY_FREESPACE
2005-04-13 03:03:28.637 Protocol error: 'BACKEND_' is not a valid size 
prefix. 4
3 bytes pending.
ASSERT: "i <= nodes" in /usr/qt/3/include/qvaluelist.h (373)
2005-04-13 03:03:28.639 PruneOldRecords...
Waiting for data: 0 51
2005-04-13 03:03:28.651 AddNewRecords...
2005-04-13 03:03:28.660  |-- Start DB Query...
2005-04-13 03:03:28.677 Overlapping calls to readSocket.
EOF readStringList 15
2005-04-13 03:03:28.834 Unknown command: 7
2005-04-13 03:03:28.835 15      UNKNOWN_COMMAND
2005-04-13 03:03:29.083  |-- 1504 results in 0.422666 sec. Processing...
2005-04-13 03:03:29.455  +-- Cleanup...
2005-04-13 03:03:29.456 Sort by time...
2005-04-13 03:03:29.458 PruneOverlaps...
...
2005-04-13 03:04:17.272 Starting Commercial Flagging for "A Life of 
Grime" recor
ded from channel 4000 at Wed Apr 13 02:25:00 2005.
2005-04-13 03:04:17.276 commflag: Commercial Flagging Starting
2005-04-13 03:04:18.283 New DB connection, total: 1
2005-04-13 03:04:18.351 New DB connection, total: 2
----------------------------------------

SBE:
----------------------------------------
2005-04-13 03:05:00.018 Finished recording A Life of Grime on channel: 4000
2005-04-13 03:05:00.033 Changing from RecordingOnly to None
2005-04-13 03:05:00.033 53 
BACKEND_MESSAGE[]:[]RESCHEDULE_RECORDINGS 0[]:[.
..
2005-04-13 03:05:00.033 51      BACKEND_MESSAGE[]:[]DONE_RECORDING 3 
2335[]:[]e.
..
2005-04-13 03:05:00.042 Closing DVB recorder
2005-04-13 03:05:00.089 7       0[]:[]0
2005-04-13 03:05:00.328 Got 'UNKNOWN_COMMAND' out of sequence.
2005-04-13 03:05:00.565 51 
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]e.
..
----------------------------------------

Also, is it really necessary to:
2005-04-13 02:31:17.632 54 
BACKEND_MESSAGE[]:[]RESCHEDULE_RECORDINGS -1[]:.
..
2005-04-13 02:31:20.638 54 
BACKEND_MESSAGE[]:[]RESCHEDULE_RECORDINGS -1[]:.
..
2005-04-13 02:31:23.849 54 
BACKEND_MESSAGE[]:[]RESCHEDULE_RECORDINGS -1[]:.
..

Quite so often? Surely once per second (or, preferably, 30 seconds) 
would be better?