Freeswitch seems to be giving conflicting timestamps - what's the deal here?
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 <http://www.qsystemsengineering.com/>
See https://wiki.freeswitch.org/wiki/Fsctl#sync_clock and https://wiki.freeswitch.org/wiki/Fsctl#sync_clock_when_idle (the latter being much better to avoid incorrect durations in CDRs) FS initiates an internal clock from the time at start then uses the monotonic clock to run it. The result is it can diverge from the system clock in some cases. The reason your're seeing two different times is probably that one (SIP trace) is using the system time and the other (log messages) is using the internal FreeSWITCH one. On 17 June 2014 18:11, Phil Quesinberry <philq@qsystemsengineering.com> wrote:
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/+1 410xxx3048@209.216.2.202 entering state [ready][200]
2014-06-17 12:07:58.787035 [DEBUG] sofia.c:5863 Channel sofia/external/+1 410xxx3048@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* <http://www.qsystemsengineering.com/>
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
This is the difference between freeswitch timestamps and sofia having its own timestamps. On Jun 17, 2014, at 5:39 PM, Steven Ayre <steveayre@gmail.com> wrote:
See https://wiki.freeswitch.org/wiki/Fsctl#sync_clock and https://wiki.freeswitch.org/wiki/Fsctl#sync_clock_when_idle (the latter being much better to avoid incorrect durations in CDRs)
FS initiates an internal clock from the time at start then uses the monotonic clock to run it. The result is it can diverge from the system clock in some cases.
The reason your're seeing two different times is probably that one (SIP trace) is using the system time and the other (log messages) is using the internal FreeSWITCH one.
On 17 June 2014 18:11, Phil Quesinberry <philq@qsystemsengineering.com> wrote: 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
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
participants (3)
-
Michael Jerris
-
Phil Quesinberry
-
Steven Ayre