I tried the command in a cluster environment
so 9999 can be on node1 and 7777 on node2
 
here is the log
 

2011-04-01 19:54:45.192621 [DEBUG] switch_ivr_originate.c:1973 variable string 0 = [presence_id=9999@boophone.com]
2011-04-01 19:54:45.193638 [NOTICE] switch_channel.c:812 New Channel sofia/internal/sip:9999@192.168.0.18:58251 [43cf3947-e9b3-4828-befc-e284dc4a9e3a]
2011-04-01 19:54:45.193638 [DEBUG] mod_sofia.c:4286 (sofia/internal/sip:9999@192.168.0.18:58251) State Change CS_NEW -> CS_INIT
2011-04-01 19:54:45.193638 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:54:45.193638 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_INIT
2011-04-01 19:54:45.193638 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:9999@192.168.0.18:58251) State INIT
2011-04-01 19:54:45.193638 [DEBUG] mod_sofia.c:84 sofia/internal/sip:9999@192.168.0.18:58251 SOFIA INIT
2011-04-01 19:54:45.194651 [DEBUG] mod_sofia.c:124 (sofia/internal/sip:9999@192.168.0.18:58251) State Change CS_INIT -> CS_ROUTING
2011-04-01 19:54:45.194651 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:9999@192.168.0.18:58251) State INIT going to sleep
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_ROUTING
2011-04-01 19:54:45.194651 [DEBUG] switch_channel.c:1668 (sofia/internal/sip:9999@192.168.0.18:58251) Callstate Change DOWN -> RINGING
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:9999@192.168.0.18:58251) State ROUTING
2011-04-01 19:54:45.194651 [DEBUG] mod_sofia.c:147 sofia/internal/sip:9999@192.168.0.18:58251 SOFIA ROUTING
2011-04-01 19:54:45.194651 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:9999@192.168.0.18:58251) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-04-01 19:54:45.194651 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:9999@192.168.0.18:58251) State ROUTING going to sleep
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_CONSUME_MEDIA
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:9999@192.168.0.18:58251) State CONSUME_MEDIA
2011-04-01 19:54:45.194651 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:9999@192.168.0.18:58251) State CONSUME_MEDIA going to sleep
2011-04-01 19:54:45.195670 [DEBUG] sofia.c:4754 Channel sofia/internal/sip:9999@192.168.0.18:58251 entering state [calling][0]
2011-04-01 19:54:48.856682 [DEBUG] mod_nibblebill.c:572 Received request via SESSION_HEARTBEAT!
2011-04-01 19:54:48.856682 [DEBUG] mod_nibblebill.c:433 Attempting to bill at $0.03 per minute to account 9999
2011-04-01 19:54:48.856682 [DEBUG] mod_nibblebill.c:491 60 seconds passed since last bill time of 2011-04-01 19:53:48
2011-04-01 19:54:48.856682 [DEBUG] mod_nibblebill.c:498 Billing $0.030010 to 9999 (Call: 704fa1fc-7b97-40b3-ad16-b5fc9da6d667 / 0.134583 so far)
2011-04-01 19:54:48.856682 [DEBUG] mod_nibblebill.c:321 Doing update query
[UPDATE accounts SET cash=cash-0.030010 WHERE id='9999']
2011-04-01 19:54:48.944981 [DEBUG] mod_nibblebill.c:366 Doing lookup query
[SELECT cash AS nibble_balance FROM accounts WHERE id='9999']
2011-04-01 19:54:48.951074 [DEBUG] mod_nibblebill.c:376 Retrieved current balance for account 9999 (balance = 10.105113)
2011-04-01 19:55:01.857456 [DEBUG] mod_nibblebill.c:572 Received request via SESSION_HEARTBEAT!
2011-04-01 19:55:01.857456 [DEBUG] mod_nibblebill.c:433 Attempting to bill at $0.03 per minute to account 9999
2011-04-01 19:55:01.857456 [DEBUG] mod_nibblebill.c:491 60 seconds passed since last bill time of 2011-04-01 19:54:01
2011-04-01 19:55:01.857456 [DEBUG] mod_nibblebill.c:498 Billing $0.030010 to 9999 (Call: 2879366a-0478-4480-9977-8b22847be252 / 0.150150 so far)
2011-04-01 19:55:01.857456 [DEBUG] mod_nibblebill.c:321 Doing update query
[UPDATE accounts SET cash=cash-0.030010 WHERE id='9999']
2011-04-01 19:55:01.943873 [DEBUG] mod_nibblebill.c:366 Doing lookup query
[SELECT cash AS nibble_balance FROM accounts WHERE id='9999']
2011-04-01 19:55:01.949965 [DEBUG] mod_nibblebill.c:376 Retrieved current balance for account 9999 (balance = 10.075103)
2011-04-01 19:55:17.196147 [DEBUG] sofia.c:4754 Channel sofia/internal/sip:9999@192.168.0.18:58251 entering state [terminated][408]
2011-04-01 19:55:17.196147 [DEBUG] switch_channel.c:2563 (sofia/internal/sip:9999@192.168.0.18:58251) Callstate Change RINGING -> HANGUP
2011-04-01 19:55:17.196147 [NOTICE] sofia.c:5394 Hangup sofia/internal/sip:9999@192.168.0.18:58251 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2011-04-01 19:55:17.196147 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [KILL]
2011-04-01 19:55:17.196147 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:55:17.196147 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_HANGUP
2011-04-01 19:55:17.196147 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:9999@192.168.0.18:58251) State HANGUP
2011-04-01 19:55:17.196147 [DEBUG] mod_sofia.c:451 sofia/internal/sip:9999@192.168.0.18:58251 Overriding SIP cause 504 with 408 from the other leg
2011-04-01 19:55:17.196147 [DEBUG] mod_sofia.c:457 Channel sofia/internal/sip:9999@192.168.0.18:58251 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:9999@192.168.0.18:58251 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:9999@192.168.0.18:58251) State HANGUP going to sleep
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:9999@192.168.0.18:58251) State Change CS_HANGUP -> CS_REPORTING
2011-04-01 19:55:17.204366 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_REPORTING
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:9999@192.168.0.18:58251) State REPORTING
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:9999@192.168.0.18:58251 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:9999@192.168.0.18:58251) State REPORTING going to sleep
2011-04-01 19:55:17.204366 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/sip:9999@192.168.0.18:58251) State Change CS_REPORTING -> CS_DESTROY
2011-04-01 19:55:17.204366 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:9999@192.168.0.18:58251 [BREAK]
2011-04-01 19:55:17.204366 [DEBUG] switch_core_session.c:1288 Session 79 (sofia/internal/sip:9999@192.168.0.18:58251) Locked, Waiting on external entities
2011-04-01 19:55:17.206396 [DEBUG] switch_ivr_originate.c:3506 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2011-04-01 19:55:17.206396 [ERR] switch_ivr_originate.c:2640 Cannot create outgoing channel of type [user] cause: [RECOVERY_ON_TIMER_EXPIRE]
2011-04-01 19:55:17.206396 [NOTICE] switch_core_session.c:1306 Session 79 (sofia/internal/sip:9999@192.168.0.18:58251) Ended
2011-04-01 19:55:17.206396 [DEBUG] switch_ivr_originate.c:3506 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2011-04-01 19:55:17.206396 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/sip:9999@192.168.0.18:58251 [CS_DESTROY]
2011-04-01 19:55:17.206396 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/sip:9999@192.168.0.18:58251) Callstate Change HANGUP -> DOWN
2011-04-01 19:55:17.206396 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:9999@192.168.0.18:58251) Running State Change CS_DESTROY
2011-04-01 19:55:17.206396 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:9999@192.168.0.18:58251) State DESTROY
2011-04-01 19:55:17.206396 [DEBUG] mod_sofia.c:362 sofia/internal/sip:9999@192.168.0.18:58251 SOFIA DESTROY
2011-04-01 19:55:17.206396 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:9999@192.168.0.18:58251 Standard DESTROY
2011-04-01 19:55:17.206396 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:9999@192.168.0.18:58251) State DESTROY going to sleep


thanks

----- Original Message -----
From: Steven Ayre
To: FreeSWITCH Users Help
Sent: Friday, April 01, 2011 5:30 PM
Subject: Re: [Freeswitch-users] originate from cli

It can also be that the other side sent FS a reply saying that *it* had timed out. siptrace will also show if that's the case.


On 1 April 2011 22:29, Steven Ayre <steveayre@gmail.com> wrote:
It means FS sent a message and didn't get a reply (timed out).

As anthm says, look at the siptrace - that'll show you what's being sent / received.

-Steve


On 1 April 2011 21:17, Madovsky <infos@madovsky.org> wrote:
I make some test with originate from cli.
 
/usr/local/freeswitch/bin/fs_cli -x "originate user/9999 7777 XML public"
-ERR RECOVERY_ON_TIMER_EXPIRE
 
9999 and 7777 are ready to receive calls and I don't have any NAT.
 
is anyone can explain what it means ?
 
Thanks
 

_______________________________________________
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



_______________________________________________
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