Need help with no answer voice , but good SIP

Asterisk Asterisk SIP
1

Intermittent dialing issue.
Hello everyone! I’m having a strange, intermittent issue with the pre-zone for this number. According to the operator, the call comes in, but he can’t pick it up. In the Asterisk console, I’m seeing strange behavior with MixMonitor, specifically when calling from the operator’s queue.
VERBOSE itself is attached:
route → queue 5799 → call 5930 (no answer timeout and pause) → call 5755 (according to the operator, he couldn’t answer because the phone was inactive) → call 5823 (same thing) → call 5755 again (same thing).

What’s confusing to me is that:

  1. When calling 5755, the app_dial.c task doesn’t appear, like with 5930:
    [Dec 23 22:50:49] VERBOSE[30532][C-00005003] app_dial.c: Called SIP/5930
    [Dec 23 22:50:49] VERBOSE[30532][C-00005003] app_dial.c: SIP/5930-0000a8c8 is ringing

  2. When Dec 23 23:06:07 arrived (i.e., 15 minutes after trying to start MixMonitor on 5755), logs about MixMonitor operation, or rather about its completion, began appearing en masse, and after that, operators continued working normally. I suspect something is wrong: MixMonitor, or something with the recording file, or with the voice channels, since the SIP signaling was reaching the endpoint (it saw the call).
    Can anyone tell me where to start and what versions it might be?
    Asterisk 18.19.0, using chan_sip
    Need help with no answer voice, but good SIP
    All channels are SIP

context from-queue :

[from-queue]
exten 	=>	_5[789]XX,1,Set(YEAR=${STRFTIME(${NOW},,%Y)})
same	=>	n,Set(MONTH=${STRFTIME(${NOW},,%m)})
same	=>	n,Set(DAY=${STRFTIME(${NOW},,%d)})

same	=		n,Set(MixFile=from-q-${EXTEN}-${CALLERID(num)}-${STRFTIME(${EPOCH},GMT+3,%H%M%S)}-${UNIQUEID})
same	=>	n,MixMonitor(/tmp/${MixFile}.wav,ai(LOCAL_MIXMON_ID),mv /tmp/${MixFile}.wav /mnt/data/asterisk/monitor/${YEAR}/${MONTH}/${DAY}/${MixFile}.wav)
same	=>	n,Set(CDR(recordingfile)=/mnt/data/asterisk/monitor/${YEAR}/${MONTH}/${DAY}/${MixFile}.wav) 

same	=>	n,Dial(SIP/${EXTEN},60)
same	=>	n,Hangup

Here’s the console output (unfortunately, I can’t attach the file) :

[Dec 23 22:50:49] VERBOSE[30516][C-00005003] app_queue.c: Called Local/5930@from-queue/n
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:1] Set("Local/5930@from-queue-00002607;2", "YEAR=2025") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:2] Set("Local/5930@from-queue-00002607;2", "MONTH=12") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:3] Set("Local/5930@from-queue-00002607;2", "DAY=23") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:4] Set("Local/5930@from-queue-00002607;2", "MixFile=from-q-5930-00019262058847-165049-1766519449.148120") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:5] MixMonitor("Local/5930@from-queue-00002607;2", "/tmp/from-q-5930-00019262058847-165049-1766519449.148120.wav,ai(LOCAL_MIXMON_ID),mv /tmp/from-q-5930-00019262058847-165049-1766519449.148120.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5930-00019262058847-165049-1766519449.148120.wav &") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:6] Set("Local/5930@from-queue-00002607;2", "CDR(recordingfile)=/mnt/data/asterisk/monitor/2025/12/23/from-q-5930-00019262058847-165049-1766519449.148120.wav") in new stack
[Dec 23 22:50:49] VERBOSE[30533][C-00005003] app_mixmonitor.c: Begin MixMonitor Recording Local/5930@from-queue-00002607;2
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] pbx.c: Executing [5930@from-queue:7] Dial("Local/5930@from-queue-00002607;2", "SIP/5930,60") in new stack
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] netsock2.c: Using SIP RTP CoS mark 5
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] app_dial.c: Called SIP/5930
[Dec 23 22:50:49] VERBOSE[30532][C-00005003] app_dial.c: SIP/5930-0000a8c8 is ringing
[Dec 23 22:50:49] VERBOSE[30516][C-00005003] app_queue.c: Local/5930@from-queue-00002607;1 is ringing
[Dec 23 22:51:04] VERBOSE[30516][C-00005003] app_queue.c: Nobody picked up in 15000 ms
[Dec 23 22:51:04] VERBOSE[30516][C-00005003] app_queue.c: Auto-Pausing Queue Member Local/5930@from-queue/n in queue TechS since they failed to answer.
[Dec 23 22:51:04] VERBOSE[30532][C-00005003] pbx.c: Spawn extension (from-queue, 5930, 7) exited non-zero on 'Local/5930@from-queue-00002607;2'
[Dec 23 22:51:04] VERBOSE[30533][C-00005003] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 22:51:04] VERBOSE[30533][C-00005003] app_mixmonitor.c: Executing [mv /tmp/from-q-5930-00019262058847-165049-1766519449.148120.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5930-00019262058847-165049-1766519449.148120.wav]
[Dec 23 22:51:04] VERBOSE[30533][C-00005003] app_mixmonitor.c: End MixMonitor Recording Local/5930@from-queue-00002607;2

