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

Mon Aug 23 03:36:43 PDT 2010

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100823/a5bc2b48/attachment.html 