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....
--