FreeSWITCH

FS Not sending 200 OK on T.38 re-INVITE using rxfax

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Minor Minor
  • Resolution: Not A Bug
  • Affects Version/s: None
  • Fix Version/s: None
  • Component/s: mod_spandsp
  • Labels:
    None
  • Environment:
    Latest GIT from 2012-05-01 on x86_64 Gentoo Linux
  • Platform:
    Linux x86_64/gcc
  • CPU Info:
    Hide
    processor : 0
    vendor_id : GenuineIntel
    cpu family : 15
    model : 6
    model name : Intel(R) Pentium(R) D CPU 3.40GHz
    stepping : 5
    cpu MHz : 3400.000
    cache size : 2048 KB
    physical id : 0
    siblings : 2
    core id : 0
    cpu cores : 2
    apicid : 0
    initial apicid : 0
    fpu : yes
    fpu_exception : yes
    cpuid level : 6
    wp : yes
    flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc pebs bts nopl pni dtes64 monitor ds_cpl est cid cx16 xtpr pdcm lahf_lm
    bogomips : 6782.12
    clflush size : 64
    cache_alignment : 128
    address sizes : 36 bits physical, 48 bits virtual
    power management:

    processor : 1
    vendor_id : GenuineIntel
    cpu family : 15
    model : 6
    model name : Intel(R) Pentium(R) D CPU 3.40GHz
    stepping : 5
    cpu MHz : 3400.000
    cache size : 2048 KB
    physical id : 0
    siblings : 2
    core id : 1
    cpu cores : 2
    apicid : 1
    initial apicid : 1
    fpu : yes
    fpu_exception : yes
    cpuid level : 6
    wp : yes
    flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc pebs bts nopl pni dtes64 monitor ds_cpl est cid cx16 xtpr pdcm lahf_lm
    bogomips : 6781.64
    clflush size : 64
    cache_alignment : 128
    address sizes : 36 bits physical, 48 bits virtual
    power management:
    Show
    processor : 0 vendor_id : GenuineIntel cpu family : 15 model : 6 model name : Intel(R) Pentium(R) D CPU 3.40GHz stepping : 5 cpu MHz : 3400.000 cache size : 2048 KB physical id : 0 siblings : 2 core id : 0 cpu cores : 2 apicid : 0 initial apicid : 0 fpu : yes fpu_exception : yes cpuid level : 6 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc pebs bts nopl pni dtes64 monitor ds_cpl est cid cx16 xtpr pdcm lahf_lm bogomips : 6782.12 clflush size : 64 cache_alignment : 128 address sizes : 36 bits physical, 48 bits virtual power management: processor : 1 vendor_id : GenuineIntel cpu family : 15 model : 6 model name : Intel(R) Pentium(R) D CPU 3.40GHz stepping : 5 cpu MHz : 3400.000 cache size : 2048 KB physical id : 0 siblings : 2 core id : 1 cpu cores : 2 apicid : 1 initial apicid : 1 fpu : yes fpu_exception : yes cpuid level : 6 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc pebs bts nopl pni dtes64 monitor ds_cpl est cid cx16 xtpr pdcm lahf_lm bogomips : 6781.64 clflush size : 64 cache_alignment : 128 address sizes : 36 bits physical, 48 bits virtual power management:
  • FreeSWITCH GIT Revision:
    git-1c6d7ce
  • Reproduced with GIT HEAD?:
    Yes

Description

When using rxfax to receive a fax, FS does not send a 200 OK on a recieved T.38 re-INVITE.
FS only sends a 100 Trying followed by a BYE with cause "ACK Timeout", after this FS also sends a 500 Internal Server Error.

