core: debug message with details of callid and cseq when a sip message is received
[sip-router] / 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 unsigned int msg_no=0;
64 /* address preset vars */
65 str default_global_address={0,0};
66 str default_global_port={0,0};
67 str default_via_address={0,0};
68 str default_via_port={0,0};
69
70 /**
71  * increment msg_no and return the new value
72  */
73 unsigned int inc_msg_no(void)
74 {
75         return ++msg_no;
76 }
77
78 /**
79  *
80  */
81 int sip_check_fline(char* buf, unsigned int len)
82 {
83         char *p;
84         int m;
85
86         m = 0;
87         for(p=buf; p<buf+len; p++) {
88                 /* first check if is a reply - starts with SIP/2.0 */
89                 if(m==0) {
90                         if(*p==' ' || *p=='\t' || *p=='\r' || *p=='\n') continue;
91                         if(buf+len-p<10) return -1;
92                         if(strncmp(p, "SIP/2.0 ", 8)==0) {
93                                 LM_DBG("first line indicates a SIP reply\n");
94                                 return 0;
95                         }
96                         m=1;
97                 } else {
98                         /* check if a request - before end of first line is SIP/2.0 */
99                         if(*p!='\r' && *p!='\n') continue;
100                         if(p-10>=buf) {
101                                 if(strncmp(p-8, " SIP/2.0", 8)==0) {
102                                         LM_DBG("first line indicates a SIP request\n");
103                                         return 0;
104                                 }
105                         }
106                         return -1;
107                 }
108         }
109         return -1;
110 }
111
112 /** Receive message
113  *  WARNING: buf must be 0 terminated (buf[len]=0) or some things might
114  * break (e.g.: modules/textops)
115  */
116 int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
117 {
118         struct sip_msg* msg;
119         struct run_act_ctx ctx;
120         struct run_act_ctx *bctx;
121         int ret;
122 #ifdef STATS
123         int skipped = 1;
124         int stats_on = 1;
125 #else
126         int stats_on = 0;
127 #endif
128         struct timeval tvb, tve;
129         struct timezone tz;
130         unsigned int diff = 0;
131         str inb;
132         sr_net_info_t netinfo;
133         sr_kemi_eng_t *keng = NULL;
134
135         if(sr_event_enabled(SREV_NET_DATA_RECV)) {
136                 if(sip_check_fline(buf, len)==0) {
137                         memset(&netinfo, 0, sizeof(sr_net_info_t));
138                         netinfo.data.s = buf;
139                         netinfo.data.len = len;
140                         netinfo.rcv = rcv_info;
141                         sr_event_exec(SREV_NET_DATA_RECV, (void*)&netinfo);
142                 }
143         }
144
145         inb.s = buf;
146         inb.len = len;
147         sr_event_exec(SREV_NET_DATA_IN, (void*)&inb);
148         len = inb.len;
149
150         msg=pkg_malloc(sizeof(struct sip_msg));
151         if (msg==0) {
152                 LM_ERR("no mem for sip_msg\n");
153                 goto error00;
154         }
155         msg_no++;
156         /* number of vias parsed -- good for diagnostic info in replies */
157         via_cnt=0;
158
159         memset(msg,0, sizeof(struct sip_msg)); /* init everything to 0 */
160         /* fill in msg */
161         msg->buf=buf;
162         msg->len=len;
163         /* zero termination (termination of orig message bellow not that
164          * useful as most of the work is done with scratch-pad; -jiri  */
165         /* buf[len]=0; */ /* WARNING: zero term removed! */
166         msg->rcv=*rcv_info;
167         msg->id=msg_no;
168         msg->pid=my_pid();
169         msg->set_global_address=default_global_address;
170         msg->set_global_port=default_global_port;
171
172         if(likely(sr_msg_time==1)) msg_set_time(msg);
173
174         if (parse_msg(buf,len, msg)!=0){
175                 if((ret=sr_event_exec(SREV_RCV_NOSIP, (void*)msg))<NONSIP_MSG_DROP) {
176                         LOG(cfg_get(core, core_cfg, corelog),
177                                 "core parsing of SIP message failed (%s:%d/%d)\n",
178                                 ip_addr2a(&msg->rcv.src_ip), (int)msg->rcv.src_port,
179                                 (int)msg->rcv.proto);
180                         sr_core_ert_run(msg, SR_CORE_ERT_RECEIVE_PARSE_ERROR);
181                 }
182                 else if(ret == NONSIP_MSG_DROP) goto error02;
183         }
184         LM_DBG("--- received sip message - %s - call-id: [%.*s] - cseq: [%.*s]\n",
185                         (msg->first_line.type==SIP_REQUEST)?"request":"reply",
186                         (msg->callid && msg->callid->body.s)?msg->callid->body.len:0,
187                         (msg->callid && msg->callid->body.s)?msg->callid->body.s:"",
188                         (msg->cseq && msg->cseq->body.s)?msg->cseq->body.len:0,
189                         (msg->cseq && msg->cseq->body.s)?msg->cseq->body.s:"");
190
191         /* set log prefix */
192         log_prefix_set(msg);
193
194         /* ... clear branches from previous message */
195         clear_branches();
196
197         if (msg->first_line.type==SIP_REQUEST){
198                 ruri_mark_new(); /* ruri is usable for forking (not consumed yet) */
199                 if (!IS_SIP(msg)){
200                         if ((ret=nonsip_msg_run_hooks(msg))!=NONSIP_MSG_ACCEPT){
201                                 if (unlikely(ret==NONSIP_MSG_ERROR))
202                                         goto error03;
203                                 goto end; /* drop the message */
204                         }
205                 }
206                 /* sanity checks */
207                 if ((msg->via1==0) || (msg->via1->error!=PARSE_OK)){
208                         /* no via, send back error ? */
209                         LM_ERR("no via found in request\n");
210                         STATS_BAD_MSG();
211                         goto error02;
212                 }
213                 /* check if necessary to add receive?->moved to forward_req */
214                 /* check for the alias stuff */
215 #ifdef USE_TCP
216                 if (msg->via1->alias && cfg_get(tcp, tcp_cfg, accept_aliases) &&
217                                 (((rcv_info->proto==PROTO_TCP) && !tcp_disable)
218 #ifdef USE_TLS
219                                         || ((rcv_info->proto==PROTO_TLS) && !tls_disable)
220 #endif
221                                 )
222                         ){
223                         if (tcpconn_add_alias(rcv_info->proto_reserved1, msg->via1->port,
224                                                                         rcv_info->proto)!=0){
225                                 LM_ERR("tcp alias failed\n");
226                                 /* continue */
227                         }
228                 }
229 #endif
230
231         /*      skip: */
232                 LM_DBG("preparing to run routing scripts...\n");
233                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
234                                 || stats_on==1) {
235                         gettimeofday( & tvb, &tz );
236                 }
237                 /* execute pre-script callbacks, if any; -jiri */
238                 /* if some of the callbacks said not to continue with
239                  * script processing, don't do so
240                  * if we are here basic sanity checks are already done
241                  * (like presence of at least one via), so you can count
242                  * on via1 being parsed in a pre-script callback --andrei
243                 */
244                 if (exec_pre_script_cb(msg, REQUEST_CB_TYPE)==0 )
245                 {
246                         STATS_REQ_FWD_DROP();
247                         goto end; /* drop the request */
248                 }
249
250                 set_route_type(REQUEST_ROUTE);
251                 /* exec the routing script */
252                 if(unlikely(main_rt.rlist[DEFAULT_RT]==NULL)) {
253                         keng = sr_kemi_eng_get();
254                         if(keng==NULL) {
255                                 LM_ERR("no config routing engine registered\n");
256                                 goto error_req;
257                         }
258                         if(keng->froute(msg, REQUEST_ROUTE, NULL)<0) {
259                                 LM_NOTICE("negative return code from engine function\n");
260                         }
261                 } else {
262                         if (run_top_route(main_rt.rlist[DEFAULT_RT], msg, 0)<0){
263                                 LM_WARN("error while trying script\n");
264                                 goto error_req;
265                         }
266                 }
267
268                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
269                                 || stats_on==1) {
270                         gettimeofday( & tve, &tz );
271                         diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
272                         LOG(cfg_get(core, core_cfg, latency_cfg_log),
273                                         "request-route executed in: %d usec\n", diff);
274 #ifdef STATS
275                         stats->processed_requests++;
276                         stats->acc_req_time += diff;
277                         STATS_RX_REQUEST( msg->first_line.u.request.method_value );
278 #endif
279                 }
280
281                 /* execute post request-script callbacks */
282                 exec_post_script_cb(msg, REQUEST_CB_TYPE);
283         }else if (msg->first_line.type==SIP_REPLY){
284                 /* sanity checks */
285                 if ((msg->via1==0) || (msg->via1->error!=PARSE_OK)){
286                         /* no via, send back error ? */
287                         LM_ERR("no via found in reply\n");
288                         STATS_BAD_RPL();
289                         goto error02;
290                 }
291
292                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
293                                 || stats_on==1) {
294                         gettimeofday( & tvb, &tz );
295                 }
296 #ifdef STATS
297                 STATS_RX_RESPONSE ( msg->first_line.u.reply.statuscode / 100 );
298 #endif
299
300                 /* execute pre-script callbacks, if any; -jiri */
301                 /* if some of the callbacks said not to continue with
302                  * script processing, don't do so
303                  * if we are here basic sanity checks are already done
304                  * (like presence of at least one via), so you can count
305                  * on via1 being parsed in a pre-script callback --andrei
306                 */
307                 if (exec_pre_script_cb(msg, ONREPLY_CB_TYPE)==0 )
308                 {
309                         STATS_RPL_FWD_DROP();
310                         goto end; /* drop the reply */
311                 }
312
313                 /* exec the onreply routing script */
314                 keng = sr_kemi_eng_get();
315                 if (onreply_rt.rlist[DEFAULT_RT]!=NULL || keng!=NULL){
316                         set_route_type(CORE_ONREPLY_ROUTE);
317                         ret = 1;
318                         if(unlikely(keng!=NULL)) {
319                                 bctx = sr_kemi_act_ctx_get();
320                                 init_run_actions_ctx(&ctx);
321                                 sr_kemi_act_ctx_set(&ctx);
322                                 ret = keng->froute(msg, CORE_ONREPLY_ROUTE, NULL);
323                                 sr_kemi_act_ctx_set(bctx);
324                         } else {
325                                 ret=run_top_route(onreply_rt.rlist[DEFAULT_RT], msg, &ctx);
326                         }
327 #ifndef NO_ONREPLY_ROUTE_ERROR
328                         if (unlikely(ret<0)){
329                                 LM_WARN("error while trying onreply script\n");
330                                 goto error_rpl;
331                         }else
332 #endif /* NO_ONREPLY_ROUTE_ERROR */
333                         if (unlikely(ret==0 || (ctx.run_flags&DROP_R_F))){
334                                 STATS_RPL_FWD_DROP();
335                                 goto skip_send_reply; /* drop the message, no error */
336                         }
337                 }
338                 /* send the msg */
339                 forward_reply(msg);
340         skip_send_reply:
341                 if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
342                                 || stats_on==1) {
343                         gettimeofday( & tve, &tz );
344                         diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
345                         LOG(cfg_get(core, core_cfg, latency_cfg_log),
346                                         "reply-route executed in: %d usec\n", diff);
347 #ifdef STATS
348                         stats->processed_responses++;
349                         stats->acc_res_time+=diff;
350 #endif
351                 }
352
353                 /* execute post reply-script callbacks */
354                 exec_post_script_cb(msg, ONREPLY_CB_TYPE);
355         }
356
357 end:
358 #ifdef STATS
359         skipped = 0;
360 #endif
361         /* free possible loaded avps -bogdan */
362         reset_avps();
363 #ifdef WITH_XAVP
364         xavp_reset_list();
365 #endif
366         LM_DBG("cleaning up\n");
367         free_sip_msg(msg);
368         pkg_free(msg);
369 #ifdef STATS
370         if (skipped) STATS_RX_DROPS;
371 #endif
372         /* reset log prefix */
373         log_prefix_set(NULL);
374         return 0;
375
376 #ifndef NO_ONREPLY_ROUTE_ERROR
377 error_rpl:
378         /* execute post reply-script callbacks */
379         exec_post_script_cb(msg, ONREPLY_CB_TYPE);
380         reset_avps();
381 #ifdef WITH_XAVP
382         xavp_reset_list();
383 #endif
384         goto error02;
385 #endif /* NO_ONREPLY_ROUTE_ERROR */
386 error_req:
387         LM_DBG("error:...\n");
388         /* execute post request-script callbacks */
389         exec_post_script_cb(msg, REQUEST_CB_TYPE);
390 error03:
391         /* free possible loaded avps -bogdan */
392         reset_avps();
393 #ifdef WITH_XAVP
394         xavp_reset_list();
395 #endif
396 error02:
397         free_sip_msg(msg);
398         pkg_free(msg);
399 error00:
400         STATS_RX_DROPS;
401         /* reset log prefix */
402         log_prefix_set(NULL);
403         return -1;
404 }
405