search

MythTV / mythtv

The official MythTV repository
https://www.mythtv.org
GNU General Public License v2.0
708 stars 346 forks source link

Frontend and backend do not exit in a timely manner #274

Open stuarta opened 4 years ago

stuarta commented 4 years ago

master & fixes/31

n/a

How often does it reproduce? Is there a required condition?

100%

What is the expected behaviour?

Exiting quickly

What do you see instead?

Slow application shutdown due to some threads taking ages to die.

mark-kendall commented 4 years ago

I've looked at this before. The main problem appears to be the UPnP code (custom socket code, blocking calls etc)

kmdewaal commented 3 years ago

Looking at the log message of my mythbackend shows that the exit of mythbackend always takes at least about 14 seconds. This is indeed caused by UPnP code; there is a two-phase UPnP shutdown and each takes about 7 seconds. See attachment 20210104-t1.log. It can be discussed whether the UPnP shutdown is necessary. It is the correct thing to do, telling the clients that this server does disappear, but it is also possible that the server crashes or is switched of and then the clients also have to handle this.

Sometimes the backend shutdown takes much longer, even several minutes. See attachment 20210104-t2.log where the complete shutdown takes 3 minutes. What I did here was channel zapping with LiveTV, where each channel is only watched for a few seconds before moving to the next channel. In MythTV for each channel a separate recording is created. On shutdown, mythbackend is going to delete all these files. This is in itself not wrong, but each file deletion takes about five seconds. The five seconds is caused by sleep statements in mainserver.cpp where the file deletions are done. There must have been a good reason for the five seconds delay but it was probably never intended that these delays are used at system shutdown. A possible solution can be to delete all files without the sleep statements when the system is shutting down. Or not to delete the files at all but delete them later in the background when the system is running again.

kmdewaal commented 3 years ago

20210104-t1.log

kmdewaal commented 3 years ago

20210104-t2.log

garybuhrmaster commented 3 years ago

Looking at the log message of my mythbackend shows that the exit of mythbackend always takes at least about 14 seconds. This is indeed caused by UPnP code; there is a two-phase UPnP shutdown and each takes about 7 seconds. ... It can be discussed whether the UPnP shutdown is necessary.

Not really. The uPnP standard uses a "SHOULD" to specify that the notifications are to be withdrawn.

It is the correct thing to do, telling the clients that this server does disappear, but it is also possible that the server crashes or is switched of and then the clients also have to handle this.

And that is why the specification also states that the advertisements are expected to include a timeout (so that abrupt losses can be handed, although many clients will themselves react poorly with continued attempts to contact a server that is considered alive, which is the why of the SHOULD in the withdrawal expectation).

Now, perhaps, MythTV is not optimally implementing the full standards such that timing could change a bit. That is a worthwhile thing to investigate.

stuarta commented 3 years ago

Looking at the log message of my mythbackend shows that the exit of mythbackend always takes at least about 14 seconds. This is indeed caused by UPnP code; there is a two-phase UPnP shutdown and each takes about 7 seconds. See attachment 20210104-t1.log. It can be discussed whether the UPnP shutdown is necessary. It is the correct thing to do, telling the clients that this server does disappear, but it is also possible that the server crashes or is switched of and then the clients also have to handle this.

We should look into whether something like ADSL's dying gasp is possible. ie. Fire off a "bye bye" message then terminate without waiting for any replies.

Sometimes the backend shutdown takes much longer, even several minutes. See attachment 20210104-t2.log where the complete shutdown takes 3 minutes. What I did here was channel zapping with LiveTV, where each channel is only watched for a few seconds before moving to the next channel. In MythTV for each channel a separate recording is created. On shutdown, mythbackend is going to delete all these files. This is in itself not wrong, but each file deletion takes about five seconds. The five seconds is caused by sleep statements in mainserver.cpp where the file deletions are done. There must have been a good reason for the five seconds delay but it was probably never intended that these delays are used at system shutdown. A possible solution can be to delete all files without the sleep statements when the system is shutting down. Or not to delete the files at all but delete them later in the background when the system is running again.

This sounds like the code that was added to slow down delete's of recordings so they didn't DOS the backend during normal operation. What needs to happen is that at shutdown, these are pushed to a "delete later queue" which is probably as simple as moving them to the deleted storage group (like what happens when a recording is explicitly deleted).

When the backend is back up and running, the normal housekeeping functions will take care of removing deleted recordings.

ulmus-scott commented 2 years ago

