Slave backend sending events to master

[gregorio.gervasio@…]

After the recent socket merge, I started having communication problems between slave and master backends. It seems the slave is sending events to the master, which can cause the master to receive the wrong response to a request.

Here's an example where the master is asking the slave to start recording a show. The logs are "-v socket,network --loglevel debug". On the master:

2012-12-28 19:43:28.590069 I [25772/25852] MythSocketThread(91) mythsocket.cpp:697 (WriteStringListReal) - MythSocket(b247f0:91): write -> 91 564     QUERY_REMOTEENCODER 5[]:[]START_RECORDING[]:[]Access Hollywood[]:[][]:[]Top stories of 2012; celebrity scandals; ''The Promised Land'' cast.[]:[]0[]:[]0[]:[]4255[]:[]Talk[]:[]2703[]:[]703[]:[]KNTVDT[]:[]KNTVDT (KNTV-DT)[]:[]/home/mythtv/store.w2[]:[]0[]:[]1356751800[]:[]1356753600[]:[]0[]:[]slave1.home[]:[]2[]:[]5[]:[]5[]:[]3[]:[]-1[]:[]10549[]:[]1[]:[]15[]:[]6[]:[]1356752580[]:[]1356753600[]:[]0[]:[]Default[]:[][]:[]EP00188707[]:[]EP001887074533[]:[][]:[]1356752607[]:[]0[]:[]2012-12-28[]:[]Default[]:[]0[]:[]0[]:[]Default[]:[]1[]:[]33[]:[]0[]:[]0[]:[]0[]:[]0
2012-12-28 19:43:28.636219 I [25772/25852] MythSocketThread(91) mythsocket.cpp:898 (ReadStringListReal) - MythSocket(b247f0:91): read  <- 91 138     BACKEND_MESSAGE[]:[]SYSTEM_EVENT REC_STARTED CARDID 5 CHANID 2703 STARTTIME 2012-12-29T03:43:00Z RECSTATUS -1 SENDER slave1.home[]:[]empty
2012-12-28 19:43:28.636276 E [25772/25808] Scheduler mythsocket.cpp:351 (SendReceiveStringList) - MythSocket(b247f0:91): Got MythEvent on non-event socket
2012-12-28 19:43:28.636285 E [25772/25808] Scheduler playbacksock.cpp:94 (SendReceiveStringList) - PlaybackSock::SendReceiveStringList(): No response.

On the slave:

2012-12-28 19:43:28.590328 I [8761/8798] MythSocketThread(-1) mythsocket.cpp:898 (ReadStringListReal) - MythSocket(ee0390:70): read  <- 70 564     QUERY_REMOTEENCODER 5[]:[]START_RECORDING[]:[]Access Hollywood[]:[][]:[]Top stories of 2012; celebrity scandals; ''The Promised Land'' cast.[]:[]0[]:[]0[]:[]4255[]:[]Talk[]:[]2703[]:[]703[]:[]KNTVDT[]:[]KNTVDT (KNTV-DT)[]:[]/home/mythtv/store.w2[]:[]0[]:[]1356751800[]:[]1356753600[]:[]0[]:[]slave1.home[]:[]2[]:[]5[]:[]5[]:[]3[]:[]-1[]:[]10549[]:[]1[]:[]15[]:[]6[]:[]1356752580[]:[]1356753600[]:[]0[]:[]Default[]:[][]:[]EP00188707[]:[]EP001887074533[]:[][]:[]1356752607[]:[]0[]:[]2012-12-28[]:[]Default[]:[]0[]:[]0[]:[]Default[]:[]1[]:[]33[]:[]0[]:[]0[]:[]0[]:[]0
2012-12-28 19:43:28.590350 D [8761/8799] ProcessRequest mainserver.cpp:470 (ProcessRequestWork) - PRW: command='QUERY_REMOTEENCODER'
2012-12-28 19:43:28.635909 I [8761/8799] ProcessRequest mythcorecontext.cpp:1211 (dispatch) - MythEvent: SYSTEM_EVENT REC_STARTED CARDID 5 CHANID 2703 STARTTIME 2012-12-29T03:43:00Z RECSTATUS -1 SENDER slave1.home
2012-12-28 19:43:28.636038 I [8761/8798] MythSocketThread(-1) mythsocket.cpp:697 (WriteStringListReal) - MythSocket(ee0390:70): write -> 70 138     BACKEND_MESSAGE[]:[]SYSTEM_EVENT REC_STARTED CARDID 5 CHANID 2703 STARTTIME 2012-12-29T03:43:00Z RECSTATUS -1 SENDER slave1.home[]:[]empty

