Registration problem: failed to query Kazoo for authentication credentials

[Alexander Mustafin]

Hello.

I've this problem on two different clusters: kazoo-R15B-3.19-53 and kazoo-R15B-3.20-2(fresh install). Devices can't register on kazoo, time to time. I've tried to debug this problem, and I'm sure that it'd related with RabbitMQ.

I have the next errors in logs:

kamailio.log

May 11 14:53:56 sip kamailio[1269]: INFO: <script>: 1034611299@192_168_68_101|log|failed to query Kazoo for authentication credentials for user_...@sip.example.com 84.84.84.84:14094

rabbitmq.log

=ERROR REPORT==== 11-May-2015::14:45:50 ===

connection <0.30980.3>, channel 624 - soft error:

{amqp_error,precondition_failed,

            "queue 'whistl...@sip.example.com-<0.27019.3>-648b53d9' in vhost '/' in use",

            'queue.delete'}

I have no errors in 2600hz-platform.log an others.

I am use only one RabbitMQ server on localhost.

[James Aimonetti]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

The PID in the queue name, "0.27019.3", try grepping for that in
/var/log/2600hz/kazoo.log

That is the process in the whistle_apps VM that "owns" the queue on
RabbitMQ; when the process dies, the queue is deleted from the broker.
Could be a clue as to what is happening!

- --
James Aimonetti
Lead Systems Architect / Impressionable Scallywag
"I thought I fixed that"

2600Hz | http://2600hz.com
sip:ja...@2600hz.com
tel:415.886.7905
irc:mc_ @ freenode
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQEcBAEBCAAGBQJVUMnZAAoJENTKa+JPXCVgv1oH/15dJigEtpHkQpBO1SUOqGli
uvUpxGnx9oPTWbaEZAdSP4L3wGs9tozkI2JStGxGmXAwshpbA1226JduzaMUbr4M
mGbTQXRRpVGNO75d5QlwnjCl6Wu4qJbrPcaJ68uJpYSMWISfVyA8PzVFSra2FzXl
I9MJ5DOOybokXroEbodqS0O9pw+e+uJPqgtcE9pv9zr//3eAGKcChG+B7vC1c8sn
5+I7gFRdUghMcvM0Dmf7Zel0E81zWb7nwhkp+9mt2TaPBtBVxO71jAfXhgt9N97r
3r4guVsgFNWOx1fZf74vieXYQUiMZf2jSrbphJo9KFleTmmUyO20+0wxcg83UjQ=
=10DJ
-----END PGP SIGNATURE-----

[Alexander Mustafin]

Thank you, James. 

Unfortunately, today registration errors still persists, but rabbitmq errors not.

I have tried to listen rabbitmq port 5672, but it dumps so many messages and debug it unreal. Kamailio log also not answer what's going on. 

May 12 04:23:53 sip kamailio[1271]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)

May 12 04:23:53 sip kamailio[1271]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)

May 12 04:23:53 sip kamailio[1271]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)

May 12 04:23:53 sip kamailio[1271]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)

May 12 04:23:53 sip kamailio[1271]: DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up

May 12 04:23:53 sip kamailio[1281]: INFO: <script>: 3333151432@192_168_0_100|log|failed to query Kazoo for authentication credentials for user_...@pbx.example.com 80.80.80.80:5060

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [auth_mod.c:766]: pv_auth_check(): realm [pbx.example.com] flags [0] checks [0]

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [api.c:96]: pre_auth(): auth: digest-algo:  parsed value: 0

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [auth_mod.c:522]: pv_authenticate(): HA1 string calculated: ba7a0239032f93372c95abba758fd78f

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [api.c:211]: auth_check_response(): check_response: Our result = '20c9cee9733e84b6e23354f660a974bb'

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [api.c:221]: auth_check_response(): check_response: Authorization failed

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [challenge.c:127]: get_challenge_hf(): build_challenge_hf: realm='pbx.example.com'

May 12 04:23:53 sip kamailio[1281]: DEBUG: auth [challenge.c:269]: get_challenge_hf(): auth: 'WWW-Authenticate: Digest realm="pbx.example.com", nonce="VVGBhVVRgFmDGDrUbxvijjgVxEul+xaN"#015#012'

