| Summary: | ASTERISK-09933: T.38 passthrough with 2 Asterisk boxes not working | ||
| Reporter: | Christoph Stadlmann (cstadlmann) | Labels: | |
| Date Opened: | 2007-07-23 08:41:47 | Date Closed: | 2007-08-06 17:16:14 |
| Priority: | Blocker | Regression? | No |
| Status: | Closed/Complete | Components: | Channels/chan_sip/T.38 |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ( 0) 10274.patch ( 1) Log_Asterisk_1.txt ( 2) Log_Asterisk_2.txt | |
| Description: | This is the configuration I'm using: ATA 1 <-> Asterisk 1 <-> Asterisk 2 <-> ATA 2 As long ATA's are resided on the same Asterisk box, no T.38 problem. But if ATA 1 is trying to send a fax via T.38 to ATA 2, the complete call fails because Asterisk 1 is killing it during re-invite and Asterisk 2 gives up. Both Asterisk boxes are: SVN-branch-1.4-r76410 ****** ADDITIONAL INFORMATION ****** Attached are the log files of both Asterisk boxes. T.38 negotiation starts at the following lines: Log Asterisk 1.txt: 3008 Log Asterisk 2.txt: 1074 The following happens: ATA 2 is sending the reinvite. Asterisk 2 is passing it to Asterisk 1. Because Asterisk 1 is not responding the correct way, Asterisk retransmits the packet again and again, and Asterisk 1 is "Ignoring this INVITE request" again and again till Asterisk 2 gives up (Line 1446). As of my understanding, Asterisk can ONLY manage T.38 passthrough and no endpoint operation. In my scenario, the endpoints are the two ATA boxes, so everything should go THROUGH the two Asterisk boxes. So please advise because my whole system is not working. | ||
| Comments: | By: Christoph Stadlmann (cstadlmann) 2007-07-24 00:48:04 BTW, Asterisk 1 does not close the channels of the failed t38 calls correctly: asnode1*CLI> sip show channels Peer User/ANR Call ID Seq (Tx/Rx) Form Hold Last Message 192.168.255.1 210 048b051b682 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 1686279678- 00106/00082 unkn No (d) Rx: BYE 192.168.255.1 210 5cd2a1f22c3 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 1566241514- 00105/00072 unkn No (d) Rx: BYE 192.168.255.1 210 20ab2e6b1dc 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 1025305174- 00104/00062 unkn No (d) Rx: BYE 192.168.255.1 210 78edc311695 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 1570281691- 00104/00052 unkn No (d) Rx: BYE 192.168.255.1 210 56a7f2cd49a 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 349579561-5 00104/00042 unkn No (d) Rx: BYE 192.168.255.1 210 21a3d2822ae 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 2061138247- 00104/00032 unkn No (d) Rx: BYE 192.168.255.1 210 3e3b148a319 00103/00102 unkn No Rx: INVITE 83.65.56.170 v205357an 512992895-5 00105/00022 unkn No (d) Rx: BYE 192.168.255.1 210 2bd3c32e77a 00103/00102 unkn No Rx: INVITE By: Christoph Stadlmann (cstadlmann) 2007-07-24 02:11:46 This is sip history on Asterisk 1: * SIP Call 1. Rx INVITE / 100 INVITE / sip:057272210@85.193.128.15 2. AuthChal Auth challenge sent for - nc 0 3. TxRespRel SIP/2.0 / 100 INVITE - 407 Proxy Authentication Required 4. SchedDestroy 1664 ms 5. Rx ACK / 100 ACK / sip:057272210@85.193.128.15 6. Rx INVITE / 101 INVITE / sip:057272210@85.193.128.15 7. CancelDestroy 8. Invite New call: 756623685-55279-12@83.65.56.170 9. AuthOK Auth challenge succesful for v205357an 10. NewChan Channel SIP/v205357an-08226a58 - from 756623685-55279-12@83.65. 11. TxResp SIP/2.0 / 101 INVITE - 100 Trying 12. TxResp SIP/2.0 / 101 INVITE - 180 Ringing 13. TxRespRel SIP/2.0 / 101 INVITE - 200 OK 14. Rx ACK / 101 ACK / sip:057272210@85.193.128.15 15. TxReqRel INVITE / 102 INVITE - -UNKNOWN- 16. Rx SIP/2.0 / 102 INVITE / 100 Trying 17. ReInv Re-invite sent 18. TxReqRel INVITE / 103 INVITE - -UNKNOWN- 19. Rx SIP/2.0 / 102 INVITE / 200 OK 20. Ignore Ignoring this retransmit 21. Rx SIP/2.0 / 103 INVITE / 100 Trying 22. ReInv Re-invite sent 23. TxReqRel INVITE / 104 INVITE - -UNKNOWN- 24. Rx SIP/2.0 / 103 INVITE / 200 OK 25. Ignore Ignoring this retransmit 26. Rx SIP/2.0 / 104 INVITE / 100 Trying 27. ReInv Re-invite sent 28. TxReqRel INVITE / 105 INVITE - -UNKNOWN- 29. Rx SIP/2.0 / 104 INVITE / 200 OK 30. Ignore Ignoring this retransmit 31. Rx SIP/2.0 / 105 INVITE / 100 Trying 32. Rx SIP/2.0 / 105 INVITE / 200 OK 33. TxReq ACK / 105 ACK - -UNKNOWN- 34. Rx BYE / 102 BYE / sip:057272210@85.193.128.15 35. RTCPaudio Quality:ssrc=1103484493;themssrc=0;lp=0;rxjitter=0.000000;rxcou 36. TxResp SIP/2.0 / 102 BYE - 200 OK 37. Hangup Cause Normal Clearing This is sip history on Asterisk 2: * SIP Call 1. Rx INVITE / 102 INVITE / sip:210@192.168.255.1 2. AuthChal Auth challenge sent for - nc 0 3. TxRespRel SIP/2.0 / 102 INVITE - 407 Proxy Authentication Required 4. SchedDestroy 64 ms 5. Rx ACK / 102 ACK / sip:210@192.168.255.1 6. Rx INVITE / 103 INVITE / sip:210@192.168.255.1 7. CancelDestroy 8. Invite New call: 31134bfc29b720cd099dc1c2221a52f0@192.168.255.2 9. AuthOK Auth challenge succesful for v203500aa 10. NewChan Channel SIP/v203500aa-081efe50 - from 31134bfc29b720cd099dc1c22 11. TxResp SIP/2.0 / 103 INVITE - 100 Trying 12. TxResp SIP/2.0 / 103 INVITE - 180 Ringing 13. TxRespRel SIP/2.0 / 103 INVITE - 200 OK 14. Rx ACK / 103 ACK / sip:210@192.168.255.1 15. TxReqRel INVITE / 102 INVITE - -UNKNOWN- 16. ReTx 2 INVITE sip:0720440931013@192.168.255.2 SIP/2.0 [Jul 24 09:24:59] WARNING[16793]: chan_sip.c:1920 retrans_pkt: Maximum retries exceeded on transmission 31134bfc29b720cd099dc1c2221a52f0@192.168.255.2 for seqno 102 (Critical Request) [Jul 24 09:24:59] WARNING[16793]: chan_sip.c:1944 retrans_pkt: Hanging up call 31134bfc29b720cd099dc1c2221a52f0@192.168.255.2 - no reply to our critical packet. By: Christoph Stadlmann (cstadlmann) 2007-07-27 01:49:37 Additional info: If you look at the log file 'Log Asterisk 1.txt' at line 3390 ongoing, you will see the following: The ATA 1 sends a '100 Trying' to Asterisk 1. Asterisk 1 parses the SIP message and then something strange happens: In line 3424 chan_sip.c it calls the function 'check_pendings', which sends a completely senseless re-invite to the ATA with NO T.38 information. So I took a look at chan_sip.c (Line 11768 ongoing): switch (resp) { case 100: /* Trying */ case 101: /* Dialog establishment */ if (!ast_test_flag(req, SIP_PKT_IGNORE)) sip_cancel_destroy(p); check_pendings(p); break; In case of '100 Trying' nothing should happen in my opinion. But because there is no 'break;' stetement, code for '101' is executed. So just to find out what happens, I changed line 11769 to the following: case 100: /* Trying */ -> case 100: break; /*Trying */ Now T.38 negotiation between ATA 1 and ATA 2 through both Asterisk boxes is fine because Asterisk 1 waits for '200 OK' from the ATA 1 without executing any code. After '200 OK' from ATA 1 UDPTL packets start to run from ATA 2 to ATA 1, but now Asterisk 1 kills the call at line 11864 in chan_sip.c. So I guess that the problem is not T.38 related. Something strange happens when Asterisk receives a '100 Trying' SIP message during T.38 negotation. Please could someone who knows what chan_sip.c is doing have a look at it. Again my setup: ATA 1, ATA 2: Grandstream HT-502 1.0.0.44 Asterisk 1, Asterisk 2: SVN-branch-1.4-r77460M By: Mark Michelson (mmichelson) 2007-07-30 10:38:20 Just so you don't think no one's looking at this, I'll put in my thoughts. Keep in mind that I'm still learning SIP and so what I say may or may not be right. It appears that the re-invite sent from ATA2 is reaching ATA1 properly. There are other problems along the way that need to be addressed. 1. It would appear that Asterisk2 is expecting to receive a response to the re-invite it transmits, such as possibly a 100 trying. Since it's not receiving such a response, it continues retransmitting the re-invites. Should Asterisk1 (or for that matter, Asterisk2) be generating provisional responses to the re-invites? 2. Let's say that Asterisk shouldn't be generating the provisional responses in point 1 above, and so Asterisk2 should be generating all the retransmissions. Even so, RFC3621 specifies that if a UAS receives a reinvite for an INVITE already in progress, it should send a 491 response. In this case, Asterisk1 is not sending the 491 to Asterisk2 and in fact is deferring the re-invites for later. This is why that call to check_pendings you mentioned is causing Asterisk1 to send a re-invite to ATA1, and it could also be why the passthrough fails later when you removed the call to check_pendings. So in summary, it seems that T38 negotiation fails due to lack of expected responses being generated for reinvites. Thoughts? By: Christoph Stadlmann (cstadlmann) 2007-07-30 13:11:34 Puh... I really thought noone concerns about that issue... To 1) During the last week's testing and tracking and tracing I found out that every ATA or other device immediately sends a '100 Trying' after it receives the reinvite. After that the device responds with '200 OK'. So if Asterisk1 would also send a 100 response immedately to Asterisk2 I think the whole situation wouldn't go that far in the wrong direction. I tried to figure out where to put in that code snippet, but had no luck because I'm not familiar with chan_sip.c at all. To 2) As I mentioned before, Asterisk1 sends a completely senseless reinvite to ATA1 with NO T.38 information, just plain RTP information. Please have a look at line 3424 of 'Log Asterisk 1.txt' and below. You will see what I mean. While ATA1 is responding with a '200 OK' for the T.38 reinvite it receives that useless invite , reponds with '200 OK' again and 'falls back' to plain RTP, so Asterisk 1 thinks that ATA 1 is not capable of T.38. This is that I meant with Asterisk is not handling '100 Trying' correctly because it sends wrong invite packets. So again, I think that all problems are located in the missing '100 Trying' message. Maybe you can implement that code segment into chan_sip.c or just tell me where I can find it and I will try to patch by myself although I'm not a C guru... Anyway, I would appreciate a quick solution 'cause my boss is already on my tail... By: Mark Michelson (mmichelson) 2007-07-30 14:28:02 Try the patch I just uploaded and let me know how it works. By: Christoph Stadlmann (cstadlmann) 2007-07-31 01:49:49 I just patched both Asterisk boxes and T.38 it's working like a breeze. Thanks a lot! This patch should make it into branch as soon as possible so I don't have to patch every time I update my boxes. Although T.38 is working now, we also have to bother about the 491 response. In some cases when the 100 response doesn't arrive at Asterisk2, Asterisk1 should respond with a 491 so Asterisk2 doesn't retransmit again and again. If it's specified in RFC3261, I don't see the point why Asterisk shouldn't do it. Again, thanks a lot for the patch and please don't forget to update branch version. By: Digium Subversion (svnbot) 2007-07-31 10:04:00 Repository: asterisk Revision: 77824 ------------------------------------------------------------------------ r77824 | mmichelson | 2007-07-31 10:03:59 -0500 (Tue, 31 Jul 2007) | 6 lines This patch makes Asterisk send 100 Trying provisional responses upon receipt of re-invites. This makes it so that if there are two or more Asterisk servers between endpoints, the Asterisk servers will not keep retransmitting the re-invites. (closes issue ASTERISK-9933, reported by cstadlmann, patched by me with approval from file) ------------------------------------------------------------------------ By: Digium Subversion (svnbot) 2007-07-31 10:05:10 Repository: asterisk Revision: 77825 ------------------------------------------------------------------------ r77825 | mmichelson | 2007-07-31 10:05:09 -0500 (Tue, 31 Jul 2007) | 14 lines Merged revisions 77824 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77824 | mmichelson | 2007-07-31 10:21:22 -0500 (Tue, 31 Jul 2007) | 6 lines This patch makes Asterisk send 100 Trying provisional responses upon receipt of re-invites. This makes it so that if there are two or more Asterisk servers between endpoints, the Asterisk servers will not keep retransmitting the re-invites. (closes issue ASTERISK-9933, reported by cstadlmann, patched by me with approval from file) ........ ------------------------------------------------------------------------ By: Digium Subversion (svnbot) 2007-07-31 21:28:04 Repository: asterisk Revision: 77850 ------------------------------------------------------------------------ r77850 | murf | 2007-07-31 21:28:01 -0500 (Tue, 31 Jul 2007) | 99 lines Merged revisions 77819-77821,77825,77828-77829,77833-77834,77838,77847 via svnmerge from https://origsvn.digium.com/svn/asterisk/trunk ................ r77819 | kpfleming | 2007-07-31 08:54:46 -0600 (Tue, 31 Jul 2007) | 3 lines umm... let's build with --enable-dev-mode, mmkay? ................ r77820 | kpfleming | 2007-07-31 08:55:37 -0600 (Tue, 31 Jul 2007) | 2 lines use a different method for overriding the send_digit_begin pointer, as the old one fails to compile on my 64-bit system with gcc-4.1 and --enable-dev-mode turned on ................ r77821 | kpfleming | 2007-07-31 09:01:27 -0600 (Tue, 31 Jul 2007) | 2 lines there is no use in having functions that have no code in them, and hide the locking info when DEBUG_THREADS is enabled... i could have fixed this to be dependent on DEBUG_THREADS, but it would be just as easy for someone to add their test/debugging code to the macros as it would have been to the functions ................ r77825 | mmichelson | 2007-07-31 09:22:32 -0600 (Tue, 31 Jul 2007) | 14 lines Merged revisions 77824 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77824 | mmichelson | 2007-07-31 10:21:22 -0500 (Tue, 31 Jul 2007) | 6 lines This patch makes Asterisk send 100 Trying provisional responses upon receipt of re-invites. This makes it so that if there are two or more Asterisk servers between endpoints, the Asterisk servers will not keep retransmitting the re-invites. (closes issue ASTERISK-9933, reported by cstadlmann, patched by me with approval from file) ........ ................ r77828 | kpfleming | 2007-07-31 09:54:29 -0600 (Tue, 31 Jul 2007) | 10 lines Merged revisions 77827 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77827 | kpfleming | 2007-07-31 10:53:42 -0500 (Tue, 31 Jul 2007) | 2 lines DETECT_DEADLOCKS can't be enabled without DEBUG_THREADS or it does nothing ........ ................ r77829 | murf | 2007-07-31 09:59:01 -0600 (Tue, 31 Jul 2007) | 1 line thanks to Russel, for pointing out that the dialoglist_lock/unlock routines also need to be macros if DETECT_DEADLOCKS is set ................ r77833 | file | 2007-07-31 10:21:34 -0600 (Tue, 31 Jul 2007) | 10 lines Merged revisions 77831 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77831 | file | 2007-07-31 13:17:09 -0300 (Tue, 31 Jul 2007) | 2 lines Add a flag to the speech API that allows an engine to set whether it received results or not. ........ ................ r77834 | tilghman | 2007-07-31 10:44:25 -0600 (Tue, 31 Jul 2007) | 3 lines Add func_lock, which creates dialplan mutexes, and note that the Macro apps are now deprecated. (Closes issue ASTERISK-9923) ................ r77838 | tilghman | 2007-07-31 12:50:06 -0600 (Tue, 31 Jul 2007) | 2 lines Add some documentation detailing an aspect of dialplan functions, as requested by Russell ................ r77847 | murf | 2007-07-31 15:33:37 -0600 (Tue, 31 Jul 2007) | 17 lines Merged revisions 77844 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ................ r77844 | murf | 2007-07-31 14:59:10 -0600 (Tue, 31 Jul 2007) | 9 lines Merged revisions 77842 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.2 ........ r77842 | murf | 2007-07-31 13:19:35 -0600 (Tue, 31 Jul 2007) | 1 line This probably isn't super-general, but it's a first stab at using kill -11 to generate a core file instead of gcore. ........ ................ ................ ------------------------------------------------------------------------ By: Digium Subversion (svnbot) 2007-08-06 17:16:14 Repository: asterisk Revision: 78298 ------------------------------------------------------------------------ r78298 | murf | 2007-08-06 17:16:13 -0500 (Mon, 06 Aug 2007) | 151 lines Merged revisions 77850,77893,77906,77961,78003,78038,78070,78110,78199,78230,78250,78267 via svnmerge from https://origsvn.digium.com/svn/asterisk/team/group/CDRfix5 ................ r77850 | murf | 2007-07-31 20:45:22 -0600 (Tue, 31 Jul 2007) | 99 lines Merged revisions 77819-77821,77825,77828-77829,77833-77834,77838,77847 via svnmerge from https://origsvn.digium.com/svn/asterisk/trunk ................ r77819 | kpfleming | 2007-07-31 08:54:46 -0600 (Tue, 31 Jul 2007) | 3 lines umm... let's build with --enable-dev-mode, mmkay? ................ r77820 | kpfleming | 2007-07-31 08:55:37 -0600 (Tue, 31 Jul 2007) | 2 lines use a different method for overriding the send_digit_begin pointer, as the old one fails to compile on my 64-bit system with gcc-4.1 and --enable-dev-mode turned on ................ r77821 | kpfleming | 2007-07-31 09:01:27 -0600 (Tue, 31 Jul 2007) | 2 lines there is no use in having functions that have no code in them, and hide the locking info when DEBUG_THREADS is enabled... i could have fixed this to be dependent on DEBUG_THREADS, but it would be just as easy for someone to add their test/debugging code to the macros as it would have been to the functions ................ r77825 | mmichelson | 2007-07-31 09:22:32 -0600 (Tue, 31 Jul 2007) | 14 lines Merged revisions 77824 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77824 | mmichelson | 2007-07-31 10:21:22 -0500 (Tue, 31 Jul 2007) | 6 lines This patch makes Asterisk send 100 Trying provisional responses upon receipt of re-invites. This makes it so that if there are two or more Asterisk servers between endpoints, the Asterisk servers will not keep retransmitting the re-invites. (closes issue ASTERISK-9933, reported by cstadlmann, patched by me with approval from file) ........ ................ r77828 | kpfleming | 2007-07-31 09:54:29 -0600 (Tue, 31 Jul 2007) | 10 lines Merged revisions 77827 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77827 | kpfleming | 2007-07-31 10:53:42 -0500 (Tue, 31 Jul 2007) | 2 lines DETECT_DEADLOCKS can't be enabled without DEBUG_THREADS or it does nothing ........ ................ r77829 | murf | 2007-07-31 09:59:01 -0600 (Tue, 31 Jul 2007) | 1 line thanks to Russel, for pointing out that the dialoglist_lock/unlock routines also need to be macros if DETECT_DEADLOCKS is set ................ r77833 | file | 2007-07-31 10:21:34 -0600 (Tue, 31 Jul 2007) | 10 lines Merged revisions 77831 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r77831 | file | 2007-07-31 13:17:09 -0300 (Tue, 31 Jul 2007) | 2 lines Add a flag to the speech API that allows an engine to set whether it received results or not. ........ ................ r77834 | tilghman | 2007-07-31 10:44:25 -0600 (Tue, 31 Jul 2007) | 3 lines Add func_lock, which creates dialplan mutexes, and note that the Macro apps are now deprecated. (Closes issue ASTERISK-9923) ................ r77838 | tilghman | 2007-07-31 12:50:06 -0600 (Tue, 31 Jul 2007) | 2 lines Add some documentation detailing an aspect of dialplan functions, as requested by Russell ................ r77847 | murf | 2007-07-31 15:33:37 -0600 (Tue, 31 Jul 2007) | 17 lines Merged revisions 77844 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ................ r77844 | murf | 2007-07-31 14:59:10 -0600 (Tue, 31 Jul 2007) | 9 lines Merged revisions 77842 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.2 ........ r77842 | murf | 2007-07-31 13:19:35 -0600 (Tue, 31 Jul 2007) | 1 line This probably isn't super-general, but it's a first stab at using kill -11 to generate a core file instead of gcore. ........ ................ ................ ................ r77893 | murf | 2007-08-01 18:16:13 -0600 (Wed, 01 Aug 2007) | 1 line As per suggestion of Tilghman, we split the read and write of CDR_CONTROL; begin automation of CDR output for non-answer cases ................ r77906 | automerge | 2007-08-02 09:39:28 -0600 (Thu, 02 Aug 2007) | 1 line automerge commit ................ r77961 | automerge | 2007-08-02 13:51:54 -0600 (Thu, 02 Aug 2007) | 1 line automerge commit ................ r78003 | automerge | 2007-08-02 17:36:08 -0600 (Thu, 02 Aug 2007) | 1 line automerge commit ................ r78038 | automerge | 2007-08-03 01:35:47 -0600 (Fri, 03 Aug 2007) | 1 line automerge commit ................ r78070 | automerge | 2007-08-03 11:35:27 -0600 (Fri, 03 Aug 2007) | 1 line automerge commit ................ r78110 | automerge | 2007-08-03 14:35:41 -0600 (Fri, 03 Aug 2007) | 1 line automerge commit ................ r78199 | automerge | 2007-08-06 12:28:47 -0600 (Mon, 06 Aug 2007) | 1 line automerge commit ................ r78230 | automerge | 2007-08-06 14:26:05 -0600 (Mon, 06 Aug 2007) | 1 line automerge commit ................ r78250 | automerge | 2007-08-06 15:27:29 -0600 (Mon, 06 Aug 2007) | 1 line automerge commit ................ r78267 | murf | 2007-08-06 15:36:13 -0600 (Mon, 06 Aug 2007) | 1 line Next installment on getting Asterisk to post unanswered, busy, failed calls ................ ------------------------------------------------------------------------ | ||