[asterisk-bugs] [JIRA] (ASTERISK-29035) chan_local: Multistream support breaks T.38 faxing
Matthias Hensler (JIRA)
noreply at issues.asterisk.org
Fri Mar 19 04:14:23 CDT 2021
[ https://issues.asterisk.org/jira/browse/ASTERISK-29035?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=254226#comment-254226 ]
Matthias Hensler commented on ASTERISK-29035:
---------------------------------------------
Unfortunately I have to reopen this issue. The current patch (used on Asterisk 16.16.2) did cause another deadlock on our asterisk. As last time I could connect to the console and check open channels, but no new call was possible and trying to gracefully shut down did not work either. At the time of the deadlock we had 144 channels active (112516 calls processed).
The last successful call was a T38-fax on a local channel. According to the logs and our external monitoring that fax was processed, however some seconds before the fax was finished new calls were no longer possible. INVITES to asterisk were not replied to. Also the problematic T38-call (while the fax was already finished) did not hang up properly in the sip-trace (the caller sent several "BYE" without any answer from asterisk).
I add some of the last logfilelines, although I doubt they a of much help.
This is the excerpt for the fax-call from our verbose log:
{quote}
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:9] NoOp("Local/004940XXX at routing_intern-00001c77;2", "Registrierung folgt") in new stack
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:10] Set("Local/004940XXX at routing_intern-00001c77;2", "CDR(EinkaufTelefonieProviderID)=0") in new stack
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:11] Set("Local/004940XXX at routing_intern-00001c77;2", "AGI_SUCCESS=0") in new stack
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:12] AGI("Local/004940XXX at routing_intern-00001c77;2", "agi://127.0.0.1/faxhandler,inreg,"004940XXX","004940XXX",TERM") in new stack
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] res_agi.c: agi://127.0.0.1/faxhandler,inreg,"004940XXX","004940XXX",TERM: Faxhandler: Aktion=inreg, Rufnummer=004940XXX, Callerid=004940XXX
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] res_agi.c: agi://127.0.0.1/faxhandler,inreg,"004940XXX","004940XXX",TERM: Faxhandler: zugewiesene ID=104168, FN=/var/spool/asterisk/fax/0000104168-inbound-4399.tif
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] res_agi.c: <Local/004940XXX at routing_intern-00001c77;2>AGI Script agi://127.0.0.1/faxhandler completed, returning 0
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:13] GotoIf("Local/004940XXX at routing_intern-00001c77;2", "1?:Overlimit") in new stack
[2021-03-19 08:47:46] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:14] Answer("Local/004940XXX at routing_intern-00001c77;2", "") in new stack
[2021-03-19 08:47:46] VERBOSE[27306][C-0002ec8b] app_dial.c: Local/004940XXX at routing_intern-00001c77;1 answered SIP/trunk_XXXXXX-00033467
[2021-03-19 08:47:46] VERBOSE[27311][C-0002ec8b] bridge_channel.c: Channel Local/004940XXX at routing_intern-00001c77;1 joined 'simple_bridge' basic-bridge <a722361d-b600-4cd9-ac30-b4b62a6c4394>
[2021-03-19 08:47:46] VERBOSE[27306][C-0002ec8b] bridge_channel.c: Channel SIP/trunk_XXXXXX-00033467 joined 'simple_bridge' basic-bridge <a722361d-b600-4cd9-ac30-b4b62a6c4394>
[2021-03-19 08:47:46] VERBOSE[4141][C-0002ec8b] netsock2.c: Using UDPTL TOS bits 184
[2021-03-19 08:47:46] VERBOSE[4141][C-0002ec8b] netsock2.c: Using UDPTL TOS bits 184 in TCLASS field.
[2021-03-19 08:47:46] VERBOSE[4141][C-0002ec8b] netsock2.c: Using UDPTL CoS mark 5
[2021-03-19 08:47:47] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:15] Wait("Local/004940XXX at routing_intern-00001c77;2", "1") in new stack
[2021-03-19 08:47:48] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:16] ReceiveFAX("Local/004940XXX at routing_intern-00001c77;2", "/var/spool/asterisk/fax/0000104168-inbound-4399.tif,fd") in new stack
[2021-03-19 08:47:48] VERBOSE[27308][C-0002ec8b] res_fax.c: Channel 'Local/004940XXX at routing_intern-00001c77;2' receiving FAX '/var/spool/asterisk/fax/0000104168-inbound-4399.tif'
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [004940XXX at inbound_fax:17] Hangup("Local/004940XXX at routing_intern-00001c77;2", "") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Spawn extension (inbound_fax, 004940XXX, 17) exited non-zero on 'Local/004940XXX at routing_intern-00001c77;2'
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:1] NoOp("Local/004940XXX at routing_intern-00001c77;2", "Hangup occured, processing fax") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:2] NoOp("Local/004940XXX at routing_intern-00001c77;2", "Status=SUCCESS, Str=OK, Error=") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:3] NoOp("Local/004940XXX at routing_intern-00001c77;2", "Station=040XXX , Pages=3, Rate=14400, Resolution=8031x7700") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:4] Set("Local/004940XXX at routing_intern-00001c77;2", "AGI_SUCCESS=0") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:5] AGI("Local/004940XXX at routing_intern-00001c77;2", "agi://127.0.0.1/faxhandler,inhangup,"104168","SUCCESS","OK","3","14400","040XXX ","8031x7700","",TERM") in new stack
[2021-03-19 08:48:36] VERBOSE[27308][C-0002ec8b] res_agi.c: agi://127.0.0.1/faxhandler,inhangup,"104168","SUCCESS","OK","3","14400","040XXX ","8031x7700","",TERM: Faxhandler: Aktion=inhangup, ID=104168
[2021-03-19 08:48:37] VERBOSE[27308][C-0002ec8b] res_agi.c: <Local/004940XXX at routing_intern-00001c77;2>AGI Script agi://127.0.0.1/faxhandler completed, returning 0
[2021-03-19 08:48:37] VERBOSE[27308][C-0002ec8b] pbx.c: Executing [h at inbound_fax:6] NoOp("Local/004940XXX at routing_intern-00001c77;2", "Handler-Result: 1") in new stack
[2021-03-19 08:48:37] VERBOSE[27311][C-0002ec8b] bridge_channel.c: Channel Local/004940XXX at routing_intern-00001c77;1 left 'simple_bridge' basic-bridge <a722361d-b600-4cd9-ac30-b4b62a6c4394>
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] bridge_channel.c: Channel SIP/trunk_XXXXXX-00033467 left 'simple_bridge' basic-bridge <a722361d-b600-4cd9-ac30-b4b62a6c4394>
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Spawn extension (gosub-outbound_peer_intern, 004940XXXXXted non-zero on 'SIP/trunk_XXXXXX-00033467'
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Executing [h at gosub-outbound_peer_intern:1] Return("SIP/trunk_XXXXXX-00033467", "0") in new stack
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Executing [004940XXX at routing_full:9] NoOp("SIP/trunk_XXXXXX-00033467", "Macro outbound_peer_intern Retval=0") in new stack
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Executing [004940XXX at routing_full:10] GotoIf("SIP/trunk_XXXXXX-00033467", "1?SkipFax:") in new stack
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx_builtins.c: Goto (routing_full,004940XXX,13)
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Executing [004940XXX at routing_full:13] GotoIf("SIP/trunk_XXXXXX-00033467", "0?LokalFailed:") in new stack
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Executing [004940XXX at routing_full:14] Hangup("SIP/trunk_XXXXXX-00033467", "") in new stack
[2021-03-19 08:48:37] VERBOSE[27306][C-0002ec8b] pbx.c: Spawn extension (routing_full, 004940XXX, 14) exited non-zero on 'SIP/trunk_XXXXXX-00033467'
{quote}
And the last message from our fax-log:
{quote}
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Page no = 3
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Image size = 1728 x 2287 pixels
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Image resolution = 8031/m x 7700/m
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Compression = T.6 (3)
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Compressed image size = 11837 bytes
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from state 13 to 14
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Tx: MCF with final frame tag
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Tx: ff 13 8c
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 760: IFP c0 01 10
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 760: (0) data v21/hdlc-sig-end + 0 byte(s)
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Receive complete in phase T30_PHASE_D_RX, state 14
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from phase T30_PHASE_D_RX to T30_PHASE_D_TX
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set rx type 0
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set tx type 4
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 No signal is present
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 761: IFP 00
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 761: indicator no-signal
[2021-03-19 08:48:33] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 61: indicator v21-preamble
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 62: (0) data v21/hdlc-data + 1 byte(s)
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 62: IFP c0 01 80 00 00 ff
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 63: (0) data v21/hdlc-data + 1 byte(s)
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 63: IFP c0 01 80 00 00 c8
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 64: (0) data v21/hdlc-data + 1 byte(s)
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 64: IFP c0 01 80 00 00 31
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 14
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 65: (0) data v21/hdlc-fcs-OK-sig-end + 0 byte(s)
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 65: IFP c0 01 40
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 14
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_D_RX
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set rx type 4
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set tx type 0
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Start T4
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Tx 66: indicator no-signal
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 762: IFP 06
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 762: indicator v21-preamble
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 A signal is present
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 HDLC signal status is Framing OK (-6) in state 14
[2021-03-19 08:48:34] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Start T4A
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 763: IFP c0 01 80 00 01 ff c8
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 763: (0) data v21/hdlc-data + 2 byte(s)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 764: IFP c0 02 80 00 00 df 20
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 764: (0) data v21/hdlc-data + 1 byte(s)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 764: (1) data v21/hdlc-fcs-OK + 0 byte(s)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Type DCN - CRC OK (clean)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Stop T4A (15520 remaining)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Rx: DCN with final frame tag
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Rx: ff 13 fb
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Rx final frame in state 14
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Disconnecting
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from phase T30_PHASE_D_RX to T30_PHASE_E
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set rx type 0
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set tx type 1
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from state 14 to 2
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 765: IFP c0 01 10
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 765: (0) data v21/hdlc-sig-end + 0 byte(s)
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Receive complete in phase T30_PHASE_E, state 2
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 HDLC signal status is Carrier down (-1) in state 2
[2021-03-19 08:48:35] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 No signal is present
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 766: IFP 00
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38 Rx 766: indicator no-signal
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Send complete in phase T30_PHASE_E, state 2
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from state 2 to 32
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set rx type 9
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T Set tx type 9
[2021-03-19 08:48:36] FAX[27308][C-0002ec8b] res_fax.c: FLOW T.38T FAX exchange complete
{quote}
> 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
> Labels: fax, patch
> Target Release: 16.17.0, 18.3.0
>
> 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