Paging Server Crash/Music Fade issue

[danry25]

Paging server seems to delay inbound calls to let music fade out, not sure if this was what caused the server crash on the 4th call.

Jun  1 23:00:02 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#3)] event: state
Jun  1 23:00:02 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#3)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  1 23:00:02 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  1 23:00:02 localhost paging[2909]: paging.PulseClient DEBUG :: Starting music fade-in for 0 pulse stream(s)
Jun  1 23:00:12 localhost paging[2909]: paging.PulseClient DEBUG :: Finished music fade-in sequence for 0 stream(s)
Jun  1 23:00:23 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  1 23:00:23 localhost paging[2909]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#4)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  1 23:00:23 localhost paging[2909]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#4)
Jun  1 23:00:23 localhost paging[2909]: paging.PulseClient DEBUG :: Starting music fade-out for 0 pulse stream(s)
Jun  1 23:00:24 localhost paging[2909]: paging.PagingServer DEBUG :: Started blocking playback of wav for time: 0.9s
Jun  1 23:00:24 localhost paging[2909]: paging.PagingServer DEBUG :: wav playback finished
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] event: media_state
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] media-state change: 'null' -> 'active' (call time: 0)
Jun  1 23:00:25 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: cs_media_activated
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] event: state
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] state change: 'incoming' -> 'connecting' (SIP status: 200 OK)
Jun  1 23:00:25 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: cs_timeout
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] event: state
Jun  1 23:00:25 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  1 23:00:26 localhost paging[2909]: paging.PulseClient DEBUG :: Finished music fade-out sequence for0 stream(s)
Jun  1 23:00:33 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] event: state
Jun  1 23:00:33 localhost paging[2909]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#4)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  1 23:00:33 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  1 23:00:33 localhost paging[2909]: paging.PulseClient DEBUG :: Starting music fade-in for 0 pulse stream(s)
Jun  1 23:00:44 localhost paging[2909]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  1 23:00:44 localhost paging[2909]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#5)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  1 23:00:44 localhost paging[2909]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#5)
Jun  1 23:00:49 localhost paging[2909]: main ERROR :: ERROR (call_init): poll_wakeup() hangs, likely locking issue
Jun  1 23:00:49 localhost paging[2909]: Traceback (most recent call last):
Jun  1 23:00:49 localhost paging[2909]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 73, in_wrapper
Jun  1 23:00:49 localhost paging[2909]:     try: return func(*args, **kws)
Jun  1 23:00:49 localhost paging[2909]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 299, in call_init
Jun  1 23:00:49 localhost paging[2909]:     self.server.set_music_mute(True)
Jun  1 23:00:49 localhost paging[2909]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 837, in set_music_mute
Jun  1 23:00:49 localhost paging[2909]:     with self.poll_wakeup(): self.pulse.set_music_mute(muted)
Jun  1 23:00:49 localhost paging[2909]:   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
Jun  1 23:00:49 localhost paging[2909]:     return self.gen.next()
Jun  1 23:00:49 localhost paging[2909]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 741, in poll_wakeup
Jun  1 23:00:49 localhost paging[2909]:     raise PagingServerError('poll_wakeup() hangs, likely lockingissue')
Jun  1 23:00:49 localhost paging[2909]: PagingServerError: poll_wakeup() hangs, likely locking issue
Jun  1 23:00:51 localhost systemd[1]: paging.service: Watchdog timeout (limit 30s)!
Jun  1 23:00:51 localhost systemd[1]: paging.service: Killing process 2909 (paging) with signal SIGABRT.
Jun  1 23:00:51 localhost systemd[1]: paging.service: Main process exited, code=killed, status=6/ABRT
Jun  1 23:00:51 localhost systemd[1]: paging.service: Unit entered failed state.
Jun  1 23:00:51 localhost systemd[1]: paging.service: Failed with result 'watchdog'.
Jun  1 23:01:22 localhost systemd[1]: paging.service: Service hold-off time over, scheduling restart.
Jun  1 23:01:22 localhost systemd[1]: Stopped paging.service.
Jun  1 23:01:22 localhost systemd[1]: Starting paging.service...
Jun  1 23:01:23 localhost paging[2956]: main DEBUG :: Initializing systemd watchdog pinger with interval: 15.0s
Jun  1 23:01:23 localhost paging[2956]: main INFO :: Starting PagingServer...
Jun  1 23:01:23 localhost paging[2956]: paging.PagingServer DEBUG :: pulse init
Jun  1 23:01:23 localhost paging[2956]: paging.PagingServer DEBUG :: pjsua init
Jun  1 23:01:24 localhost paging[2956]: WARNING: no real random source present!
Jun  1 23:01:24 localhost paging[2956]: paging.PagingServer DEBUG :: Using output device: sysdefault:CARD=Codec [1]
Jun  1 23:01:24 localhost paging[2956]: paging.PagingServer DEBUG :: Using output port: sysdefault:CARD=Codec [0]
Jun  1 23:01:24 localhost paging[2956]: paging.PagingServer DEBUG :: pjsua event loop started
Jun  1 23:01:24 localhost systemd[1]: Started paging.service.
Jun  1 23:01:24 localhost paging[2956]: paging.PSAccountState DEBUG :: PSAccountState event: reg_state
Jun  1 23:01:24 localhost paging[2956]: paging.PSAccountState DEBUG :: acc registration state (active: 1): 200 OK

