Queue agents being called twice

Asterisk Asterisk Support
1

Hi,

I recently upgraded from Asterisk 13.12.2 and PJSIP 2.4.5 to Asterisk 13.22.0 with embedded PJSIP (2.7.2) from source and noticed that every time a call enters a queue, all the members are called at the same time (this is the expected behaviour) but when one of the agents picks up the call, then all the other phones show a missed call and this wasn’t happening before the upgrade.

I noticed the following in the logs:

With version 13.12.2:

[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] pbx.c: Executing [s@sales_queue:9] Queue("DAHDI/i1/111111111-64e", "marketing,k,,,10") in new stack
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] res_musiconhold.c: Started music on hold, class 'default', on channel 'DAHDI/i1/111111111-64e'
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: Called PJSIP/671
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: Called PJSIP/672
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: PJSIP/671-000014e5 connected line has changed. Saving it until answer for DAHDI/i1/402781718-64e
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: PJSIP/672-000014e6 connected line has changed. Saving it until answer for DAHDI/i1/402781718-64e
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: PJSIP/672-000014e6 is ringing
[Aug 20 08:38:36] VERBOSE[15324][C-00000f5d] app_queue.c: PJSIP/671-000014e5 is ringing
[Aug 20 08:38:38] VERBOSE[15324][C-00000f5d] app_queue.c: PJSIP/672-000014e6 answered DAHDI/i1/402781718-64e
[Aug 20 08:38:38] VERBOSE[15324][C-00000f5d] res_musiconhold.c: Stopped music on hold on DAHDI/i1/402781718-64e

With version 13.22.0:

[Aug 22 15:02:01] VERBOSE[26405][C-00000102] pbx.c: Executing [s@support_queue:29] Queue("DAHDI/i1/111111111-62", "marketing,k,,,30") in new stack
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] res_musiconhold.c: Started music on hold, class 'default', on channel 'DAHDI/i1/111111111-62'
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: Called PJSIP/671
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: Called PJSIP/672
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/671-00000167 connected line has changed. Saving it until answer for DAHDI/i1/417356526-62
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/672-00000168 connected line has changed. Saving it until answer for DAHDI/i1/417356526-62
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/671-00000167 is ringing
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/671-00000167 is ringing
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/672-00000168 is ringing
[Aug 22 15:02:01] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/672-00000168 is ringing
[Aug 22 15:02:08] VERBOSE[24977] res_rtp_asterisk.c: 0x7f6cfc014000 -- Strict RTP learning after remote address set to: 192.168.4.233:16386
[Aug 22 15:02:08] VERBOSE[26405][C-00000102] app_queue.c: PJSIP/671-00000167 answered DAHDI/i1/417356526-62
[Aug 22 15:02:08] VERBOSE[26405][C-00000102] res_musiconhold.c: Stopped music on hold on DAHDI/i1/417356526-62

The logs show that the app_queue is application is ringing each member twice.

There was no dialplan change, just the Asterisk and PJSIP versions. I’m not 100% sure that this is causing the phone to show a missed call when the call is answered by another agent but everything points to it at the moment.

Has anyone seen this happening before?

The queue configuration in (queues.conf) is:

[StandardQueue_w_recording](!)
music=default
strategy=ringall
timeout=25
retry=5
setinterfacevar=yes
monitor-type=MixMonitor
monitor-format=gsm

[marketing](StandardQueue_w_recording)

member => PJSIP/671,,Agent 1
member => PJSIP/672,,Agent 2
2

There are not two channels in that log, so they aren’t being called twice. If you look at the output you can see that the channel name is the same on the duplicate log messages for ringing. The Dial application has an option that tells the phone to not show a missed call if it is answered elsewhere, this may need to be enabled here too (I don’t know how but it would be documented).

You could also check the difference in SIP traffic between the two versions using pjsip set logger on and see what is different.

3