While perhaps implied by the comment thread, running mythbackend --noupnp does allow the backend to almost instantly (within 5 ms) close, e.g. by Ctrl+C interrupt.

stuarta commented 2 years ago

@ulmus-scott the SSDP specification documents the required "bye-bye" procedure which includes sending 3 goodbye messages with a minimum delay between them.

I'll do some more digging to see if there are any other threads which do not die in a timely manner

ulmus-scott commented 2 years ago

@stuarta from my reading of the specification you are incorrect.

Conformance terminology on page 13: in particular recommended/should §1.2 Advertisement on pages 24-35 §1.2.2 Device available - NOTIFY with ssdp:alive in particular page 28

Due to the unreliable nature of UDP, devices should send the entire set of discovery messages more than once with some delay between sets e.g. a few hundred milliseconds. To avoid network congestion discovery messages should not be sent more than three times.

Note should; this is only for ssdp:alive; delay between each set of messages, not each message as MythTV does currently; should not send more than thrice in a short period.

§1.2.3 Device unavailable -- NOTIFY with ssdp:byebye pages 32 and 33

When a device and its services are going to be removed from the network, the device should multicast an ssdp:byebye message corresponding to each of the ssdp:alive messages it multicasted that have not already expired. If the device is removed abruptly from the network, it might not be possible to multicast a message. As a fallback, discovery messages shall include an expiration value in a CACHE-CONTROL field value (as explained above); if not re- advertised, the discovery message eventually expires on its own.

(Note: when a control point is about to be removed from the network, no discovery-related action is required.)

When a device is about to be removed from the network, it should explicitly revoke its discovery messages by sending one multicast message for each ssdp:alive message it sent.

Note should; one ssdp:byebye message per unexpired ssdp:alive; no mention of repeating the message (which follows from it being optional/recommended; if the device is going off the network, it makes no sense to try extending its lifetime on the network, which the device may not be able to control).

stuarta commented 2 years ago

Should be easy enough to fire off a single bye-bye and then shutdown

ulmus-scott commented 2 years ago

https://github.com/MythTV/mythtv/commit/8e206e3d05095baab30de53a4dcece0806e010ed could also be applied to fixes/31. However, it does not apply cleanly since random() was changed to MythRandom() in master. Edited That commit should speed up the shutdown of both the backend and the frontend.

backend

There is still a 0.3 s - 4 s delay between the two sets of byebye messages:

2021-12-07 17:55:30.090780 C [21906/21906] CoreContext signalhandling.cpp:288 (handleSignal) - Received Interrupt: Code 128, PID 0, UID 0, Value 0x00000000
2021-12-07 17:55:30.093084 N [21906/21906] CoreContext main_helpers.cpp:796 (run_backend) - MythBackend exiting
2021-12-07 17:55:30.093517 I [21906/21906] CoreContext bonjourregister.cpp:30 (~BonjourRegister) - Bonjour: De-registering service '_http._tcp.' on 'mythbackend on htpc'
2021-12-07 17:55:30.097411 I [21906/21906] CoreContext bonjourregister.cpp:30 (~BonjourRegister) - Bonjour: De-registering service '_mythbackend._tcp.' on 'Mythbackend on htpc'
2021-12-07 17:55:30.097563 I [21906/21906] CoreContext upnp.cpp:194 (CleanUp) - UPnp::CleanUp() - disabling SSDP notifications
2021-12-07 17:55:30.097655 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : upnp:rootdevice : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::upnp:rootdevice
2021-12-07 17:55:30.097763 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14
2021-12-07 17:55:30.097797 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:device:MediaServer:4 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:device:MediaServer:4
2021-12-07 17:55:30.098032 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1
2021-12-07 17:55:30.098071 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ConnectionManager:3 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:service:ConnectionManager:3
2021-12-07 17:55:30.098103 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ContentDirectory:4 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:service:ContentDirectory:4
2021-12-07 17:55:30.098133 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8
2021-12-07 17:55:30.098164 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-mythtv-org:device:MasterMediaServer:1 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8::urn:schemas-mythtv-org:device:MasterMediaServer:1
<variable delay>
2021-12-07 17:55:30.582601 I [21906/21906] CoreContext platforms/mythpowerdbus.cpp:72 (~MythPowerDBus) - PowerDBus: Closing interfaces
2021-12-07 17:55:30.583125 I [21906/21906] CoreContext mythcontext.cpp:1667 (~MythContext) - Waiting for threads to exit.
2021-12-07 17:55:30.583137 N [21906/21906] CoreContext ssdp.cpp:115 (~SSDP) - Shutting Down SSDP Thread...
2021-12-07 17:55:30.583279 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : upnp:rootdevice : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::upnp:rootdevice
2021-12-07 17:55:30.583498 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14
2021-12-07 17:55:30.583554 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:device:MediaServer:4 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:device:MediaServer:4
2021-12-07 17:55:30.583608 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1
2021-12-07 17:55:30.583660 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ConnectionManager:3 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:service:ConnectionManager:3
2021-12-07 17:55:30.583712 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ContentDirectory:4 : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::urn:schemas-upnp-org:service:ContentDirectory:4
2021-12-07 17:55:30.583761 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8
2021-12-07 17:55:30.583812 I [21906/21906] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-mythtv-org:device:MasterMediaServer:1 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8::urn:schemas-mythtv-org:device:MasterMediaServer:1
2021-12-07 17:55:30.583938 I [21906/21906] CoreContext ssdp.cpp:131 (~SSDP) - SSDP Thread Terminated.
2021-12-07 17:55:30.583965 I [21906/21906] CoreContext mythcontext.cpp:1673 (~MythContext) - Exiting

