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