I checked the SIP traffic with both versions of Asterisk and the only thing different thing is the order of two “Reason” lines:

NOT OK

[Sep 24 13:49:11] VERBOSE[28836] res_pjsip_logger.c: <— Transmitting SIP request (506 bytes) to TLS:192.168.4.241:5075 —>
CANCEL sip:662@192.168.4.241:5075;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.4.199:5061;rport;branch=z9hG4bKPjfce163f0-c43b-4370-85b7-4ad43ca4402b;alias
From: “Support” <sip:00111111111@192.168.4.199>;tag=01dde803-5e08-4fd7-9b26-4f2b3e035180
To: <sip:662@192.168.4.241>
Call-ID: 7d6e44c4-9496-4bce-972b-75e112536286
CSeq: 30652 CANCEL
Reason: SIP;cause=200;text=“Call completed elsewhere”
Reason: Q.850;cause=26
Max-Forwards: 70
User-Agent: Asterisk PBX 13.22.0
Content-Length: 0

OK

<— Transmitting SIP request (476 bytes) to UDP:192.168.4.241:5062 —>
CANCEL sip:662@192.168.4.241:5062 SIP/2.0
Via: SIP/2.0/UDP 192.168.4.170:5060;rport;branch=z9hG4bKPj8e0a5f24-b5d4-47c5-adf2-7b90f9ef6e01
From: “Support” <sip:616@119.31.226.70>;tag=0031aef7-2c58-4ee6-9ac2-442890f93336
To: <sip:662@192.168.4.241>
Call-ID: 2eff77f9-d66d-4353-810d-4ae6725f212d
CSeq: 3769 CANCEL
Reason: Q.850;cause=26
Reason: SIP;cause=200;text=“Call completed elsewhere”
Max-Forwards: 70
User-Agent: Asterisk PBX 13.12.2
Content-Length: 0

It’s still strange that in the logs the

app_queue.c: PJSIP/671-00000167 is ringing

Appears twice per call and this didn’t happen before with an earlier version.

Any thoughts?

4

I did some more research by checking exactly in which version of Asterisk the problem started. The version is 13.21.0. I compared a full SIP capture from version 13.20.0 and 13.21.0 and the only difference between those two is the order of the “Reason” line in the CANCEL message:

In 13.20.0, it looks like this:

Reason: Q.850;cause=26
Reason: SIP;cause=200;text=“Call completed elsewhere”

In 13.21.0, it looks like this:

Reason: SIP;cause=200;text=“Call completed elsewhere”
Reason: Q.850;cause=26

I think that the problem is that my IP Phone is using the last Reason value received (you can see that the difference is that the order is inverted). Since in 13.21.0 the last reason received is the one for Q.850, then it uses reason 26 which is not actually “Call Completed elsewhere” but “Non-selected user clearing” according to the latest Q.850 standard published by the ITU. The “Call Completed elsewhere” reason in Q.850 is reason 13.

So I think that the solution would be to invert the order of the Reason lines or change the value to 13 for the Q.850 part.

5

OK. So I found the problem. It’s documented on issue ASTERISK-27554.

What’s interesting is that the issue found that was breaking many endpoints wasn’t breaking mine and the fix proposed apparently helped other endpoints but broke mine so I’m guess I’m not upgrading above version 13.20.0

6

The change itself is minor, so even in the future you should be able to undo it. The behavior of devices in this regard is rather annoying though. What endpoint do you have?

7

I’m using a Cisco SPA504G on the latest firmware (7.6.2e). I already changed the source code and inverted the order of the Reason header as per the information provided in the diff file in the Issue tracker and that did the trick.

I just need to remember to change it again in the new code with every upgrade I make. It’s annoying but you can’t win them all.

It would be good, though if the order of these headers could be selected in the config file. That way, it may fix the issue for everyone.

8

I just found out that version 16 has a new option in pjsip called suppress_q850_reason_headers which eliminates the Q.850 reason header so that may work as well.