May 12 04:23:53 sip kamailio[1281]: DEBUG: sl [sl.c:296]: send_reply(): reply in stateless mode (sl)

May 12 04:23:53 sip kamailio[1281]: INFO: <script>: 3333151432@192_168_0_100|end|issued auth challenge to failed registration attempt for user_...@pbx.example.com 80.80.80.80:5060

[Alexander Mustafin]

I've done dump of RabbitMQ packets exchange on dev server. I see requests from one port, but no responses.

After restart of kz-whistle_apps device registers fine some time, but on the next registration after 360 seconds I have the same problem.

T 2015/05/12 07:50:43.583024 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..L...0.<.(...callmgr authn.req.test%2Epbx2%2Eexample%2Eio..

T 2015/05/12 07:50:43.583042 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..L.....<.............application/json.

T 2015/05/12 07:50:43.583049 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..L....{ "Event-Category": "directory", "Event-Name": "authn_req", "Method": "REGISTER", "Auth-Realm": "test.pbx2.example.com", "Auth-User": "user_ivan", "From": "sip:user...@test.pbx2.example.com;transport=UDP", "To": "sip:user...@test.pbx2.example.com;transport=UDP", "App-Name": "kamailio", "App-Version": "4.2.3", "Node": "kama...@sip.example.com", "Msg-ID": "f31cf770-fc2d-4867-9d76-bd3629116000", "Server-ID": "kama...@sip.example.com-<1206>-targeted-75" }.

T 2015/05/12 07:50:43.583529 127.0.0.1:5672 -> 127.0.0.1:36345 [AP]

......V.<.<.amq.ctag-oJrehKl3lmKMQuYM_74C1Q.......%..callmgr authn.req.test%2Epbx2%2Eexample%2Eio.........<.............application/json........{ "Event-Category": "directory", "Event-Name": "authn_req", "Method": "REGISTER", "Auth-Realm": "test.pbx2.example.com", "Auth-User": "user_ivan", "From": "sip:user...@test.pbx2.example.com;transport=UDP", "To": "sip:user...@test.pbx2.example.com;transport=UDP", "App-Name": "kamailio", "App-Version": "4.2.3", "Node": "kama...@sip.example.com", "Msg-ID": "f31cf770-fc2d-4867-9d76-bd3629116000", "Server-ID": "kama...@sip.example.com-<1206>-targeted-75" }.

T 2015/05/12 07:50:43.583566 127.0.0.1:5672 -> 127.0.0.1:36345 [AP]

......V.<.<.amq.ctag-jkiai7NYrAC0PWUINUpD0Q.......%..callmgr authn.req.test%2Epbx2%2Eexample%2Eio.........<.............application/json........{ "Event-Category": "directory", "Event-Name": "authn_req", "Method": "REGISTER", "Auth-Realm": "test.pbx2.example.com", "Auth-User": "user_ivan", "From": "sip:user...@test.pbx2.example.com;transport=UDP", "To": "sip:user...@test.pbx2.example.com;transport=UDP", "App-Name": "kamailio", "App-Version": "4.2.3", "Node": "kama...@sip.example.com", "Msg-ID": "f31cf770-fc2d-4867-9d76-bd3629116000", "Server-ID": "kama...@sip.example.com-<1206>-targeted-75" }.

T 2015/05/12 07:50:45.834849 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..M...0.<.(...callmgr authn.req.test%2Epbx2%2Eexample%2Eio..

T 2015/05/12 07:50:45.834865 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..M.....<.............application/json.

T 2015/05/12 07:50:45.834872 127.0.0.1:55188 -> 127.0.0.1:5672 [AP]

..M....{ "Event-Category": "directory", "Event-Name": "authn_req", "Method": "REGISTER", "Auth-Realm": "test.pbx2.example.com", "Auth-User": "user_ivan", "From": "sip:user...@test.pbx2.example.com;transport=UDP", "To": "sip:user...@test.pbx2.example.com;transport=UDP", "App-Name": "kamailio", "App-Version": "4.2.3", "Node": "kama...@sip.example.com", "Msg-ID": "1e59143e-4e78-4cdc-a301-020740943997", "Server-ID": "kama...@sip.example.com-<1206>-targeted-76" }.

[James Aimonetti]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

I'm fairly certain RabbitMQ is not the issue.

The basic flow, minus caching, of a registration is:

Device --[REGISTER]--> Kamailio
Kamailio --[AMQP authn_req]--> RabbitMQ
RabbitMQ --[AMQP authn_req]--> Registrar
Registrar --[HTTP cred lookup]--> BigCouch

This flow then unwinds returning the creds (if found) to Kamailio.

So, you'll need to follow the request through (using the
call-id/msg-id) to see where the request failed. But grepping the
Kamailio and Kazoo logs with the call-id of the REGISTER is a good
place to start.

- --
James Aimonetti
Lead Systems Architect / Impressionable Scallywag
"I thought I fixed that"

2600Hz | http://2600hz.com
sip:ja...@2600hz.com
tel:415.886.7905
irc:mc_ @ freenode
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQEcBAEBCAAGBQJVUhonAAoJENTKa+JPXCVggXgIAJadf73bDKJJhi0xCPGAMKvp
a1j7AIfdF0+5EtYlnrx8nwDeihVblsB5++bnR0yYoDLL2YPyZzCEvqnKyglj45nQ
yiTuVaY4Vs47cpDHF/j9NmXeMAwfDiUx0mE+8nRPIonSVERYvq8N7R0y7J62kt1q
qAu+iXBQXhgbTchEkX0xjJ7iX0ppz6RGlFg63RsODq82XpWYYJdhRoK34tr4FbOg
kzwkGJX3Gl58hh6abVozRcfG+ZB+PEdXTL8RCaALPjxnWfiHwTDvATP9J1/3BNAT
W4iOSiplAL/jQhXo2/L0w7J1uWz+veXKN06tmhyCv6sT6dItK0E8BK5LbOIntyk=
=hyle
-----END PGP SIGNATURE-----

[Alexander Mustafin]

Yep, you absolutely right. My problem related with kamailio and registrar app, as I understand. 

First of all:

sip:~$ sudo service kz-whistle_apps status

Node          : whistl...@sip.example.com

Version       : R15B03

Memory Usage  : 55.88MB

Processes     : 1795

Ports         : 39

Zone          : local

Broker        : amqp://guest:gu...@127.0.0.1:5672

WhApps        : callflow            cdr                 conference          crossbar

                fax                 hangups             media_mgr           milliwatt

                notify              omnipresence        pivot               registrar

                reorder             stepswitch          sysconf             trunkstore

Node          : ecal...@sip.example.com

Version       : R15B03

Memory Usage  : 27.52MB

Processes     : 1016

Ports         : 49

Zone          : local

Broker        : amqp://guest:gu...@127.0.0.1:5672

WhApps        : ecallmgr

Channels      : 2

Registrations : 97

Media Servers : frees...@sip.somegw.net

Node: kama...@sip.example.com is absent. But it running, and after kamailio restart, all works fine some time (this related with 3.19-53 version), maybe while it run. I will try to monitore behaviour of registrar app.

But why I can't see kamailio app in apps list at this moment?

вторник, 12 мая 2015 г., 20:20:09 UTC+5 пользователь James Aimonetti написал:

[Joshua Laroff]

--
You received this message because you are subscribed to the Google Groups "2600hz-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-dev+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[VCCS Telecom]

I am experiencing the same issue, I'm guessing it appeared with the latest kamailio. It is with Kam though not being able to connect to the Kazoo db. You should see something like this in the kamailio log:

May 13 05:45:24 yoda kamailio[2740]: ERROR: db_text [dbt_base.c:207]: dbt_query(): table presentity not loaded! (too few columns)

May 13 05:45:24 yoda kamailio[2740]: ERROR: db_text [dbt_base.c:306]: dbt_query(): failed to query the table!

May 13 05:45:24 yoda kamailio[2740]: ERROR: <core> [db_query.c:441]: db_fetch_query_internal(): unable to do full db querry

May 13 05:45:24 yoda kamailio[2740]: ERROR: presence [publish.c:108]: msg_presentity_clean(): failed to query database for expired messages

May 13 05:45:24 yoda kamailio[2740]: ERROR: db_text [dbt_res.c:186]: dbt_get_refs(): column <expires> not found

May 13 05:45:24 yoda kamailio[2740]: ERROR: db_text [dbt_base.c:538]: dbt_delete(): failed to delete from table!

May 13 05:45:24 yoda kamailio[2740]: ERROR: presence [publish.c:227]: msg_presentity_clean(): failed to delete expired records from DB

I just searched this up looking for help after I've tried for a while, so I'll keep at it and see what I can do.. 

[VCCS Telecom]

Scratch that, I didnt realize it wasnt Kamailio that was updated recently, how ever I think configs were. I rolled back and was able to resolve the problem, although the database errors still show in the Kamailio log with the system now up to date. Check your permissions in kamailio and change them to kamailio:daemon where as now it may be root:root or kamailio:kamailio. Alternatively check that the whapps service is in fact loaded without errors.

Curious to know if this works for you.

Matt

On Monday, May 11, 2015 at 11:07:45 AM UTC-4, Alexander Mustafin wrote:

[Luis Azedo]

Hi,

if you get "dbt_query(): table presentity not loaded! (too few
columns)" it means your presentity table is out of sync.
stop kamailio, get the updated presentity table in place and start
kamailio. also check the versions table is updated.

