Hi Team, Strange issue with Nibblebill module. My setup is like that I am using newfies-dialer for making call from server to any number. I am using Nibblebill for realtime billing. Call don't come to my mobile and status at Freeswitch changed to Answer and nibblebill start deduction of my balance from define tables...... *Below is the FS_CLI output:* 2012-07-31 03:10:09.668193 [DEBUG] switch_ivr_originate.c:1947 Parsing global variables 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_request_uuid]=[c395799a-dade-11e1-b432-00163e908c9f] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_answer_url]=[http://46.252.152.160:8008/api/v1/answercall/] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_hangup_url]=[http://46.252.152.160:8008/api/v1/hangupcall/] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [origination_caller_id_number]=[0498722120] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [bridge_early_media]=[true] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [hangup_after_bridge]=[true] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [hangup_after_bridge]=[true] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [nibble_account]=[97183008] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [nibble_rate]=[5] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [nibble_increment]=[30] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_from]=[0498722120] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_to]=[919718300881] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [plivo_app]=[true] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [absolute_codec_string]=[PCMA] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [originate_timeout]=[60] 2012-07-31 03:10:09.668193 [DEBUG] switch_event.c:1519 Parsing variable [ignore_early_media]=[true] 2012-07-31 03:10:09.668193 [NOTICE] switch_channel.c:926 New Channel sofia/external/919718300881 [c3961efe-dade-11e1-b60f-1782e99edc0a] 2012-07-31 03:10:09.668193 [DEBUG] mod_sofia.c:4705 (sofia/external/919718300881) State Change CS_NEW -> CS_INIT 2012-07-31 03:10:09.668193 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_INIT 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:424 (sofia/external/919718300881) State INIT 2012-07-31 03:10:09.668193 [DEBUG] mod_sofia.c:85 sofia/external/919718300881 SOFIA INIT 2012-07-31 03:10:09.668193 [DEBUG] mod_sofia.c:125 (sofia/external/919718300881) State Change CS_INIT -> CS_ROUTING 2012-07-31 03:10:09.668193 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:424 (sofia/external/919718300881) State INIT going to sleep 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_ROUTING 2012-07-31 03:10:09.668193 [DEBUG] switch_channel.c:1919 (sofia/external/919718300881) Callstate Change DOWN -> RINGING 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:433 (sofia/external/919718300881) State ROUTING 2012-07-31 03:10:09.668193 [DEBUG] mod_sofia.c:148 sofia/external/919718300881 SOFIA ROUTING 2012-07-31 03:10:09.668193 [DEBUG] switch_ivr_originate.c:67 (sofia/external/919718300881) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-07-31 03:10:09.668193 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:453 Attempting to bill at $5 per minute to account 97183008 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:465 Not billing 97183008 - call is not in answered state 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:09.668193 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 500.500000) 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:469 Comparing 500.500000 to hangup balance of 0.000000 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 500.500000) 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:433 (sofia/external/919718300881) State ROUTING going to sleep 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_CONSUME_MEDIA 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:452 (sofia/external/919718300881) State CONSUME_MEDIA 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:453 Attempting to bill at $5 per minute to account 97183008 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:465 Not billing 97183008 - call is not in answered state 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 500.500000) 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:469 Comparing 500.500000 to hangup balance of 0.000000 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:09.668193 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 500.500000) 2012-07-31 03:10:09.668193 [INFO] switch_core_session.c:1376 sofia/external/919718300881 setting session heartbeat to 30 second(s). 2012-07-31 03:10:09.668193 [DEBUG] switch_core_state_machine.c:452 (sofia/external/919718300881) State CONSUME_MEDIA going to sleep 2012-07-31 03:10:09.668193 [DEBUG] sofia.c:5745 Channel sofia/external/919718300881 entering state [calling][0] 2012-07-31 03:10:09.708195 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.708195 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:09.708195 [DEBUG] sofia.c:5745 Channel sofia/external/919718300881 entering state [calling][0] 2012-07-31 03:10:20.808198 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:20.808198 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:20.808198 [DEBUG] sofia.c:5745 Channel sofia/external/919718300881 entering state [proceeding][183] 2012-07-31 03:10:20.808198 [DEBUG] sofia.c:5756 Remote SDP: v=0 o=root 3607 3607 IN IP4 31.216.132.13 s=session c=IN IP4 31.216.132.13 t=0 0 m=audio 19974 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:4915 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:2995 Set Codec sofia/external/919718300881 PCMA/8000 20 ms 160 samples 64000 bits 2012-07-31 03:10:20.808198 [DEBUG] switch_core_codec.c:111 sofia/external/919718300881 Original read codec set to PCMA:8 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:5029 Set 2833 dtmf send payload to 101 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:3244 AUDIO RTP [sofia/external/919718300881] 46.252.152.160 port 26726 -> 31.216.132.13 port 19974 codec: 8 ms: 20 2012-07-31 03:10:20.808198 [DEBUG] switch_rtp.c:1676 Starting timer [soft] 160 bytes per 20ms 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:3508 Set 2833 dtmf send payload to 101 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:3514 Set 2833 dtmf receive payload to 101 2012-07-31 03:10:20.808198 [DEBUG] sofia_glue.c:3541 sofia/external/919718300881 Set rtp dtmf delay to 40 2012-07-31 03:10:20.808198 [NOTICE] sofia_glue.c:4052 Pre-Answer sofia/external/919718300881! 2012-07-31 03:10:20.808198 [DEBUG] switch_channel.c:3019 (sofia/external/919718300881) Callstate Change RINGING -> EARLY 2012-07-31 03:10:48.328196 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.328196 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.328196 [DEBUG] sofia.c:5745 Channel sofia/external/919718300881 entering state [completing][200] 2012-07-31 03:10:48.328196 [DEBUG] sofia.c:5756 Remote SDP: v=0 o=root 3607 3608 IN IP4 31.216.132.13 s=session c=IN IP4 31.216.132.13 t=0 0 m=audio 19974 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 2012-07-31 03:10:48.328196 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.328196 [DEBUG] switch_core_session.c:919 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.328196 [DEBUG] sofia.c:5745 Channel sofia/external/919718300881 entering state [ready][200] 2012-07-31 03:10:48.328196 [DEBUG] switch_channel.c:3278 (sofia/external/919718300881) Callstate Change EARLY -> ACTIVE 2012-07-31 03:10:48.328196 [DEBUG] switch_ivr_originate.c:3330 Originate Resulted in Success: [sofia/external/919718300881] 2012-07-31 03:10:48.328196 [NOTICE] sofia.c:6420 Channel [sofia/external/919718300881] has been answered 2012-07-31 03:10:48.328196 [INFO] switch_channel.c:2744 sofia/external/919718300881 Flipping CID from "" <0498722120> to "Outbound Call" <919718300881> 2012-07-31 03:10:48.328196 [DEBUG] mod_commands.c:3616 (sofia/external/919718300881) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 2012-07-31 03:10:48.328196 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.328196 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_EXECUTE 2012-07-31 03:10:48.328196 [DEBUG] switch_core_state_machine.c:440 (sofia/external/919718300881) State EXECUTE 2012-07-31 03:10:48.328196 [DEBUG] mod_sofia.c:241 sofia/external/919718300881 SOFIA EXECUTE 2012-07-31 03:10:48.328196 [INFO] switch_core_session.c:1376 sofia/external/919718300881 setting session heartbeat to 30 second(s). 2012-07-31 03:10:48.328196 [DEBUG] switch_core_state_machine.c:196 sofia/external/919718300881 Standard EXECUTE EXECUTE sofia/external/919718300881 socket(127.0.0.1:8084 async full) 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:612 Received request via SESSION_HEARTBEAT! 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:453 Attempting to bill at $5 per minute to account 97183008 2012-07-31 03:10:48.328196 [INFO] mod_nibblebill.c:505 Beginning new billing on c3961efe-dade-11e1-b60f-1782e99edc0a 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:511 0 seconds passed since last bill time of 2012-07-31 03:10:48 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:528 Billing $2.500000 to 97183008 (Call: c3961efe-dade-11e1-b60f-1782e99edc0a / 0.000000 so far) 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:338 Doing update query [UPDATE accounts SET cash=cash-30 WHERE id='97183008'] 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:48.328196 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 470.500000) 2012-07-31 03:10:48.348194 [DEBUG] switch_core_session.c:1056 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.348194 [DEBUG] switch_core_session.c:1056 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.368196 [DEBUG] switch_rtp.c:3253 Correct ip/port confirmed. 2012-07-31 03:10:48.368196 [DEBUG] switch_ivr.c:598 sofia/external/919718300881 Command Execute set(plivo_app=true) EXECUTE sofia/external/919718300881 set(plivo_app=true) 2012-07-31 03:10:48.368196 [DEBUG] mod_dptools.c:1305 sofia/external/919718300881 SET [plivo_app]=[true] 2012-07-31 03:10:48.408195 [DEBUG] switch_ivr.c:598 sofia/external/919718300881 Command Execute set(hangup_after_bridge=false) EXECUTE sofia/external/919718300881 set(hangup_after_bridge=false) 2012-07-31 03:10:48.408195 [DEBUG] mod_dptools.c:1305 sofia/external/919718300881 SET [hangup_after_bridge]=[false] 2012-07-31 03:10:48.468630 [DEBUG] switch_core_session.c:1056 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:48.488187 [DEBUG] switch_ivr.c:598 sofia/external/919718300881 Command Execute speak(flite|slt|Hello World this is demo IVR message) EXECUTE sofia/external/919718300881 speak(flite|slt|Hello World this is demo IVR message) 2012-07-31 03:10:48.488187 [DEBUG] switch_ivr_play_say.c:2473 OPEN TTS flite 2012-07-31 03:10:48.488187 [DEBUG] switch_ivr_play_say.c:2482 Raw Codec Activated 2012-07-31 03:10:48.608191 [DEBUG] switch_ivr_play_say.c:2164 Speaking text: Hello World this is demo IVR message 2012-07-31 03:10:51.428188 [DEBUG] switch_ivr_play_say.c:2361 done speaking text 2012-07-31 03:10:51.428188 [DEBUG] switch_core_session.c:1056 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:51.428188 [DEBUG] mod_event_socket.c:2644 (sofia/external/919718300881) State Change CS_EXECUTE -> CS_RESET 2012-07-31 03:10:51.428188 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:51.448191 [DEBUG] switch_ivr.c:598 sofia/external/919718300881 Command Execute hangup() EXECUTE sofia/external/919718300881 hangup() 2012-07-31 03:10:51.448191 [DEBUG] switch_channel.c:2882 (sofia/external/919718300881) Callstate Change ACTIVE -> HANGUP 2012-07-31 03:10:51.448191 [NOTICE] mod_dptools.c:1134 Hangup sofia/external/919718300881 [CS_RESET] [NORMAL_CLEARING] 2012-07-31 03:10:51.448191 [DEBUG] switch_channel.c:2905 Send signal sofia/external/919718300881 [KILL] 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:2329 sofia/external/919718300881 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:2329 sofia/external/919718300881 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:440 (sofia/external/919718300881) State EXECUTE going to sleep 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_HANGUP 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:625 (sofia/external/919718300881) State HANGUP 2012-07-31 03:10:51.448191 [DEBUG] mod_sofia.c:469 Channel sofia/external/919718300881 hanging up, cause: NORMAL_CLEARING 2012-07-31 03:10:51.448191 [DEBUG] mod_sofia.c:517 Sending BYE to sofia/external/919718300881 2012-07-31 03:10:51.448191 [DEBUG] mod_nibblebill.c:453 Attempting to bill at $5 per minute to account 97183008 2012-07-31 03:10:51.448191 [DEBUG] mod_nibblebill.c:511 -26 seconds passed since last bill time of 2012-07-31 03:11:18 2012-07-31 03:10:51.448191 [DEBUG] mod_nibblebill.c:383 Doing lookup query [SELECT cash AS nibble_balance FROM accounts WHERE id='97183008'] 2012-07-31 03:10:51.448191 [DEBUG] mod_nibblebill.c:393 Retrieved current balance for account 97183008 (balance = 470.500000) 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:47 sofia/external/919718300881 Standard HANGUP, cause: NORMAL_CLEARING 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:625 (sofia/external/919718300881) State HANGUP going to sleep 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:416 (sofia/external/919718300881) State Change CS_HANGUP -> CS_REPORTING 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:385 (sofia/external/919718300881) Running State Change CS_REPORTING 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:685 (sofia/external/919718300881) State REPORTING 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:79 sofia/external/919718300881 Standard REPORTING, cause: NORMAL_CLEARING 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:685 (sofia/external/919718300881) State REPORTING going to sleep 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:410 (sofia/external/919718300881) State Change CS_REPORTING -> CS_DESTROY 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:1224 Send signal sofia/external/919718300881 [BREAK] 2012-07-31 03:10:51.448191 [DEBUG] switch_core_session.c:1424 Session 105 (sofia/external/919718300881) Locked, Waiting on external entities 2012-07-31 03:10:51.448191 [NOTICE] switch_core_session.c:1442 Session 105 (sofia/external/919718300881) Ended 2012-07-31 03:10:51.448191 [NOTICE] switch_core_session.c:1444 Close Channel sofia/external/919718300881 [CS_DESTROY] 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:514 (sofia/external/919718300881) Callstate Change HANGUP -> DOWN 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:517 (sofia/external/919718300881) Running State Change CS_DESTROY 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:527 (sofia/external/919718300881) State DESTROY 2012-07-31 03:10:51.448191 [DEBUG] mod_sofia.c:374 sofia/external/919718300881 SOFIA DESTROY 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:86 sofia/external/919718300881 Standard DESTROY 2012-07-31 03:10:51.448191 [DEBUG] switch_core_state_machine.c:527 (sofia/external/919718300881) State DESTROY going to sleep if anything is required from my end then please let me know if will provide here.... -- Thanks and regards Virendra Bhati +91-9718300881 Asterisk Developer E-mail-: virbhati@gmail.com Skype id:- virbhati2 New Delhi(India)