from a run with --loglevel=debug -v all

2021-12-08 00:52:12.836474 I [33800/33800] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-mythtv-org:device:MasterMediaServer:1 : uuid:28e7dff2-736d-4bce-8ef6-270bfabe5bd8::urn:schemas-mythtv-org:device:MasterMediaServer:1
2021-12-08 00:52:12.836499 D [33800/33800] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 21
2021-12-08 00:52:12.836503 I [33800/33800] CoreContext referencecounter.cpp:143 (DecrRef) - (0x55cdf9354ac0)::DecrRef() -> 1
<delay here>
2021-12-08 00:52:13.314112 I [33800/33800] CoreContext tv_rec.cpp:4352 (ClearFlags) - TVRec[1]: ClearFlags(RunMainLoop,) -> 0x0 @ tv_rec.cpp:182
2021-12-08 00:52:13.314164 I [33800/33805] TVRecEvent tv_rec.cpp:197 (TeardownAll) - TVRec[1]: TeardownAll
2021-12-08 00:52:13.314189 I [33800/33805] TVRecEvent eitscanner.cpp:226 (StopPassiveScan) - EITScanner[1]: Stopped processing EIT events in active scan
2021-12-08 00:52:13.314194 I [33800/33805] TVRecEvent eitscanner.cpp:308 (StopActiveScan) - EITScanner[1]: Stopped active scan
2021-12-08 00:52:13.314445 I [33800/33805] TVRecEvent tv_rec.cpp:1110 (TeardownRecorder) - TVRec[1]: TeardownRecorder(kFlagKillRec)
2021-12-08 00:52:13.314465 I [33800/33805] TVRecEvent tv_rec.cpp:4352 (ClearFlags) - TVRec[1]: ClearFlags(NeedToStartRecorder,RecorderRunning,) -> 0x0 @ tv_rec.cpp:1124
2021-12-08 00:52:13.314478 I [33800/33805] TVRecEvent recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[1](10414922): Closing HDHR channel
2021-12-08 00:52:13.314488 I [33800/33805] TVRecEvent mythdbcon.cpp:481 (CloseDatabases) - Closing DB connection named 'DBManager2'
2021-12-08 00:52:13.314781 I [33800/33800] CoreContext recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[1](10414922): Closing HDHR channel
2021-12-08 00:52:13.314878 I [33800/33800] CoreContext tv_rec.cpp:4352 (ClearFlags) - TVRec[2]: ClearFlags(RunMainLoop,) -> 0x0 @ tv_rec.cpp:182
2021-12-08 00:52:13.314991 I [33800/33807] TVRecEvent tv_rec.cpp:197 (TeardownAll) - TVRec[2]: TeardownAll
2021-12-08 00:52:13.315000 I [33800/33807] TVRecEvent tv_rec.cpp:1110 (TeardownRecorder) - TVRec[2]: TeardownRecorder(kFlagKillRec)
2021-12-08 00:52:13.315017 I [33800/33807] TVRecEvent tv_rec.cpp:4352 (ClearFlags) - TVRec[2]: ClearFlags(NeedToStartRecorder,RecorderRunning,) -> 0x0 @ tv_rec.cpp:1124
2021-12-08 00:52:13.315028 I [33800/33807] TVRecEvent recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[2](10414922): Closing HDHR channel
2021-12-08 00:52:13.315154 I [33800/33800] CoreContext recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[2](10414922): Closing HDHR channel
2021-12-08 00:52:13.315256 I [33800/33800] CoreContext tv_rec.cpp:4352 (ClearFlags) - TVRec[3]: ClearFlags(RunMainLoop,) -> 0x0 @ tv_rec.cpp:182
2021-12-08 00:52:13.315339 I [33800/33808] TVRecEvent tv_rec.cpp:197 (TeardownAll) - TVRec[3]: TeardownAll
2021-12-08 00:52:13.315349 I [33800/33808] TVRecEvent tv_rec.cpp:1110 (TeardownRecorder) - TVRec[3]: TeardownRecorder(kFlagKillRec)
2021-12-08 00:52:13.315365 I [33800/33808] TVRecEvent tv_rec.cpp:4352 (ClearFlags) - TVRec[3]: ClearFlags(NeedToStartRecorder,RecorderRunning,) -> 0x0 @ tv_rec.cpp:1124
2021-12-08 00:52:13.315376 I [33800/33808] TVRecEvent recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[3](10414922): Closing HDHR channel
2021-12-08 00:52:13.315497 I [33800/33800] CoreContext recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[3](10414922): Closing HDHR channel
2021-12-08 00:52:13.315602 I [33800/33800] CoreContext tv_rec.cpp:4352 (ClearFlags) - TVRec[4]: ClearFlags(RunMainLoop,) -> 0x0 @ tv_rec.cpp:182
2021-12-08 00:52:13.315684 I [33800/33809] TVRecEvent tv_rec.cpp:197 (TeardownAll) - TVRec[4]: TeardownAll
2021-12-08 00:52:13.315693 I [33800/33809] TVRecEvent tv_rec.cpp:1110 (TeardownRecorder) - TVRec[4]: TeardownRecorder(kFlagKillRec)
2021-12-08 00:52:13.315710 I [33800/33809] TVRecEvent tv_rec.cpp:4352 (ClearFlags) - TVRec[4]: ClearFlags(NeedToStartRecorder,RecorderRunning,) -> 0x0 @ tv_rec.cpp:1124
2021-12-08 00:52:13.315720 I [33800/33809] TVRecEvent recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[4](10414922): Closing HDHR channel
2021-12-08 00:52:13.315851 I [33800/33800] CoreContext recorders/hdhrchannel.cpp:79 (Close) - HDHRChan[4](10414922): Closing HDHR channel
2021-12-08 00:52:13.315948 I [33800/33800] CoreContext referencecounter.cpp:143 (DecrRef) - (0x55cdf9354ac0)::DecrRef() -> 0
2021-12-08 00:52:13.315953 D [33800/33800] CoreContext platforms/mythpowerdbus.cpp:563 (ReleaseLock) - PowerDBus: Releasing delay FD: 13
2021-12-08 00:52:13.315990 I [33800/33800] CoreContext platforms/mythpowerdbus.cpp:72 (~MythPowerDBus) - PowerDBus: Closing interfaces
2021-12-08 00:52:13.316528 I [33800/33800] CoreContext mythcontext.cpp:1667 (~MythContext) - Waiting for threads to exit.
2021-12-08 00:52:13.316542 N [33800/33800] CoreContext ssdp.cpp:115 (~SSDP) - Shutting Down SSDP Thread...
2021-12-08 00:52:13.316622 D [33800/33800] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 9
2021-12-08 00:52:13.316697 I [33800/33800] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : upnp:rootdevice : uuid:e98009fe-ccc2-4df1-b7a9-1059a5d2ab14::upnp:rootdevice