When the slave sends the actual response:

2012-12-28 19:43:28.669287 I [8761/8798] MythSocketThread(-1) mythsocket.cpp:697 (WriteStringListReal) - MythSocket(ee0390:70): write -> 70 3       -10

the master thinks there is an unknown command:

2012-12-28 19:43:28.669410 D [25772/25852] MythSocketThread(91) mythsocket.cpp:284 (CallReadyReadHandler) - MythSocket(b247f0:91): calling m_callback->readyRead()
2012-12-28 19:43:28.669447 D [25772/25848] ProcessRequest mainserver.cpp:148 (run) - Processing request for sock 91
2012-12-28 19:43:28.669521 I [25772/25852] MythSocketThread(91) mythsocket.cpp:898 ReadStringListReal) - MythSocket(b247f0:91): read  <- 91 3       -10
2012-12-28 19:43:28.669543 D [25772/25848] ProcessRequest mainserver.cpp:470 (ProcessRequestWork) - PRW: command='-10'
2012-12-28 19:43:28.669553 E [25772/25848] ProcessRequest mainserver.cpp:877 (ProcessRequestWork) - Unknown command: -10
2012-12-28 19:43:28.669586 I [25772/25852] MythSocketThread(91) mythsocket.cpp:697 (WriteStringListReal) - MythSocket(b247f0:91): write -> 91 15      UNKNOWN_COMMAND

The attached patch seems to fix the issue but I'm not sure if it will cause other problems.

[verycoldpenguin@…]

Hello, I have been running this patch for a while now. It believe it has stopped the cause of the segfaults I experienced in #11318 (I am also running my patch from there, which logs and drops the corruption). However, I have got a problem which O believe might be a side-effect. I have efectively 3 backends in the setup. a master backend b backend/frontend combined c slave backend

I can play recordings on b which have been recorded on a or b, but I cannot play any recorded from c at the moment. I receive an Operation not permitted response at the front end.

[gregorio.gervasio@…]

more correct patch

[gregorio.gervasio@…]

Sorry, the first patch is incorrect. If you're using it, you should revert it*. I misunderstood how things were being done before the socket changes. Here's another patch that I believe restores the processing of backend messages received by the master backend while waiting for a response (like it did before 0b106b10692ed7efd5eae81b498f591ad39b6222).

[Yianni Vidalis <yiannividalis@…>]

Gregorio, your second patch seems to bee correcting my problem at ticket #11272.

Thanks a lot.

Yianni.

[danielk]

This seems to be pointing to the slave backend sending events on the command socket. Which is not allowed for obvious reasons.

[sphery]

Master backend log (-v socket --loglevel debug) from David Shay without #11316 patch showing errors

[sphery]

Remote backend log (-v socket --loglevel debug) from David Shay without #11316 patch showing errors

[gregorio.gervasio@…]

Replying to danielk:

This seems to be pointing to the slave backend sending events on the command socket. Which is not allowed for obvious reasons.

I first assumed that it wasn't allowed so that's why this ticket has that title and why the first patch was submitted (it has the slave disable events when it creates its socket to master). However, although the first patch also stopped segfaults like the ones in #11272 and #11318, it didn't fix other things (eg. missed recordings).

Is there a separate socket to the master where the slave is allowed to send events?

[davideshay@…]

Per conversation with danielk on irc, please note that it seems that the master sends the slave a QUERY_FREE_SPACE command. The slave then responds with the standard hostname-directory-etc. response, but the master seems to be interpreting this as a new command rather than a response to "QUERY_FREE_SPACE" and thus issues "unknown command" and finally crashes. Seems like that might a part of the problem.

[gregorio.gervasio@…]

David, I believe that mode of failure is described in ​http://code.mythtv.org/trac/ticket/11318#comment:3

[stuartm]

See also #11272

[Gregorio Gervasio <gregorio.gervasio@…>]

In a6c0330baa5ab01d3877a3d56818c3fcf8068a28/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Gregorio Gervasio <gregorio.gervasio@…>]

In 033883bbde71217d85f51ed8eef2f8528aeeca33/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available