By the way ... I forgot to change my real domains in the logs .... "p2b.sip.uniza.sk" is "sip.uniza.sk" and user "katka" is "SIP_client"

2011/4/5 Martin Pohančeník <pohancenik.martin@gmail.com>
These are logged messages from kamailio debug (I hope it is suffieciet .. or not too much text):

"Message SIP -> XMPP worked correctly like this:"
...
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:630]: SIP Request:
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:632]:  method:  <MESSAGE>
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:634]:  uri:     <sip:XMPP_client*xmpp.uniza.sk@sip.uniza.sk>
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:636]:  version: <SIP/2.0>
...
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: xmpp [xmpp.c:381]: cmd_send_message
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: xmpp [xmpp.c:415]: message from <sip:SIP_client@sip.uniza.sk>
Apr  5 09:12:36 server /usr/sbin/kamailio[21200]: DEBUG: xmpp [xmpp.c:424]: using R-URI as destination
Apr  5 09:12:36 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:242]: got pipe cmd 2
Apr  5 09:12:36 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:157]: do_send_message_component from=[sip:SIP_client@sip.uniza.sk] to=[sip:XMPP_client*xmpp.uniza.sk@sip.uniza.sk] body=[ahoj]
Apr  5 09:12:36 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:68]: xode_send [<message id='8c7117b7' from='SIP_client*sip.uniza.sk@xmpp-sip.uniza.sk' to='XMPP_client@xmpp.uniza.sk' type='chat'><body>ahoj</body></message>]
...

"Message SIP -> XMPP does not work properly:"
...
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:235]: server read#012[<message xmlns='jabber:client' type='chat' to='SIP_client*sip.uniza.sk@xmpp-sip.uniza.sk' id='mir_45' from='XMPP_client@xmpp.uniza.sk/Miranda'><body>DOBRY DEN</body></message>]
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:85]: stream callback: 1: message
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: xmpp [xmpp_component.c:102]: XMPP IM received
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: tm [uac.c:240]: DEBUG:tm:t_uac: next_hop=<sip:SIP_client@sip.uniza.sk>
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [dns_cache.c:567]: dns_hash_find(_sip._udp.sip.uniza.sk(26), 33), h=524
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [resolve.c:924]: get_record: skipping 1 NS (p=0x816f57, end=0x816f90)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [resolve.c:940]: get_record: parsing 2 ARs (p=0x816f70, end=0x816f90)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [dns_cache.c:1777]: dns_get_related(0x7ffb6f526770 (_sip._udp.sip.uniza.sk, 33), 33, *0x960ce8) (0)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [dns_cache.c:870]: dns_cache_add: adding _sip._udp.sip.uniza.sk(26) 33 (flags=0) at 524
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [dns_cache.c:870]: dns_cache_add: adding server.sip.uniza.sk(23) 1 (flags=0) at 476
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [dns_cache.c:567]: dns_hash_find(server.sip.uniza.sk(23), 1), h=476
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: tm [uac.c:181]: DEBUG: dlg2hash: 40039
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:630]: SIP Request:
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:632]:  method:  <MESSAGE>
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:634]:  uri:     <sip:SIP_client@sip.uniza.sk>
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:636]:  version: <SIP/2.0>
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK76c9.3ad70364.0>; state=16
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [receive.c:145]: After parse_msg...
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts...
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=9
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [28]; uri=[sip:katka@p2b.sip.uniza.sk]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body [sip:katka@p2b.sip.uniza.sk#015#012]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <10> <MESSAGE>
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=9
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: maxfwd [mf_funcs.c:66]: max_forwards header not found!
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=533cb9e91f4b999cf76861cbb9ed54ed-07b4
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: siputils [checks.c:73]: no totag
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=2 global id=1 T start=0xffffffffffffffff
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=40039, isACK=0
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 16==9 &&  [p2b.sip.uniza.sk] == [127.0.0.1]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 16==14 &&  [p2b.sip.uniza.sk] == [158.193.139.65]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 16==9 &&  [p2b.sip.uniza.sk] == [127.0.0.1]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 16==14 &&  [p2b.sip.uniza.sk] == [158.193.139.65]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: auth_db [authorize.c:239]: realm value [p2b.sip.uniza.sk]
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: auth [api.c:85]: auth:pre_auth: Credentials with realm 'p2b.sip.uniza.sk' not found
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: auth_db [authorize.c:257]: not authenticated
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: auth [challenge.c:102]: build_challenge_hf: realm='p2b.sip.uniza.sk'
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: auth [challenge.c:236]: auth: 'Proxy-Authenticate: Digest realm="p2b.sip.uniza.sk", nonce="TZrCGE2awOxSpM6/mMSW
aCcpGpCCn2al"#015#012'
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: sl [sl.c:278]: reply in stateless mode (sl)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [msg_translator.c:204]: check_via_address(158.193.139.65, 158.193.139.65, 0)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:640]: SIP Reply  (status):
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:642]:  version: <SIP/2.0>
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:644]:  status:  <407>
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:646]:  reason:  <Proxy Authentication Required>
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK76c9.3ad70364.0>; state=16
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this is the first via
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [receive.c:145]: After parse_msg...
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=2 global id=1 T start=(nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=b27e1a1d33761e85846fc98f5f3a7e58.1808
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field: <To> [70]; uri=[sip:katka@p2b.sip.uniza.sk]
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body [sip:katka@p2b.sip.uniza.sk]
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq <CSeq>: <10> <MESSAGE>
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body : content_length=0
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [parser/msg_parser.c:103]: found end of header
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_lookup.c:967]: DEBUG: t_reply_matching: hash 40039 label 1177583011 branch 0
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0x7ffb6f526990)!
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=2 global id=2 T end=0x7ffb6f526990
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_reply.c:2014]: DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_reply.c:1129]: ->>>>>>>>> T_code=0, new_code=407
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_reply.c:1892]: DEBUG: local_reply: branch=0, save=0, winner=0
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_reply.c:1929]: DEBUG: local transaction completed
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: tm [t_reply.c:1470]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21197]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
Apr  5 09:12:45 server /usr/sbin/kamailio[21200]: DEBUG: <core> [receive.c:289]: receive_msg: cleaning up
Apr  5 09:12:45 server /usr/sbin/kamailio[21210]: DEBUG: tm [timer.h:145]: _set_fr_timer: too late, timer already marked for deletion
...