frontend

2021-12-08 00:51:45.087234 I [33825/33825] CoreContext main.cpp:291 (cleanup) - Shutting down UPnP client...
2021-12-08 00:51:45.087636 D [33825/33825] CoreContext upnp.cpp:64 (~UPnp) - UPnp - Destructor
2021-12-08 00:51:45.087638 I [33825/33825] CoreContext upnp.cpp:194 (CleanUp) - UPnp::CleanUp() - disabling SSDP notifications
2021-12-08 00:51:45.087667 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 23
2021-12-08 00:51:45.087696 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : upnp:rootdevice : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::upnp:rootdevice
2021-12-08 00:51:45.088029 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc
2021-12-08 00:51:45.088056 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:device:MediaRenderer:1 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-upnp-org:device:MediaRenderer:1
2021-12-08 00:51:45.088147 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-mythtv-org:service:MythFrontend:1 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-mythtv-org:service:MythFrontend:1
2021-12-08 00:51:45.088262 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ConnectionManager:3 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-upnp-org:service:ConnectionManager:3
2021-12-08 00:51:45.088316 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 24
2021-12-08 00:51:45.088345 I [33825/33825] CoreContext referencecounter.cpp:143 (DecrRef) - (0x56067fa3daf0)::DecrRef() -> 1
2021-12-08 00:51:45.088353 I [33825/33825] CoreContext referencecounter.cpp:143 (DecrRef) - (0x56067fa3daf0)::DecrRef() -> 0
2021-12-08 00:51:45.088355 D [33825/33825] CoreContext platforms/mythpowerdbus.cpp:563 (ReleaseLock) - PowerDBus: Releasing delay FD: 22
2021-12-08 00:51:45.088368 I [33825/33825] CoreContext platforms/mythpowerdbus.cpp:72 (~MythPowerDBus) - PowerDBus: Closing interfaces
2021-12-08 00:51:45.089362 I [33825/33825] CoreContext mythcontext.cpp:1667 (~MythContext) - Waiting for threads to exit.
2021-12-08 00:51:45.089368 N [33825/33825] CoreContext ssdp.cpp:115 (~SSDP) - Shutting Down SSDP Thread...
2021-12-08 00:51:45.089395 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 22
2021-12-08 00:51:45.089416 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : upnp:rootdevice : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::upnp:rootdevice
2021-12-08 00:51:45.089530 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc
2021-12-08 00:51:45.089652 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:device:MediaRenderer:1 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-upnp-org:device:MediaRenderer:1
2021-12-08 00:51:45.089692 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-mythtv-org:service:MythFrontend:1 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-mythtv-org:service:MythFrontend:1
2021-12-08 00:51:45.089706 I [33825/33825] CoreContext upnptasknotify.cpp:78 (SendNotifyMsg) - UPnpNotifyTask::SendNotifyMsg : 239.255.255.250:1900 : urn:schemas-upnp-org:service:ConnectionManager:3 : uuid:d43110bd-1a85-4c6d-a78f-316e89d4cccc::urn:schemas-upnp-org:service:ConnectionManager:3
2021-12-08 00:51:45.089726 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 23