[Dec 23 22:51:05] VERBOSE[30516][C-00005003] app_queue.c: Called Local/5755@from-queue/n
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:1] Set("Local/5755@from-queue-00002608;2", "YEAR=2025") in new stack
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:2] Set("Local/5755@from-queue-00002608;2", "MONTH=12") in new stack
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:3] Set("Local/5755@from-queue-00002608;2", "DAY=23") in new stack
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:4] Set("Local/5755@from-queue-00002608;2", "MixFile=from-q-5755-00019262058847-165105-1766519465.148124") in new stack
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:5] MixMonitor("Local/5755@from-queue-00002608;2", "/tmp/from-q-5755-00019262058847-165105-1766519465.148124.wav,ai(LOCAL_MIXMON_ID),mv /tmp/from-q-5755-00019262058847-165105-1766519465.148124.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165105-1766519465.148124.wav &") in new stack
[Dec 23 22:51:05] VERBOSE[30552][C-00005003] pbx.c: Executing [5755@from-queue:6] Set("Local/5755@from-queue-00002608;2", "CDR(recordingfile)=/mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165105-1766519465.148124.wav") in new stack
[Dec 23 22:51:05] VERBOSE[30553][C-00005003] app_mixmonitor.c: Begin MixMonitor Recording Local/5755@from-queue-00002608;2
[Dec 23 22:51:20] VERBOSE[30516][C-00005003] app_queue.c: Nobody picked up in 15000 ms
[Dec 23 22:51:20] VERBOSE[30516][C-00005003] app_queue.c: Auto-Pausing Queue Member Local/5755@from-queue/n in queue TechS since they failed to answer.

[Dec 23 22:51:25] VERBOSE[30516][C-00005003] app_queue.c: Called Local/5823@from-queue/n
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:1] Set("Local/5823@from-queue-00002609;2", "YEAR=2025") in new stack
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:2] Set("Local/5823@from-queue-00002609;2", "MONTH=12") in new stack
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:3] Set("Local/5823@from-queue-00002609;2", "DAY=23") in new stack
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:4] Set("Local/5823@from-queue-00002609;2", "MixFile=from-q-5823-00019262058847-165125-1766519485.148126") in new stack
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:5] MixMonitor("Local/5823@from-queue-00002609;2", "/tmp/from-q-5823-00019262058847-165125-1766519485.148126.wav,ai(LOCAL_MIXMON_ID),mv /tmp/from-q-5823-00019262058847-165125-1766519485.148126.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5823-00019262058847-165125-1766519485.148126.wav &") in new stack
[Dec 23 22:51:25] VERBOSE[30574][C-00005003] pbx.c: Executing [5823@from-queue:6] Set("Local/5823@from-queue-00002609;2", "CDR(recordingfile)=/mnt/data/asterisk/monitor/2025/12/23/from-q-5823-00019262058847-165125-1766519485.148126.wav") in new stack
[Dec 23 22:51:25] VERBOSE[30575][C-00005003] app_mixmonitor.c: Begin MixMonitor Recording Local/5823@from-queue-00002609;2
[Dec 23 22:51:40] VERBOSE[30516][C-00005003] app_queue.c: Nobody picked up in 15000 ms
[Dec 23 22:51:40] VERBOSE[30516][C-00005003] app_queue.c: Auto-Pausing Queue Member Local/5823@from-queue/n in queue TechS since they failed to answer.

