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

Mon Aug 23 08:22:37 PDT 2010

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
> 