2021-12-08 00:51:45.379225 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 2
2021-12-08 00:51:45.879611 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 0
2021-12-08 00:51:46.379963 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 2
2021-12-08 00:51:46.880292 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 0
2021-12-08 00:51:47.380642 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 2
2021-12-08 00:51:47.881000 D [33825/33836] SSDP portchecker.cpp:193 (checkPort) - PortChecker::checkPort(): socket state 0
2021-12-08 00:51:47.881060 I [33825/33836] SSDP referencecounter.cpp:143 (DecrRef) - (0x7f1b44003520)::DecrRef() -> 1

2021-12-08 00:51:47.881301 I [33825/33825] CoreContext referencecounter.cpp:143 (DecrRef) - (0x56067f879d10)::DecrRef() -> 1
2021-12-08 00:51:47.881333 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 25
2021-12-08 00:51:47.881361 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 27
2021-12-08 00:51:47.881380 D [33825/33825] CoreContext msocketdevice_unix.cpp:228 (close) - MSocketDevice::close: Closed socket 28
2021-12-08 00:51:47.881383 I [33825/33825] CoreContext ssdp.cpp:131 (~SSDP) - SSDP Thread Terminated.
2021-12-08 00:51:47.911538 I [33825/33825] CoreContext referencecounter.cpp:143 (DecrRef) - (0x7f1b44004ca0)::DecrRef() -> 0
2021-12-08 00:51:47.911556 I [33825/33825] CoreContext referencecounter.cpp:143 (DecrRef) - (0x56067f879d10)::DecrRef() -> 0
2021-12-08 00:51:47.911568 I [33825/33825] CoreContext mythcontext.cpp:1673 (~MythContext) - Exiting

The frontend has its variable delay after sending both sets of messages. Note the suspicious SSDP portchecker log entries every half second.

ulmus-scott commented 2 years ago

For redesigning the Upnp send notify message code:

Instead of halting thread execution with sleep, add the message to a resend queue.

This queue will, if it was empty, compute a random number in the range (100, 300) to use as its delay. (I'm not sure if it would be better to flush all at once, or retain the message time spacing. It's probably easier to flush all at once)

Note: the random() function should take parameters that specify what range of values is desired and by overload resolution the type (integer or floating point). Many PRNGs have higher entropy in their higher order bits, so modulus may pessimize the available randomness.

stuarta commented 2 years ago

Oh the rebuilt version will most certainly use a queue, and it will also have a concept of "when" the messages need to be sent