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

Wed Aug 25 05:16:34 PDT 2010

It would also help to see your dialstring / originate command.

In answer to your other questions:
B) originate_timeout is until it gets answered from the time the invite is
sent.
C) Can't really comment since I don't use ESL in that way, but it's entirely
up to you really.
D) Can your hardware handle it. There is also some optimisation that can be
done for high call loads. See
http://wiki.freeswitch.org/wiki/Performance_testing_and_configurations

-Steve

On 25 August 2010 13:02, Steven Ayre <steveayre at gmail.com> wrote:

> How are you retrieving the log that you posted? It looks like some
> information about the call is missing. This line:
>
> 2010-08-17 22:41:42.895440 [DEBUG] sofia.c:4329 Remote SDP:
> Would normally be followed by a dump of the SDP.
>
> If some of the log is missing, then we don't know what else might be
> missing.
>
> -Steve
>
>
> 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/20100825/0f19e908/attachment.html 