Asterisk 1.6 stops responding

dcitelecom · February 28, 2011, 8:32pm

Anyone know why an Asterisk server would stop working suddenly? Incoming DIDs ring busy. Outgoing trunk calls ring busy but calls to voice mail and internal extension to extension calls continue to work. On reboot everything works again.

I am running Asterisk 1.6.2.11 with PIAF 1.7.5.5 and FreePBX version 2.8.1.0

dcitelecom · March 18, 2011, 5:24pm

OK. Thanks.
We’ll have to create user accounts

Could this be causing our problem?
http://www.freepbx.org/support/documentation/howtos/how-to-install-bind-so-that-sip-extensions-continue-to-work-when-intern

dcitelecom · March 18, 2011, 5:43pm

TCP transport is only used for our cell phone SIP extensions but we never had a problem with it before (which means nothing I know) but it’s essential to our business model so turning it off would not be an option.

plindheimer · March 18, 2011, 4:52pm

TCP
the current support is pre-paid, they almost always need root access to the system or sudo with adequate privileges. They will typically document everything that was done but you are more then welcome to request additional details if they are not there. (There are no ‘secrets’).

dcitelecom · March 18, 2011, 3:53pm

what do you mean by non-experimental transports?
how does paid support work? Would they ask for root access into the system? If they fix it would they disclose what they did?

dcitelecom · March 18, 2011, 3:15pm

Anyone? I am even willing to pay a bounty for help on this. Keeps happening every day now.

plindheimer · March 18, 2011, 3:29pm

you are aways welcome to contact the paid support channel to have a look at it.

you may also want to consider using non-experimental transports, could be related.

dcitelecom · March 16, 2011, 1:51pm

We are now running, PIAF 1.7.5.5, FreePBX 2.8.1.4, Asterisk 1.6.2.17
and we had the same problem again yesterday evening

First our customers call to complain that there is no audio on outbound calls.
We then test *97 (voicemail) and it works (we get audio) but when we try a couple of test calls there is no audio even though the calls are processed and show in the log.

We start up x-lite sip client and notice that Asterisk does not accept the registration.
x-lite reports error 408 request timeout when trying to register a new extension.

We try to restart Asterisk but amportal stop does not shut down asterisk. Only fix is to reboot the server.

I did as you said and increased Debug and Verbosity to 5 AFTER the issue happened and tried to make a couple of calls. Problem is the log only shows symptoms not the reason why the problem suddenly started.

Sorry for the long log. I tried to remove everything that wasn’t relevant. As best as I can tell there seems to be a problem with IAX channels and calltokens for extension 3334602 as well as the UDP/TCP transport. E.g. extension 7000 can not register because TCP is not a valid transport yet the extension is defined as UDP type in the server and client but the server wants TCP.

Yes when I try to make a call from extension 5149271234 which is configured for TCP the calls fail with “devicestate.c: No provider found, checking channel drivers for SIP - 5149271234”

Can anyone help please? We keep getting the same issue week after week and it’s a real problem for us.

