[asterisk-bugs] [JIRA] (ASTERISK-29035) chan_local: Multistream support breaks T.38 faxing

Matthias Hensler (JIRA) noreply at issues.asterisk.org
Thu Jan 14 05:42:00 CST 2021 

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29035?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=253492#comment-253492 ] 

Matthias Hensler edited comment on ASTERISK-29035 at 1/14/21 5:40 AM:
----------------------------------------------------------------------

Unfortunately I had to revert the patch, as our Asteriskinstance stopped working properly after less than <36 hours with this patch.

Symptoms:
* I was able to connect via the CLI and issue commands like "core show channels verbose". At the time of the problem there were 303 active channels, 154 active calls and 37134 calls processed.
* In that moment the manager-API did not work properly and yielded no results (connection was possible, but in some way no results were given). Unfortunately I had no time to investigate further
* active calls were still being processed and working
* new calls were no longer possible
* according to a tcpdump a lot of register-requests where dispatched to asterisk but not being replied to
* our verboselog did only show manager-logins and warnings about chan_sip not able to send 10 type frames (which is perfectly normal).

The last interesting messages on the verboselog were:
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] res_agi.c: agi://127.0.0.1/faxhandler,outhangup,"97416","SUCCESS","OK","10","9600","+49 241/....-.....  ","8031x7700","",TERM: Faxhandler: Aktion=outhangup, ID=97416
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] res_agi.c: <Local/0049241.... at routing_billing-000008d5;1>AGI Script agi://127.0.0.1/faxhandler completed, returning 0
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Executing [h at outbound_fax:7] NoOp("Local/0049241.... at routing_billing-000008d5;1", "Handler-Result: 1") in new stack
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Executing [h at outbound_fax:8] Hangup("Local/0049241.... at routing_billing-000008d5;1", "") in new stack
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Spawn extension (outbound_fax, h, 8) exited non-zero on 'Local/0049241.... at routing_billing-000008d5;1'
[2021-01-14 12:08:11] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:11] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:12] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:12] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:13] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:13] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:13] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:14] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:14] VERBOSE[29430] manager.c: Manager 'relaix_intern' logged on from 127.0.0.1
[2021-01-14 12:08:14] VERBOSE[29430] manager.c: Manager 'relaix_intern' logged off from 127.0.0.1
[2021-01-14 12:08:15] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:15] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:15] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:17] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:17] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:17] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:17] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:18] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:19] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:19] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:19] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:20] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:21] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:21] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:22] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:22] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:23] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:24] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:26] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:27] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:27] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:28] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:29] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1


So it seems that asterisk entered a deadlock after an outgoing (SendFax)-call was finished and already hang up.

As this is our productionsystem and the issue happend at a prime time, i had to roll back to our previous version for the moment.


was (Author: cubbi):
Unfortunately I had to revert the patch, as our Asteriskinstance stopped working properly after less than <36 hours with this patch.

Symptoms:
* I was able to connect via the CLI and issue commands like "core show channels verbose". At the time of the problem there were 303 active channels, 154 active calls and 37134 calls processed.
* In that moment the manager-API did not work properly and yielded now results (connection was possible, but in some why no results were given). Unfortunately I had no time to investigate further
* active calls were still being processed and working
* new calls were no longer possible
* according to a tcpdump a lot of register-requests where dispatched to asterisk but not being replied to
* our verboselog did only show manager-logins and warnings about chan_sip not able to send 10 type frames (which is perfectly normal).

