Unexpected Call Termination in Asterisk Queue Setup

celsoannes · April 23, 2024, 1:43pm

Hello,

I am encountering an issue that I have never faced before, and I am unsure of the cause. Here is the scenario:

Asterisk: 20.4.0
Asterisk IP: 192.168.5.10
IP Phone: 192.168.5.1

Problem: I am receiving calls from the telephone operator via E1 R2 through a TDMoE Gateway. The call is answered by a queue and forwarded to extension 7400 (192.168.5.1). The IP phone answers the call, but 30 seconds later, the call is terminated by Asterisk.

The call drops in this scenario: PSTN -> open_r2 -> Asterisk -> Queue -> PJSIP/7400

The call is terminated by Asterisk:

`INVITE (SDP)`

                                                            │INVITE sip:7400@192.168.5.1:5060 SIP/2.0
            192.168.5.10:5060              192.168.5.1:5060 │Via: SIP/2.0/UDP 192.168.5.10:5060;rport;branch=z9hG4bKPjd20b3f03-e56a-45a4-b9f6-8417f9fc8dc5
          ──────────┬─────────          ──────────┬─────────│From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
  09:59:19.076398   │        INVITE (SDP)         │         │To: <sip:7400@192.168.5.1>
        +0.024243   │ ──────────────────────────> │         │Contact: <sip:asterisk@192.168.5.10:5060>
  09:59:19.100641   │         100 Trying          │         │Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
        +0.191745   │ <────────────────────────── │         │CSeq: 20028 INVITE
  09:59:19.292386   │         180 Ringing         │         │Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
        +2.180236   │ <────────────────────────── │         │Supported: 100rel, timer, replaces, norefersub, histinfo
  09:59:21.472622   │        200 OK (SDP)         │         │Session-Expires: 1800
        +0.000792   │ <────────────────────────── │         │Min-SE: 90
  09:59:21.473414   │             ACK             │         │Max-Forwards: 70
        +9.435270   │ ──────────────────────────> │         │User-Agent: Asterisk PBX 20.4.0
  09:59:30.908684   │             BYE             │         │Content-Type: application/sdp
        +0.008793   │ ──────────────────────────> │         │Content-Length:   237
  09:59:30.917477   │           200 OK            │         │
                    │ <────────────────────────── │         │v=0
                    │                             │         │o=- 1564605616 1564605616 IN IP4 192.168.5.10
                    │                             │         │s=Asterisk
                    │                             │         │c=IN IP4 192.168.5.10
                    │                             │         │t=0 0
                    │                             │         │m=audio 13548 RTP/AVP 0 101
                    │                             │         │a=rtpmap:0 PCMU/8000
                    │                             │         │a=rtpmap:101 telephone-event/8000
                    │                             │         │a=fmtp:101 0-16
                    │                             │         │a=ptime:20
                    │                             │         │a=maxptime:150
                    │                             │         │a=sendrecv

2024/04/23 09:59:19.100641 192.168.5.1:5060 -> 192.168.5.10:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.5.10:5060;rport=5060;branch=z9hG4bKPjd20b3f03-e56a-45a4-b9f6-8417f9fc8dc5
From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
To: <sip:7400@192.168.5.1>
Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
CSeq: 20028 INVITE
User-Agent: Yealink SIP-T48S 66.86.0.160
Content-Length: 0

2024/04/23 09:59:19.292386 192.168.5.1:5060 -> 192.168.5.10:5060
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.5.10:5060;rport=5060;branch=z9hG4bKPjd20b3f03-e56a-45a4-b9f6-8417f9fc8dc5
From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
To: <sip:7400@192.168.5.1>;tag=663955336
Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
CSeq: 20028 INVITE
Contact: <sip:7400@192.168.5.1:5060>
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
User-Agent: Yealink SIP-T48S 66.86.0.160
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0

`200 OK (SDP)`

                                                            │SIP/2.0 200 OK
            192.168.5.10:5060              192.168.5.1:5060 │Via: SIP/2.0/UDP 192.168.5.10:5060;rport=5060;branch=z9hG4bKPjd20b3f03-e56a-45a4-b9f6-8417f9fc8dc5
          ──────────┬─────────          ──────────┬─────────│From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
  09:59:19.076398   │        INVITE (SDP)         │         │To: <sip:7400@192.168.5.1>;tag=663955336
        +0.024243   │ ──────────────────────────> │         │Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
  09:59:19.100641   │         100 Trying          │         │CSeq: 20028 INVITE
        +0.191745   │ <────────────────────────── │         │Contact: <sip:7400@192.168.5.1:5060>
  09:59:19.292386   │         180 Ringing         │         │Content-Type: application/sdp
        +2.180236   │ <────────────────────────── │         │Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
  09:59:21.472622   │        200 OK (SDP)         │         │User-Agent: Yealink SIP-T48S 66.86.0.160
        +0.000792   │ <────────────────────────── │         │Allow-Events: talk,hold,conference,refer,check-sync
  09:59:21.473414   │             ACK             │         │Supported: replaces
        +9.435270   │ ──────────────────────────> │         │Content-Length: 209
  09:59:30.908684   │             BYE             │         │
        +0.008793   │ ──────────────────────────> │         │v=0
  09:59:30.917477   │           200 OK            │         │o=- 20032 20032 IN IP4 192.168.5.1
                    │ <────────────────────────── │         │s=SDP data
                    │                             │         │c=IN IP4 192.168.5.1
                    │                             │         │t=0 0
                    │                             │         │m=audio 12232 RTP/AVP 0 101
                    │                             │         │a=rtpmap:0 PCMU/8000
                    │                             │         │a=ptime:20
                    │                             │         │a=rtpmap:101 telephone-event/8000
                    │                             │         │a=fmtp:101 0-15
                    │                             │         │a=sendrecv

