Recursive
2014-Dec-02 08:24 UTC
[asterisk-users] T.38 not working - help needed with log interpretation
Dear all, I have the following situation: Local T.38 endpoint <-> ASTERISK <-> SIP provider (with T.38 support) I am trying to send a fax from my local T.38 endpoint to arbitrary external fax numbers (which I am not in control of, so I don't know if the other end supports T.38, is connected to a PBX, who is their provider, and so on), of course trying to use T.38 at least from my local endpoint to the provider's gateway. This always fails. I have recorded the respective network traffic with Wireshark. From the log, I can see that the training is successful. The transmission fails exactly at the moment when it should switch to T.38. I think that my endpoint is misbehaving in that situation and wanted to make sure that I am right by asking the experts. Here is an excerpt of the log (the part which I am considering relevant): No. Time Source Destination Protocol Length Info 14308 16.089226 192.168.20.48 192.168.20.14 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x8A086DE, Seq=63333, Time=23840 14311 16.109178 83.125.8.155 192.168.20.48 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x71FD8337, Seq=41621, Time=24000 14312 16.110788 192.168.20.48 192.168.20.14 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x8A086DE, Seq=63334, Time=24000 14313 16.118096 83.125.8.71 192.168.20.48 SIP/SDP 988 Request: INVITE sip:000387839679 at 79.211.71.113:64280, in-dialog | 14314 16.118466 192.168.20.48 83.125.8.71 SIP 633 Status: 100 Trying | 14315 16.118739 192.168.20.48 192.168.20.14 SIP/SDP 923 Request: INVITE sip:bCo9m7OfHWK2Y2sb at 192.168.20.14:5060, in-dialog | 14321 16.169196 192.168.20.14 192.168.20.48 SIP/SDP 982 Status: 200 OK | 14322 16.170900 192.168.20.48 192.168.20.14 SIP 476 Request: ACK sip:bCo9m7OfHWK2Y2sb at 192.168.20.14:5060 | 14323 16.171160 192.168.20.48 83.125.8.71 SIP/SDP 951 Status: 200 OK | 14329 16.208396 83.125.8.71 192.168.20.48 SIP 559 Request: ACK sip:000387839679 at 79.211.71.113:64280 | 14453 17.611041 192.168.20.14 192.168.20.48 SIP/SDP 1204 Request: INVITE sip:004921123704144 at spock-asterisk.home.omeganet.de:5060, in-dialog | 14454 17.611304 192.168.20.48 192.168.20.14 SIP 577 Status: 100 Trying | 14649 22.611128 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | 14650 22.661007 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] 14651 23.111663 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | 14652 23.162024 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] 14653 24.112190 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | 14654 24.162038 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] 14655 25.838900 192.168.20.14 192.168.20.48 SIP 484 Request: BYE sip:004921123704144 at 192.168.20.48:5060 | 14656 25.839076 192.168.20.48 192.168.20.14 SIP 519 Status: 500 Server error | 14657 26.110508 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | 14658 26.161125 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] 19910 30.111548 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | 19911 30.162368 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] 192.168.20.14 is my local T.38 endpoint, 192.168.20.48 is ASTERISK, and 83.125.8.xxx are the provider's gateways / servers. My interpretation of the log is as follows: - The first three packets are the end of the training (quite sure about that) - Packets 14313, 14314: The provider re-invites asterisk for T.38 (confirmed by viewing the packet's details), asterisk answers "Trying ..." to the provider - Packets 14315, 14321, 14322: Asterisk re-invites the local endpoint (again confirmed by looking into the packet's details), the local endpoint answers "OK", and asterisk ACKs the OK. - Packets 14323, 14329: Asterisk accepts the invitation from the provider by sending "OK" to the provider, and the provider ACKs the OK. - Packets 14453, 14454 and 14649: The local endpoint again tries to re-invite asterisk for T.38 (confirmed by looking into the packet's details), Asterisk answers "Trying" and then refuses, saying "488: Not acceptable here" - From then on, things go horribly wrong (probably, the local endpoint is still expecting G.711 packets, but gets T.38 packets) I have provided all packets which are relevant. The packet numbers are not contiguous since asterisk currently is on a test server which runs many other services (the packets of which I have filtered out). I didn't want to clutter this post too much, thus I have only provided an overview and not the details of each packet. Furthermore, please forgive me that it's much easier for me to read Wireshark's logs than Asterisk's logs. Of course, I will provide every log anybody trying to help out asks me for. But my first question is a very simple one:>From the log above, I am quite sure that switching to T.38 is done right up to (and including) packet 14329. I think that my local endpoint then misbehaves by again re-inviting asterisk for T.38 (as all parties already have agreed upon T.38).Thus, is my endpoint really misbehaving, and if yes, is there anything I can do about it on Asterisk's side? Or do the SIP/T.38 state machines allow such (seemingly superfluous) re-invite, and it's Asterisk's fault to answer with 488? Thank you very much, Recursive
Frederic Van Espen
2014-Dec-10 10:42 UTC
[asterisk-users] T.38 not working - help needed with log interpretation
Hi, On Tue, Dec 2, 2014 at 9:24 AM, Recursive <lists at binarus.de> wrote:> - Packets 14313, 14314: The provider re-invites asterisk for T.38 (confirmed by viewing the packet's details), asterisk answers "Trying ..." to the provider > - Packets 14315, 14321, 14322: Asterisk re-invites the local endpoint (again confirmed by looking into the packet's details), the local endpoint answers "OK", and asterisk ACKs the OK. > - Packets 14323, 14329: Asterisk accepts the invitation from the provider by sending "OK" to the provider, and the provider ACKs the OK. > - Packets 14453, 14454 and 14649: The local endpoint again tries to re-invite asterisk for T.38 (confirmed by looking into the packet's details), Asterisk answers "Trying" and then refuses, saying "488: Not acceptable here" > - From then on, things go horribly wrong (probably, the local endpoint is still expecting G.711 packets, but gets T.38 packets) > > I have provided all packets which are relevant. The packet numbers are not contiguous since asterisk currently is on a test server which runs many other services (the packets of which I have filtered out). > > I didn't want to clutter this post too much, thus I have only provided an overview and not the details of each packet. Furthermore, please forgive me that it's much easier for me to read Wireshark's logs than Asterisk's logs. Of course, I will provide every log anybody trying to help out asks me for. > > But my first question is a very simple one: > > From the log above, I am quite sure that switching to T.38 is done right up to (and including) packet 14329. I think that my local endpoint then misbehaves by again re-inviting asterisk for T.38 (as all parties already have agreed upon T.38). > > Thus, is my endpoint really misbehaving, and if yes, is there anything I can do about it on Asterisk's side? Or do the SIP/T.38 state machines allow such (seemingly superfluous) re-invite, and it's Asterisk's fault to answer with 488?- Could you share the details of the SDP in each INVITE and OK packet? - How are your SIP endpoints configured in asterisk sip.conf? (the SIP trunk provider and the local endpoint) - What type is the local endpoint? Cheers, Frederic
Recursive
2014-Dec-11 08:52 UTC
[asterisk-users] T.38 not working - help needed with log interpretation
Hello,
at first, thanks for helping!
In the meantime, I have done a lot of research and trial and error, and I could
solve that specific problem. Obviously, the dialplan application
"Answer" was playing a key role here. My original dialplan snippet
(which produced that problem) was:
exten => _00., 1, NoOp()
same => n, Set(FAXOPT(gateway)=yes)
same => n, Dial(SIP/${EXTEN}@27XgY8YwfI2S9NAg)
same => n, Hangup()
The problem vanished when I changed that to:
exten => _00., 1, NoOp()
same => n, Answer()
same => n, Progress()
same => n, Set(FAXOPT(gateway)=yes)
same => n, Dial(SIP/${EXTEN}@27XgY8YwfI2S9NAg)
same => n, Hangup()
However, I got another problem then:
The fax training now went well, and a part of the fax was transmitted, i.e.
switching from G711 to T32 now worked. But after 32 seconds (measured from the
begin of the transmission) Asterisk claimed that there was a timeout with
receiving an answer to a critical packet, and ended the transmission (by sending
BYE messages to both ends).
Wireshark and SIP debug analysis have shown that this error message is
completely humbug. I have thoroughly gone through the logs line by line more
times that I could count, and (by following the CSeq) I every time have seen
that the error message was relating to one or more OK messages which Asterisk
had sent to the provider, but I swear that the provider correctly had ACKed
every single of these OK messages. So I really can't imagine how Asterisk
came to the idea that it hadn't received the answer. Maybe my interpretation
of the logs is wrong, but if Wireshark's logs show an ACK for every OK, all
should be well, shouldn't it?
Anyway, that means that I now can send an average one page fax document to fast
endpoints which do the training quickly and provide high data rates. But if the
endpoint is slower or if the fax document has multiple pages or a
disadvantageous structure, it will take more than 32 seconds to transmit and
thus will be cut by Asterisk. The receiving fax machine in this case either sees
a part of the page or some weird random patterns.
I think that this is a bug in chan_sip which seemingly does not have the best
reputation when it comes to T38. The erroneous behaviour has shown in every test
I have done (4 different fax machines at the other end serviced by three
different providers, each tested with two different SIP providers (trunks)).
At this point, I have given up chan_sip and hoped that pjsip would behave
correctly, but what a frustration: Although spending three complete days with
it, I even couldn't make it do the training. It always makes the SIP
provider switch to T38 at once at the very beginning of the transmission which
of course won't work. I think I'll open another thread about that
problem; it's somehow off-topic here.
Regards and thank you very much,
Recursive
On 10.12.2014 11:42, Frederic Van Espen wrote:> Hi,
>
> On Tue, Dec 2, 2014 at 9:24 AM, Recursive <lists at binarus.de>
wrote:
>> - Packets 14313, 14314: The provider re-invites asterisk for T.38
(confirmed by viewing the packet's details), asterisk answers "Trying
..." to the provider
>> - Packets 14315, 14321, 14322: Asterisk re-invites the local endpoint
(again confirmed by looking into the packet's details), the local endpoint
answers "OK", and asterisk ACKs the OK.
>> - Packets 14323, 14329: Asterisk accepts the invitation from the
provider by sending "OK" to the provider, and the provider ACKs the
OK.
>> - Packets 14453, 14454 and 14649: The local endpoint again tries to
re-invite asterisk for T.38 (confirmed by looking into the packet's
details), Asterisk answers "Trying" and then refuses, saying
"488: Not acceptable here"
>> - From then on, things go horribly wrong (probably, the local endpoint
is still expecting G.711 packets, but gets T.38 packets)
>>
>> I have provided all packets which are relevant. The packet numbers are
not contiguous since asterisk currently is on a test server which runs many
other services (the packets of which I have filtered out).
>>
>> I didn't want to clutter this post too much, thus I have only
provided an overview and not the details of each packet. Furthermore, please
forgive me that it's much easier for me to read Wireshark's logs than
Asterisk's logs. Of course, I will provide every log anybody trying to help
out asks me for.
>>
>> But my first question is a very simple one:
>>
>> From the log above, I am quite sure that switching to T.38 is done
right up to (and including) packet 14329. I think that my local endpoint then
misbehaves by again re-inviting asterisk for T.38 (as all parties already have
agreed upon T.38).
>>
>> Thus, is my endpoint really misbehaving, and if yes, is there anything
I can do about it on Asterisk's side? Or do the SIP/T.38 state machines
allow such (seemingly superfluous) re-invite, and it's Asterisk's fault
to answer with 488?
>
> - Could you share the details of the SDP in each INVITE and OK packet?
> - How are your SIP endpoints configured in asterisk sip.conf? (the SIP
> trunk provider and the local endpoint)
> - What type is the local endpoint?
>
> Cheers,
>
> Frederic
>
Recursive
2014-Dec-15 08:03 UTC
[asterisk-users] T.38 not working - help needed with log interpretation
On 10.12.2014 11:42, Frederic Van Espen wrote:> Hi, > > - Could you share the details of the SDP in each INVITE and OK packet? > - How are your SIP endpoints configured in asterisk sip.conf? (the SIP > trunk provider and the local endpoint) > - What type is the local endpoint? > > Cheers, > > Frederic >Frederic, I now have tried to describe the situation very clearly, and I have provided some logs for download. Sorry for not directly including them, but they are too lengthy so the moderator rejected the respective message. I would be grateful if you could refer to my message from some minutes ago. I have provided all the details there. Thank you very much, Recursive
Recursive
2014-Dec-21 10:17 UTC
[asterisk-users] T.38 not working - help needed with log interpretation
Dear Frederic, Larry and Matt, I believe I now have tried all suggestions which you have made. Unfortunately, none of them worked. Generally, I am still unable to send faxes. I now have one fax machine (serviced by another provider) to which I can reliably send faxes with arbitrary size (i.e. arbitrary number of pages), but trying to send faxes to other fax machines still reliably fails for seemingly weird reasons, either Asterisk, the ITSP or my local fax software initiating the hangup, depending on the configuration. So, I now have decided to give up on chan_sip and to try res_pjsip / chan_pjsip instead. Thank you very much again to all who tried to help. Regards, Recursive On 02.12.2014 09:24, Recursive wrote:> Dear all, > > I have the following situation: > > Local T.38 endpoint <-> ASTERISK <-> SIP provider (with T.38 support) > > I am trying to send a fax from my local T.38 endpoint to arbitrary external fax numbers (which I am not in control of, so I don't know if the other end supports T.38, is connected to a PBX, who is their provider, and so on), of course trying to use T.38 at least from my local endpoint to the provider's gateway. This always fails. > > I have recorded the respective network traffic with Wireshark. From the log, I can see that the training is successful. The transmission fails exactly at the moment when it should switch to T.38. I think that my endpoint is misbehaving in that situation and wanted to make sure that I am right by asking the experts. > > Here is an excerpt of the log (the part which I am considering relevant): > > No. Time Source Destination Protocol Length Info > 14308 16.089226 192.168.20.48 192.168.20.14 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x8A086DE, Seq=63333, Time=23840 > 14311 16.109178 83.125.8.155 192.168.20.48 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x71FD8337, Seq=41621, Time=24000 > 14312 16.110788 192.168.20.48 192.168.20.14 RTP 214 PT=ITU-T G.711 PCMU, SSRC=0x8A086DE, Seq=63334, Time=24000 > 14313 16.118096 83.125.8.71 192.168.20.48 SIP/SDP 988 Request: INVITE sip:000387839679 at 79.211.71.113:64280, in-dialog | > 14314 16.118466 192.168.20.48 83.125.8.71 SIP 633 Status: 100 Trying | > 14315 16.118739 192.168.20.48 192.168.20.14 SIP/SDP 923 Request: INVITE sip:bCo9m7OfHWK2Y2sb at 192.168.20.14:5060, in-dialog | > 14321 16.169196 192.168.20.14 192.168.20.48 SIP/SDP 982 Status: 200 OK | > 14322 16.170900 192.168.20.48 192.168.20.14 SIP 476 Request: ACK sip:bCo9m7OfHWK2Y2sb at 192.168.20.14:5060 | > 14323 16.171160 192.168.20.48 83.125.8.71 SIP/SDP 951 Status: 200 OK | > 14329 16.208396 83.125.8.71 192.168.20.48 SIP 559 Request: ACK sip:000387839679 at 79.211.71.113:64280 | > 14453 17.611041 192.168.20.14 192.168.20.48 SIP/SDP 1204 Request: INVITE sip:004921123704144 at spock-asterisk.home.omeganet.de:5060, in-dialog | > 14454 17.611304 192.168.20.48 192.168.20.14 SIP 577 Status: 100 Trying | > 14649 22.611128 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | > 14650 22.661007 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] > 14651 23.111663 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | > 14652 23.162024 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] > 14653 24.112190 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | > 14654 24.162038 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] > 14655 25.838900 192.168.20.14 192.168.20.48 SIP 484 Request: BYE sip:004921123704144 at 192.168.20.48:5060 | > 14656 25.839076 192.168.20.48 192.168.20.14 SIP 519 Status: 500 Server error | > 14657 26.110508 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | > 14658 26.161125 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] > 19910 30.111548 192.168.20.48 192.168.20.14 SIP 612 Status: 488 Not acceptable here | > 19911 30.162368 192.168.20.14 192.168.20.48 UDP 42 Source port: 5060 Destination port: 5060[Malformed Packet] > > 192.168.20.14 is my local T.38 endpoint, 192.168.20.48 is ASTERISK, and 83.125.8.xxx are the provider's gateways / servers. My interpretation of the log is as follows: > > - The first three packets are the end of the training (quite sure about that) > - Packets 14313, 14314: The provider re-invites asterisk for T.38 (confirmed by viewing the packet's details), asterisk answers "Trying ..." to the provider > - Packets 14315, 14321, 14322: Asterisk re-invites the local endpoint (again confirmed by looking into the packet's details), the local endpoint answers "OK", and asterisk ACKs the OK. > - Packets 14323, 14329: Asterisk accepts the invitation from the provider by sending "OK" to the provider, and the provider ACKs the OK. > - Packets 14453, 14454 and 14649: The local endpoint again tries to re-invite asterisk for T.38 (confirmed by looking into the packet's details), Asterisk answers "Trying" and then refuses, saying "488: Not acceptable here" > - From then on, things go horribly wrong (probably, the local endpoint is still expecting G.711 packets, but gets T.38 packets) > > I have provided all packets which are relevant. The packet numbers are not contiguous since asterisk currently is on a test server which runs many other services (the packets of which I have filtered out). > > I didn't want to clutter this post too much, thus I have only provided an overview and not the details of each packet. Furthermore, please forgive me that it's much easier for me to read Wireshark's logs than Asterisk's logs. Of course, I will provide every log anybody trying to help out asks me for. > > But my first question is a very simple one: > > From the log above, I am quite sure that switching to T.38 is done right up to (and including) packet 14329. I think that my local endpoint then misbehaves by again re-inviting asterisk for T.38 (as all parties already have agreed upon T.38). > > Thus, is my endpoint really misbehaving, and if yes, is there anything I can do about it on Asterisk's side? Or do the SIP/T.38 state machines allow such (seemingly superfluous) re-invite, and it's Asterisk's fault to answer with 488? > > Thank you very much, > > Recursive >