The last interesting messages on the verboselog were:
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] res_agi.c: agi://127.0.0.1/faxhandler,outhangup,"97416","SUCCESS","OK","10","9600","+49 241/....-.....  ","8031x7700","",TERM: Faxhandler: Aktion=outhangup, ID=97416
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] res_agi.c: <Local/0049241.... at routing_billing-000008d5;1>AGI Script agi://127.0.0.1/faxhandler completed, returning 0
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Executing [h at outbound_fax:7] NoOp("Local/0049241.... at routing_billing-000008d5;1", "Handler-Result: 1") in new stack
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Executing [h at outbound_fax:8] Hangup("Local/0049241.... at routing_billing-000008d5;1", "") in new stack
[2021-01-14 12:08:10] VERBOSE[26758][C-0000cedf] pbx.c: Spawn extension (outbound_fax, h, 8) exited non-zero on 'Local/0049241.... at routing_billing-000008d5;1'
[2021-01-14 12:08:11] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:11] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:12] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:12] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:13] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:13] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:13] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:14] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:14] VERBOSE[29430] manager.c: Manager 'relaix_intern' logged on from 127.0.0.1
[2021-01-14 12:08:14] VERBOSE[29430] manager.c: Manager 'relaix_intern' logged off from 127.0.0.1
[2021-01-14 12:08:15] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:15] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:15] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:17] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:17] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:17] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:17] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:18] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:19] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:19] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:19] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:20] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:21] WARNING[4818][C-0000c148] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:21] WARNING[5183][C-0000c15c] chan_sip.c: Can't send 10 type frames with SIP write
[2021-01-14 12:08:22] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:22] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:23] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:24] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:26] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:27] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:27] VERBOSE[27384][C-0000cf06] res_srtp.c: SRTCP unprotect failed on SSRC 1334759288 because of authentication failure
[2021-01-14 12:08:28] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1
[2021-01-14 12:08:29] WARNING[26759][C-0000cede] channel.c: Exceptionally long voice queue length queuing to Local/0049241.... at routing_billing-000008d5;1


So it seems that asterisk entered a deadlock after an outgoing (SendFax)-call was finished and already hang up.

As this is our productionsystem and the issue happend at a prime time, i had to roll back to our previous version for the moment.

> chan_local: Multistream support breaks T.38 faxing
> --------------------------------------------------
>
>                 Key: ASTERISK-29035
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29035
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_local
>    Affects Versions: 16.12.0, 18.1.0
>         Environment: CentOS 7
>            Reporter: Matthias Hensler
>            Assignee: Benjamin Keith Ford
>            Severity: Minor
>              Labels: fax, patch
>         Attachments: ASTERISK-29035.diff, Inbound-16.11.0-LocalChannel.pcap, Inbound-16.12.0-LocalChannel.pcap, Inbound-16.12.0-NoLocal.pcap
>
>
> After updating from 16.11.0 to 16.12.0 all faxes via SendFax() and ReceiveFax()-applications break, when placed on a Local-channel and T.38 is used.
> Our dialplan makes use of Local-channels when dialing internal numbers and is also used for issuing outgoing fax-traffic via an originate-call using the manager-API. With the rework of chan_local in 16.12.0 (I suspect ASTERISK-28938 here) this breaks our outgoing fax-traffic when the destination uses T.38. If G.711a is used the problem does not occur.
> When looking at some pcap-traces I can see, that the destination reinvites to T.38 after a call is established and sends lots of T.38 packets. However Asterisk simple ignores any T.38-packet and does not respond to any of these packets, until the call is then finally dropped and fax-transmission ultimately fails.
> Fortunately the problem is very easy to reproduce with an inbound fax also. For that I used an older test-instance of Asterisk 17.1.0 which dials in to our real Asterisk instance where the call is placed via a `Dial(Local/...)` to the appropriate extension where ReceiveFax() is running.
> When running Asterisk 16.11.0 everything works as expected (see Inbound-16.11.0-LocalChannel.pcap) where the connection is established with T.38 and the fax is received properly.
> When switching to Asterisk 16.12.0 on the receiving end the exact same setup breaks (see Inbound-16.12.0-LocalChannel.pcap). The connection is established with T.38 and packets are send from the test-instance, but no replies are issued by Asterisk 16.12.0 (we are running ReceiveFax() in debug mode and it does not log anything with 16.12.0, so obviously chan_local does not properly relays the T.38-frames).
> Just by removing the `Dial(Local/...)` from the dialplan and jumping directly to the ReceiveFax()-extension makes the setup work again on Asterisk 16.12.0 (see Inbound-16.12.0-NoLocal.pcap). So I am pretty sure that the culprit results from the recent changes to chan_local.
> I know that using local-channels is not the nicest thing to do, but we rely on it to process call redirections on local numbers, while still keeping proper call data records for correct billing.
> If more debug output besides the pcap-traces, or a proper dialplan example is needed, I am happy to provide it of course.



--
This message was sent by Atlassian JIRA
(v6.2#6252)

More information about the asterisk-bugs mailing list