core: debug message when dropping a sip reply
[sip-router] / src / core / receive.c
1 /*
2  * Copyright (C) 2001-2003 FhG Fokus
3  *
4  * This file is part of Kamailio, a free SIP server.
5  *
6  * Kamailio is free software; you can redistribute it and/or modify
7  * it under the terms of the GNU General Public License as published by
8  * the Free Software Foundation; either version 2 of the License, or
9  * (at your option) any later version
10  *
11  * Kamailio is distributed in the hope that it will be useful,
12  * but WITHOUT ANY WARRANTY; without even the implied warranty of
13  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
14  * GNU General Public License for more details.
15  *
16  * You should have received a copy of the GNU General Public License
17  * along with this program; if not, write to the Free Software
18  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
19  *
20  */
21
22 /*!
23  * \file
24  * \brief Kamailio core ::
25  * \ingroup core
26  * Module: \ref core
27  */
28
29
30 #include <string.h>
31 #include <stdlib.h>
32 #include <sys/time.h>
33
34 #include "receive.h"
35 #include "globals.h"
36 #include "dprint.h"
37 #include "route.h"
38 #include "parser/msg_parser.h"
39 #include "forward.h"
40 #include "action.h"
41 #include "mem/mem.h"
42 #include "stats.h"
43 #include "ip_addr.h"
44 #include "script_cb.h"
45 #include "nonsip_hooks.h"
46 #include "dset.h"
47 #include "usr_avp.h"
48 #ifdef WITH_XAVP
49 #include "xavp.h"
50 #endif
51 #include "select_buf.h"
52
53 #include "tcp_server.h"  /* for tcpconn_add_alias */
54 #include "tcp_options.h" /* for access to tcp_accept_aliases*/
55 #include "cfg/cfg.h"
56 #include "core_stats.h"
57 #include "kemi.h"
58
59 #ifdef DEBUG_DMALLOC
60 #include <mem/dmalloc.h>
61 #endif
62
63 int _sr_ip_free_bind = 0;
64
65 unsigned int msg_no = 0;
66 /* address preset vars */
67 str default_global_address = {0, 0};
68 str default_global_port = {0, 0};
69 str default_via_address = {0, 0};
70 str default_via_port = {0, 0};
71
72 int ksr_route_locks_size = 0;
73 static rec_lock_set_t* ksr_route_locks_set = NULL;
74
75 int ksr_route_locks_set_init(void)
76 {
77         if(ksr_route_locks_set!=NULL || ksr_route_locks_size<=0)
78                 return 0;
79
80         ksr_route_locks_set = rec_lock_set_alloc(ksr_route_locks_size);
81         if(ksr_route_locks_set) {
82                 LM_ERR("failed to allocate route locks set\n");
83                 return -1;
84         }
85         if(rec_lock_set_init(ksr_route_locks_set)==NULL) {
86                 LM_ERR("failed to init route locks set\n");
87                 return -1;
88         }
89         return 0;
90 }
91
92 void ksr_route_locks_set_destroy(void)
93 {
94         if(ksr_route_locks_set==NULL)
95                 return;
96
97         rec_lock_set_destroy(ksr_route_locks_set);
98         rec_lock_set_dealloc(ksr_route_locks_set);
99         ksr_route_locks_set = NULL;
100 }
101
102 /**
103  * increment msg_no and return the new value
104  */
105 unsigned int inc_msg_no(void)
106 {
107         return ++msg_no;
108 }
109
110 /**
111  *
112  */
113 int sip_check_fline(char *buf, unsigned int len)
114 {
115         char *p;
116         int m;
117
118         m = 0;
119         for(p = buf; p < buf + len; p++) {
120                 /* first check if is a reply - starts with SIP/2.0 */
121                 if(m == 0) {
122                         if(*p == ' ' || *p == '\t' || *p == '\r' || *p == '\n')
123                                 continue;
124                         if(buf + len - p < 10)
125                                 return -1;
126                         if(strncmp(p, "SIP/2.0 ", 8) == 0) {
127                                 LM_DBG("first line indicates a SIP reply\n");
128                                 return 0;
129                         }
130                         m = 1;
131                 } else {
132                         /* check if a request - before end of first line is SIP/2.0 */
133                         if(*p != '\r' && *p != '\n')
134                                 continue;
135                         if(p - 10 >= buf) {
136                                 if(strncmp(p - 8, " SIP/2.0", 8) == 0) {
137                                         LM_DBG("first line indicates a SIP request\n");
138                                         return 0;
139                                 }
140                         }
141                         return -1;
142                 }
143         }
144         return -1;
145 }
146
147 /** Receive message
148  *  WARNING: buf must be 0 terminated (buf[len]=0) or some things might
149  * break (e.g.: modules/textops)
150  */
151 int receive_msg(char *buf, unsigned int len, struct receive_info *rcv_info)
152 {
153         struct sip_msg *msg;
154         struct run_act_ctx ctx;
155         struct run_act_ctx *bctx;
156         int ret;
157 #ifdef STATS
158         int skipped = 1;
159         int stats_on = 1;
160 #else
161         int stats_on = 0;
162 #endif
163         struct timeval tvb, tve;
164         struct timezone tz;
165         unsigned int diff = 0;
166         str inb;
167         sr_net_info_t netinfo;
168         sr_kemi_eng_t *keng = NULL;
169         sr_event_param_t evp = {0};
170         unsigned int cidlockidx = 0;
171         unsigned int cidlockset = 0;
172
173         if(sr_event_enabled(SREV_NET_DATA_RECV)) {
174                 if(sip_check_fline(buf, len) == 0) {
175                         memset(&netinfo, 0, sizeof(sr_net_info_t));
176                         netinfo.data.s = buf;
177                         netinfo.data.len = len;
178                         netinfo.rcv = rcv_info;
179                         evp.data = (void *)&netinfo;
180                         sr_event_exec(SREV_NET_DATA_RECV, &evp);
181                 }
182         }
183
184         inb.s = buf;
185         inb.len = len;
186         evp.data = (void *)&inb;
187         evp.rcv = rcv_info;
188         sr_event_exec(SREV_NET_DATA_IN, &evp);
189         len = inb.len;
190
191         msg = pkg_malloc(sizeof(struct sip_msg));
192         if(unlikely(msg == 0)) {
193                 LM_ERR("no mem for sip_msg\n");
194                 goto error00;
195         }
196         msg_no++;
197         /* number of vias parsed -- good for diagnostic info in replies */
198         via_cnt = 0;
199
200         memset(msg, 0, sizeof(struct sip_msg)); /* init everything to 0 */
201         /* fill in msg */
202         msg->buf = buf;
203         msg->len = len;
204         /* zero termination (termination of orig message bellow not that
205          * useful as most of the work is done with scratch-pad; -jiri  */
206         /* buf[len]=0; */ /* WARNING: zero term removed! */
207         msg->rcv = *rcv_info;
208         msg->id = msg_no;
209         msg->pid = my_pid();
210         msg->set_global_address = default_global_address;
211         msg->set_global_port = default_global_port;
212
213         if(likely(sr_msg_time == 1))
214                 msg_set_time(msg);
215
216         if(parse_msg(buf, len, msg) != 0) {
217                 evp.data = (void *)msg;
218                 if((ret = sr_event_exec(SREV_RCV_NOSIP, &evp)) < NONSIP_MSG_DROP) {
219                         LOG(cfg_get(core, core_cfg, corelog),
220                                         "core parsing of SIP message failed (%s:%d/%d)\n",
221                                         ip_addr2a(&msg->rcv.src_ip), (int)msg->rcv.src_port,
222                                         (int)msg->rcv.proto);
223                         sr_core_ert_run(msg, SR_CORE_ERT_RECEIVE_PARSE_ERROR);
224                 } else if(ret == NONSIP_MSG_DROP)
225                         goto error02;
226         }
227
228         if(unlikely(parse_headers(msg, HDR_FROM_F | HDR_TO_F | HDR_CALLID_F | HDR_CSEQ_F, 0)
229                         < 0)) {
230                 LM_WARN("parsing relevant headers failed\n");
231         }
232         LM_DBG("--- received sip message - %s - call-id: [%.*s] - cseq: [%.*s]\n",
233                         (msg->first_line.type == SIP_REQUEST) ? "request" : "reply",
234                         (msg->callid && msg->callid->body.s) ? msg->callid->body.len : 0,
235                         (msg->callid && msg->callid->body.s) ? msg->callid->body.s : "",
236                         (msg->cseq && msg->cseq->body.s) ? msg->cseq->body.len : 0,
237                         (msg->cseq && msg->cseq->body.s) ? msg->cseq->body.s : "");
238
239         /* set log prefix */
240         log_prefix_set(msg);
241
242         /* ... clear branches from previous message */
243         clear_branches();
244
245         if(unlikely(ksr_route_locks_set!=NULL && msg->callid && msg->callid->body.s
246                         && msg->callid->body.len >0)) {
247                 cidlockidx = get_hash1_raw(msg->callid->body.s, msg->callid->body.len);
248                 cidlockidx = cidlockidx % ksr_route_locks_set->size;
249                 cidlockset = 1;
250         }
251
252         if(msg->first_line.type == SIP_REQUEST) {
253                 ruri_mark_new(); /* ruri is usable for forking (not consumed yet) */
254                 if(!IS_SIP(msg)) {
255                         if((ret = nonsip_msg_run_hooks(msg)) != NONSIP_MSG_ACCEPT) {
256                                 if(unlikely(ret == NONSIP_MSG_ERROR))
257                                         goto error03;
258                                 goto end; /* drop the message */
259                         }
260                 }
261                 /* sanity checks */
262                 if(unlikely((msg->via1 == 0) || (msg->via1->error != PARSE_OK))) {
263                         /* no via, send back error ? */
264                         LM_ERR("no via found in request\n");
265                         STATS_BAD_MSG();
266                         goto error02;
267                 }
268 /* check if necessary to add receive?->moved to forward_req */
269 /* check for the alias stuff */
270 #ifdef USE_TCP
271                 if(msg->via1->alias && cfg_get(tcp, tcp_cfg, accept_aliases)
272                                 && (((rcv_info->proto == PROTO_TCP) && !tcp_disable)
273 #ifdef USE_TLS
274                                                    || ((rcv_info->proto == PROTO_TLS) && !tls_disable)
275 #endif
276                                                                    )) {
277                         if(tcpconn_add_alias(rcv_info->proto_reserved1, msg->via1->port,
278                                            rcv_info->proto)
279                                         != 0) {
280                                 LM_ERR("tcp alias failed\n");
281                                 /* continue */
282                         }
283                 }
284 #endif
285
286                 /*      skip: */
287                 LM_DBG("preparing to run routing scripts...\n");
288                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
289                                 || stats_on == 1) {
290                         gettimeofday(&tvb, &tz);
291                 }
292                 /* execute pre-script callbacks, if any; -jiri */
293                 /* if some of the callbacks said not to continue with
294                  * script processing, don't do so
295                  * if we are here basic sanity checks are already done
296                  * (like presence of at least one via), so you can count
297                  * on via1 being parsed in a pre-script callback --andrei
298                 */
299                 if(exec_pre_script_cb(msg, REQUEST_CB_TYPE) == 0) {
300                         STATS_REQ_FWD_DROP();
301                         goto end; /* drop the request */
302                 }
303
304                 set_route_type(REQUEST_ROUTE);
305                 /* exec the routing script */
306                 if(unlikely(main_rt.rlist[DEFAULT_RT] == NULL)) {
307                         keng = sr_kemi_eng_get();
308                         if(keng == NULL) {
309                                 LM_ERR("no request_route {...} and no other config routing"
310                                                 " engine registered\n");
311                                 goto error_req;
312                         }
313                         if(unlikely(cidlockset)) {
314                                 rec_lock_set_get(ksr_route_locks_set, cidlockidx);
315                                 if(keng->froute(msg, REQUEST_ROUTE, NULL, NULL) < 0)
316                                         LM_NOTICE("negative return code from engine function\n");
317                                 rec_lock_set_release(ksr_route_locks_set, cidlockidx);
318                         } else {
319                                 if(keng->froute(msg, REQUEST_ROUTE, NULL, NULL) < 0)
320                                         LM_NOTICE("negative return code from engine function\n");
321                         }
322                 } else {
323                         if(unlikely(cidlockset)) {
324                                 rec_lock_set_get(ksr_route_locks_set, cidlockidx);
325                                 if(run_top_route(main_rt.rlist[DEFAULT_RT], msg, 0) < 0) {
326                                         rec_lock_set_release(ksr_route_locks_set, cidlockidx);
327                                         LM_WARN("error while trying script\n");
328                                         goto error_req;
329                                 }
330                                 rec_lock_set_release(ksr_route_locks_set, cidlockidx);
331                         } else {
332                                 if(run_top_route(main_rt.rlist[DEFAULT_RT], msg, 0) < 0) {
333                                         LM_WARN("error while trying script\n");
334                                         goto error_req;
335                                 }
336                         }
337                 }
338
339                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
340                                 || stats_on == 1) {
341                         gettimeofday(&tve, &tz);
342                         diff = (tve.tv_sec - tvb.tv_sec) * 1000000
343                                    + (tve.tv_usec - tvb.tv_usec);
344                         LOG(cfg_get(core, core_cfg, latency_cfg_log),
345                                         "request-route executed in: %d usec\n", diff);
346 #ifdef STATS
347                         stats->processed_requests++;
348                         stats->acc_req_time += diff;
349                         STATS_RX_REQUEST(msg->first_line.u.request.method_value);
350 #endif
351                 }
352
353                 /* execute post request-script callbacks */
354                 exec_post_script_cb(msg, REQUEST_CB_TYPE);
355         } else if(msg->first_line.type == SIP_REPLY) {
356                 /* sanity checks */
357                 if((msg->via1 == 0) || (msg->via1->error != PARSE_OK)) {
358                         /* no via, send back error ? */
359                         LM_ERR("no via found in reply\n");
360                         STATS_BAD_RPL();
361                         goto error02;
362                 }
363
364                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
365                                 || stats_on == 1) {
366                         gettimeofday(&tvb, &tz);
367                 }
368 #ifdef STATS
369                 STATS_RX_RESPONSE(msg->first_line.u.reply.statuscode / 100);
370 #endif
371
372                 /* execute pre-script callbacks, if any; -jiri */
373                 /* if some of the callbacks said not to continue with
374                  * script processing, don't do so
375                  * if we are here basic sanity checks are already done
376                  * (like presence of at least one via), so you can count
377                  * on via1 being parsed in a pre-script callback --andrei
378                 */
379                 if(exec_pre_script_cb(msg, ONREPLY_CB_TYPE) == 0) {
380                         STATS_RPL_FWD_DROP();
381                         goto end; /* drop the reply */
382                 }
383
384                 /* exec the onreply routing script */
385                 if(kemi_reply_route_callback.len>0) {
386                         keng = sr_kemi_eng_get();
387                 }
388                 if(onreply_rt.rlist[DEFAULT_RT] != NULL || keng != NULL) {
389                         set_route_type(CORE_ONREPLY_ROUTE);
390                         ret = 1;
391                         if(unlikely(keng != NULL)) {
392                                 bctx = sr_kemi_act_ctx_get();
393                                 init_run_actions_ctx(&ctx);
394                                 sr_kemi_act_ctx_set(&ctx);
395                                 if(unlikely(cidlockset)) {
396                                         rec_lock_set_get(ksr_route_locks_set, cidlockidx);
397                                         ret = keng->froute(msg, CORE_ONREPLY_ROUTE, NULL, NULL);
398                                         rec_lock_set_release(ksr_route_locks_set, cidlockidx);
399                                 } else {
400                                         ret = keng->froute(msg, CORE_ONREPLY_ROUTE, NULL, NULL);
401                                 }
402                                 sr_kemi_act_ctx_set(bctx);
403                         } else {
404                                 if(unlikely(cidlockset)) {
405                                         rec_lock_set_get(ksr_route_locks_set, cidlockidx);
406                                         ret = run_top_route(onreply_rt.rlist[DEFAULT_RT], msg, &ctx);
407                                         rec_lock_set_release(ksr_route_locks_set, cidlockidx);
408                                 } else  {
409                                         ret = run_top_route(onreply_rt.rlist[DEFAULT_RT], msg, &ctx);
410                                 }
411                         }
412 #ifndef NO_ONREPLY_ROUTE_ERROR
413                         if(unlikely(ret < 0)) {
414                                 LM_WARN("error while trying onreply script\n");
415                                 goto error_rpl;
416                         } else
417 #endif /* NO_ONREPLY_ROUTE_ERROR */
418                                 if(unlikely(ret == 0 || (ctx.run_flags & DROP_R_F))) {
419                                         STATS_RPL_FWD_DROP();
420                                         LM_DBG("drop flag set - skip forwarding the reply\n");
421                                         goto skip_send_reply; /* drop the message, no error */
422                                 }
423                 }
424                 /* send the msg */
425                 forward_reply(msg);
426         skip_send_reply:
427                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
428                                 || stats_on == 1) {
429                         gettimeofday(&tve, &tz);
430                         diff = (tve.tv_sec - tvb.tv_sec) * 1000000
431                                    + (tve.tv_usec - tvb.tv_usec);
432                         LOG(cfg_get(core, core_cfg, latency_cfg_log),
433                                         "reply-route executed in: %d usec\n", diff);
434 #ifdef STATS
435                         stats->processed_responses++;
436                         stats->acc_res_time += diff;
437 #endif
438                 }
439
440                 /* execute post reply-script callbacks */
441                 exec_post_script_cb(msg, ONREPLY_CB_TYPE);
442         }
443
444 end:
445 #ifdef STATS
446         skipped = 0;
447 #endif
448         ksr_msg_env_reset();
449         LM_DBG("cleaning up\n");
450         free_sip_msg(msg);
451         pkg_free(msg);
452 #ifdef STATS
453         if(skipped)
454                 STATS_RX_DROPS;
455 #endif
456         /* reset log prefix */
457         log_prefix_set(NULL);
458         return 0;
459
460 #ifndef NO_ONREPLY_ROUTE_ERROR
461 error_rpl:
462         /* execute post reply-script callbacks */
463         exec_post_script_cb(msg, ONREPLY_CB_TYPE);
464         goto error02;
465 #endif /* NO_ONREPLY_ROUTE_ERROR */
466 error_req:
467         LM_DBG("error:...\n");
468         /* execute post request-script callbacks */
469         exec_post_script_cb(msg, REQUEST_CB_TYPE);
470 error03:
471 error02:
472         free_sip_msg(msg);
473         pkg_free(msg);
474 error00:
475         ksr_msg_env_reset();
476         STATS_RX_DROPS;
477         /* reset log prefix */
478         log_prefix_set(NULL);
479         return -1;
480 }
481
482 /**
483  * clean up msg environment, such as avp and xavp lists
484  */
485 void ksr_msg_env_reset(void)
486 {
487         reset_avps();
488 #ifdef WITH_XAVP
489         xavp_reset_list();
490 #endif
491 }