[Freeswitch-users] Nibble Billing deducted balance from account even call doesn't come to my mobile number

virendra bhati virbhati at gmail.com
Tue Jul 31 11:35:24 MSD 2012 

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 at gmail.com
Skype id:- virbhati2
New Delhi(India)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120731/388580e9/attachment-0001.html

Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users mailing list