2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 6
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Retry number 2
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 0
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 4
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 DCS:
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... 0...= 3G mobile network: Not set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ..1.= Receive fax: Set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   1... ....= 2-D coding: Set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... 10..= Recording length: Unlimited
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .111 ....= Minimum scan line time: 0ms
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   0... ....= Extension indicator: Not set
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 6 to 4
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Sending ident 'boophone.com'
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: TSI without final frame tag
2011-04-15 16:54:07.685484 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: ff 03 43 6d 6f 63 2e 65 6e 6f 68 70 6f 6f 62 20 20 20 20 20 20 20 20
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 DCS:
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... 0...= 3G mobile network: Not set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ..1.= Receive fax: Set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   1... ....= 2-D coding: Set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .... 10..= Recording length: Unlimited
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   .111 ....= Minimum scan line time: 0ms
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30   0... ....= Extension indicator: Not set
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: DCS with final frame tag
2011-04-15 16:54:09.265684 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: ff 13 83 00 e2 78
2011-04-15 16:54:09.546048 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 4 to 5
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_C_NON_ECM_TX
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 0
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 0
2011-04-15 16:54:09.626076 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 7
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_C_NON_ECM_TX, state 5
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_TX to T30_PHASE_B_RX
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 4
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 0
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Start T4
2011-04-15 16:54:12.645314 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 5 to 6
2011-04-15 16:54:13.166347 [DEBUG] mod_nibblebill.c:572 Received request via SESSION_HEARTBEAT!
2011-04-15 16:54:13.166347 [DEBUG] mod_nibblebill.c:433 Attempting to bill at $0.17304 per minute to account 9999999999999
2011-04-15 16:54:13.166347 [DEBUG] mod_nibblebill.c:491 30 seconds passed since last bill time of 2011-04-15 16:53:43
2011-04-15 16:54:13.166347 [DEBUG] mod_nibblebill.c:498 Billing $0.086548 to 9999999999999 (Call: 1132765120@67.205.80.135 / 0.000009 so far)
2011-04-15 16:54:13.166347 [DEBUG] mod_nibblebill.c:321 Doing update query
[UPDATE accounts SET cash=cash-0.086548 WHERE id='9999999999999']
2011-04-15 16:54:13.288037 [DEBUG] mod_nibblebill.c:366 Doing lookup query
[SELECT cash AS nibble_balance FROM accounts WHERE id='9999999999999']
2011-04-15 16:54:13.293107 [DEBUG] mod_nibblebill.c:376 Retrieved current balance for account 9999999999999 (balance = 6.655555)
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 6
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Too many retries. Giving up.
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_D_TX
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 0
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 4
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 6 to 3
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: DCN with final frame tag
2011-04-15 16:54:16.105756 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Tx: ff 13 fb
2011-04-15 16:54:17.165849 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Disconnecting
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 0
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 1
2011-04-15 16:54:17.245860 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 3 to 2
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Send complete in phase T30_PHASE_E, state 2
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:333 ==============================================================================
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:345 Fax processing not successful - result (20) Received no response to DCS or TCF.
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:350 Remote station id: 33456809528
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:351 Local station id: boophone.com
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:352 Pages transferred: 0
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:354 Total fax pages:   1
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:355 Image resolution: 8031x7700
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:356 Transfer Rate:     14400
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:358 ECM status         off
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:359 remote country:
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:360 remote vendor:
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:361 remote model:
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:363 ==============================================================================
2011-04-15 16:54:18.245661 [DEBUG] switch_core_session.c:954 Send signal sofia/external/0033456809528 [BREAK]
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from state 2 to 32
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set rx type 9
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX FAX exchange complete
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX Set tx type 9
2011-04-15 16:54:18.245661 [DEBUG] mod_spandsp_fax.c:296 FLOW FAX FAX exchange complete
2011-04-15 16:54:18.265918 [DEBUG] switch_core_codec.c:141 sofia/external/0033456809528 Restore previous codec PCMU:0.