FROM ASTERISK log:
[2011-03-15 18:20:45] VERBOSE[25019] manager.c: == Manager ‘admin’ logged off from 127.0.0.1
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Starting thread for TCP server
[2011-03-15 18:20:50] DEBUG[25027] acl.c: Found IP address for this socket
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Target address 65.41.183.2 is not local, substituting externip
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 60.30.180.84:5060
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Allocating new SIP dialog for ZDU5ZjE4MjNiYjVjZjIwMjlkODE5YzhiM2IzZTQ2Njk. - REGISTER (No RTP)
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto TCP socket destined for 65.41.183.2:50704
[2011-03-15 18:20:50] DEBUG[25027] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TCP socket destined for 65.41.183.2:50704
[2011-03-15 18:20:51] DEBUG[25027] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-03-15 18:20:51] DEBUG[25027] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto TCP socket destined for 65.41.183.2:50704
[2011-03-15 18:20:51] ERROR[25027] chan_sip.c: ‘TCP’ is not a valid transport for ‘7000’. we only use ‘UDP’! ending call.
[2011-03-15 18:20:51] DEBUG[25027] chan_sip.c: Trying to put ‘SIP/2.0 403’ onto TCP socket destined for 65.41.183.2:50704
[2011-03-15 18:20:51] NOTICE[25027] chan_sip.c: Registration from ‘"JB"sip:[email protected]’ failed for ‘65.41.183.2’ - Device not configured to use this transport type
[2011-03-15 18:20:51] DEBUG[24992] chan_iax2.c: Determining if address 74.59.232.77 with username 3334602 requires calltoken validation. Optional = 0 calltoken_required = 3
[2011-03-15 18:20:51] DEBUG[24992] chan_iax2.c: ip callno count incremented to 3 for 74.59.232.77
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:20:51] DEBUG[24975] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:20:51] DEBUG[24975] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=60
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: Changing state for IAX2/3334602 - state 0 (Unknown)
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: device ‘IAX2/3334602’ state ‘0’
[2011-03-15 18:20:51] DEBUG[24999] app_queue.c: Device ‘IAX2/3334602’ changed to state ‘0’ (Unknown) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:20:51] DEBUG[24976] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:20:51] DEBUG[24976] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=60
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND3334602
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:20:51] DEBUG[24976] db.c: Unable to find key ‘DND3334602’ in family ‘CustomDevstate’
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:20:51] DEBUG[24975] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:20:51] DEBUG[24975] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=60
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: Changing state for IAX2/3334602 - state 0 (Unknown)
[2011-03-15 18:20:51] DEBUG[24975] devicestate.c: device ‘IAX2/3334602’ state ‘0’
[2011-03-15 18:20:51] DEBUG[24999] app_queue.c: Device ‘IAX2/3334602’ changed to state ‘0’ (Unknown) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:20:51] DEBUG[24976] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:20:51] DEBUG[24976] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=60
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND3334602
[2011-03-15 18:20:51] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:20:51] DEBUG[24976] db.c: Unable to find key ‘DND3334602’ in family ‘CustomDevstate’
[2011-03-15 18:20:51] DEBUG[24990] chan_iax2.c: schedule decrement of callno used for 74.59.232.77 in 60 seconds
[2011-03-15 18:20:51] DEBUG[24984] chan_iax2.c: ip callno count decremented to 2 for 74.59.232.77
[2011-03-15 18:21:33] DEBUG[24984] chan_iax2.c: ip callno count decremented to 1 for 74.59.232.77
[2011-03-15 18:21:33] DEBUG[24993] chan_iax2.c: ip callno count incremented to 2 for 74.59.232.77
[2011-03-15 18:21:33] DEBUG[24991] chan_iax2.c: schedule decrement of callno used for 74.59.232.77 in 60 seconds
[2011-03-15 18:21:33] DEBUG[24991] chan_iax2.c: Peer 3334602: got pong, lastms 65, historicms 65, maxms 2000
[2011-03-15 18:21:51] DEBUG[24984] chan_iax2.c: ip callno count decremented to 1 for 74.59.232.77
[2011-03-15 18:21:51] DEBUG[24988] chan_iax2.c: Determining if address 74.59.232.77 with username 3334602 requires calltoken validation. Optional = 0 calltoken_required = 3
[2011-03-15 18:21:51] DEBUG[24988] chan_iax2.c: ip callno count incremented to 2 for 74.59.232.77
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:21:51] DEBUG[24975] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:21:51] DEBUG[24975] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=65
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: Changing state for IAX2/3334602 - state 0 (Unknown)
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: device ‘IAX2/3334602’ state ‘0’
[2011-03-15 18:21:51] DEBUG[24999] app_queue.c: Device ‘IAX2/3334602’ changed to state ‘0’ (Unknown) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:21:51] DEBUG[24976] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:21:51] DEBUG[24976] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=65
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND3334602
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:21:51] DEBUG[24976] db.c: Unable to find key ‘DND3334602’ in family ‘CustomDevstate’
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:21:51] DEBUG[24975] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:21:51] DEBUG[24975] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=65
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: Changing state for IAX2/3334602 - state 0 (Unknown)
[2011-03-15 18:21:51] DEBUG[24975] devicestate.c: device ‘IAX2/3334602’ state ‘0’
[2011-03-15 18:21:51] DEBUG[24999] app_queue.c: Device ‘IAX2/3334602’ changed to state ‘0’ (Unknown) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: No provider found, checking channel drivers for IAX2 - 3334602
[2011-03-15 18:21:51] DEBUG[24976] chan_iax2.c: Checking device state for device 3334602
[2011-03-15 18:21:51] DEBUG[24976] chan_iax2.c: iax2_devicestate: Found peer. What’s device state of 3334602? addr=1307065162, defaddr=0 maxms=2000, lastms=65
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND3334602
[2011-03-15 18:21:51] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:21:51] DEBUG[24976] db.c: Unable to find key ‘DND3334602’ in family ‘CustomDevstate’
[2011-03-15 18:21:51] DEBUG[24985] chan_iax2.c: schedule decrement of callno used for 74.59.232.77 in 60 seconds
[2011-03-15 18:21:59] DEBUG[21751] acl.c: Found IP address for this socket
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Target address 174.47.40.244 is not local, substituting externip
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 60.30.180.84:5060
[2011-03-15 18:21:59] VERBOSE[21751] netsock.c: == Using SIP RTP TOS bits 184
[2011-03-15 18:21:59] VERBOSE[21751] netsock.c: == Using SIP RTP CoS mark 5
[2011-03-15 18:21:59] VERBOSE[21751] netsock.c: == Using UDPTL TOS bits 184
[2011-03-15 18:21:59] VERBOSE[21751] netsock.c: == Using UDPTL CoS mark 5
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Setting NAT on RTP to On
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Setting NAT on UDPTL to On
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Allocating new SIP dialog for 2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8 - INVITE (With RTP)
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Setting NAT on RTP to On
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Setting NAT on UDPTL to On
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TCP socket destined for 174.47.40.244:49210
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2011-03-15 18:21:59] DEBUG[21751] chan_sip.c: Stopping retransmission on ‘2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8’ of Response 25095: Match Not Found
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Setting NAT on RTP to On
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Setting NAT on UDPTL to On
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing session-level SDP o=- 3509216512 3509216512 IN IP4 174.47.40.244… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing session-level SDP s=cpc_med… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing session-level SDP c=IN IP4 174.47.40.244… OK.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000… OK.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing media-level (audio) SDP a=sendrecv… OK.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000… OK.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15… UNSUPPORTED.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: We’re settling with these formats: 0x100 (g729)
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Checking SIP call limits for device 5149271234
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Updating call counter for incoming call
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: *** Our native formats are 0x100 (g729)
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: *** Joint capabilities are 0x100 (g729)
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: *** Our capabilities are 0x10e (gsm|ulaw|alaw|g729)
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729)
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: This channel will not be able to handle video.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: build_route: Contact hop: “5149271234” sip:[email protected]:49209;transport=TCP
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Incoming INVITE with ‘timer’ option supported and “Session-Expires” header.
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Session-Expires: 1800
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Received Min-SE: 90
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Session timer started: 2219984 - 2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for SIP - 5149271234
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: SIP/5149271234-00001a51: New call is still down… Trying…
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto TCP socket destined for 174.47.40.244:49210
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Macro’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:1] Macro(“SIP/5149271234-00001a51”, “user-callerid,SKIPTTL,”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/5149271234-00001a51”, “AMPUSER=5149271234”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/5149271234-00001a51”, “0?report”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Not taking any branch
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘ExecIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/5149271234-00001a51”, “1?Set(REALCALLERIDNUM=5149271234)”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: ExecIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:4] Set(“SIP/5149271234-00001a51”, “AMPUSER=5149271234”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘Jack Birnbaum’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/5149271234-00001a51”, “AMPUSERCIDNAME=Jack Birnbaum”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/5149271234-00001a51”, “0?report”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Not taking any branch
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:7] Set(“SIP/5149271234-00001a51”, “AMPUSERCID=5149271234”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:8] Set(“SIP/5149271234-00001a51”, “CALLERID(all)=“Jack Birnbaum” <5149271234>”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:9] GotoIf(“SIP/5149271234-00001a51”, “1?continue”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-user-callerid,s,18)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:18] Set(“SIP/5149271234-00001a51”, “CALLERID(number)=5149271234”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘Jack Birnbaum’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:19] Set(“SIP/5149271234-00001a51”, “CALLERID(name)=Jack Birnbaum”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘“Jack Birnbaum” <5149271234>’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘NoOp’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/5149271234-00001a51”, “Using CallerID “Jack Birnbaum” <5149271234>”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Noop
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘NoOp’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:2] NoOp(“SIP/5149271234-00001a51”, “Calling Out Route: Montreal”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘default’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:3] Set(“SIP/5149271234-00001a51”, “MOHCLASS=default”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:4] Set(“SIP/5149271234-00001a51”, “_NODEST=”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Macro’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:5] Macro(“SIP/5149271234-00001a51”, “record-enable,5149271234,OUT,”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘MacroExit’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-record-enable:1] MacroExit(“SIP/5149271234-00001a51”, “”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Macro’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [5144481234@from-internal:6] Macro(“SIP/5149271234-00001a51”, “dialout-enum,12,5144481234,”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] db.c: Unable to find key ‘5149271234/pinless’ in family ‘AMPUSER’
[2011-03-15 18:22:13] DEBUG[25169] func_db.c: DB: AMPUSER/5149271234/pinless not found in database.
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GosubIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:1] GosubIf(“SIP/5149271234-00001a51”, “0?sub-pincheck,s,1”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GosubIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] db.c: Unable to find key ‘5149271234/pinless’ in family ‘AMPUSER’
[2011-03-15 18:22:13] DEBUG[25169] func_db.c: DB: AMPUSER/5149271234/pinless not found in database.
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Macro’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:2] Macro(“SIP/5149271234-00001a51”, “outbound-callerid,12”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘ExecIf’
[2011-03-15 18:22:13] DEBUG[24975] chan_sip.c: Checking device state for peer 5149271234
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/5149271234-00001a51”, “0?Set(CALLERPRES()=)”) in new stack
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: Changing state for SIP/5149271234 - state 2 (In use)
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: device ‘SIP/5149271234’ state ‘2’
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for SIP - 5149271234
[2011-03-15 18:22:13] DEBUG[24975] chan_sip.c: Checking device state for peer 5149271234
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: Changing state for SIP/5149271234 - state 2 (In use)
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: device ‘SIP/5149271234’ state ‘2’
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: ExecIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[24999] app_queue.c: Device ‘SIP/5149271234’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:22:13] DEBUG[24999] app_queue.c: Device ‘SIP/5149271234’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘ExecIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/5149271234-00001a51”, “0?Set(REALCALLERIDNUM=5149271234)”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: ExecIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘5149271234’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/5149271234-00001a51”, “1?normcid”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘“JB” <5149271234>’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/5149271234-00001a51”, “USEROUTCID=“JB” <5149271234>”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] db.c: Unable to find key ‘5149271234/emergency_cid’ in family ‘DEVICE’
[2011-03-15 18:22:13] DEBUG[25169] func_db.c: DB: DEVICE/5149271234/emergency_cid not found in database.
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/5149271234-00001a51”, “EMERGENCYCID=”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/5149271234-00001a51”, “TRUNKOUTCID=”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/5149271234-00001a51”, “1?trunkcid”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-outbound-callerid,s,12)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘ExecIf’
…
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/5149271234-00001a51”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: ExecIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘JB’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘0’
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Macro
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:3] Set(“SIP/5149271234-00001a51”, “OUTBOUND_GROUP=OUT_12”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:4] GotoIf(“SIP/5149271234-00001a51”, “1?nomax”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-dialout-enum,s,6)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:6] Set(“SIP/5149271234-00001a51”, “DIAL_NUMBER=5144481234”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Set’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:7] Set(“SIP/5149271234-00001a51”, “DIAL_TRUNK=12”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: Set
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GosubIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:8] GosubIf(“SIP/5149271234-00001a51”, “1?sub-flp-12,s,1”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_stack.c: Channel SIP/5149271234-00001a51 has no datastore, so we’re allocating one.
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GosubIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Incrementing gosub_level
[2011-03-15 18:22:13] DEBUG[25169] func_strings.c: FUNCTION REGEX (^[0-9#*+]+$)(5144481234)
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘ExecIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@sub-flp-12:1] ExecIf(“SIP/5149271234-00001a51”, “1?Return()”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: ExecIf
[2011-03-15 18:22:13] DEBUG[25169] func_strings.c: FUNCTION REGEX (^[0-9#*+]+$)(5144481234)
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Function result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘AGI’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-dialout-enum:9] AGI(“SIP/5149271234-00001a51”, “enumlookup.agi”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] res_agi.c: – Launched AGI Script /var/lib/asterisk/agi-bin/enumlookup.agi
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND5149271234
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:22:13] DEBUG[24976] db.c: Unable to find key ‘DND5149271234’ in family ‘CustomDevstate’
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND5149271234
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:22:13] DEBUG[24976] db.c: Unable to find key ‘DND5149271234’ in family ‘CustomDevstate’
[2011-03-15 18:22:13] VERBOSE[25169] res_agi.c: enumlookup.agi: 5144481234
[2011-03-15 18:22:13] DEBUG[25145] manager.c: Manager received command ‘Command’
[2011-03-15 18:22:13] VERBOSE[25145] manager.c: == Manager ‘admin’ logged off from 127.0.0.1
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Updating call counter for incoming call
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Trying to put ‘SIP/2.0 487’ onto TCP socket destined for 174.47.40.244:49210
[2011-03-15 18:22:13] DEBUG[21751] chan_sip.c: Trying to put ‘SIP/2.0 200’ onto TCP socket destined for 174.47.40.244:49210
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for SIP - 5149271234
[2011-03-15 18:22:13] DEBUG[24975] chan_sip.c: Checking device state for peer 5149271234
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: Changing state for SIP/5149271234 - state 1 (Not in use)
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: device ‘SIP/5149271234’ state ‘1’
[2011-03-15 18:22:13] DEBUG[24999] app_queue.c: Device ‘SIP/5149271234’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND5149271234
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:22:13] DEBUG[24976] db.c: Unable to find key ‘DND5149271234’ in family ‘CustomDevstate’
[2011-03-15 18:22:13] DEBUG[25169] res_agi.c: SIP/5149271234-00001a51 hungup
[2011-03-15 18:22:13] VERBOSE[25169] res_agi.c: – <SIP/5149271234-00001a51>AGI Script enumlookup.agi completed, returning -1
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: AGI
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Extension s, macroexten 5144481234, priority 9 returned normally even though call was hung up
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Extension 5144481234, priority 6 returned normally even though call was hung up
[2011-03-15 18:22:13] DEBUG[25169] channel.c: Soft-Hanging up channel ‘SIP/5149271234-00001a51’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Macro’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [h@from-internal:1] Macro(“SIP/5149271234-00001a51”, “hangupcall”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/5149271234-00001a51”, “1?skiprg”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-hangupcall,s,4)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/5149271234-00001a51”, “1?skipblkvm”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-hangupcall,s,7)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Expression result is ‘1’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘GotoIf’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/5149271234-00001a51”, “1?theend”) in new stack
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Goto (macro-hangupcall,s,9)
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Executed application: GotoIf
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Launching ‘Hangup’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/5149271234-00001a51”, “”) in new stack
[2011-03-15 18:22:13] DEBUG[25169] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on ‘SIP/5149271234-00001a51’ in macro ‘hangupcall’
[2011-03-15 18:22:13] VERBOSE[25169] app_macro.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/5149271234-00001a51’ in macro ‘hangupcall’
[2011-03-15 18:22:13] DEBUG[25169] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on ‘SIP/5149271234-00001a51’
[2011-03-15 18:22:13] VERBOSE[25169] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/5149271234-00001a51’
[2011-03-15 18:22:13] DEBUG[25169] channel.c: Hanging up channel ‘SIP/5149271234-00001a51’
[2011-03-15 18:22:13] DEBUG[25169] chan_sip.c: Hangup call SIP/5149271234-00001a51, SIP callid 2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for SIP - 5149271234
[2011-03-15 18:22:13] DEBUG[24975] chan_sip.c: Checking device state for peer 5149271234
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: Changing state for SIP/5149271234 - state 1 (Not in use)
[2011-03-15 18:22:13] DEBUG[24975] devicestate.c: device ‘SIP/5149271234’ state ‘1’
[2011-03-15 18:22:13] DEBUG[24999] app_queue.c: Device ‘SIP/5149271234’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND5149271234
[2011-03-15 18:22:13] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:22:13] DEBUG[24976] db.c: Unable to find key ‘DND5149271234’ in family ‘CustomDevstate’
[2011-03-15 18:22:14] DEBUG[21751] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2011-03-15 18:22:14] DEBUG[21751] chan_sip.c: Stopping retransmission on ‘2ycc5vlbT5TModS5OeaSv0DjuW2Y3Cd8’ of Response 25096: Match Not Found
[2011-03-15 18:22:19] DEBUG[25203] manager.c: Manager received command ‘login’
[2011-03-15 18:22:19] VERBOSE[25203] manager.c: == Manager ‘admin’ logged on from 127.0.0.1
[2011-03-15 18:22:20] DEBUG[25203] manager.c: Manager received command ‘Command’
[2011-03-15 18:22:28] VERBOSE[25239] manager.c: == Manager ‘admin’ logged off from 127.0.0.1
[2011-03-15 18:22:29] DEBUG[17975] acl.c: Found IP address for this socket
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Target address 74.198.164.254 is not local, substituting externip
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 60.30.180.84:5060
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Allocating new SIP dialog for [email protected]:54009 - REGISTER (No RTP)
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto TCP socket destined for 74.198.164.254:41519
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TCP socket destined for 74.198.164.254:41519
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto TCP socket destined for 74.198.164.254:41519
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Store REGISTER’s src-IP:port for call routing.
[2011-03-15 18:22:29] DEBUG[17975] chan_sip.c: Trying to put ‘SIP/2.0 200’ onto TCP socket destined for 74.198.164.254:41519
[2011-03-15 18:22:29] DEBUG[24975] devicestate.c: No provider found, checking channel drivers for SIP - 5142618357
[2011-03-15 18:22:29] DEBUG[24975] chan_sip.c: Checking device state for peer 5142618357
[2011-03-15 18:22:29] DEBUG[24975] devicestate.c: Changing state for SIP/5142618357 - state 1 (Not in use)
[2011-03-15 18:22:29] DEBUG[24975] devicestate.c: device ‘SIP/5142618357’ state ‘1’
[2011-03-15 18:22:29] DEBUG[24976] devicestate.c: Checking if I can find provider for “Custom” - number: DND5142618357
[2011-03-15 18:22:29] DEBUG[24976] devicestate.c: Checking provider Custom with Custom
[2011-03-15 18:22:29] DEBUG[24976] db.c: Unable to find key ‘DND5142618357’ in family ‘CustomDevstate’
[2011-03-15 18:22:29] DEBUG[24999] app_queue.c: Device ‘SIP/5142618357’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2011-03-15 18:22:33] DEBUG[24984] chan_iax2.c: ip callno count decremented to 1 for 74.59.232.77
[2011-03-15 18:22:33] DEBUG[24994] chan_iax2.c: ip callno count incremented to 2 for 74.59.232.77
[2011-03-15 18:22:33] DEBUG[24989] chan_iax2.c: schedule decrement of callno used for 74.59.232.77 in 60 seconds
[2011-03-15 18:22:33] DEBUG[24989] chan_iax2.c: Peer 3334602: got pong, lastms 64, historicms 64, maxms 2000
[2011-03-15 18:22:34] DEBUG[25265] manager.c: Manager received command ‘login’
[2011-03-15 18:22:34] VERBOSE[25265] manager.c: == Manager ‘admin’ logged on from 127.0.0.1
[2011-03-15 18:22:34] DEBUG[25265] manager.c: Manager received command ‘Command’

mickecarlsson · March 1, 2011, 5:39am

There could be a ton of reasons, the easiest way to see what’s going on is to set verbose and debug to 5, then let some calls into the system. Then set back verbose to 3 and debug to 0 and check the logs in /var(log/asterisk/full.