[danry25]

Just had it crash again, but this time the service didn't die. The first call after the error was thrown did not audibly play the klaxon, after that it returned to normal.

Jun  2 00:01:43 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#8)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  2 00:01:44 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#8)] event: state
Jun  2 00:01:44 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#8)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  2 00:01:44 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  2 00:01:52 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  2 00:01:52 localhost paging[3252]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#9)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  2 00:01:52 localhost paging[3252]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#9)
Jun  2 00:01:52 localhost paging[3252]: paging.PagingServer DEBUG :: Started blocking playback of wav for time: 0.9s
Jun  2 00:01:53 localhost paging[3252]: paging.PagingServer DEBUG :: wav playback finished
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] event: media_state
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] media-state change: 'null' -> 'active' (call time: 0)
Jun  2 00:01:53 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_media_activated
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] event: state
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] state change: 'incoming' -> 'connecting' (SIP status: 200 OK)
Jun  2 00:01:53 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_timeout
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] event: state
Jun  2 00:01:53 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  2 00:02:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] event: state
Jun  2 00:02:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#9)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  2 00:02:09 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  2 00:05:02 localhost CRON[3503]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jun  2 00:05:08 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  2 00:05:08 localhost paging[3252]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#10)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  2 00:05:08 localhost paging[3252]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#10)
Jun  2 00:05:09 localhost paging[3252]: paging.PagingServer DEBUG :: Started blocking playback of wav for time: 0.9s
Jun  2 00:05:09 localhost paging[3252]: paging.PagingServer DEBUG :: wav playback finished
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] event: media_state
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] media-state change: 'null' -> 'active' (call time: 0)
Jun  2 00:05:09 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_media_activated
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] event: state
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] state change: 'incoming' -> 'connecting' (SIP status: 200 OK)
Jun  2 00:05:09 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_timeout
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] event: state
Jun  2 00:05:09 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  2 00:05:20 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] event: state
Jun  2 00:05:20 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#10)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  2 00:05:20 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  2 00:05:29 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  2 00:05:29 localhost paging[3252]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#11)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  2 00:05:29 localhost paging[3252]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#11)
Jun  2 00:05:34 localhost paging[3252]: main ERROR :: ERROR (call_init): poll_wakeup() hangs, likely locking issue
Jun  2 00:05:34 localhost paging[3252]: Traceback (most recent call last):
Jun  2 00:05:34 localhost paging[3252]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 73, in_wrapper
Jun  2 00:05:34 localhost paging[3252]:     try: return func(*args, **kws)
Jun  2 00:05:34 localhost paging[3252]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 299, in call_init
Jun  2 00:05:34 localhost paging[3252]:     self.server.set_music_mute(True)
Jun  2 00:05:34 localhost paging[3252]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 837, in set_music_mute
Jun  2 00:05:34 localhost paging[3252]:     with self.poll_wakeup(): self.pulse.set_music_mute(muted)
Jun  2 00:05:34 localhost paging[3252]:   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
Jun  2 00:05:34 localhost paging[3252]:     return self.gen.next()
Jun  2 00:05:34 localhost paging[3252]:   File "/usr/lib/python2.7/dist-packages/paging.py", line 741, in poll_wakeup
Jun  2 00:05:34 localhost paging[3252]:     raise PagingServerError('poll_wakeup() hangs, likely lockingissue')
Jun  2 00:05:34 localhost paging[3252]: PagingServerError: poll_wakeup() hangs, likely locking issue
Jun  2 00:05:59 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#11)] event: state
Jun  2 00:05:59 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#11)] state change: 'incoming' -> 'disconnected' (SIP status: 487 Request Terminated)
Jun  2 00:05:59 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  2 00:06:00 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: reg_state
Jun  2 00:06:00 localhost paging[3252]: paging.PSAccountState DEBUG :: acc registration state (active: 1): 200 OK
Jun  2 00:08:59 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  2 00:08:59 localhost paging[3252]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#12)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  2 00:08:59 localhost paging[3252]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#12)
Jun  2 00:08:59 localhost paging[3252]: paging.PagingServer DEBUG :: Started blocking playback of wav for time: 0.9s
Jun  2 00:09:00 localhost paging[3252]: paging.PagingServer DEBUG :: wav playback finished
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] event: media_state
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] media-state change: 'null' -> 'active' (call time: 0)
Jun  2 00:09:00 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_media_activated
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] event: state
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] state change: 'incoming' -> 'connecting' (SIP status: 200 OK)
Jun  2 00:09:00 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_timeout
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] event: state
Jun  2 00:09:00 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  2 00:09:04 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] event: state
Jun  2 00:09:04 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#12)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  2 00:09:04 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected
Jun  2 00:09:09 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: incoming_call
Jun  2 00:09:09 localhost paging[3252]: paging.PSCallState DEBUG :: New incoming call [sip:1000@sipdomain.com (#13)] (remote contact: <sip:mod_sofia@SIP.server:5060>)
Jun  2 00:09:09 localhost paging[3252]: paging.PSAccountState INFO :: Handling call: sip:1000@sipdomain.com (#13)
Jun  2 00:09:10 localhost paging[3252]: paging.PagingServer DEBUG :: Started blocking playback of wav for time: 0.9s
Jun  2 00:09:10 localhost paging[3252]: paging.PagingServer DEBUG :: wav playback finished
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] event: media_state
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] media-state change: 'null' -> 'active' (call time: 0)
Jun  2 00:09:11 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_media_activated
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] event: state
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] state change: 'incoming' -> 'connecting' (SIP status: 200 OK)
Jun  2 00:09:11 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_timeout
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] event: state
Jun  2 00:09:11 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] state change: 'connecting' -> 'confirmed' (SIP status: 200 OK)
Jun  2 00:09:12 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] event: state
Jun  2 00:09:12 localhost paging[3252]: paging.PSCallState DEBUG :: call [sip:1000@sipdomain.com (#13)] state change: 'confirmed' -> 'disconnected' (SIP status: 200 Normal call clearing)
Jun  2 00:09:12 localhost paging[3252]: paging.PSAccountState DEBUG :: PSAccountState event: cs_disconnected

[danry25]

On further debugging, it appears to be a problem triggered by setting klaxon-padding = -0.5 with a klaxon file that is 0.9 seconds long, without this option set I can't reproduce. The issue that caused me to try setting this was the half-second gap between when the klaxon finishes playing and the person is allowed to start speaking.

In testing I noticed that 12% of the time there is a 5 second delay before the klaxon is played, and the klaxon gets clipped to its last 0.1 second when this occurs. The polling loop seems to be the root of both the crashes before, and this 5 second delay issue.

[mk-fg]

Not sure which "crashes before" do you mean there.
If you mean PulseOperationError stuff fixed recently - nope, different unrelated issue to loop itself.

[danry25]

Oh, "crashes before" was a reference to these two crashes (#1 & #2).

I tried setting loop_wait=1.0 and loop_interval=0.03 which made the same error much more common, and I also tried loop_wait=5.0 and loop_interval=0.03 based on this but the script still threw this error 3 times in 40 runs.

[mk-fg]

Wrt this issue though:

• pjsua has its own event-loop running in a separate thread, which is how that python2 module is written.
• Pulse client has its glib event loop running in other thread.
• A bit complicating the issue, is how pulseaudio eventloop is not really implemented as such, with the gist being that event handlers stop the event_listen() loop, start loop to run whatever pulse operations are needed, restart pulse-event-handling loop.
• That poll thing is where the two meet, a bit messy due to threads, which again thanks to pjsua, but maybe can be implemented a bit better.

[mk-fg]

As mentioned in an earlier email, I'd suggest that it might be more cost-effective to rewrite this from scratch, maybe using proper python3/asyncio eventloop hooking into libpulse fds in place of this pseudo-synchronous operation.
Given that it's either just that, or that plus figuring out and debugging all the old stuff in addition :)

[danry25]

Yeah, this pseudo-synchronous function seems to be troublesome, planning to refactor this in late June/early July. Would you recommend pulsectl or something else?

The error this issue is about seems to happen inconsistently based on my testing, sometimes I can call many times without issue.

[mk-fg]

Note that when rewriting the script, you'd probably be using different bindings entirely (pjsua2.so swig module, not old python2 pjsua code), which will probably work differently.
But even if not, I'd suggest starting with asyncio and sending all events there properly.

While it's possible to make pulsectl work with that (see README there), imo copying few ctype defs for only calls you need from there with proper async wrapping would be easier to maintain/understand/debug, given how relatively little this script needs to do.
And if there's a decent pulseaudio asyncio module, can maybe use that as an alternative.

[mk-fg]

The error this issue is about seems to happen inconsistently based on my testing, sometimes I can call many times without issue.

Yeah, it's almost certainly some trivial race condition - log all event starting/stopping stuff into single logger (they do locking for proper ordering) and you'd probably see something out of place.
I remember having trouble figuring out how to do proper locking for everything there, but it can usually be solved easier by some kind of excessive locking :)

EDIT: I hate these mutexes and threads!

[danry25]

Perhaps I could comment out the volume controls/fading entirely and remove this dependency (for now)?

I don't mind if the caller can speak while the klaxon is playing, and the music stream feature is currently unused (so adjusting the volume level of the sinks is not needed).

[mk-fg]

Sorry for the delay.

Don't think it'd remove the dependency, as volume-setting is needed all over the place there iirc, and maybe there's some other stuff like moving streams between sinks, which I don't quite remember off the top of my head.
Most of it might be related to mixing mpd and pjsua streams though, and pulse has module-stream-restore to keep an otherwise constant volume between application runs.

Can probably be a workaround, as that part of code switches between loops often to adjust volume in steps, so if race conditions like that pop-up, would be way more likely to happen there.
Same as suggested above, enabling a ton of logging with timestamps for when it happens should probably help, as you'd easily see what locks-up or goes out-of-order there compared to normal case.

[danry25]

FYI, pretty sure the cause of this issue is from passwords with special characters (eg: !#!) which are included in passwords generated by FusionPBX. Changing passwords to exclude these characters seems to have resolved this issue.