[VCCS Telecom]

Thanks Luis, im checking into that. It may be the db is not loading also, or that issue is preventing it from loading. Once Kamailio starts I do see INFO: db_text [dbt_base.c:99]: dbt_init(): using database at: /etc/kazoo/kamailio/dbtext

Then im seeing no db loaded: 

kamctl db show /etc/kazoo/kamailio/dbtext

which: no gdb in (/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin:/)

ERROR: This command requires a database engine - none was loaded

I was able to fix gdb with a yum install gdb , so far I cant see how to update the database. Will check some more and post back.

[Luis Azedo]

Hi,

for "kamctl db" to work, you need a kamctlrc file in
/etc/kazoo/kamailio or ~/.kamctlrc file
also, remember that dbtext doesn't immediately write to disk, it does
this only on exit. you can however issue the command "kamcmd
db_text.dump" to force the write at any time.
so, between "kamctl db" commands to query tables, if you want more
updated data you need to run the kamcmd command.

for registrar related tables, you may also want to change db_mode=1 in
registrar-role.cfg (db_mode=0) is memory only.

the INFO messages are ok and expected.

[Luis Azedo]

sample kamctlrc to put in /etc/kazoo/kamailio
if it doesn't work, try put it as ~/.kamctlrc (note the dot)

hope this helps

