asterisk users - Oct 2010 - Intermittent failure when placing calls - unable to create channel of type SIP

Hello community,

I've been running Asterisk on an embedded device for about six months, and
my operation has been largely trouble-free. I'm hoping I could get some help
with a minor problem:

Every week or three, my PBX gets stuck in a state where it can receive
calls, but it becomes completely unable to originate outgoing calls until I
do a "sip reload". After doing the SIP reload, everything immediately
begins
works perfectly again and I can make outgoing calls until it gets stuck
again several weeks later.

I recently upgraded to Asterisk 1.6.2.13, although I was also running
1.6.2.1 for a long time with identical symptoms. My system is an embedded
ar71xx running the OpenWRT distribution.

When I attempt to place a call, after Asterisk has transmitted the "100
Trying" message to the calling extension (an ATA), I see the following
"Unable to create channel of type SIP" message in the log:

[Oct 27 18:46:48] DEBUG[25028]: pbx.c:3696 pbx_extension_helper: Launching
'Set'
[Oct 27 18:46:48] DEBUG[25028]: pbx.c:3696 pbx_extension_helper: Launching
'Dial'
[Oct 27 18:46:48] DEBUG[25028]: chan_sip.c:23241 sip_request_call: Asked to
create a SIP channel with formats: 0x4 (ulaw)
[Oct 27 18:46:48] DEBUG[25028]: chan_sip.c:7381 sip_alloc: Allocating new
SIP dialog for 2ccf324d10670f2c73f478b523f926a4 at 10.15.1.1 - INVITE (With
RTP)
Really destroying SIP dialog '2ccf324d10670f2c73f478b523f926a4 at
10.15.1.1'
Method: INVITE
[Oct 27 18:46:48] WARNING[25028]: app_dial.c:1750 dial_exec_full: Unable to
create channel of type 'SIP' (cause 20 - Unknown)
[Oct 27 18:46:48] DEBUG[25028]: rtp.c:2148 ast_rtp_early_bridge: Channel
'<unspecified>' has no RTP, not doing anything
[Oct 27 18:46:48] DEBUG[25028]: app_dial.c:2326 dial_exec_full: Exiting with
DIALSTATUS=CHANUNAVAIL.
[Oct 27 18:46:48] DEBUG[25028]: pbx.c:3696 pbx_extension_helper: Launching
'Hangup'
[Oct 27 18:46:48] DEBUG[25028]: pbx.c:4322 __ast_pbx_run: Spawn extension
(phones,15102857673,3) exited non-zero on 'SIP/101-0000000a'
[Oct 27 18:46:48] DEBUG[25028]: channel.c:1715 ast_softhangup_nolock:
Soft-Hanging up channel 'SIP/101-0000000a'

The calling extension then receives a "480 Temporarily Unavailable"
and a
fast busy.

Doing a "sip show peers" appears normal. When I do a detailed
"sip show
mypeername", the one anomalous thing I see is that that the
"Addr->IP"
setting is listed as "(Unspecified)".

 * Name       : voipms
  Secret       : <Set>
[...]
  ToHost       : dallas.voip.ms
  Addr->IP     : (Unspecified) Port 5060
  Defaddr->IP  : 0.0.0.0 Port 5060
  Prim.Transp. : UDP
  Allowed.Trsp : UDP
[...]

In contrast, after I do a "sip reload", outbound calls start working
again
and the "sip show" output looks identical except for showing the
correct
address under "Addr->IP":

* Name       : voipms
  Secret       : <Set>
[...]
  ToHost       : dallas.voip.ms
  Addr->IP     : 74.54.54.178 Port 5060
  Defaddr->IP  : 0.0.0.0 Port 5060
  Prim.Transp. : UDP
  Allowed.Trsp : UDP
[...]

Does anyone know how/where/why Asterisk could lose the IP address of the
peer?

One thing potentially related is that, in the previous registration to the
peer (two minutes prior to my failed call), we do the usual
REGISTER/Unauthorized+Nonce/REGISTER+Response/OK business. Immediately after
that, we get a NOTIFY from the remote, which Asterisk responds to with a 489
Bad Event:

NOTIFY sip:s at my.ip.add.ress:6010 SIP/2.0
Via: SIP/2.0/UDP 74.54.54.178:5060;branch=z9hG4bK008e70db;rport
From: "Unknown" <sip:Unknown at 74.54.54.178 <sip%3AUnknown at
74.54.54.178>
>;tag=as5c60da37
To: <sip:s at my.ip.add.ress:6010>
Contact: <sip:Unknown at 74.54.54.178 <sip%3AUnknown at
74.54.54.178>>
Call-ID: 266322e108872eab12fb307772a4af79 at 74.54.54.178
CSeq: 102 NOTIFY
User-Agent: VoIPMS SERAST
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 92

Messages-Waiting: no
Message-Account: sip:asterisk at 74.54.54.178 <sip%3Aasterisk at
74.54.54.178>
Voice-Message: 0/0 (0/0)

SIP/2.0 489 Bad event
Via: SIP/2.0/UDP 74.54.54.178:5060
;branch=z9hG4bK008e70db;received=74.54.54.178;rport=5060
From: "Unknown" <sip:Unknown at 74.54.54.178 <sip%3AUnknown at
74.54.54.178>
>;tag=as5c60da37
To: <sip:s at my.ip.add.ress:6010>;tag=as4b162a1c
Call-ID: 266322e108872eab12fb307772a4af79 at 74.54.54.178
CSeq: 102 NOTIFY
Server: Asterisk PBX 1.6.2.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

Immediately after that exchange, I see the following curious set of
messages:

[Oct 27 18:44:58] DEBUG[1676]: chan_sip.c:3608 __sip_xmit: Trying to put
'SIP/2.0 489' onto UDP socket destined for 74.54.54.178:5060
[Oct 27 18:44:58] DEBUG[1676]: chan_sip.c:22105 handle_request_do: Invalid
SIP message - rejected , no callid, len 541

Could those messages be related to my problem? I see this "489 Bad
Event"
issue may be related to https://issues.asterisk.org/view.php?id=17379, but
it's unclear if this can somehow cause the SIP remote peer address to get
lost, as opposed to just being potentially bad manners with our SIP peer.

Lastly, in case it matters, the general and peer-specific sections of my
sip.conf are as follows:

[general]
dtmfmode = rfc2833
context=from-voipms
srvlookup=yes
register => myuserid:mypass at dallas.voip.ms:5060~600
session-timers=refuse
session-expires=3600
session-minse=600
session-refresher=uas
localnet=192.168.0.0/255.255.0.0
localnet=10.0.0.0/255.0.0.0
localnet=172.16.0.0/12
localnet=169.254.0.0/255.255.0.0
stunaddr=stun01.sipphone.com
allow=ulaw
allow=gsm

[voipms]
canreinvite=yes
context=from-voipms
host=dallas.voip.ms
secret=mypass
type=friend
username=myuserid
disallow=all
allow=gsm
fromuser=myuserid
trustrpid=yes
sendrpid=yes
insecure=port,invite

I have complete logs and SIP debugging from the time that I discovered the
latest incarnation of this problem, which I would be happy to provide...but
since I don't dial out much, that logging presumably begins long past
whatever point in time it was that the problem was triggered. My embedded
device also has limited storage, so it would be difficult (but not
impossible!) to run on full-debug logging for long periods of time.

Any advice or pointers would be appreciated!

Scott
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
http://lists.digium.com/pipermail/asterisk-users/attachments/20101027/c797d662/attachment.htm