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

Mon Aug 23 07:24:55 PDT 2010

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
>>
>>
>> An extraction of the log (regard to the first issue):
>>
>> 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
>>
>>
>>
>> _______________________________________________
>> 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/20100823/92ed5b7f/attachment-0001.html 