[Dec 23 22:52:02] VERBOSE[30516][C-00005003] app_queue.c: Called Local/5755@from-queue/n
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:1] Set("Local/5755@from-queue-0000260a;2", "YEAR=2025") in new stack
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:2] Set("Local/5755@from-queue-0000260a;2", "MONTH=12") in new stack
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:3] Set("Local/5755@from-queue-0000260a;2", "DAY=23") in new stack
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:4] Set("Local/5755@from-queue-0000260a;2", "MixFile=from-q-5755-00019262058847-165202-1766519522.148128") in new stack
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:5] MixMonitor("Local/5755@from-queue-0000260a;2", "/tmp/from-q-5755-00019262058847-165202-1766519522.148128.wav,ai(LOCAL_MIXMON_ID),mv /tmp/from-q-5755-00019262058847-165202-1766519522.148128.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165202-1766519522.148128.wav &") in new stack
[Dec 23 22:52:02] VERBOSE[30617][C-00005003] pbx.c: Executing [5755@from-queue:6] Set("Local/5755@from-queue-0000260a;2", "CDR(recordingfile)=/mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165202-1766519522.148128.wav") in new stack
[Dec 23 22:52:02] VERBOSE[30618][C-00005003] app_mixmonitor.c: Begin MixMonitor Recording Local/5755@from-queue-0000260a;2
.
.
.
[Dec 23 23:06:07] VERBOSE[30553][C-00005003] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30553][C-00005003] app_mixmonitor.c: Executing [mv /tmp/from-q-5755-00019262058847-165105-1766519465.148124.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165105-1766519465.148124.wav &]
[Dec 23 23:06:07] VERBOSE[30553][C-00005003] app_mixmonitor.c: End MixMonitor Recording Local/5755@from-queue-00002608;2
[Dec 23 23:06:07] VERBOSE[30575][C-00005003] app_mixmonitor.c: MixMonitor close filestream (mixed)

[Dec 23 23:06:07] VERBOSE[30575][C-00005003] app_mixmonitor.c: Executing [mv /tmp/from-q-5823-00019262058847-165125-1766519485.148126.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5823-00019262058847-165125-1766519485.148126.wav &]
[Dec 23 23:06:07] VERBOSE[30618][C-00005003] app_mixmonitor.c: MixMonitor close filestream (mixed)

[Dec 23 23:06:07] VERBOSE[30618][C-00005003] app_mixmonitor.c: Executing [mv /tmp/from-q-5755-00019262058847-165202-1766519522.148128.wav /mnt/data/asterisk/monitor/2025/12/23/from-q-5755-00019262058847-165202-1766519522.148128.wav &]
[Dec 23 23:06:07] VERBOSE[30575][C-00005003] app_mixmonitor.c: End MixMonitor Recording Local/5823@from-queue-00002609;2
[Dec 23 23:06:07] VERBOSE[30693][C-00005004] app_mixmonitor.c: MixMonitor close filestream (mixed)

[Dec 23 23:06:07] VERBOSE[30693][C-00005004] app_mixmonitor.c: Executing [mv /tmp/in-5799-00019262058847-165310-1766519590.148129.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-00019262058847-165310-1766519590.148129.wav &]
[Dec 23 23:06:07] VERBOSE[30618][C-00005003] app_mixmonitor.c: End MixMonitor Recording Local/5755@from-queue-0000260a;2