Why is Kamailio doing a DNS SRV query for himself after he has recieved a message from XMPP and translated it to SIP ??

2011/4/4 Daniel-Constantin Mierla <daniel@kamailio.org>
Hello,

if you run kamailio with debug=3, what log messages are printed when the xmpp message arrives to kamailio?

Cheers,
Daniel


On 4/4/11 7:19 PM, Martin Pohančeník wrote:
Hello everyone.
I am a student at University of Žilina (Faculty of Management Science and Informatics), which has been recently awarded Kamailio 2010 Awards for various articles about SIP and KAMAILIO on portal nil.uniza.sk.
I am doing a bachelor thesis on topic SIP/SIMPLE - XMPP traversal, but I am experiencing some problems.
I have a working Kamailio server serving domain sip.uniza.sk and a working Jabberd2 server serving domain xmpp.uniza.sk.
I am running Kamailio 3.1 with XMPP module with following configuration:

fork=yes
children=4
log_stderror=yes
alias="sip.uniza.sk"
...
loadmodule "XMPP.so"
...
modparam("xmpp", "backend", "component")
modparam("xmpp", "domain_separator", "*")
modparam("xmpp", "gateway_domain", "sip.uniza.sk")
modparam("xmpp", "xmpp_domain", "xmpp-sip.uniza.sk")
modparam("xmpp", "xmpp_host", "server.xmpp.uniza.sk")
modparam("xmpp", "xmpp_password", "secret")
...
#main routing logic
route {
...
 if( uri=~"sip:.+[*].+@sip.uniza.sk")
        {
                # absorb retransmissions ###
                if (!t_newtran())
                {
                        sl_reply_error();
                        return;
                }
                if (method == "MESSAGE")
                {
                        log("*** xmpp-handled MESSAGE message.\n");
                        if (xmpp_send_message())
                        {
                                t_reply("200", "Accepted");
                        } else
                        {
                                t_reply("404", "Not found");
                        }
                        return;
                } else
                {
                        t_reply("403","not supported");
                        exit;
                }
        }
...
}

To my knowledge there is no configuration required on the Jabberd2 server (except the password, that the XMPP component authenticates with).
I am trying to enable SIP clients to chat with the XMPP clients and vice versa.
SIP clients can send messages to XMPP clients. XMPP modules translates SIP to XMPP and forwards the massage to Jabberd2 server.
URIs look like:
XMPP client from SIP view: xmpp_client*xmpp.uniza.sk@sip.uniza.sk
SIP client from XMPP view: sip_client*sip.uniza.sk@xmpp-sip.uniza.sk
The message arrives to XMPP client, but he can not reply.
I have sniffed the traffic on the Kamailio server. The XMPP message arrives to kamailio XMPP module (correct port and everything), but the module somehow ignores it, doesn't translate XMPP to SIP and doesn't send it to the SIP recipient.
The sniffed message looks like:

<message xmlns='jabber:client' type='chat' to='SIP_client*sip.uniza.sk@xmpp-sip.uniza.sk' id='mir_47' from='XMPP_client@xmpp.uniza.sk/Miranda'><body>hello</body></message>

Any suggestions on where can the problem be ??
Do I have to add some lines to routing logic for XMPP module to process the XMPP message (from Jabberd2) for SIP_client ??

Thanks
Martin

_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users