Also see the attached trace via a OpenSIPS server (192.168.250.69)
  1. Text File
    t38_fax_debug_log_all_9_with_answer.txt
    08/May/12 2:15 AM
    42 kB
    Steven Lam
  2. Text File
    t38_fax_debug_log_all_9.txt
    08/May/12 1:57 AM
    42 kB
    Steven Lam
  3. Text File
    t38_fax_debug_log.txt
    01/May/12 1:58 PM
    45 kB
    Steven Lam
  4. File
    t38_fax.pcap
    01/May/12 7:20 AM
    134 kB
    Steven Lam

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Anthony Minessale II added a comment -
as usual, a full debug log with "console loglevel debug" and "sofia global siptrace on" would be appreciated.
pcaps only tell 25% of the story
Show
Anthony Minessale II added a comment - as usual, a full debug log with "console loglevel debug" and "sofia global siptrace on" would be appreciated. pcaps only tell 25% of the story
Hide
Permalink
Steven Lam added a comment -
You are right, i'm sorry.
I just retested with the same result, the console output is now attached in t38_fax_debug_log.txt
Show
Steven Lam added a comment - You are right, i'm sorry. I just retested with the same result, the console output is now attached in t38_fax_debug_log.txt
Hide
Permalink
Anthony Minessale II added a comment -
recv 589 bytes from udp/[192.168.250.69]:5060 at 18:52:44.603273:
   ------------------------------------------------------------------------
   ACK sip:+31881102299@192.168.9.22:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 192.168.250.69;branch=z9hG4bK6a98.772fbbe3.4
   Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa0310778fcb9251f183f8b15d30c16632a05f3",uri="sip:0881102299@192.168.250.69:10120",response="8657e721846d78926ce505380b0f18b7"
   Max-Forwards: 69
   From: <sip:+31492780040@192.168.250.69>;tag=f924963b9c
   To: <sip:+31881102299@192.168.250.69>;tag=pB9BB5Dj1HSHm
   Call-ID: 64937e0951c0c294
   CSeq: 281940181 ACK
   User-Agent: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66
   Content-Length: 0
    



 Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa0310778fcb9251f183f8b15d30c16632a05f3",uri="sip:0881102299@192.168.250.69:10120",response="8657e721846d78926ce505380b0f18b7"


this looks odd, its in the ack from the original invite, I have a feeling that FS is ignoring this packet because of some reason.
you can retry the same debug_log but add in the cli command "sofia loglevel all 9" to get even more debug.

I think maybe the <CR> in the middle of that auth header might break something but even more odd is there should not be an auth header in this packet,

Show
Anthony Minessale II added a comment - recv 589 bytes from udp/[192.168.250.69]:5060 at 18:52:44.603273:    ------------------------------------------------------------------------    ACK sip:+ 31881102299@192.168.9.22 :5060;transport=udp SIP/2.0    Via: SIP/2.0/UDP 192.168.250.69;branch=z9hG4bK6a98.772fbbe3.4    Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa0310778fcb9251f183f8b15d30c16632a05f3",uri="sip: 0881102299@192.168.250.69 :10120",response="8657e721846d78926ce505380b0f18b7"    Max-Forwards: 69    From: <sip:+ 31492780040@192.168.250.69 >;tag=f924963b9c    To: <sip:+ 31881102299@192.168.250.69 >;tag=pB9BB5Dj1HSHm    Call-ID: 64937e0951c0c294    CSeq: 281940181 ACK    User-Agent: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66    Content-Length: 0       Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa0310778fcb9251f183f8b15d30c16632a05f3",uri="sip: 0881102299@192.168.250.69 :10120",response="8657e721846d78926ce505380b0f18b7" this looks odd, its in the ack from the original invite, I have a feeling that FS is ignoring this packet because of some reason. you can retry the same debug_log but add in the cli command "sofia loglevel all 9" to get even more debug. I think maybe the <CR> in the middle of that auth header might break something but even more odd is there should not be an auth header in this packet,
Hide
Permalink
Anthony Minessale II added a comment -
The <CR> only seems to be in the text display so never-mind that, but the problem is still related to this ACK is ignored and discounted for some reason.
Show
Anthony Minessale II added a comment - The <CR> only seems to be in the text display so never-mind that, but the problem is still related to this ACK is ignored and discounted for some reason.
Hide
Permalink
Steven Lam added a comment -
Same as "t38_fax_debug_log.txt", only now with "sofia loglevel all 9" set.
Show
Steven Lam added a comment - Same as "t38_fax_debug_log.txt", only now with "sofia loglevel all 9" set.
Hide
Permalink
Steven Lam added a comment -
Are you sure the ACK is the problem? To me all looks to be okay (sure the Proxy-Authorization is a bit funny):

recv 590 bytes from udp/[192.168.250.69]:5060 at 06:48:24.037888:
   ------------------------------------------------------------------------
   ACK sip:+31881102299@192.168.9.22:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 192.168.250.69;branch=z9hG4bKc004.3ab9a127.4
   Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa8c1c3db74cdb725a666792177e85584ad1cbb",uri="sip:0881102299@192.168.250.69:10120",response="37d604bec55288ec26c1233b1aa0a45e"
   Max-Forwards: 69
   From: <sip:+31492780040@192.168.250.69>;tag=25c0cbabf5
   To: <sip:+31881102299@192.168.250.69>;tag=eN8NpeNX72jac
   Call-ID: 0da956e08311dbf1
   CSeq: 1561989446 ACK
   User-Agent: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66
   Content-Length: 0
   
   ------------------------------------------------------------------------