[Dec 23 23:06:07] VERBOSE[30693][C-00005004] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8c9
[Dec 23 23:06:07] VERBOSE[30722][C-00005005] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30722][C-00005005] app_mixmonitor.c: Executing [mv /tmp/in-5799-00019262058847-165334-1766519614.148130.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-00019262058847-165334-1766519614.148130.wav &]
[Dec 23 23:06:07] VERBOSE[30731][C-00005006] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30731][C-00005006] app_mixmonitor.c: End MixMonitor Recording SIP/5823-0000a8cb
[Dec 23 23:06:07] VERBOSE[30722][C-00005005] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8ca
[Dec 23 23:06:07] VERBOSE[30763][C-00005007] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30763][C-00005007] app_mixmonitor.c: Executing [mv /tmp/in-5799-00019262058847-165410-1766519650.148132.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-00019262058847-165410-1766519650.148132.wav &]
[Dec 23 23:06:07] VERBOSE[30763][C-00005007] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8cc
[Dec 23 23:06:07] VERBOSE[30792][C-00005008] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30792][C-00005008] app_mixmonitor.c: Executing [mv /tmp/in-5799-00019262058847-165434-1766519674.148133.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-00019262058847-165434-1766519674.148133.wav &]
[Dec 23 23:06:07] VERBOSE[30792][C-00005008] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8cd
[Dec 23 23:06:07] VERBOSE[30824][C-00005009] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30824][C-00005009] app_mixmonitor.c: Executing [mv /tmp/in-5799-9262058847-165501-1766519701.148134.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-9262058847-165501-1766519701.148134.wav &]
[Dec 23 23:06:07] VERBOSE[30847][C-0000500a] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30847][C-0000500a] app_mixmonitor.c: Executing [mv /tmp/in-5799-9262058847-165522-1766519722.148135.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-9262058847-165522-1766519722.148135.wav &]
[Dec 23 23:06:07] VERBOSE[30824][C-00005009] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8ce
[Dec 23 23:06:07] VERBOSE[30851][C-0000500b] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30851][C-0000500b] app_mixmonitor.c: End MixMonitor Recording SIP/5823-0000a8d0
[Dec 23 23:06:07] VERBOSE[30847][C-0000500a] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8cf
[Dec 23 23:06:07] VERBOSE[30866][C-0000500c] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30866][C-0000500c] app_mixmonitor.c: Executing [mv /tmp/in-5799-9262058847-165535-1766519735.148137.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-9262058847-165535-1766519735.148137.wav &]
[Dec 23 23:06:07] VERBOSE[30876][C-0000500d] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30876][C-0000500d] app_mixmonitor.c: Executing [mv /tmp/in-5799-9262058847-165545-1766519745.148138.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-9262058847-165545-1766519745.148138.wav &]
[Dec 23 23:06:07] VERBOSE[30866][C-0000500c] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8d1
[Dec 23 23:06:07] VERBOSE[30902][C-0000500e] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30902][C-0000500e] app_mixmonitor.c: Executing [mv /tmp/in-5799-9262058847-165606-1766519766.148139.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-9262058847-165606-1766519766.148139.wav &]
[Dec 23 23:06:07] VERBOSE[30876][C-0000500d] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8d2
[Dec 23 23:06:07] VERBOSE[30917][C-0000500f] app_mixmonitor.c: MixMonitor close filestream (mixed)
[Dec 23 23:06:07] VERBOSE[30917][C-0000500f] app_mixmonitor.c: Executing [mv /tmp/in-5799-00019262058847-165618-1766519778.148140.wav /mnt/data/asterisk/monitor/2025/12/23/in-5799-00019262058847-165618-1766519778.148140.wav &]
[Dec 23 23:06:07] VERBOSE[30902][C-0000500e] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8d3
[Dec 23 23:06:07] VERBOSE[30917][C-0000500f] app_mixmonitor.c: End MixMonitor Recording SIP/with-TSE-LIM2-0000a8d4
2

This seems more like a media or MixMonitor/queue channel issue than a SIP signaling problem, so I’d suggest checking recording behavior, RTP flow, and MixMonitor timing first.

1 Like
3

It looks like the Set(CDR… has stalled, but I can’t think why that might happen.

Can you confirm that you are using the latest community supported sub- version (NB not a .cert version) of a supported version?

1 Like
4

Excuse me, but the latest version of what? I ‘m using same => n,Set(CDR(recordingfile).. for CRM system which reads data from MySQL

5

Asterisk.

6

Set CDR should return after only changing data in memory, which makes it difficult to understand why it doesn’t seem to be returning. Any database update will be at the end of the call.

(I do note that you only seem to have Verbose messages, so might be missing Informational,Warning, or Error, messages, which are significant.)

7

Based on the logs, the mv command moving files to /mnt/data/ (likely a network share) hung, which blocked your call processing for 15 minutes.

Immediate Solution

Remove the mv command from the MixMonitor application in your dialplan.

Change this line:

text

same=>n,MixMonitor(/tmp/${MixFile}.wav,ai(LOCAL_MIXMON_ID),mv /tmp/${MixFile}.wav /mnt/data/asterisk/monitor/${YEAR}/${MONTH}/${DAY}/${MixFile}.wav)

To this (record to local disk only):

text

same=>n,MixMonitor(/tmp/${MixFile}.wav,ai(LOCAL_MIXMON_ID))

Long-Term Fix

  1. Use a Cron Job: Create a separate script to move files from /tmp/ to /mnt/data/ every minute. This decouples the slow storage operation from your live calls.

  2. Check Mounts: If /mnt/data is NFS, use soft,timeo=50 mount options so it fails fast instead of freezing Asterisk.

8

Whilst I do think that moving to a temporarily mounted file system is risky, I think your AI has missed the fact that mv would not be executed until the Dial had completed, but the Dial would have been logged before it started. Also the exact 15 minutes implies an explicit 15 minute timer, not the random duration of an outage.

I’d also mention that “mv” across file systems is not an atomic operation, so in fault, or race, conditions, could end up with a half written final file, and even with the /tmp file left undeleted (although the ways that Debian handles /tmp means it would be cleared on a reboot).