Opened 6 years ago

Closed 6 years ago

Last modified 6 years ago

#11316 closed Bug Report - Crash (fixed)

Slave backend sending events to master

Reported by: gregorio.gervasio@… Owned by: danielk
Priority: blocker Milestone: 0.27
Component: MythTV - General Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

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.

Attachments (4)

slave_events-v0.27-pre2-460-g83872a3.patch (769 bytes) - added by gregorio.gervasio@… 6 years ago.
slave_events-v0.27-pre2-596-g397d1e9.patch (1.4 KB) - added by gregorio.gervasio@… 6 years ago.
more correct patch
master_backend_without_patch.log (193.7 KB) - added by sphery 6 years ago.
Master backend log (-v socket --loglevel debug) from David Shay without #11316 patch showing errors
remote_backend_without_patch.log (10.0 KB) - added by sphery 6 years ago.
Remote backend log (-v socket --loglevel debug) from David Shay without #11316 patch showing errors

Download all attachments as: .zip

Change History (17)

Changed 6 years ago by gregorio.gervasio@…

comment:1 Changed 6 years ago by danielk

Milestone: unknown0.27
Owner: set to danielk
Status: newassigned
Version: UnspecifiedMaster Head

comment:2 Changed 6 years ago by 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.

Changed 6 years ago by gregorio.gervasio@…

more correct patch

comment:3 Changed 6 years ago by 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).

comment:4 Changed 6 years ago by Yianni Vidalis <yiannividalis@…>

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

Thanks a lot.

Yianni.

comment:5 Changed 6 years ago by danielk

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

Changed 6 years ago by sphery

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

Changed 6 years ago by sphery

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

comment:6 in reply to:  5 Changed 6 years ago by 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?

comment:7 Changed 6 years ago by 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.

comment:8 Changed 6 years ago by gregorio.gervasio@…

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

comment:9 Changed 6 years ago by stuartm

Priority: minorblocker

comment:10 Changed 6 years ago by stuartm

Type: Bug Report - GeneralBug Report - Crash

comment:11 Changed 6 years ago by stuartm

See also #11272

comment:12 Changed 6 years ago by Gregorio Gervasio <gregorio.gervasio@…>

Resolution: fixed
Status: assignedclosed

In a6c0330baa5ab01d3877a3d56818c3fcf8068a28/mythtv:

Fix master backend crashing when receiving events from a slave

This is a workaround for 0.27 and requires a proper fix.

Fixes #11316

Signed-off-by: Daniel Kristjansson <danielk@…>
Signed-off-by: Stuart Morgan <smorgan@…>

comment:13 Changed 6 years ago by Gregorio Gervasio <gregorio.gervasio@…>

In 033883bbde71217d85f51ed8eef2f8528aeeca33/mythtv:

Fix master backend crashing when receiving events from a slave

This is a workaround for 0.27 and requires a proper fix.

Fixes #11316

Signed-off-by: Daniel Kristjansson <danielk@…>
Signed-off-by: Stuart Morgan <smorgan@…>
(cherry picked from commit a6c0330baa5ab01d3877a3d56818c3fcf8068a28)

Note: See TracTickets for help on using tickets.