Re: [Freeswitch-users] Registration problem after attempting to install mod_opal and updating to latest git pull

10 Feb 2012

      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=50
80
   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=50
80
   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=50
80
   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=50
80
   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-0
000-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:qs
ystemseng.mydomain.org:5060",response="48feb96d103538b600c37e6bef966799",alg
orithm=MD5,qop=auth,cnonce="xxxxxxxx",nc=00000004
   Contact: "Tina"
<sip:257@74.93.xx.xx:1060;transport=udp>;+sip.instance="<urn:uuid:00000000-0
000-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:qs
ystemseng.mydomain.org:5060",response="05a8d65372aef7cbd3d7968ba5844fa8",alg
orithm=MD5,qop=auth,cnonce="xxxxxxxx",nc=00000003
   Contact: "Laura"
<sip:227@74.93.xx.xx:1064;transport=udp>;+sip.instance="<urn:uuid:00000000-0
000-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
http://www.qsystemsengineering.com