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

Mon Aug 23 03:53:33 PDT 2010

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/86265ffb/attachment.html 