Ok, here's part of the sip trace as requested. I won't have time to sanitize the whole thing until later but in the meantime, here's an interesting excerpt that I wanted to make a few comments on:
First, notice the "Unauthorized" response to the first registration attempt but the next attempt is successful. This has actually been going on as long as I can remember with this particular provider.
------------------------------------------------------------------------
2012-02-10 12:14:32.174952 [WARNING] sofia.c:4717 Unregister HL7611
2012-02-10 12:14:32.174952 [WARNING] sofia.c:4730 Ping failed HL7611 with code 900 - count -1/-1/1, state UP
send 854 bytes to udp/[140.239.143.5]:5060 at 17:14:33.595032:
------------------------------------------------------------------------
REGISTER sip:sip16.vitelity.net;transport=udp SIP/2.0
Via: SIP/2.0/UDP 71.179.xx.xx:5080;rport;branch=z9hG4bK7857r78Xt8pKg
Max-Forwards: 70
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054543 REGISTER
Contact: <sip:gw+HL7611@71.179.xx.xx:5080;transport=udp;gw=HL7611>
Expires: 120
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
Authorization: Digest username="thisis7611", realm="asterisk", nonce="xxxxxxxx", algorithm=MD5, uri="sip:sip16.vitelity.net;transport=udp", response="d7ecbd5585a7bef456be36b8e5fe0b8e"
Content-Length: 0
------------------------------------------------------------------------
recv 463 bytes from udp/[140.239.143.5]:5060 at 17:14:33.656879:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 71.179.xx.xx:5080;branch=z9hG4bK7857r78Xt8pKg;received=71.179.xx.xx;rport=5080
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054543 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0
------------------------------------------------------------------------
recv 560 bytes from udp/[140.239.143.5]:5060 at 17:14:33.656961:
------------------------------------------------------------------------
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 71.179.xx.xx:5080;branch=z9hG4bK7857r78Xt8pKg;received=71.179.xx.xx;rport=5080
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=as117f4b90
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054543 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="xxxxxxxx"
Content-Length: 0
------------------------------------------------------------------------
send 854 bytes to udp/[140.239.143.5]:5060 at 17:14:33.657072:
------------------------------------------------------------------------
REGISTER sip:sip16.vitelity.net;transport=udp SIP/2.0
Via: SIP/2.0/UDP 71.179.xx.xx:5080;rport;branch=z9hG4bK8HZ0t2S1QHD6B
Max-Forwards: 70
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054544 REGISTER
Contact: <sip:gw+HL7611@71.179.xx.xx:5080;transport=udp;gw=HL7611>
Expires: 120
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
Authorization: Digest username="thisis7611", realm="asterisk", nonce="xxxxxxxx", algorithm=MD5, uri="sip:sip16.vitelity.net;transport=udp", response="d82a35caa676c34e817dd63a658d34ac"
Content-Length: 0
------------------------------------------------------------------------
recv 463 bytes from udp/[140.239.143.5]:5060 at 17:14:33.719551:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 71.179.xx.xx:5080;branch=z9hG4bK8HZ0t2S1QHD6B;received=71.179.xx.xx;rport=5080
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054544 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0
------------------------------------------------------------------------
recv 604 bytes from udp/[140.239.143.5]:5060 at 17:14:33.721743:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 71.179.xx.xx:5080;branch=z9hG4bK8HZ0t2S1QHD6B;received=71.179.xx.xx;rport=5080
From: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=D0jHcrrtFjtym
To: <sip:thisis7611@sip16.vitelity.net;transport=udp>;tag=as117f4b90
Call-ID: 04cac6f5-9608-4019-9658-6c0e6d1fd7af
CSeq: 24054544 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Expires: 60
Contact: <sip:gw+HL7611@71.179.xx.xx:5080;transport=udp;gw=HL7611>;expires=60
Date: Fri, 10 Feb 2012 17:14:33 GMT
Content-Length: 0
Next, what's with the "Bad event", the time discrepancy, and "sip:ping@invalid" in the following exchange?
------------------------------------------------------------------------
recv 683 bytes from udp/[192.168.1.4]:5060 at 19:33:11.486617:
------------------------------------------------------------------------
SUBSCRIBE sip:102@192.168.1.6:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.4;branch=z9hG4bKfe095021fa5ec8e60;rport
Route: <sip:192.168.1.6:5060;lr>
Max-Forwards: 70
From: "Phil" <sip:102@192.168.1.6:5060>;tag=a4efbafcef
To: <sip:102@192.168.1.6:5060>
Call-ID: 17f321dbe885cc25
CSeq: 24812 SUBSCRIBE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
Allow-Events: talk, hold, conference, LocalModeStatus
Contact: "Phil" <sip:102@192.168.1.4:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-1000-8000-00085D296BF3>"
Event: as-feature-event
Expires: 3600
Supported: path
User-Agent: Aastra 9480i/3.2.2.1136
Content-Length: 0
------------------------------------------------------------------------
send 653 bytes to udp/[192.168.1.4]:5060 at 19:33:11.486724:
------------------------------------------------------------------------
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 192.168.1.4;branch=z9hG4bKfe095021fa5ec8e60;rport=5060
From: "Phil" <sip:102@192.168.1.6:5060>;tag=a4efbafcef
To: <sip:102@192.168.1.6:5060>;tag=gS042N7B17j3j
Call-ID: 17f321dbe885cc25
CSeq: 24812 SUBSCRIBE
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
recv 958 bytes from udp/[74.93.xx.xx]:1060 at 19:33:11.837860:
------------------------------------------------------------------------
REGISTER sip:qsystemseng.mydomain.org:5060 SIP/2.0
Via: SIP/2.0/UDP 74.93.xx.xx:51660;branch=z9hG4bKaaab13558da89266a;rport
Route: <sip:qsystemseng.mydomain.org:5060;lr>
Max-Forwards: 70
From: "Tina" <sip:257@qsystemseng.mydomain.org:5060>;tag=5dfb41956c
To: "Tina" <sip:257@qsystemseng.mydomain.org:5060>
Call-ID: 69748b87cb4b8d1d
CSeq: 35981 REGISTER
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
Allow-Events: talk, hold, conference, LocalModeStatus
Authorization: Digest username="257",realm="qsystemseng.mydomain.org",nonce="xxxxxxxx",uri="sip:qsystemseng.mydomain.org:5060",response="48feb96d103538b600c37e6bef966799",algorithm=MD5,qop=auth,cnonce="xxxxxxxx",nc=00000004
Contact: "Tina" <sip:257@74.93.xx.xx:1060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-1000-8000-00085D26F8E9>";expires=90
Supported: path, gruu
User-Agent: Aastra 9143i/3.2.2.1136
Content-Length: 0
------------------------------------------------------------------------
send 640 bytes to udp/[74.93.xx.xx]:1060 at 19:33:11.839412:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 74.93.xx.xx:51660;branch=z9hG4bKaaab13558da89266a;rport=1060
From: "Tina" <sip:257@qsystemseng.mydomain.org:5060>;tag=5dfb41956c
To: "Tina" <sip:257@qsystemseng.mydomain.org:5060>;tag=H2SX4grFyg9Ne
Call-ID: 69748b87cb4b8d1d
CSeq: 35981 REGISTER
Contact: <sip:257@74.93.xx.xx:1060;transport=udp>;expires=90
Date: Fri, 10 Feb 2012 19:33:11 GMT
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Content-Length: 0
------------------------------------------------------------------------
2012-02-10 14:33:12.381474 [WARNING] sofia.c:4717 Unregister HL7611
2012-02-10 14:33:12.381474 [WARNING] sofia.c:4730 Ping failed HL7611 with code 900 - count -1/-1/1, state UP
2012-02-10 14:33:13.389496 [WARNING] sofia_reg.c:474 HL7611 Failed Registration [0], setting retry to 90 seconds.
recv 917 bytes from udp/[74.93.xx.xx]:1064 at 19:33:13.465516:
------------------------------------------------------------------------
REGISTER sip:qsystemseng.mydomain.org:5060 SIP/2.0
Via: SIP/2.0/UDP 74.93.xx.xx:51620;branch=z9hG4bKc6b28c84c8b2a8b8e;rport
Max-Forwards: 70
From: "Laura" <sip:227@qsystemseng.mydomain.org:5060>;tag=87516cda24
To: "Laura" <sip:227@qsystemseng.mydomain.org:5060>
Call-ID: 09856e1e62e97740
CSeq: 27466 REGISTER
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
Allow-Events: talk, hold, conference, LocalModeStatus
Authorization: Digest username="227",realm="qsystemseng.mydomain.org",nonce="xxxxxxxx",uri="sip:qsystemseng.mydomain.org:5060",response="05a8d65372aef7cbd3d7968ba5844fa8",algorithm=MD5,qop=auth,cnonce="xxxxxxxx",nc=00000003
Contact: "Laura" <sip:227@74.93.xx.xx:1064;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-1000-8000-00085D223D29>";expires=90
Supported: path, gruu
User-Agent: Aastra 9143i/3.2.2.1136
Content-Length: 0
------------------------------------------------------------------------
send 642 bytes to udp/[74.93.xx.xx]:1064 at 19:33:13.467000:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 74.93.xx.xx:51620;branch=z9hG4bKc6b28c84c8b2a8b8e;rport=1064
From: "Laura" <sip:227@qsystemseng.mydomain.org:5060>;tag=87516cda24
To: "Laura" <sip:227@qsystemseng.mydomain.org:5060>;tag=jBKp6B9jUSZ8S
Call-ID: 09856e1e62e97740
CSeq: 27466 REGISTER
Contact: <sip:227@74.93.xx.xx:1064;transport=udp>;expires=90
Date: Fri, 10 Feb 2012 19:33:13 GMT
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Content-Length: 0
------------------------------------------------------------------------
recv 450 bytes from udp/[216.115.69.144]:5060 at 19:33:15.332881:
------------------------------------------------------------------------
OPTIONS sip:71.179.xx.xx:5080 SIP/2.0
Max-Forwards: 10
Record-Route: <sip:216.115.69.144;lr>
Via: SIP/2.0/UDP 216.115.69.144;branch=z9hG4bKfc94.cc57baa771388125df1b041bbd688213.0
Via: SIP/2.0/UDP 70.167.153.136:5060;branch=0
Route: <sip:216.115.69.144;lr;received="sip:71.179.xx.xx:5080">
From: sip:ping@invalid;tag=6c8e4582
To: sip:71.179.xx.xx:5080
Call-ID: aa72439-f0144116-cf3b885@70.167.153.136
CSeq: 1 OPTIONS
Content-Length: 0
------------------------------------------------------------------------
send 670 bytes to udp/[216.115.69.144]:5060 at 19:33:15.333175:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.115.69.144;branch=z9hG4bKfc94.cc57baa771388125df1b041bbd688213.0
Via: SIP/2.0/UDP 70.167.153.136:5060;branch=0
From: sip:ping@invalid;tag=6c8e4582
To: <sip:71.179.xx.xx:5080>;tag=21ecKKFFNK3cj
Call-ID: aa72439-f0144116-cf3b885@70.167.153.136
CSeq: 1 OPTIONS
Contact: <sip:thisis7612@71.179.xx.xx:5080;transport=udp;gw=HL7612>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-4c07a00 2012-02-08 16-52-13 -0600
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, refer
Content-Length: 0
Interestingly, I can't reproduce the SIPBroker problem after the last update, even though I re-enabled ping. Ping is not necessary with SIPBroker as it's only for outgoing calls and you don't need to register with them.
I'll try to sanitize and post a complete trace here later tonight.
Thanks again,
- Phil
-----Original Message-----
From: Phil Quesinberry [mailto:philq@qsystemsengineering.com]
Sent: Thursday, February 09, 2012 12:51 AM
To: 'freeswitch-users@lists.freeswitch.org'
Subject: Registration problem after attempting to install mod_opal and updating to latest git pull
After a recent unsuccessful attempt to install mod_opal and updating to a recent git, I now get some odd reports of gateway registration failures, although everything appears to be working ok call-wise for the moment. Doing a ‘make uninstall’ from /root/opal and updating to the latest git tonight yielded no improvement.
Here are some excerpts of failures reported in fs_cli:
2012-02-09 00:12:59.992099 [WARNING] sofia.c:4717 Unregister QS8002
2012-02-09 00:12:59.992099 [WARNING] sofia.c:4730 Ping failed QS8002 with code 900 - count -1/-1/1, state UP
2012-02-09 00:12:59.992099 [WARNING] sofia.c:4717 Unregister HL7612
2012-02-09 00:12:59.992099 [WARNING] sofia.c:4730 Ping failed HL7612 with code 900 - count -1/-1/1, state UP
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4717 Unregister HL7611
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4730 Ping failed HL7611 with code 900 - count -1/-1/1, state UP
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4717 Unregister HL7519
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4730 Ping failed HL7519 with code 900 - count -1/-1/1, state UP
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4717 Unregister CallCentric_T.38
2012-02-09 00:13:00.011988 [WARNING] sofia.c:4730 Ping failed CallCentric_T.38 with code 900 - count -1/-1/1, state UP
2012-02-09 00:13:01.992050 [WARNING] sofia_reg.c:474 QS8002 Failed Registration [0], setting retry to 60 seconds.
2012-02-09 00:13:01.992050 [WARNING] sofia_reg.c:474 HL7612 Failed Registration [0], setting retry to 90 seconds.
2012-02-09 00:13:01.992050 [WARNING] sofia_reg.c:474 HL7611 Failed Registration [0], setting retry to 90 seconds.
2012-02-09 00:13:01.992050 [WARNING] sofia_reg.c:474 HL7519 Failed Registration [0], setting retry to 60 seconds.
2012-02-09 00:13:01.992050 [WARNING] sofia_reg.c:474 CallCentric_T.38 Failed Registration [0], setting retry to 60 seconds.
To give a sense of the timing, the three groups of warnings below are contiguous, from a single fs_cli session:
2012-02-09 00:21:18.984384 [WARNING] sofia.c:4717 Unregister HL7611
2012-02-09 00:21:18.984384 [WARNING] sofia.c:4730 Ping failed HL7611 with code 900 - count -1/-1/1, state UP
2012-02-09 00:21:20.988379 [WARNING] sofia_reg.c:474 HL7611 Failed Registration [0], setting retry to 90 seconds.
2012-02-09 00:21:22.988382 [WARNING] sofia.c:4717 Unregister HL7519
2012-02-09 00:21:22.988382 [WARNING] sofia.c:4730 Ping failed HL7519 with code 900 - count -1/-1/1, state UP
2012-02-09 00:21:24.988318 [WARNING] sofia_reg.c:474 HL7519 Failed Registration [0], setting retry to 60 seconds.
2012-02-09 00:22:00.447778 [WARNING] sofia_reg.c:1422 SIP auth challenge (REGISTER) on sofia profile 'internal' for [226@qsystemseng.no-ip.org] from ip 74.93.222.182
2012-02-09 00:22:04.147688 [WARNING] sofia.c:4717 Unregister HL7612
2012-02-09 00:22:04.147688 [WARNING] sofia.c:4730 Ping failed HL7612 with code 900 - count -1/-1/1, state UP
2012-02-09 00:22:04.167699 [WARNING] sofia.c:4717 Unregister HL7611
2012-02-09 00:22:04.167699 [WARNING] sofia.c:4730 Ping failed HL7611 with code 900 - count -1/-1/1, state UP
2012-02-09 00:22:04.167699 [WARNING] sofia.c:4717 Unregister CallCentric_T.38
2012-02-09 00:22:04.167699 [WARNING] sofia.c:4730 Ping failed CallCentric_T.38 with code 900 - count -1/-1/1, state UP
2012-02-09 00:22:05.167744 [WARNING] sofia_reg.c:474 HL7611 Failed Registration [0], setting retry to 90 seconds.
2012-02-09 00:22:05.167744 [WARNING] sofia_reg.c:474 CallCentric_T.38 Failed Registration [0], setting retry to 60 seconds.
2012-02-09 00:22:05.167744 [WARNING] sofia.c:4717 Unregister QS8002
2012-02-09 00:22:05.167744 [WARNING] sofia.c:4730 Ping failed QS8002 with code 900 - count -1/-1/1, state UP
2012-02-09 00:22:07.171680 [WARNING] sofia_reg.c:474 QS8002 Failed Registration [0], setting retry to 60 seconds.
2012-02-09 00:22:07.171680 [WARNING] sofia.c:4717 Unregister HL7519
2012-02-09 00:22:07.171680 [WARNING] sofia.c:4730 Ping failed HL7519 with code 900 - count -1/-1/1, state UP
One of the gateways is SIPBroker, and calls through that gate starting failing after the update. I realized that the gateway was configured to ping SIPBroker unnecessarily and restarting the gateway would restore service until the ping. I disabled the ping for that gateway and calls kept working after that.
Any ideas as to what might be going on? There was no such problem before the FS update/attempt to use mod_opal. I can provide additional/more detailed info if needed.
Thanks!
Phil Quesinberry
Q Systems Engineering, Inc.
Electronic Controls and Embedded Systems Development
(410) 969-8002