Device is not added back after removal, and aircast doesn't respond to SIGTERM

[zhouguiheng]

The aircast-arm is launched by service in raspberry pi: ExecStart=/home/pi/AirConnect/aircast-arm -Z -x /home/pi/AirConnect/config.xml

Starting log:

Feb 28 21:28:50 raspberrypi systemd[1]: Started airconnect.service.
Feb 28 21:28:50 raspberrypi aircast-arm[23553]: [21:28:50.052946] main:966 Starting aircast version: v0.2.43.1 (Jan 14 2021 @ 22:16:20)
Feb 28 21:28:50 raspberrypi aircast-arm[23553]: [21:28:50.053512] Start:727 Binding to 192.168.1.8
Feb 28 21:28:50 raspberrypi aircast-arm[23553]: [21:28:50.080355] AddCastDevice:664 [0xbe428]: adding renderer (Study Room Wifi)
Feb 28 21:28:50 raspberrypi aircast-arm[23553]: [21:28:50.236520] AddCastDevice:664 [0xbeda0]: adding renderer (Family Room Mini)
Feb 28 21:28:50 raspberrypi aircast-arm[23553]: [21:28:50.257954] AddCastDevice:664 [0xbf718]: adding renderer (Kids Bedroom Mini)
Feb 28 21:29:10 raspberrypi aircast-arm[23553]: [21:29:10.840600] AddCastDevice:664 [0xc0090]: adding renderer (Master Bedroom Wifi)

Then one device Study Room Wifi (renamed to Study Room in config.xml) got removed after 6 hours:

Mar 01 03:26:41 raspberrypi aircast-arm[23553]: [03:26:41.016724] mDNSsearchCallback:535 [0xbe428]: removing renderer (Study Room) -1259305400
Mar 01 03:26:41 raspberrypi aircast-arm[23553]: [03:26:41.021981] DeleteCastDevice:512 [0xbe428]: Cast device stopped
Mar 01 03:26:52 raspberrypi aircast-arm[23553]: [03:26:52.126967] AddCastDevice:664 [0xbe428]: adding renderer (Study Room Wifi)
Mar 01 03:26:52 raspberrypi aircast-arm[23553]: [03:26:52.128503] mDNSsearchCallback:535 [0xbe428]: removing renderer (Study Room) 1

it never gets added back. I then restart the service by sudo systemctl restart airconnect.service, log:

Mar 01 11:41:11 raspberrypi systemd[1]: Stopping airconnect.service...
Mar 01 11:42:41 raspberrypi systemd[1]: airconnect.service: State 'stop-sigterm' timed out. Killing.
Mar 01 11:42:41 raspberrypi systemd[1]: airconnect.service: Killing process 23553 (aircast-arm) with signal SIGKILL.
Mar 01 11:42:41 raspberrypi systemd[1]: airconnect.service: Main process exited, code=killed, status=9/KILL
Mar 01 11:42:41 raspberrypi systemd[1]: airconnect.service: Failed with result 'timeout'.
Mar 01 11:42:41 raspberrypi systemd[1]: Stopped airconnect.service.
Mar 01 11:42:41 raspberrypi systemd[1]: Started airconnect.service.
Mar 01 11:42:41 raspberrypi aircast-arm[22830]: [11:42:41.883172] main:966 Starting aircast version: v0.2.43.1 (Jan 14 2021 @ 22:16:20)
Mar 01 11:42:41 raspberrypi aircast-arm[22830]: [11:42:41.883792] Start:727 Binding to 192.168.1.8
Mar 01 11:42:41 raspberrypi aircast-arm[22830]: [11:42:41.916516] AddCastDevice:664 [0xa6a428]: adding renderer (Master Bedroom Wifi)
Mar 01 11:42:41 raspberrypi aircast-arm[22830]: [11:42:41.921600] AddCastDevice:664 [0xa6ada0]: adding renderer (Study Room Wifi)
Mar 01 11:42:41 raspberrypi aircast-arm[22830]: [11:42:41.977692] AddCastDevice:664 [0xa6b718]: adding renderer (Kids Bedroom Mini)
Mar 01 11:42:42 raspberrypi aircast-arm[22830]: [11:42:42.045770] AddCastDevice:664 [0xa6c090]: adding renderer (Family Room Mini)

(No logs are omitted in between the logs above).

As seen in the last log above, aircast was force-killed as stop-sigterm timed out, and the Study Room Wifi was rediscovered once the service gets restarted. Seems some thread stuck? Below is the log for a normal service restart:

Mar 01 11:59:56 raspberrypi systemd[1]: Stopping airconnect.service...
Mar 01 11:59:56 raspberrypi aircast-arm[22830]: [11:59:56.707072] DeleteCastDevice:512 [0xa6a428]: Cast device stopped
Mar 01 11:59:56 raspberrypi aircast-arm[22830]: [11:59:56.710033] DeleteCastDevice:512 [0xa6ada0]: Cast device stopped
Mar 01 11:59:56 raspberrypi aircast-arm[22830]: [11:59:56.711351] DeleteCastDevice:512 [0xa6b718]: Cast device stopped
Mar 01 11:59:56 raspberrypi aircast-arm[22830]: [11:59:56.712987] DeleteCastDevice:512 [0xa6c090]: Cast device stopped
Mar 01 11:59:56 raspberrypi systemd[1]: airconnect.service: Succeeded.
Mar 01 11:59:56 raspberrypi systemd[1]: Stopped airconnect.service.
Mar 01 11:59:56 raspberrypi systemd[1]: Started airconnect.service.
Mar 01 11:59:56 raspberrypi aircast-arm[27479]: [11:59:56.742069] main:966 Starting aircast version: v0.2.43.1 (Jan 14 2021 @ 22:16:20)
Mar 01 11:59:56 raspberrypi aircast-arm[27479]: [11:59:56.742515] Start:727 Binding to 192.168.1.8
Mar 01 11:59:56 raspberrypi aircast-arm[27479]: [11:59:56.762268] AddCastDevice:664 [0x202f428]: adding renderer (Master Bedroom Wifi)
Mar 01 11:59:56 raspberrypi aircast-arm[27479]: [11:59:56.766432] AddCastDevice:664 [0x202fda0]: adding renderer (Study Room Wifi)
Mar 01 11:59:56 raspberrypi aircast-arm[27479]: [11:59:56.841489] AddCastDevice:664 [0x2030718]: adding renderer (Kids Bedroom Mini)
Mar 01 12:00:37 raspberrypi aircast-arm[27479]: [12:00:37.866842] AddCastDevice:664 [0x2031090]: adding renderer (Family Room Mini)

[zhouguiheng]

It's likely a bug introduced in version 0.2.43.0 by this commit. Not sure if there's other bug but one obvious bug is that Device->Remove is not initialized back to false in AddCastDevice. It means that a new device will be immediately removed if it reuses an old free spot.

I downloaded the older version and it worked well so far.

[philippe44]

Thanks - fixed

[zhouguiheng]

Thanks for the quick fix! Verified the new version worked well.