search

OpenSIPS / opensips

OpenSIPS is a GPL implementation of a multi-functionality SIP Server that targets to deliver a high-level technical solution (performance, security and quality) to be used in professional SIP server platforms.
https://opensips.org
Other
1.28k stars 583 forks source link

MSILO Module is not safe with db_cachedb and MongoDB #798

Open jalung opened 8 years ago

jalung commented 8 years ago

If the messages are stored in a Mongo Replicaset using the CACHEDB module, messages are stored, but being sent out repeatedly on each re-registration of the client. It seems not able to update mongo on the 2xx.

bogdan-iancu commented 8 years ago

@jalung , do you see any errors (in opensips log) on handling the 200 OK from the end point ? Also, do you see any attempt to actually run the delete query? using debug level 4 will help in providing more output from opensips.

bogdan-iancu commented 8 years ago

BTW, what opensips version are you using ?

jalung commented 8 years ago

Bogdan, the debug did not really print anything from the MSILO module as posted below, Opensips 2.1.2. There is only a comment in the script during registration when the m_dump() is executed. The mongdb query you see is just housekeeping.

Mar 18 10:20:15 : route[initial_requests] : REGISTER: 33.33.33.33 REGISTER message flags: NAT Mar 18 10:20:15 : DBG:core:comp_scriptvar: int 27 : 2 / 2 Mar 18 10:20:15 : route[initial_requests] : REGISTER: 33.33.33.33 REGISTER branch flags: uas_ip4 NAT_BFLAG Mar 18 10:20:15 : DBG:core:parse_headers: flags=ffffffffffffffff Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Running raw mongo query on table db.location Mar 18 10:20:15 : DBG:core:db_new_result: allocate 48 bytes for result set at 0x7f1a4d005930 Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: We have 1 rows Mar 18 10:20:15 : DBG:core:db_allocate_columns: allocate 420 bytes for result columns at 0x7f1a4d0007b8 Mar 18 10:20:15 : DBG:core:db_allocate_rows: allocate 496 bytes for result rows and values at 0x7f1a4d0059f8 Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [contact]=[sip:1111111111@33.33.33.33:5071] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found time [expires]=[1458296438] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found double [q]=[-1.000000] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [callid]=[WHdaFfxJD~] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found int [cseq]=[85] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found int [flags]=[0] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [cflags]=[uas_ip4 NAT_BFLAG] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [user_agent]=[Linphone/3.9.1 (belle-sip/1.4.2)] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [received]=[sip:33.33.33.33:5071] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found empty [path] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [socket]=[udp:204.204.204.66:5060] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found empty [methods] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found time [last_modified]=[1458296198] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [sip_instance]=[urn:uuid:5dd97c4f-fc88-4557-a013-cc682a366546] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Found string [attr]=[172.16.1] Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_query_trans: Successfully ran query Mar 18 10:20:15 : DBG:usrloc:dbrow2info: flag str: 'uas_ip4 NAT_BFLAG' Mar 18 10:20:15 : DBG:usrloc:dbrow2info: set flags: 1025 Mar 18 10:20:15 : DBG:core:grep_sock_info: checking if host==us: 14==14 && [204.204.204.66] == [204.204.204.66] Mar 18 10:20:15 : DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 18 10:20:15 : DBG:core:evi_param_set: adding string param Mar 18 10:20:15 : DBG:core:evi_param_set: adding string param Mar 18 10:20:15 : DBG:core:evi_param_set: adding string param Mar 18 10:20:15 : DBG:core:evi_param_set: adding string param Mar 18 10:20:15 : DBG:core:evi_param_set: adding int param Mar 18 10:20:15 : DBG:core:destroy_avp_list: destroying list (nil) Mar 18 10:20:15 : DBG:cachedb_mongodb:mongo_db_free_result_trans: freeing mongo query result **Mar 18 10:20:15 : MSILO: offline messages dumped - if any** Mar 18 10:20:15 osys2 /usr/sbin/opensips[20264]: REDIRECTMESSAGE method=MESSAGE r-uri=sip:1111111111@nstagge.net F=sip:2234444444@nstagge.net IP=204.204.204.66 [Offline message - Fri Mar 18 08:50:08 2016] .... Mar 18 10:20:15 osys2 /usr/sbin/opensips[20264]: CALL TO LOCAL method=MESSAGE rd=33.33.33.33 r-uri=sip:1111111111@33.33.33.33:5071 F=sip:2234444444@nstagge.net IP=204.204.204.66 ID=5d5cf2c441e16243-20274@204.204.204.66 contact=sip:2234444444@nstagge.net;msilo=yes ft=9ae6a27177c2efc6893cae261e4a0588-6a45 ci=5d5cf2c441e16243-20274@204.204.204.66 Mar 18 10:20:15 osys2 /usr/sbin/opensips[20264]: RRINITIAL -1 10 du= method=MESSAGE r-uri=sip:1111111111@33.33.33.33:5071 F=sip:2234444444@nstagge.net IP=204.204.204.66 ID=5d5cf2c441e16243-20274@204.204.204.66 Mar 18 10:20:15 osys2 /usr/sbin/opensips[20264]: BRANCH : 10: MESSAGE: rd=33.33.33.33 method=MESSAGE RURI=sip:1111111111@33.33.33.33:5071 FROM=sip:2234444444@nstagge.net IP=204.204.204.66 sport=5060 reqport=5071 ci=5d5cf2c441e16243-20274@204.204.204.66 **Mar 18 10:20:15 : onreply_route : 10: 200: 33.33.33.33 response method=MESSAGE From=sip:2234444444@nstagge.net ID=5d5cf2c441e16243-20274@204.204.204.66 Mar 18 10:20:15 : onreply_route : 10: 200: 33.33.33.33 message flags: Mar 18 10:20:15 : onreply_route : 10: 200: 33.33.33.33 branch flags: NAT_BFLAG** Mar 18 10:20:17 osys2 /usr/sbin/opensips[20270]: route : 46: PUBLISH: 1111111111 33.33.33.33 : PUBLISH uac behind NAT Mar 18 10:20:17 osys2 /usr/sbin/opensips[20270]: route : 47: PUBLISH: 1111111111 33.33.33.33 : PUBLISH uac behind NAT Mar 18 10:20:17 osys2 /usr/sbin/opensips[20270]: route[initial_requests] : PUBLISH: RELAY ruri=sip:1111111111@nstagge.net F=sip:1111111111@nstagge.net IP=33.33.33.33 ID=94Xps-Z-0r Mar 18 10:20:17 osys2 /usr/sbin/opensips[20270]: RRINITIAL -1 47 du=sip:132.132.132.58:5060 method=PUBLISH r-uri=sip:1111111111@nstagge.net F=sip:1111111111@nstagge.net IP=33.33.33.33 ID=94Xps-Z-0r Mar 18 10:20:17 osys2 /usr/sbin/opensips[20270]: BRANCH : 47: PUBLISH: rd=nstagge.net method=PUBLISH RURI=sip:1111111111@nstagge.net FROM=sip:1111111111@nstagge.net IP=33.33.33.33 sport=5071 reqport=5060 ci=94Xps-Z-0r Mar 18 10:20:17 osys2 /usr/sbin/opensips[20280]: onreply_route : 47: 200: 132.132.132.58 response method=PUBLISH From=sip:1111111111@nstagge.net ID=94Xps-Z-0r Mar 18 10:20:17 osys2 /usr/sbin/opensips[20280]: onreply_route : 47: 200: 132.132.132.58 message flags: NAT Mar 18 10:20:17 osys2 /usr/sbin/opensips[20280]: onreply_route : 47: 200: 132.132.132.58 branch flags:

bogdan-iancu commented 8 years ago

@jalung , you printed/posted the debug for mdump() call, but the delete from DB is done on the reply of the sent MESSAGE...If the signaling is ok, opensips should receive a 200 OK reply for the MESSAGE request - the debugs for handling that 200 OK are important.

jalung commented 8 years ago

I highlighted the comments on the reply from the UA in the reply-route. M_dump is not printing any de bug messages. Tell me what to change in the code for m_dump to print messages.

Two points: It works ok when silo is in mariaDB . If there is a problem with signaling it should not continue to resend the messages indefinitely.

bogdan-iancu commented 8 years ago

If you monitor traffic at network level, do you seen opensips sending the delete query to the DB server ?

jalung commented 8 years ago

Systemd was Rate Limiting the console logs so that's the reason the capture above was incomplete. Piping it to disk revealed the full debug log, thanks for the tip.

The problem is that, mongo does not have the AUTO INCREMENT id field such as MySQL . The equivalent key is " _id" and is alphanumeric. MSILO uses the id key as the msgid and as such, cannot do updates or deletes. Another side effect is that, the core variable\ $mi is always zero**.

Currently using the patch below ( provided as reference). When the offline message is stored, it adds the "id" field that the module is querying on the m_dump(). Not a complete fix, but resolves the issue.

msilo.txt

bogdan-iancu commented 8 years ago

@jalung, thanks for the findings. The problem is that not all modules are safe to be used via db_cachedb (because of this ID auto increment stuff). I put this as a improvement on the list and come up with a generic solution for it. Thanks !