[VCCS Telecom]

Thanks again for your help Luis,

I tried the db_mode=0 as well as presence.cleanup but hasn't had any affect. I do have to leave Kamailio running in order to access kamctl. Do you know if I delete htables if the will be re-built? Also can you confirm please if permissions on both kamailio folders should be kamailio:kamailio or kamailio:daemon?

Worst case I will try a re-install of kam after this to see if it corrects itself or not. Thx

On Monday, May 11, 2015 at 11:07:45 AM UTC-4, Alexander Mustafin wrote:

[Luis Azedo]

i would install/reinstall kazoo-kamailio and kazoo-configs making sure
there are no .rpmnew
as for permissions, i believe its kamailio:kamailio but that can be
overriden in /etc/default/kamailio or /etc/sysconfig/kamailio (centos)

[Alexander Mustafin]

I've tried to reinstall configs, tried to change permissions. But still need ti restart kz-whistle_apps for normal work.

четверг, 14 мая 2015 г., 4:43:16 UTC+5 пользователь Luis Azedo написал:

[2000hz-dev]

i met same issue on debian. what could be a cause?

[David]

Hi,

did you solved this problem. Having the same problem here with debian. Did an upgrade to 3.20.66. Tried all the advise from above, but still not luck. We started debugging the erlang code.

[Matt - nurango (VCCS)]

Hi David, these messages still appear but they are not service affecting and are "normal". How ever if you are having issues with devices actually registering that is a problem. I have seen that with improper setup with nodes where they arent communicating registrations with each-other and act separately. 

On Monday, May 11, 2015 at 11:07:45 AM UTC-4, Alexander Mustafin wrote:

[David]

Hey Matt,

Thanks for answering. The registration problems effected our system. Also we had performance problems with inbound and outbound calls. Finally the problem was due to slow ioops from our mail bigcouch cluster. we switched to a new system based on SSDs and all problem were solved.

Thanks for helping.

Happy Christmas and a happy new year.

Best regards from Germany.

David