Wrong hangup cause (NO_ANSWER) while answered session
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@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
Do you have a sip trace for those calls? On 23 August 2010 11:36, Durmuş Ali Öztürk <ali.stgt@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@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@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Your log: 2010-08-17 22:41:43.434412 [DEBUG] sofia.c:4318 Channel sofia/internal/9055599XXXXX entering state [completing][200] Latest git: sofia.c line 4318: switch_channel_t *channel = NULL; The line number doesn't match with the latest version. You should upgrade and see whether the issue still occurs with the latest version. -Steve On 23 August 2010 11:36, Durmuş Ali Öztürk <ali.stgt@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@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@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
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@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@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@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
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@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@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@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@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
participants (2)
-
Durmuş Ali Öztürk
-
Steven Ayre