`ACK`

                                                            │ACK sip:7400@192.168.5.1:5060 SIP/2.0
            192.168.5.10:5060              192.168.5.1:5060 │Via: SIP/2.0/UDP 192.168.5.10:5060;rport;branch=z9hG4bKPja43dc6f4-ea90-479f-acdb-26662e325b8e
          ──────────┬─────────          ──────────┬─────────│From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
  09:59:19.076398   │        INVITE (SDP)         │         │To: <sip:7400@192.168.5.1>;tag=663955336
        +0.024243   │ ──────────────────────────> │         │Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
  09:59:19.100641   │         100 Trying          │         │CSeq: 20028 ACK
        +0.191745   │ <────────────────────────── │         │Max-Forwards: 70
  09:59:19.292386   │         180 Ringing         │         │User-Agent: Asterisk PBX 20.4.0
        +2.180236   │ <────────────────────────── │         │Content-Length:  0
  09:59:21.472622   │        200 OK (SDP)         │         │
        +0.000792   │ <────────────────────────── │         │
  09:59:21.473414   │             ACK             │         │
        +9.435270   │ ──────────────────────────> │         │
  09:59:30.908684   │             BYE             │         │
        +0.008793   │ ──────────────────────────> │         │
  09:59:30.917477   │           200 OK            │         │
                    │ <────────────────────────── │         │

`BYE`

                                                            │BYE sip:7400@192.168.5.1:5060 SIP/2.0
            192.168.5.10:5060              192.168.5.1:5060 │Via: SIP/2.0/UDP 192.168.5.10:5060;rport;branch=z9hG4bKPjbb0c374d-75c7-4699-8f28-7cddc11e45ee
          ──────────┬─────────          ──────────┬─────────│From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
  09:59:19.076398   │        INVITE (SDP)         │         │To: <sip:7400@192.168.5.1>;tag=663955336
        +0.024243   │ ──────────────────────────> │         │Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
  09:59:19.100641   │         100 Trying          │         │CSeq: 20029 BYE
        +0.191745   │ <────────────────────────── │         │Reason: Q.850;cause=16
  09:59:19.292386   │         180 Ringing         │         │Max-Forwards: 70
        +2.180236   │ <────────────────────────── │         │User-Agent: Asterisk PBX 20.4.0
  09:59:21.472622   │        200 OK (SDP)         │         │Content-Length:  0
        +0.000792   │ <────────────────────────── │         │
  09:59:21.473414   │             ACK             │         │
        +9.435270   │ ──────────────────────────> │         │
  09:59:30.908684   │             BYE             │         │
        +0.008793   │ ──────────────────────────> │         │
  09:59:30.917477   │           200 OK            │         │
                    │ <────────────────────────── │         │

`200 OK`

2024/04/23 09:59:30.917477 192.168.5.1:5060 -> 192.168.5.10:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.10:5060;rport=5060;branch=z9hG4bKPjbb0c374d-75c7-4699-8f28-7cddc11e45ee
From: "5433350700" <sip:5433350700@192.168.1.10>;tag=83cf1fc3-de92-4af9-a3c9-55ea2ea5bee7
To: <sip:7400@192.168.5.1>;tag=663955336
Call-ID: afafeda2-cf47-49c2-ad27-defdd753f086
CSeq: 20029 BYE
User-Agent: Yealink SIP-T48S 66.86.0.160
Content-Length: 0

If I direct the call straight to the extension PJSIP/7400 instead of sending it to the queue, the call does not drop. The problem only occurs when the queue answers and forwards the call to the extension.

In this scenario, the call does not drop: PSTN -> open_r2 -> Asterisk -> PJSIP/7400

I have no idea why this is happening. I need the calls to be sent to the queue before going to the phone. I have the same setup with several other clients, but this is the only one presenting this issue, and I have no idea what is happening.

Can anyone help me?

david551 · April 23, 2024, 2:04pm

Cause 16 is normal clearing. I cannot find any logging of the dialplan, or the incoming side.

