Looking into an intermittent problem that we’re having with one of our DIDs, I just noticed that some of the logged timestamps don’t seem to make sense, it’s like there are two different clocks at work here. What’s interesting is that I’m seeing this wrong time in received contact header info as well but I’m guessing that’s coming back to us from our own NTP timestamp in the SDP we send back to them after the initial invite. The system time is set correctly.
Here is a short excerpt of the console log with siptrace enabled on the external profile demonstrating this behavior:
recv 939 bytes from udp/[209.216.2.202]:5060 at 16:10:58.987966:
------------------------------------------------------------------------
INVITE sip:1410xxx7612@173.59.xxx.xxx:5080;transport=udp SIP/2.0
Via: SIP/2.0/UDP 209.216.2.202:5060;branch=z9hG4bK68239f89;rport
From: "+1410xxx3048" <sip:+1410xxx3048@209.216.2.202>;tag=as0e92c0c82014-06-17 12:07:58.767052 [DEBUG] switch_core_session.c:1034 Send signal sofia/external/+1410xxx3048@209.216.2.202 [BREAK]
To: <sip:1410xxx7612@voip.ourdomain.com:5080>;tag=Hj722eXX0yj8S
Contact: <sip:+1410xxx3048@209.216.2.202>2014-06-17 12:07:58.767052 [DEBUG] switch_core_session.c:1034 Send signal sofia/external/+1410xxx3048@209.216.2.202 [BREAK]
Call-ID: 63cd75ae5caa77be67d5a6944e86f5fe@209.216.2.202
CSeq: 103 INVITE
User-Agent: DidForSale-GW
Max-Forwards: 70
Remote-Party-ID: "+1410xxx3048" <sip:+1410xxx3048@209.216.2.202>;privacy=off;screen=no
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 289
v=0
o=root 2802 2803 IN IP4 207.223.69.137
s=session
c=IN IP4 207.223.69.137
t=0 0
m=audio 51480 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
------------------------------------------------------------------------
send 405 bytes to udp/[209.216.2.202]:5060 at 16:10:58.988281:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 209.216.2.202:5060;branch=z9hG4bK68239f89;rport=5060
From: "+1410xxx3048" <sip:+1410xxx3048@209.216.2.202>;tag=as0e92c0c8
To: <sip:1410xxx7612@voip.ourdomain.com:5080>;tag=Hj722eXX0yj8S
Call-ID: 63cd75ae5caa77be67d5a6944e86f5fe@209.216.2.202
CSeq: 103 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131022T212715Z~20a55d3cc6
Content-Length: 0
------------------------------------------------------------------------
2014-06-17 12:07:58.787035 [DEBUG] sofia.c:5863 Channel sofia/external/+1410xxx3048@209.216.2.202 entering state [ready][200]
2014-06-17 12:07:58.787035 [DEBUG] sofia.c:5863 Channel sofia/external/+1410xxx3048@209.216.2.202 entering state [received][100]
2014-06-17 12:07:58.787035 [DEBUG] sofia.c:5873 Remote SDP:
v=0
o=root 2802 2803 IN IP4 207.223.69.137
s=session
c=IN IP4 207.223.69.137
t=0 0
m=audio 51480 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
2014-06-17 12:07:58.787035 [DEBUG] switch_core_media.c:2990 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-06-17 12:07:58.787035 [DEBUG] switch_core_media.c:1879 Already using PCMU
2014-06-17 12:07:58.787035 [DEBUG] switch_core_media.c:3161 Set 2833 dtmf send/recv payload to 101
Is this expected behavior or is this a bug in the version we’re using?
Thanks.
Phil Quesinberry
Q Systems Engineering, Inc.
Embedded Hardware and Software Development
(410) 969-8002
http://www.qsystemsengineering.com