[Freeswitch-dev] Nortel 1535 drops connection to FS
Oleg Khovayko
khovayko at gmail.com
Thu Nov 3 03:23:18 MSK 2011
Excuse me, I can not enforce FS to write into logfile all debug info.
I trued to run according http://wiki.freeswitch.org/wiki/Reporting_Bugs:
TPORT_LOG=1 /usr/local/freeswitch/bin/freeswitch
but anyway, siptrace does not writing to log, only to fs_cli terminal output.
Anyway, I caught SIPtrace messages for Nortel, this is piece of terminal output.
I see, FS sends signal BYE, because ACK timeout:
2011-11-02 18:32:07.929071 [DEBUG] switch_ivr_play_say.c:1672 done playing file /usr/local/freeswitch/sounds/ru/RU/elena/digits/1.wav
recv 330 bytes from udp/[192.168.1.17]:5061 at 22:32:07.995778:
------------------------------------------------------------------------
NOTIFY sip:192.168.1.5 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.17:5061;branch=z9hG4bK-c51ee6c4
From: 1004<sip:1004 at 192.168.1.5>;tag=12dc6681765b973do1
To:<sip:192.168.1.5>
Call-ID: af69bdb1-3c02a9cd at 192.168.1.17
CSeq: 274133 NOTIFY
Max-Forwards: 70
Event: keep-alive
User-Agent: Linksys/PAP2-3.1.22(LS)
Content-Length: 0
------------------------------------------------------------------------
send 669 bytes to udp/[192.168.1.17]:5061 at 22:32:08.001770:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.17:5061;branch=z9hG4bK-c51ee6c4
From: 1004<sip:1004 at 192.168.1.5>;tag=12dc6681765b973do1
To:<sip:192.168.1.5>;tag=c0N5gH4XH8DQm
Call-ID: af69bdb1-3c02a9cd at 192.168.1.17
CSeq: 274133 NOTIFY
Contact:<sip:173.79.237.112>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-f847059 2011-10-28 15-58-17 -0500
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
2011-11-02 18:32:08.195841 [DEBUG] switch_ivr_play_say.c:244 Handle play-file:[ivr/ivr-to_do_a_freeswitch_echo_test.wav] (ru:ru)
2011-11-02 18:32:08.195841 [DEBUG] switch_ivr_play_say.c:1302 Codec Activated L16 at 8000hz 1 channels 20ms
send 1154 bytes to udp/[192.168.1.158]:5060 at 22:32:09.084079:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.158:5060;branch=z9hG4bK-6e-1ae15-7e234642
From: "1000"<sip:1000 at olegh.ath.cx>;tag=2f5c50-9e01a8c0-13c4-45026-6d-ad711f2-6d
To:<sip:5000 at olegh.ath.cx>;tag=1vZmX7aQH6r9m
Call-ID: 3039a8-9e01a8c0-13c4-45026-6d-1a07e714-6d
CSeq: 2 INVITE
Contact:<sip:5000 at 173.79.237.112:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-f847059 2011-10-28 15-58-17 -0500
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 242
Remote-Party-ID: "5000"<sip:5000 at olegh.ath.cx>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1320248473 1320248474 IN IP4 192.168.1.5
s=FreeSWITCH
c=IN IP4 192.168.1.5
t=0 0
m=audio 24624 RTP/AVP 0 99
a=rtpmap:0 PCMU/8000
a=rtpmap:99 telephone-event/8000
a=fmtp:99 0-16
a=silenceSupp:off - - - -
a=ptime:20
------------------------------------------------------------------------
2011-11-02 18:32:09.554915 [DEBUG] switch_core_session.c:872 Send signal sofia/internal/1000 at olegh.ath.cx [BREAK]
send 685 bytes to udp/[192.168.1.158]:5060 at 22:32:09.573772:
------------------------------------------------------------------------
BYE sip:1000 at 192.168.1.158:5060 SIP/2.0
Via: SIP/2.0/UDP 173.79.237.112;rport;branch=z9hG4bKmBgZ4SN8yDSag
Max-Forwards: 70
From:<sip:5000 at olegh.ath.cx>;tag=1vZmX7aQH6r9m
To: "1000"<sip:1000 at olegh.ath.cx>;tag=2f5c50-9e01a8c0-13c4-45026-6d-ad711f2-6d
Call-ID: 3039a8-9e01a8c0-13c4-45026-6d-1a07e714-6d
CSeq: 19800500 BYE
Contact:<sip:5000 at 173.79.237.112:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-f847059 2011-10-28 15-58-17 -0500
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Reason: SIP;cause=408;text="ACK Timeout"
Content-Length: 0
------------------------------------------------------------------------
2011-11-02 18:32:09.554915 [DEBUG] switch_core_session.c:872 Send signal sofia/internal/1000 at olegh.ath.cx [BREAK]
recv 479 bytes from udp/[192.168.1.158]:5060 at 22:32:09.586581:
------------------------------------------------------------------------
SIP/2.0 200 OK
From:<sip:5000 at olegh.ath.cx>;tag=1vZmX7aQH6r9m
To: "1000"<sip:1000 at olegh.ath.cx>;tag=2f5c50-9e01a8c0-13c4-45026-6d-ad711f2-6d
Call-ID: 3039a8-9e01a8c0-13c4-45026-6d-1a07e714-6d
CSeq: 19800500 BYE
Via: SIP/2.0/UDP 173.79.237.112;received=192.168.1.5;rport=5060;branch=z9hG4bKmBgZ4SN8yDSag
Supported: replaces
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,REFER
User-Agent: Nortel IP Phone 1535 (0.2.50.0905)
Content-Length: 0
------------------------------------------------------------------------
2011-11-02 18:32:09.582519 [DEBUG] switch_core_session.c:872 Send signal sofia/internal/1000 at olegh.ath.cx [BREAK]
2011-11-02 18:32:09.582519 [DEBUG] sofia.c:5283 Channel sofia/internal/1000 at olegh.ath.cx entering state [terminating][0]
2011-11-02 18:32:09.582519 [DEBUG] switch_channel.c:2804 (sofia/internal/1000 at olegh.ath.cx) Callstate Change ACTIVE -> HANGUP
2011-11-02 18:32:09.582519 [NOTICE] sofia.c:6039 Hangup sofia/internal/1000 at olegh.ath.cx [CS_EXECUTE] [NORMAL_UNSPECIFIED]
Anthony Minessale wrote:
> snippets of logs rarely are helpful, try complete debug logs including
> sip trace
>
>
> On Wed, Nov 2, 2011 at 4:16 PM, Oleg Khovayko <khovayko at gmail.com
> <mailto:khovayko at gmail.com>> wrote:
>
> Hi,
>
> I am using FS for couple years, it was works OK.
> And, approx 1 year ago, I tested with FreeSWITCH phone Nortel 1535.
> It worked perfect.
>
> Thereafter, I couple times upgraded FS, and right now, I run version
> from GIT, dated 11-10-29. OS: FreeBSD 7.2, 32 bits.
>
> I again connected Nortel 1535, and this time see, connection suddenly
> broken during call to any "robot":
> FS #5000, FS #4000, CallCentric #17771234567
>
> Every time, before disconnect, I see chain of log messages like:
>
> [DEBUG] switch_core_session.c:872 Send signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> and HANGUP thereafter. See following samples from the log:
>
> Another phones, like VM1188T or PAP2, still works OK.
> About Nortel: I tested 3 phones, with two firmwares (2.50 & 2.76) --
> problem same on both.
>
> Can you suggest me, how to fix this issue?
>
> Thanks,
>
> Oleg
>
>
>
> CallCentric: 7771234567
>
> 2011-11-02 16:39:20.901219 [DEBUG] sofia_reg.c:1984 Changing
> expire time
> to 103 by request of proxy sip:callcentric.com
> <http://callcentric.com>
> 2011-11-02 16:39:31.108503 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:39:31.108503 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:39:31.108503 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:39:31.108503 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:39:31.130669 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:39:31.130669 [DEBUG] sofia.c:5283 Channel
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> entering state [terminating][0]
> 2011-11-02 16:39:31.130669 [DEBUG] switch_channel.c:2804
> (sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>)
> Callstate Change ACTIVE -> HANGUP
> 2011-11-02 16:39:31.130669 [NOTICE] sofia.c:6039 Hangup
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [CS_EXECUTE] [NORMAL_UNSPECIFIED]
> 2011-11-02 16:39:31.130669 [DEBUG] switch_channel.c:2820 Send signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [KILL]
> 2011-11-02 16:39:31.130669 [DEBUG] switch_core_session.c:1177 Send
> signal sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [BREAK]
>
>
> FS: 5000
>
> 2011-11-02 17:03:08.207852 [DEBUG] switch_ivr_play_say.c:1672 done
> playing file
> /usr/local/freeswitch/sounds/ru/RU/elena/ivr/ivr-to_do_a_freeswitch_echo_test.wav
> 2011-11-02 17:03:08.459809 [DEBUG] switch_ivr_play_say.c:244 Handle
> play-file:[ivr/ivr-please.wav] (ru:ru)
> 2011-11-02 17:03:08.459809 [DEBUG] switch_ivr_play_say.c:1302 Codec
> Activated L16 at 8000hz 1 channels 20ms
> 2011-11-02 17:03:09.257683 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 17:03:09.257683 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 17:03:09.257683 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 17:03:09.280490 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 17:03:09.280490 [DEBUG] sofia.c:5283 Channel
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> entering state [terminating][0]
> 2011-11-02 17:03:09.280490 [DEBUG] switch_channel.c:2804
> (sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>)
> Callstate Change ACTIVE -> HANGUP
> 2011-11-02 17:03:09.280490 [NOTICE] sofia.c:6039 Hangup
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [CS_EXECUTE] [NORMAL_UNSPECIFIED]
> 2011-11-02 17:03:09.280490 [DEBUG] switch_channel.c:2820 Send signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [KILL]
> 2011-11-02 17:03:09.280490 [DEBUG] switch_core_session.c:1177 Send
> signal sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [BREAK]
> 2011-11-02 17:03:09.280490 [DEBUG] switch_ivr_play_say.c:1672 done
> playing file
> /usr/local/freeswitch/sounds/ru/RU/elena/ivr/ivr-please.wav
> 2011-11-02 17:03:09.532638 [DEBUG] switch_ivr_menu.c:348 waiting
> for 4/4
> digits t/o 2000
> 2011-11-02 17:03:09.532638 [DEBUG] switch_ivr_menu.c:395 digits ''
> 2011-11-02 17:03:09.532638 [DEBUG] switch_ivr_menu.c:585 IVR menu
> 'demo_ivr' no input detected
> 2011-11-02 17:03:10.587476 [DEBUG] switch_ivr_menu.c:599 exit-sound
> 'voicemail/vm-goodbye.wav'
> 2011-11-02 17:03:10.587476 [DEBUG] switch_core_session.c:2269
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> skip
> receive message
> [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
>
>
> FS: voicemail
>
> 2011-11-02 16:51:50.217856 [DEBUG] switch_ivr_play_say.c:67 No
> language
> specified - Using [ru]
> 2011-11-02 16:51:50.307721 [DEBUG] switch_ivr_play_say.c:244 Handle
> say:[1290554584] (ru:ru)
> 2011-11-02 16:51:50.307721 [INFO] mod_say_ru.c:721 ru_say!!!
> 1290554584! say_opt.gender=0 say_opt.cases=0
> 2011-11-02 16:51:50.307721 [DEBUG] switch_ivr_play_say.c:1302 Codec
> Activated L16 at 8000hz 1 channels 20ms
> 2011-11-02 16:51:50.969016 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:51:50.969016 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:51:50.969016 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:51:50.969016 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:51:50.969016 [DEBUG] switch_core_session.c:872 Send
> signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [BREAK]
> 2011-11-02 16:51:50.990445 [DEBUG] sofia.c:5283 Channel
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> entering state [terminating][0]
> 2011-11-02 16:51:50.990445 [DEBUG] switch_channel.c:2804
> (sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>)
> Callstate Change ACTIVE -> HANGUP
> 2011-11-02 16:51:50.990445 [NOTICE] sofia.c:6039 Hangup
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [CS_EXECUTE] [NORMAL_UNSPECIFIED]
> 2011-11-02 16:51:50.990445 [DEBUG] switch_channel.c:2820 Send signal
> sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx> [KILL]
> 2011-11-02 16:51:50.990445 [DEBUG] switch_core_session.c:1177 Send
> signal sofia/internal/1000 at olegh.ath.cx <mailto:1000 at olegh.ath.cx>
> [BREAK]
>
>
> _______________________________________________
> Join us at ClueCon 2011, Aug 9-11, Chicago
> http://www.cluecon.com 877-7-4ACLUE
>
> FreeSWITCH-dev mailing list
> FreeSWITCH-dev at lists.freeswitch.org
> <mailto:FreeSWITCH-dev at lists.freeswitch.org>
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org
>
>
>
>
> --
> Anthony Minessale II
>
> FreeSWITCH http://www.freeswitch.org/
> ClueCon http://www.cluecon.com/
> Twitter: http://twitter.com/FreeSWITCH_wire
>
> AIM: anthm
> MSN:anthony_minessale at hotmail.com
> <mailto:MSN%3Aanthony_minessale at hotmail.com>
> GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
> <mailto:PAYPAL%3Aanthony.minessale at gmail.com>
> IRC: irc.freenode.net <http://irc.freenode.net> #freeswitch
>
> FreeSWITCH Developer Conference
> sip:888 at conference.freeswitch.org
> <mailto:sip%3A888 at conference.freeswitch.org>
> googletalk:conf+888 at conference.freeswitch.org
> <mailto:googletalk%3Aconf%2B888 at conference.freeswitch.org>
> pstn:+19193869900
>
>
> _______________________________________________
> Join us at ClueCon 2011, Aug 9-11, Chicago
> http://www.cluecon.com 877-7-4ACLUE
>
> FreeSWITCH-dev mailing list
> FreeSWITCH-dev at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20111102/ee19aaa8/attachment-0001.html
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-dev
mailing list