tport_deliver(0x7fa7306a1b10): msg 0x7fa73066fc60 (590 bytes) from udp/192.168.250.69:5060/sip next=(nil)
nta: received ACK sip:+31881102299@192.168.9.22:5060;transport=udp SIP/2.0 (CSeq 1561989446)
nta: ACK (1561989446) is going to INVITE (1561989446)
nua: process_ack_or_cancel: entering
soa_clear_remote_sdp(static::0x11f0810) called
nua(0xd2f3e0): event i_ack 200 OK
nua(0xd2f3e0): call state changed: completed -> ready
nua(0xd2f3e0): event i_state 200 OK
nua(0xd2f3e0): event i_active 200 Call active


Can't it be FS is waiting for a ACK on a 200 OK that was never send by FS? (in response to the T.38 re-INVITE)
Show
Steven Lam added a comment - Are you sure the ACK is the problem? To me all looks to be okay (sure the Proxy-Authorization is a bit funny): recv 590 bytes from udp/[192.168.250.69]:5060 at 06:48:24.037888:    ------------------------------------------------------------------------    ACK sip:+ 31881102299@192.168.9.22 :5060;transport=udp SIP/2.0    Via: SIP/2.0/UDP 192.168.250.69;branch=z9hG4bKc004.3ab9a127.4    Proxy-Authorization: Digest username="ks-test1",realm="192.168.250.69",nonce="4fa8c1c3db74cdb725a666792177e85584ad1cbb",uri="sip: 0881102299@192.168.250.69 :10120",response="37d604bec55288ec26c1233b1aa0a45e"    Max-Forwards: 69    From: <sip:+ 31492780040@192.168.250.69 >;tag=25c0cbabf5    To: <sip:+ 31881102299@192.168.250.69 >;tag=eN8NpeNX72jac    Call-ID: 0da956e08311dbf1    CSeq: 1561989446 ACK    User-Agent: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66    Content-Length: 0        ------------------------------------------------------------------------ tport_deliver(0x7fa7306a1b10): msg 0x7fa73066fc60 (590 bytes) from udp/192.168.250.69:5060/sip next=(nil) nta: received ACK sip:+ 31881102299@192.168.9.22 :5060;transport=udp SIP/2.0 (CSeq 1561989446) nta: ACK (1561989446) is going to INVITE (1561989446) nua: process_ack_or_cancel: entering soa_clear_remote_sdp(static::0x11f0810) called nua(0xd2f3e0): event i_ack 200 OK nua(0xd2f3e0): call state changed: completed -> ready nua(0xd2f3e0): event i_state 200 OK nua(0xd2f3e0): event i_active 200 Call active Can't it be FS is waiting for a ACK on a 200 OK that was never send by FS? (in response to the T.38 re-INVITE)
Hide
Permalink
Steven Lam added a comment -
In "t38_fax_debug_log_all_9.txt" i forgot to answer the call before sending it to rxfax...
Show
Steven Lam added a comment - In "t38_fax_debug_log_all_9.txt" i forgot to answer the call before sending it to rxfax...
Hide
Permalink
Anthony Minessale II added a comment -
The ack was a guess because it fails with ACK timeout. After looking at the logs the ACK times out because there is a problem sending the SIP packets.

The snippet below seems to be the problem area: It fails trying to send the 200 OK due to some network error.
Do you possibly have selinux or some firewall or ALG up that might be restricting certain packet flows? I noticed they change ports mid call so something lurking in the traffic may get confused along the way.

I would check for all of the above and systematically eliminate them to rule it out.


Original INVITE:
recv 1147 bytes from udp/[192.168.250.69]:10120 at 07:11:38.945428:

RE-INVITE:
recv 1171 bytes from udp/[192.168.250.69]:5060 at 07:11:44.399825:

TROUBLESOME AREA OF LOG:

tport_tsend(0x7fa7306a1b10) tpn = UDP/192.168.250.69:5060
nua: nua_respond: entering
nua(0x7fa73043d880): sent signal r_respond
tport_resolve addrinfo = 192.168.250.69:5060
tport_by_addrinfo(0x7fa7306a1b10): not found by name UDP/192.168.250.69:5060
tport_vsend(0x7fa7306a1b10): Operation not permitted with (s=25 UDP/192.168.250.69:5060)
tport_vsend returned -1
incoming_reply: tport_tsend: Operation not permitted
incoming_reply: tport_tsend: error (Operation not permitted) while sending 200 OK for INVITE (52210564)
nua(0x7fa73043d880): ready call updated: completed sent answer
soa_get_local_sdp(static::0x7fa730049800, [0x7fa73b035cb8], [0x7fa73b035cb0], [(nil)]) called
soa_get_params(static::0x7fa730049800, ...) called
nua(0x7fa73043d880): event i_state 200 OK
nua(0x7fa73043d880): recv signal r_respond 200 OK
nua(0x7fa73043d880): event i_error 500 Already Sent Final Response
nua: nua_application_event: entering
2012-05-08 09:11:44.976863 [DEBUG] switch_core_session.c:900 Send signal sofia/in/+31492780040@192.168.250.69 [BREAK]
nua: nua_application_event: entering
2012-05-08 09:11:44.976863 [DEBUG] switch_core_session.c:900 Send signal sofia/in/+31492780040@192.168.250.69 [BREAK]
nua: nua_handle_magic: entering
2012-05-08 09:11:44.976863 [DEBUG] sofia.c:5601 Channel sofia/in/+31492780040@192.168.250.69 entering state [completed][200]
nua: nua_handle_magic: entering
nua: nua_handle_magic: entering
nua: nua_handle_magic: entering
nta: sending final response failed, timeout 100 response
nua: process_ack_or_cancel: entering
nua(0x7fa73043d880): event i_error 408 ACK Timeout
nua: nua_stack_set_params: entering

Show
Anthony Minessale II added a comment - The ack was a guess because it fails with ACK timeout. After looking at the logs the ACK times out because there is a problem sending the SIP packets. The snippet below seems to be the problem area: It fails trying to send the 200 OK due to some network error. Do you possibly have selinux or some firewall or ALG up that might be restricting certain packet flows? I noticed they change ports mid call so something lurking in the traffic may get confused along the way. I would check for all of the above and systematically eliminate them to rule it out. Original INVITE: recv 1147 bytes from udp/[192.168.250.69]:10120 at 07:11:38.945428: RE-INVITE: recv 1171 bytes from udp/[192.168.250.69]:5060 at 07:11:44.399825: TROUBLESOME AREA OF LOG: tport_tsend(0x7fa7306a1b10) tpn = UDP/192.168.250.69:5060 nua: nua_respond: entering nua(0x7fa73043d880): sent signal r_respond tport_resolve addrinfo = 192.168.250.69:5060 tport_by_addrinfo(0x7fa7306a1b10): not found by name UDP/192.168.250.69:5060 tport_vsend(0x7fa7306a1b10): Operation not permitted with (s=25 UDP/192.168.250.69:5060) tport_vsend returned -1 incoming_reply: tport_tsend: Operation not permitted incoming_reply: tport_tsend: error (Operation not permitted) while sending 200 OK for INVITE (52210564) nua(0x7fa73043d880): ready call updated: completed sent answer soa_get_local_sdp(static::0x7fa730049800, [0x7fa73b035cb8], [0x7fa73b035cb0], [(nil)]) called soa_get_params(static::0x7fa730049800, ...) called nua(0x7fa73043d880): event i_state 200 OK nua(0x7fa73043d880): recv signal r_respond 200 OK nua(0x7fa73043d880): event i_error 500 Already Sent Final Response nua: nua_application_event: entering 2012-05-08 09:11:44.976863 [DEBUG] switch_core_session.c:900 Send signal sofia/in/+ 31492780040@192.168.250.69 [BREAK] nua: nua_application_event: entering 2012-05-08 09:11:44.976863 [DEBUG] switch_core_session.c:900 Send signal sofia/in/+ 31492780040@192.168.250.69 [BREAK] nua: nua_handle_magic: entering 2012-05-08 09:11:44.976863 [DEBUG] sofia.c:5601 Channel sofia/in/+ 31492780040@192.168.250.69 entering state [completed][200] nua: nua_handle_magic: entering nua: nua_handle_magic: entering nua: nua_handle_magic: entering nta: sending final response failed, timeout 100 response nua: process_ack_or_cancel: entering nua(0x7fa73043d880): event i_error 408 ACK Timeout nua: nua_stack_set_params: entering
Hide
Permalink
Steven Lam added a comment -
I did not notice the port change, shame on me!
I'll do some research and get back on this.
Show
Steven Lam added a comment - I did not notice the port change, shame on me! I'll do some research and get back on this.
Hide
Permalink
Steven Lam added a comment -
You are absolutely right, the port change between the original INVITE and the T.38 re-INVITE was the problem.
After fixing this error (which originated on our OpenSIPS) the problem is solved.

I should have discovered this myself.

Anyway, thank you for looking into this!
Show
Steven Lam added a comment - You are absolutely right, the port change between the original INVITE and the T.38 re-INVITE was the problem. After fixing this error (which originated on our OpenSIPS) the problem is solved. I should have discovered this myself. Anyway, thank you for looking into this!

People

  • Assignee:
    Anthony Minessale II
    Reporter:
    Steven Lam
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: