[Freeswitch-users] Wrong hangup cause (NO_ANSWER) while answered session

Wed Aug 25 04:55:10 PDT 2010

"Brian, we are not bridging calls. FreeSWITCH (Leg A) as the caller can not
be in a 'not answered' state. Also if I see 200 then it must be come from
Leg B (the callee) which means that other party has answered the call."
You mean you're doing an originate from ESL? Then there is no 'Leg A', only
the 'Leg B' - saying otherwise confuses matters.

"And this happened more than 40.000 times between 8 hours"
Then you should have no problem providing a sip trace.

The log does not contain enough detail to see the full information. For
instance the 200 OK could be in a different SIP dialog, or there may be
something unusual in the packet that makes FS interpret it incorrectly. If
the developers ask for a sip trace saying it's neccesary to debug the
problem, don't argue, just provide it.

"It is also clear for me, that FS is *over-challenged* to set the correct
hangup cause in bulk calls over 200 cps"
The code executed will be the same, so hangup causes shouldn't be affected
by being at a higher call rate. People have had FS running at >200cps
without issue. The only reason I can think of that this might be an issue is
if your server is getting overloaded causing a race condition between the
hangup timer and the 200 OK being processed - how high is your cpu usage and
average load when NO_ANSWER occurs?

"We must to re-call all numbers again to give you a SIP trace but this is to
expensive for us :-)"
Appreciate this, so I would suggest that you either only make calls until
you see a call with the issue. Since you say you saw 40000 in 8 hours it
should be easy to reproduce, so that would be far cheaper than calling all
the numbers; or you can wait until you need to legitimately call them again
so there's no additional cost to you.

-Steve

On 24 August 2010 14:14, Durmuş Ali Öztürk <ali.stgt at gmail.com> wrote:

> Brian, we are not bridging calls. FreeSWITCH (Leg A) as the caller can not
> be in a 'not answered' state. Also if I see 200 then it must be come from
> Leg B (the callee) which means that other party has answered the call. Also,
> both legs was active but FS had reported us the opposite. And this happened
> more than 40.000 times between 8 hours.
>
> I would like to know what you are expecting from the sip trace, because the
> log is detailed enough to be verified that FS has catched the 200 SIP - but
> it seems to be ignored (maybe hangup timer started or something else)
> therefor the session is closed with the wrong state. It is also clear for
> me, that FS is *over-challenged* to set the correct hangup cause in bulk
> calls over 200 cps.
>
> @Milena
> We must to re-call all numbers again to give you a SIP trace but this is to
> expensive for us :-)
>
>
>>
>> ---------- Weitergeleitete Nachricht ----------
>> From: Milena <testeador01 at gmail.com>
>>
>> To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org>
>> Date: Mon, 23 Aug 2010 10:17:37 -0500
>>
>> Subject: Re: [Freeswitch-users] Wrong hangup cause (NO_ANSWER) while
>> answered session
>> type "version" on the CLI
>>
>> If the "sip trace wasnt active" then activate it and pastebin it, that's
>> the only way you can get help with this, you know the developers are experts
>> not soothsayers :)
>>
>>
>> -Mile
>>
>> 2010/8/23 Durmuş Ali Öztürk <ali.stgt at gmail.com>
>>
>> I have setup freeswitch by using git and followed the instructions on the
>>> wiki page. How can I retrieve the exact git version?
>>>
>>
>>
>> ---------- Weitergeleitete Nachricht ----------
>> From: Brian West <brian at freeswitch.org>
>> To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org>
>> Date: Mon, 23 Aug 2010 10:18:30 -0500
>>
>> Subject: Re: [Freeswitch-users] Wrong hangup cause (NO_ANSWER) while
>> answered session
>> Again without a SIP trace I can't say... You have to remember that
>> FreeSWITCH is a B2BUA and a call thru it results in TWO legs.  If you were
>> to ANSWER the first but then bridge to the second then it didn't answer you
>> might still get a NO_ANSWER even thou you see the 200ok for the one leg of
>> the call.
>>
>> /b
>>
>>
>> On Aug 23, 2010, at 10:08 AM, Durmuş Ali Öztürk wrote:
>>
>> > I have setup freeswitch by using git and followed the instructions on
>> the wiki page. How can I retrieve the exact git version?
>> >
>> > There is no override of the hangup cause in our code. The algorithm is
>> very simple; we call the originate function with the playback action and use
>> a wav file as argument. Hangup is done automatically by FreeSWITCH, after
>> eof of the wav file is reached. Or the other part hangs up before the file
>> ends.
>> >
>> > We dont traced the communication but in other hand, the sip codes are
>> traced out into the log file (183-->180-->200=call established). This show
>> to me, that there is no problem with the SIP transactions. Please assume,
>> that SIP messages are OK.
>> >
>> > What else could be happen?
>>
>>
>>
>>
>>
>> ---------- Weitergeleitete Nachricht ----------
>> From: Sergey Okhapkin <sos at sokhapkin.dyndns.org>
>>
>> To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org>
>> Date: Mon, 23 Aug 2010 11:22:37 -0400
>>
>> Subject: Re: [Freeswitch-users] Wrong hangup cause (NO_ANSWER) while
>> answered session
>> You're running concurrent calls, hangup cause NO_ANSWER and log line with
>> 200
>> OK belong to different calls.
>>
>> On Monday 23 August 2010, Durmuş Ali Öztürk wrote:
>> > I have setup freeswitch by using git and followed the instructions on
>> the
>> > wiki page. How can I retrieve the exact git version?
>> >
>> > There is no override of the hangup cause in our code. The algorithm is
>> very
>> > simple; we call the originate function with the playback action and use
>> a
>> > wav file as argument. Hangup is done automatically by FreeSWITCH, after
>> eof
>> > of the wav file is reached. Or the other part hangs up before the file
>> >  ends.
>> >
>> > We dont traced the communication but in other hand, the sip codes are
>> >  traced out into the log file (183-->180-->200=call established). This
>> show
>> >  to me, that there is no problem with the SIP transactions. Please
>> assume,
>> >  that SIP messages are OK.
>> >
>> > What else could be happen?
>> >
>> > 2010-08-17 22:40:51.087402 [DEBUG] switch_ivr_originate.c:1979 variable
>> > string 0 = [sip_from_uri=sip:xxxx at xxxxx]
>> > 2010-08-17 22:40:51.087402 [DEBUG] switch_ivr_originate.c:1979 variable
>> > string 1 = [ignore_early_media=true]
>> > 2010-08-17 22:40:51.087402 [DEBUG] switch_ivr_originate.c:1979 variable
>> > string 2 = [sip_cid_type=none]
>> > 2010-08-17 22:40:51.087402 [DEBUG] switch_ivr_originate.c:1979 variable
>> > string 3 = [originate_timeout=40]
>> > 2010-08-17 22:41:09.904378 [NOTICE] switch_channel.c:779 New Channel
>> > sofia/internal/9055599XXXXX [9e4b396e-3d99-445f-a2e8-
>> > 227e99f3f0ef]
>> > 2010-08-17 22:41:12.641362 [DEBUG] mod_sofia.c:3892
>> > (sofia/internal/9055599XXXXX) State Change CS_NEW -> CS_INIT
>> > 2010-08-17 22:41:12.641362 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:12.641362 [DEBUG] switch_core_session.c:454
>> > sofia/internal/9055599XXXXX set
>> UUID=9dc8a739-f439-4815-981a-347b7a90a1a8
>> > 2010-08-17 22:41:12.642441 [DEBUG] switch_core_state_machine.c:314
>> > (sofia/internal/9055599XXXXX) Running State Change CS_INIT
>> > 2010-08-17 22:41:12.642441 [DEBUG] switch_core_state_machine.c:338
>> > (sofia/internal/9055599XXXXX) State INIT
>> > 2010-08-17 22:41:12.642441 [DEBUG] mod_sofia.c:83
>> > sofia/internal/9055599XXXXX SOFIA INIT
>> > 2010-08-17 22:41:12.643399 [DEBUG] mod_sofia.c:119
>> > (sofia/internal/9055599XXXXX) State Change CS_INIT -> CS_ROUTING
>> > 2010-08-17 22:41:12.643399 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:12.643399 [DEBUG] switch_core_state_machine.c:338
>> > (sofia/internal/9055599XXXXX) State INIT going to sleep
>> > 2010-08-17 22:41:12.643399 [DEBUG] switch_core_state_machine.c:314
>> > (sofia/internal/9055599XXXXX) Running State Change CS_ROUTING
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_channel.c:1512
>> > (sofia/internal/9055599XXXXX) Callstate Change DOWN -> RINGING
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_core_state_machine.c:341
>> > (sofia/internal/9055599XXXXX) State ROUTING
>> > 2010-08-17 22:41:12.644456 [DEBUG] mod_sofia.c:142
>> > sofia/internal/9055599XXXXX SOFIA ROUTING
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_ivr_originate.c:66
>> > (sofia/internal/9055599XXXXX) State Change CS_ROUTING ->
>> CS_CONSUME_MEDIA
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_core_state_machine.c:341
>> > (sofia/internal/9055599XXXXX) State ROUTING going to sleep
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_core_state_machine.c:314
>> > (sofia/internal/9055599XXXXX) Running State Change CS_CONSUME_MEDIA
>> > 2010-08-17 22:41:12.644456 [DEBUG] switch_core_state_machine.c:360
>> > (sofia/internal/9055599XXXXX) State CONSUME_MEDIA
>> > 2010-08-17 22:41:12.645373 [DEBUG] switch_core_state_machine.c:360
>> > (sofia/internal/9055599XXXXX) State CONSUME_MEDIA going to sleep
>> > 2010-08-17 22:41:42.806367 [DEBUG] sofia.c:4318 Channel
>> > sofia/internal/9055599XXXXX entering state [calling][0]
>> > 2010-08-17 22:41:42.890442 [INFO] sofia.c:662
>> sofia/internal/9055599XXXXX
>> > Update Callee ID to "9055599XXXXX" <9055599XXXXX>
>> > 2010-08-17 22:41:42.894355 [DEBUG] sofia.c:4318 Channel
>> > sofia/internal/9055599XXXXX entering state [proceeding][183]
>> > 2010-08-17 22:41:42.894355 [NOTICE] sofia.c:4390 Ring-Ready
>> > sofia/internal/9055599XXXXX!
>> > 2010-08-17 22:41:42.895440 [DEBUG] sofia.c:4318 Channel
>> > sofia/internal/9055599XXXXX entering state [proceeding][183]
>> > 2010-08-17 22:41:42.895440 [DEBUG] sofia.c:4329 Remote SDP:
>> > 2010-08-17 22:41:42.895440 [DEBUG] sofia_glue.c:2444 Set Codec
>> > sofia/internal/9055599XXXXX PCMA/8000 20 ms 160 samples
>> > 2010-08-17 22:41:42.896357 [DEBUG] sofia_glue.c:3937 Set 2833 dtmf send
>> > payload to 101
>> > 2010-08-17 22:41:42.896357 [DEBUG] sofia_glue.c:2684 AUDIO RTP
>> > [sofia/internal/9055599XXXXX] 10.100.224.10 port 31416 -> 10.100.199.19
>> >  port 18620 codec: 8 ms: 20
>> > 2010-08-17 22:41:42.896357 [DEBUG] switch_rtp.c:1413 Starting timer
>> [soft]
>> > 160 bytes per 20ms
>> > 2010-08-17 22:41:42.897431 [DEBUG] sofia_glue.c:2894 Set 2833 dtmf send
>> > payload to 101
>> > 2010-08-17 22:41:42.897431 [DEBUG] sofia_glue.c:2899 Set 2833 dtmf
>> receive
>> > payload to 101
>> > 2010-08-17 22:41:42.897431 [NOTICE] sofia_glue.c:3292 Pre-Answer
>> > sofia/internal/9055599XXXXX!
>> > 2010-08-17 22:41:42.897431 [DEBUG] switch_channel.c:2397
>> > (sofia/internal/9055599XXXXX) Callstate Change RINGING -> EARLY
>> >  2010-08-17 22:41:42.916461 [DEBUG] sofia.c:4313 Channel
>> > sofia/internal/9055599XXXXX skipping state [proceeding][180]
>> > 2010-08-17 22:41:43.434412 [DEBUG] sofia.c:4318 Channel
>> > sofia/internal/9055599XXXXX entering state [completing][200]
>> > 2010-08-17 22:41:43.434412 [DEBUG] sofia.c:4326 Duplicate SDP
>> > 2010-08-17 22:41:52.000488 [DEBUG] switch_channel.c:2309
>> > (sofia/internal/9055599XXXXX) Callstate Change EARLY -> HANGUP
>> > 2010-08-17 22:41:52.000488 [NOTICE] switch_ivr_originate.c:3282 Hangup
>> > sofia/internal/9055599XXXXX [CS_CONSUME_MEDIA] [NO_ANSWER]
>> > 2010-08-17 22:41:52.000488 [DEBUG] switch_channel.c:2325 Send signal
>> > sofia/internal/9055599XXXXX [KILL]
>> > 2010-08-17 22:41:52.000488 [DEBUG] switch_core_state_machine.c:314
>> > (sofia/internal/9055599XXXXX) Running State Change CS_HANGUP
>> > 2010-08-17 22:41:52.000488 [DEBUG] switch_core_state_machine.c:535
>> > (sofia/internal/9055599XXXXX) State HANGUP
>> > 2010-08-17 22:41:52.000488 [DEBUG] mod_sofia.c:453 Channel
>> > sofia/internal/9055599XXXXX hanging up, cause: NO_ANSWER
>> > 2010-08-17 22:41:52.000488 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:55.204396 [DEBUG] mod_sofia.c:506 Sending CANCEL to
>> > sofia/internal/9055599XXXXX
>> > 2010-08-17 22:41:55.204396 [DEBUG] switch_core_state_machine.c:46
>> > sofia/internal/9055599XXXXX Standard HANGUP, cause: NO_ANSWER
>> > 2010-08-17 22:41:55.204396 [DEBUG] switch_core_state_machine.c:535
>> > (sofia/internal/9055599XXXXX) State HANGUP going to sleep
>> > 2010-08-17 22:41:55.204396 [DEBUG] switch_core_state_machine.c:333
>> > (sofia/internal/9055599XXXXX) State Change CS_HANGUP -> CS_REPORTING
>> > 2010-08-17 22:41:55.204396 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:55.204396 [DEBUG] switch_core_state_machine.c:314
>> > (sofia/internal/9055599XXXXX) Running State Change CS_REPORTING
>> > 2010-08-17 22:41:55.205401 [DEBUG] switch_core_state_machine.c:595
>> > (sofia/internal/9055599XXXXX) State REPORTING
>> > 2010-08-17 22:41:55.205401 [DEBUG] switch_core_state_machine.c:53
>> > sofia/internal/9055599XXXXX Standard REPORTING, cause: NO_ANSWER
>> > 2010-08-17 22:41:55.205401 [DEBUG] switch_core_state_machine.c:595
>> > (sofia/internal/9055599XXXXX) State REPORTING going to sleep
>> > 2010-08-17 22:41:55.206428 [DEBUG] switch_core_state_machine.c:327
>> > (sofia/internal/9055599XXXXX) State Change CS_REPORTING -> CS_DESTROY
>> > 2010-08-17 22:41:55.206428 [DEBUG] switch_core_session.c:1039 Send
>> signal
>> > sofia/internal/9055599XXXXX [BREAK]
>> > 2010-08-17 22:41:55.206428 [DEBUG] switch_core_session.c:1202 Session
>> 18770
>> > (sofia/internal/9055599XXXXX) Locked, Waiting on external entities
>> > 2010-08-17 22:41:55.206428 [NOTICE] switch_core_session.c:1220 Session
>> >  18770 (sofia/internal/9055599XXXXX) Ended
>> > 2010-08-17 22:41:55.206428 [NOTICE] switch_core_session.c:1222 Close
>> >  Channel sofia/internal/9055599XXXXX [CS_DESTROY]
>> > 2010-08-17 22:41:55.207463 [DEBUG] switch_core_state_machine.c:427
>> > (sofia/internal/9055599XXXXX) Callstate Change HANGUP -> DOWN
>> > 2010-08-17 22:41:55.207463 [DEBUG] switch_core_state_machine.c:430
>> > (sofia/internal/9055599XXXXX) Running State Change CS_DESTROY
>> > 2010-08-17 22:41:55.207463 [DEBUG] switch_core_state_machine.c:440
>> > (sofia/internal/9055599XXXXX) State DESTROY
>> > 2010-08-17 22:41:55.207463 [DEBUG] mod_sofia.c:358
>> > sofia/internal/9055599XXXXX SOFIA DESTROY
>> > 2010-08-17 22:41:55.207463 [DEBUG] switch_core_state_machine.c:60
>> > sofia/internal/9055599XXXXX Standard DESTROY
>> > 2010-08-17 22:41:55.207463 [DEBUG] switch_core_state_machine.c:440
>> > (sofia/internal/9055599XXXXX) State DESTROY going to sleep
>> >
>> >
>> >
>> >
>> > ---------- Weitergeleitete Nachricht ----------
>> >
>> > > From: Brian West <brian at freeswitch.org>
>> > > To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org>
>> > > Date: Mon, 23 Aug 2010 09:29:32 -0500
>> > > Subject: Re: [Freeswitch-users] Wrong hangup cause (NO_ANSWER) while
>> > > answered session
>> > > Without that we can't help.  You also need to make sure you're on the
>> > > very latest code.  The one thing I'm sure we get right are the hangup
>> > > causes unless you're doing something to override them.
>> > >
>> > > /b
>> > >
>> > > On Aug 23, 2010, at 9:24 AM, Durmuş Ali Öztürk wrote:
>> > > > I'm afraid, sip trace wasnt active.
>> > >
>> > > ---------- Weitergeleitete Nachricht ----------
>> > > From: Steven Ayre <steveayre at gmail.com>
>> > > To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org>
>> > > Date: Mon, 23 Aug 2010 11:53:33 +0100
>> > > Subject: Re: [Freeswitch-users] Wrong hangup cause (NO_ANSWER) while
>> > > answered session
>> > > Do you have a sip trace for those calls?
>> > >
>> > >
>> > > On 23 August 2010 11:36, Durmuş Ali Öztürk <ali.stgt at gmail.com>
>> wrote:
>> > > Hello,
>> > >
>> > > we had some trouble while executing a bulk call process with
>> originating
>> > > a parallel call of 200. Because in many cases, FreeSWITCH has notified
>> > > hangups (SWITCH_EVENT_CHANNEL_HANGUP_COMPLETE) with the wrong
>> > > hangup-cause. Instead of notifying the successful state, we got the
>> > > NO_ANSWER hangup cause. BUSY and NO_ANSWER states are candidates for
>> > > retries, therefor many numbers are called/payed twice. See log below.
>> > >
>> > > Some other questions:
>> > >
>> > > B) Is the originate_timeout value an overall timer or a timer for the
>> > > ringing (starts if SIP code 180 incomes?) stage.
>> > >
>> > > C) We are originating each number in a separate thread and listen to
>> the
>> > > channel events for updating the call result. Should we change this
>> > > implementation or is this a good scenario/standard way. Related to the
>> > > call result, if it is busy or not answered, the call is retried after
>> 30
>> > > min. What are the recommends on this side to be ensured, the correct
>> > > hangup case be got and the number is not called twice..
>> > >
>> > > D) What do I have to bear in mind for bulk calls with parallel calls
>> over
>> > > 200.
>> > >
>> > > Thanks for your answer in advance.
>> > >
>> > >
>> > > Ali
>> >
>>
>>
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100825/d96e163c/attachment-0001.html 