celsoannes · April 23, 2024, 3:56pm

After several tests, I have come to the following conclusion: the problem is not with the IP phone or the queue, but rather with how Asterisk answers the call using Answer and how it communicates with openr2.

chan_dahdi.conf

[channels]
busydetect=yes
busycount=5
relaxdtmf=yes
language=pt_BR
signalling=mfcr2
mfcr2_variant=br
mfcr2_get_ani_first=no
mfcr2_max_ani=20
mfcr2_max_dnis=20
mfcr2_category=national_subscriber
mfcr2_allow_collect_calls=no
mfcr2_logdir=span1
mfcr2_call_files=yes
mfcr2_logging=all
mfcr2_mfback_timeout=-1
mfcr2_metering_pulse_timeout=-1
mfcr2_metering_pulse_timeout=500
mfcr2_allow_collect_calls=yes
mfcr2_double_answer=no
mfcr2_forced_release=no
mfcr2_charge_calls=yes
callgroup=0
pickupgroup=0 
echocancel=yes
echocancelwhenbridged=no

; PSTN
group=1
context=entrada-oi
channel => 1-15
channel => 17-31

extensions.conf

[entrada-oi]
exten => 7474,1,Answer()
 same => n,MusicOnHold()
 same => n,Wait(60)

Console:

[2024-04-23 12:25:37] New MFC/R2 call detected on chan 11.
[2024-04-23 12:25:42] MFC/R2 call offered on chan 11. ANI = 5433350700, DNIS = 7474, Category = National Subscriber
[2024-04-23 12:25:42] MFC/R2 call has been accepted on backward channel 11
[2024-04-23 12:25:42]     -- Executing [7474@entrada-oi:1] Answer("DAHDI/11-1", "") in new stack
[2024-04-23 12:25:42]     -- Executing [7474@entrada-oi:2] MusicOnHold("DAHDI/11-1", "") in new stack
[2024-04-23 12:25:42]     -- Started music on hold, class 'default', on channel 'DAHDI/11-1'
[2024-04-23 12:26:14] Chan 11 - Far end disconnected. Reason: Normal Clearing
[2024-04-23 12:26:14] MFC/R2 call disconnected on channel 11
[2024-04-23 12:26:14]     -- Stopped music on hold on DAHDI/11-1
[2024-04-23 12:26:14]   == Spawn extension (entrada-oi, 7474, 2) exited non-zero on 'DAHDI/11-1'
[2024-04-23 12:26:14] MFC/R2 call end on channel 11
[2024-04-23 12:26:14]     -- Hungup 'DAHDI/11-1'

The calls answered by Asterisk only last for 30 seconds before being dropped.

Below is the log generated by openr2:

[12:25:37:741] [Thread: 140656074348288] [Chan 11] - Call started at Tue Apr 23 12:25:37 2024 on chan 11 [openr2 version 1.3.3, revision (release)]
[12:25:37:741] [Thread: 140656074348288] [Chan 11] - Initialized R2 MF detector
[12:25:37:741] [Thread: 140656074348288] [Chan 11] - CAS Tx >> [SEIZE ACK] 0x0C
[12:25:37:741] [Thread: 140656074348288] [Chan 11] - CAS Raw Tx >> 0x0D
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [ON]
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 0
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - Cannot cancel timer 0
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - Getting DNIS digit 7
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - DNIS so far: 7, expected length: 20
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - Requesting next DNIS with signal 0x31.
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [ON]
[12:25:37:822] [Thread: 140656074348288] [Chan 11] - scheduled timer id 2 (mf_back_cycle)
[12:25:38:042] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [OFF]
[12:25:38:042] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [OFF]
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [ON]
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 2
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - timer id 2 found, cancelling it now
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - Getting DNIS digit 4
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - DNIS so far: 74, expected length: 20
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - Requesting next DNIS with signal 0x31.
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [ON]
[12:25:38:142] [Thread: 140656074348288] [Chan 11] - scheduled timer id 3 (mf_back_cycle)
[12:25:38:402] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [OFF]
[12:25:38:402] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [OFF]
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [ON]
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 3
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - timer id 3 found, cancelling it now
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - Getting DNIS digit 7
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - DNIS so far: 747, expected length: 20
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - Requesting next DNIS with signal 0x31.
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [ON]
[12:25:38:522] [Thread: 140656074348288] [Chan 11] - scheduled timer id 4 (mf_back_cycle)
[12:25:38:782] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [OFF]
[12:25:38:782] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [OFF]
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [ON]
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 4
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - timer id 4 found, cancelling it now
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - Getting DNIS digit 4
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - DNIS so far: 7474, expected length: 20
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - User requested us to stop getting DNIS!
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:38:882] [Thread: 140656074348288] [Chan 11] - scheduled timer id 5 (mf_back_cycle)
[12:25:38:002] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [OFF]
[12:25:38:002] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:39:102] [Thread: 140656074348288] [Chan 11] - MF Rx << 1 [ON]
[12:25:39:102] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 5
[12:25:39:102] [Thread: 140656074348288] [Chan 11] - timer id 5 found, cancelling it now
[12:25:39:102] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:39:102] [Thread: 140656074348288] [Chan 11] - scheduled timer id 6 (mf_back_cycle)
[12:25:39:302] [Thread: 140656074348288] [Chan 11] - MF Rx << 1 [OFF]
[12:25:39:302] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - MF Rx << 5 [ON]
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 6
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - timer id 6 found, cancelling it now
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 5
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - ANI so far: 5, expected length: 20
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:39:402] [Thread: 140656074348288] [Chan 11] - scheduled timer id 7 (mf_back_cycle)
[12:25:39:622] [Thread: 140656074348288] [Chan 11] - MF Rx << 5 [OFF]
[12:25:39:622] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [ON]
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 7
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - timer id 7 found, cancelling it now
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 4
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - ANI so far: 54, expected length: 20
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:39:722] [Thread: 140656074348288] [Chan 11] - scheduled timer id 8 (mf_back_cycle)
[12:25:39:962] [Thread: 140656074348288] [Chan 11] - MF Rx << 4 [OFF]
[12:25:39:962] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [ON]
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 8
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - timer id 8 found, cancelling it now
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 3
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - ANI so far: 543, expected length: 20
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:40:082] [Thread: 140656074348288] [Chan 11] - scheduled timer id 9 (mf_back_cycle)
[12:25:40:282] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [OFF]
[12:25:40:282] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [ON]
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 9
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - timer id 9 found, cancelling it now
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 3
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - ANI so far: 5433, expected length: 20
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:40:382] [Thread: 140656074348288] [Chan 11] - scheduled timer id 10 (mf_back_cycle)
[12:25:40:602] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [OFF]
[12:25:40:602] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [ON]
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 10
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - timer id 10 found, cancelling it now
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 3
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - ANI so far: 54333, expected length: 20
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:40:702] [Thread: 140656074348288] [Chan 11] - scheduled timer id 11 (mf_back_cycle)
[12:25:40:922] [Thread: 140656074348288] [Chan 11] - MF Rx << 3 [OFF]
[12:25:40:922] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - MF Rx << 5 [ON]
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 11
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - timer id 11 found, cancelling it now
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 5
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - ANI so far: 543335, expected length: 20
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:41:022] [Thread: 140656074348288] [Chan 11] - scheduled timer id 12 (mf_back_cycle)
[12:25:41:242] [Thread: 140656074348288] [Chan 11] - MF Rx << 5 [OFF]
[12:25:41:242] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [ON]
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 12
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - timer id 12 found, cancelling it now
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 0
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - ANI so far: 5433350, expected length: 20
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:41:342] [Thread: 140656074348288] [Chan 11] - scheduled timer id 13 (mf_back_cycle)
[12:25:41:582] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [OFF]
[12:25:41:582] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [ON]
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 13
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - timer id 13 found, cancelling it now
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 7
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - ANI so far: 54333507, expected length: 20
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:41:682] [Thread: 140656074348288] [Chan 11] - scheduled timer id 14 (mf_back_cycle)
[12:25:41:782] [Thread: 140656074348288] [Chan 11] - MF Rx << 7 [OFF]
[12:25:41:782] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [ON]
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 14
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - timer id 14 found, cancelling it now
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 0
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - ANI so far: 543335070, expected length: 20
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:41:882] [Thread: 140656074348288] [Chan 11] - scheduled timer id 15 (mf_back_cycle)
[12:25:41:982] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [OFF]
[12:25:41:982] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [ON]
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 15
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - timer id 15 found, cancelling it now
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - Getting ANI digit 0
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - ANI so far: 5433350700, expected length: 20
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [ON]
[12:25:42:082] [Thread: 140656074348288] [Chan 11] - scheduled timer id 16 (mf_back_cycle)
[12:25:42:182] [Thread: 140656074348288] [Chan 11] - MF Rx << 0 [OFF]
[12:25:42:182] [Thread: 140656074348288] [Chan 11] - MF Tx >> 5 [OFF]
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - MF Rx << F [ON]
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 16
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - timer id 16 found, cancelling it now
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - Got end of ANI
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - Requesting change to Group II with signal 0x33
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - MF Tx >> 3 [ON]
[12:25:42:282] [Thread: 140656074348288] [Chan 11] - scheduled timer id 17 (mf_back_cycle)
[12:25:42:382] [Thread: 140656074348288] [Chan 11] - MF Rx << F [OFF]
[12:25:42:382] [Thread: 140656074348288] [Chan 11] - MF Tx >> 3 [OFF]
[12:25:42:482] [Thread: 140656074348288] [Chan 11] - MF Rx << 1 [ON]
[12:25:42:482] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 17
[12:25:42:482] [Thread: 140656074348288] [Chan 11] - timer id 17 found, cancelling it now
[12:25:42:482] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [ON]
[12:25:42:482] [Thread: 140656074348288] [Chan 11] - scheduled timer id 18 (mf_back_cycle)
[12:25:42:582] [Thread: 140656074348288] [Chan 11] - MF Rx << 1 [OFF]
[12:25:42:582] [Thread: 140656074348288] [Chan 11] - MF Tx >> 1 [OFF]
[12:25:42:582] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 18
[12:25:42:582] [Thread: 140656074348288] [Chan 11] - timer id 18 found, cancelling it now
[12:25:42:582] [Thread: 140656074348288] [Chan 11] - scheduled timer id 19 (r2_answer_delay)
[12:25:42:742] [Thread: 140656074348288] [Chan 11] - Attempting to cancel timer timer 19
[12:25:42:742] [Thread: 140656074348288] [Chan 11] - timer id 19 found, cancelling it now
[12:25:42:742] [Thread: 140656074348288] [Chan 11] - calling timer 19 (r2_answer_delay) callback
[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Tx >> [ANSWER] 0x04
[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Raw Tx >> 0x05
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Bits changed from 0x00 to 0x08
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - CAS Rx << [CLEAR FORWARD] 0x08
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Far end disconnected. Reason: Normal Clearing
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Call ended
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Attempting to cancel timer timer 0
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Cannot cancel timer 0

I am unable to interpret what happened, or why the call drops or is disconnected when Asterisk answers.

NOTE: If I direct the call straight to the IP phone and it answers, the call does not drop and proceeds as normal. Can anyone provide insights on this?

Can anyone help me understand this?

david551 · April 23, 2024, 4:46pm

The call drops because the caller hung up, or at least OpenR2 thinks they have.

This is going to be an OpenR2 or DAHDI problem, not an Asterisk one. Or even further upstream.

Was there audio, in both directions, before the drop? Is the MOH, by any chance, silence?

celsoannes · April 23, 2024, 6:29pm

It seems to be a combination of openR2+DAHDI+Answer().

I say this because if I send it directly to an IP phone, the problem does not occur.

[entrada-oi]
exten => 7474,1,Dial(PJSIP/7400)

If I send it directly to a queue, without Answer() the problem does not occur.

[entrada-oi]
exten => 7474,1,Queue(atendimento)
 same => n,HangUp()

The problem only occurs when there is Answer().

Yes, the call has audio on both sides, in both cases, when it goes to hold music and when it goes to the queue.

Using the above context, when answered by a queue agent, the call also drops.

[entrada-oi]
exten => 7474,1,Answer()
 same => n,Wait(2)
 same => n,Queue(atendimento)
 same => n,HangUp()

[2024-04-23 14:22:02] VERBOSE[329402][C-00000019] chan_dahdi.c: MFC/R2 call offered on chan 9. ANI = 5433350700, DNIS = 7474, Category = National Subscriber 
[2024-04-23 14:22:02] VERBOSE[333810][C-0000001a] pbx.c: Executing [7474@entrada-oi:1] Answer("DAHDI/9-1", "") in new stack 
[2024-04-23 14:22:02] VERBOSE[333810][C-0000001a] pbx.c: Executing [7474@entrada-oi:2] Wait("DAHDI/9-1", "2") in new stack 
[2024-04-23 14:22:04] VERBOSE[333810][C-0000001a] pbx.c: Executing [7474@entrada-oi:3] Queue("DAHDI/9-1", "atendimento") in new stack 
[2024-04-23 14:22:04] VERBOSE[333810][C-0000001a] res_musiconhold.c: Started music on hold, class 'default', on channel 'DAHDI/9-1' 
[2024-04-23 14:22:04] VERBOSE[333810][C-0000001a] app_queue.c: Called PJSIP/7400 
[2024-04-23 14:22:04] VERBOSE[333810][C-0000001a] app_queue.c: PJSIP/7400-00000004 is ringing 
[2024-04-23 14:22:06] VERBOSE[333810][C-0000001a] app_queue.c: PJSIP/7400-00000004 answered DAHDI/9-1 
[2024-04-23 14:22:06] VERBOSE[333810][C-0000001a] res_musiconhold.c: Stopped music on hold on DAHDI/9-1 
[2024-04-23 14:22:06] VERBOSE[333810][C-0000001a] bridge_channel.c: Channel DAHDI/9-1 joined 'simple_bridge' basic-bridge <85eb477e-711c-49b3-9cdd-e08250784bf6> 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] chan_dahdi.c: Chan 9 - Far end disconnected. Reason: Normal Clearing 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] chan_dahdi.c: MFC/R2 call disconnected on channel 9 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] bridge_channel.c: Channel DAHDI/9-1 left 'simple_bridge' basic-bridge <85eb477e-711c-49b3-9cdd-e08250784bf6> 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] pbx.c: Spawn extension (entrada-oi, 7474, 3) exited non-zero on 'DAHDI/9-1' 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] chan_dahdi.c: MFC/R2 call end on channel 9 
[2024-04-23 14:22:34] VERBOSE[333810][C-0000001a] chan_dahdi.c: Hungup 'DAHDI/9-1'

Any ideias?

david551 · April 23, 2024, 7:08pm

That doesn’t really make sense as all that Answer does is to send the same internal message as gets generated when the called party answers.

celsoannes · April 23, 2024, 9:18pm

I have never seen this happen, at least not in a DAHDI <-> Asterisk communication, and when it does happen, it happens for all calls, and in this case, it only happens when the call is answered by Answer().

From what I could understand in the openr2 log, the answer signal was made:

The answer signal is sent in the lines:

[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Tx >> [ANSWER] 0x04
[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Raw Tx >> 0x05

And as far as I can tell, the disconnection came from the operator:

[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Far end disconnected. Reason: Normal Clearing

Now, what the difference is between when the call is answered by Asterisk using Answer and when an IP phone answers, I have not found, nor understood… Can anyone help me understand this?

If you know why this is happening, if you want me to do a test, just let me know.

celsoannes · April 24, 2024, 7:11pm

I just did a test and collected the log generated by openr2 on E1 of a call that had no problem dialing directly to the IP phone, in this case going through the following context. Can you please share the log details? I might be able to help interpret them.

[entrada-oi]
exten => 7400,1,Dial(PJSIP/7400)

Full log: /var/log/asterisk/mfcr2/span1/chan-15-backward-4-20240424151636.call

[15:16:36:552] [Thread: 140348740638464] [Chan 15] - Call started at Wed Apr 24 15:16:36 2024 on chan 15 [openr2 version 1.3.4, revision (release)] 
[15:16:36:552] [Thread: 140348740638464] [Chan 15] - Initialized R2 MF detector 
[15:16:36:552] [Thread: 140348740638464] [Chan 15] - CAS Tx >> [SEIZE ACK] 0x0C 
[15:16:36:552] [Thread: 140348740638464] [Chan 15] - CAS Raw Tx >> 0x0D 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - MF Rx << 7 [ON] 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 0 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - Cannot cancel timer 0 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - Getting DNIS digit 7 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - DNIS so far: 7, expected length: 20 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - Requesting next DNIS with signal 0x31. 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [ON] 
[15:16:36:649] [Thread: 140348740638464] [Chan 15] - scheduled timer id 2 (mf_back_cycle) 
[15:16:36:849] [Thread: 140348740638464] [Chan 15] - MF Rx << 7 [OFF] 
[15:16:36:849] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [OFF] 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - MF Rx << 4 [ON] 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 2 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - timer id 2 found, cancelling it now 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - Getting DNIS digit 4 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - DNIS so far: 74, expected length: 20 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - Requesting next DNIS with signal 0x31. 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [ON] 
[15:16:36:949] [Thread: 140348740638464] [Chan 15] - scheduled timer id 3 (mf_back_cycle) 
[15:16:37:209] [Thread: 140348740638464] [Chan 15] - MF Rx << 4 [OFF] 
[15:16:37:209] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [OFF] 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [ON] 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 3 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - timer id 3 found, cancelling it now 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - Getting DNIS digit 0 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - DNIS so far: 740, expected length: 20 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - Requesting next DNIS with signal 0x31. 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [ON] 
[15:16:37:329] [Thread: 140348740638464] [Chan 15] - scheduled timer id 4 (mf_back_cycle) 
[15:16:37:589] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [OFF] 
[15:16:37:589] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [OFF] 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [ON] 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 4 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - timer id 4 found, cancelling it now 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - Getting DNIS digit 0 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - DNIS so far: 7400, expected length: 20 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - User requested us to stop getting DNIS! 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:37:689] [Thread: 140348740638464] [Chan 15] - scheduled timer id 5 (mf_back_cycle) 
[15:16:37:789] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [OFF] 
[15:16:37:789] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:37:909] [Thread: 140348740638464] [Chan 15] - MF Rx << 1 [ON] 
[15:16:37:909] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 5 
[15:16:37:909] [Thread: 140348740638464] [Chan 15] - timer id 5 found, cancelling it now 
[15:16:37:909] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:37:909] [Thread: 140348740638464] [Chan 15] - scheduled timer id 6 (mf_back_cycle) 
[15:16:38:089] [Thread: 140348740638464] [Chan 15] - MF Rx << 1 [OFF] 
[15:16:38:089] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - MF Rx << 5 [ON] 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 6 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - timer id 6 found, cancelling it now 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 5 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - ANI so far: 5, expected length: 20 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:38:189] [Thread: 140348740638464] [Chan 15] - scheduled timer id 7 (mf_back_cycle) 
[15:16:38:409] [Thread: 140348740638464] [Chan 15] - MF Rx << 5 [OFF] 
[15:16:38:409] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - MF Rx << 4 [ON] 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 7 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - timer id 7 found, cancelling it now 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 4 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - ANI so far: 54, expected length: 20 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:38:529] [Thread: 140348740638464] [Chan 15] - scheduled timer id 8 (mf_back_cycle) 
[15:16:38:789] [Thread: 140348740638464] [Chan 15] - MF Rx << 4 [OFF] 
[15:16:38:789] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [ON] 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 8 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - timer id 8 found, cancelling it now 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 3 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - ANI so far: 543, expected length: 20 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:38:889] [Thread: 140348740638464] [Chan 15] - scheduled timer id 9 (mf_back_cycle) 
[15:16:38:989] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [OFF] 
[15:16:38:989] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [ON] 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 9 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - timer id 9 found, cancelling it now 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 3 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - ANI so far: 5433, expected length: 20 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:39:089] [Thread: 140348740638464] [Chan 15] - scheduled timer id 10 (mf_back_cycle) 
[15:16:39:189] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [OFF] 
[15:16:39:189] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [ON] 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 10 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - timer id 10 found, cancelling it now 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 3 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - ANI so far: 54333, expected length: 20 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:39:289] [Thread: 140348740638464] [Chan 15] - scheduled timer id 11 (mf_back_cycle) 
[15:16:39:389] [Thread: 140348740638464] [Chan 15] - MF Rx << 3 [OFF] 
[15:16:39:389] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - MF Rx << 5 [ON] 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 11 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - timer id 11 found, cancelling it now 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 5 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - ANI so far: 543335, expected length: 20 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:39:489] [Thread: 140348740638464] [Chan 15] - scheduled timer id 12 (mf_back_cycle) 
[15:16:39:589] [Thread: 140348740638464] [Chan 15] - MF Rx << 5 [OFF] 
[15:16:39:589] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [ON] 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 12 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - timer id 12 found, cancelling it now 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 0 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - ANI so far: 5433350, expected length: 20 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:39:689] [Thread: 140348740638464] [Chan 15] - scheduled timer id 13 (mf_back_cycle) 
[15:16:39:869] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [OFF] 
[15:16:39:869] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - MF Rx << 7 [ON] 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 13 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - timer id 13 found, cancelling it now 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 7 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - ANI so far: 54333507, expected length: 20 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:39:969] [Thread: 140348740638464] [Chan 15] - scheduled timer id 14 (mf_back_cycle) 
[15:16:40:229] [Thread: 140348740638464] [Chan 15] - MF Rx << 7 [OFF] 
[15:16:40:229] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [ON] 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 14 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - timer id 14 found, cancelling it now 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 0 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - ANI so far: 543335070, expected length: 20 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:40:329] [Thread: 140348740638464] [Chan 15] - scheduled timer id 15 (mf_back_cycle) 
[15:16:40:589] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [OFF] 
[15:16:40:589] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [ON] 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 15 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - timer id 15 found, cancelling it now 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - Getting ANI digit 0 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - ANI so far: 5433350700, expected length: 20 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [ON] 
[15:16:40:689] [Thread: 140348740638464] [Chan 15] - scheduled timer id 16 (mf_back_cycle) 
[15:16:40:789] [Thread: 140348740638464] [Chan 15] - MF Rx << 0 [OFF] 
[15:16:40:789] [Thread: 140348740638464] [Chan 15] - MF Tx >> 5 [OFF] 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - MF Rx << F [ON] 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 16 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - timer id 16 found, cancelling it now 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - Got end of ANI 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - Requesting change to Group II with signal 0x33 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - MF Tx >> 3 [ON] 
[15:16:40:889] [Thread: 140348740638464] [Chan 15] - scheduled timer id 17 (mf_back_cycle) 
[15:16:40:989] [Thread: 140348740638464] [Chan 15] - MF Rx << F [OFF] 
[15:16:40:989] [Thread: 140348740638464] [Chan 15] - MF Tx >> 3 [OFF] 
[15:16:41:089] [Thread: 140348740638464] [Chan 15] - MF Rx << 1 [ON] 
[15:16:41:089] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 17 
[15:16:41:089] [Thread: 140348740638464] [Chan 15] - timer id 17 found, cancelling it now 
[15:16:41:089] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [ON] 
[15:16:41:089] [Thread: 140348740638464] [Chan 15] - scheduled timer id 18 (mf_back_cycle) 
[15:16:41:189] [Thread: 140348740638464] [Chan 15] - MF Rx << 1 [OFF] 
[15:16:41:189] [Thread: 140348740638464] [Chan 15] - MF Tx >> 1 [OFF] 
[15:16:41:189] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 18 
[15:16:41:189] [Thread: 140348740638464] [Chan 15] - timer id 18 found, cancelling it now 
[15:16:41:189] [Thread: 140348740638464] [Chan 15] - scheduled timer id 19 (r2_answer_delay) 
[15:16:41:349] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 19 
[15:16:41:349] [Thread: 140348740638464] [Chan 15] - timer id 19 found, cancelling it now 
[15:16:41:349] [Thread: 140348740638464] [Chan 15] - calling timer 19 (r2_answer_delay) callback 
[15:16:45:376] [Thread: 140350834648832] [Chan 15] - CAS Tx >> [ANSWER] 0x04 
[15:16:45:376] [Thread: 140350834648832] [Chan 15] - CAS Raw Tx >> 0x05 
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - Attempting to cancel timer timer 0 
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - Cannot cancel timer 0 
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - CAS Tx >> [CLEAR BACK] 0x0C 
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - CAS Raw Tx >> 0x0D 
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Bits changed from 0x00 to 0x08 
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - CAS Rx << [CLEAR FORWARD] 0x08 
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Call ended 
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 0 
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Cannot cancel timer 0

I noticed a difference between the handling done by the IP phone and by Asterisk’s Answer.

I will only put the end of the log from the moment it was answered by Asterisk’s Answer until the disconnection:

[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Tx >> [ANSWER] 0x04
[12:25:42:743] [Thread: 140656060507904] [Chan 11] - CAS Raw Tx >> 0x05
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Bits changed from 0x00 to 0x08
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - CAS Rx << [CLEAR FORWARD] 0x08
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Far end disconnected. Reason: Normal Clearing
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Call ended
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Attempting to cancel timer timer 0
[12:26:14:662] [Thread: 140656060507904] [Chan 11] - Cannot cancel timer 0

Below is the handling done by the IP phone from the moment of answering until the call was disconnected:

[15:16:45:376] [Thread: 140350834648832] [Chan 15] - CAS Tx >> [ANSWER] 0x04
[15:16:45:376] [Thread: 140350834648832] [Chan 15] - CAS Raw Tx >> 0x05
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - Attempting to cancel timer timer 0
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - Cannot cancel timer 0
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - CAS Tx >> [CLEAR BACK] 0x0C
[15:17:33:930] [Thread: 140350834648832] [Chan 15] - CAS Raw Tx >> 0x0D
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Bits changed from 0x00 to 0x08
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - CAS Rx << [CLEAR FORWARD] 0x08
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Call ended
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Attempting to cancel timer timer 0
[15:18:00:793] [Thread: 140348740638464] [Chan 15] - Cannot cancel timer 0

Analyzing the logs, the difference between the first log of the call handled with Asterisk’s Answer() and the second log handled by the IP phone is the presence of the line containing the action [CLEAR BACK] 0x0C, which is not present in the call handled by Asterisk’s Answer().

I’m not sure how important this is, but this could be the reason. Can anyone confirm if this is correct, could you help me?

david551 · April 24, 2024, 8:34pm

That just indicates that Asterisk terminated the call, rather than the far end. That pretty much confirms that the problem is in the media, not the signalling.

I’d suggest you are doing one of:

spoofing a signalling tone;
sending a long period of silence, which is being interpreted as the call ending;
triggering some mechanism designed to prevent the sending of large amounts of music.

An example of spoofing a signalling tone, alhtough I don’t know why it would happen at 30 seconds, is sending a 2600Hz tone. I think R2 is one of the systems that is vulnerable to that.

These days you would expect systems to defend themselves against that, which might well result in an immediate termination of the call, but, in the 1970s, this was used to trick tandem exchanges to release without disconnecting the local exchange, allowing MF5 (I think) tones to be sent, to make free long distance calls, by redirecting the tandem exchange to a new destination whilst the local exchange was still applying the local rate charge (free in the US). This is the origin of the name of the alt.2600 news group.

CLEAR FORWARD is ending the call from the originating end. CLEAR BACK is ending the call from terminating end. Clearing a call is the English technical name for disconnecting the connection between the two ends. Actually your title should really say “Clearing” not “Termination”. The latter really means answering in English telphony jargon.

celsoannes · May 9, 2024, 7:29pm

The mystery has been solved. As all the work was being done remotely, I had no idea what the local structure was like. I was informed that the communication was in R2.

The problem was that the Telco was delivering the R2 link through a Gateway, so the Telco would go to the location in SIP, convert it to R2 and deliver it in “R2”. On my side, I put an R2 to SIP converter to communicate with Asterisk, which was in a VM. By removing the two converters and making a communication with the Telco directly in SIP, the problem stopped happening.

The problem was probably happening due to the timeout of the Telco’s converter, as all these conversions take time to be completed in R2, which should have been happening above the time limit configured in the Telco’s converter.

About using “Clearing” and not “Termination”, I apologize, I am from Brazil and there are many terms that I still do not know and sometimes even forget, but I will try to remember this for next time.

Thank you.

system · June 8, 2024, 7:30pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.