2 *------------------------------------------------------------------
3 * spp_platform_trace_log.c
5 * Copyright (c) 2008-2011, 2013 Cisco and/or its affiliates.
6 * Licensed under the Apache License, Version 2.0 (the "License");
7 * you may not use this file except in compliance with the License.
8 * You may obtain a copy of the License at:
10 * http://www.apache.org/licenses/LICENSE-2.0
12 * Unless required by applicable law or agreed to in writing, software
13 * distributed under the License is distributed on an "AS IS" BASIS,
14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15 * See the License for the specific language governing permissions and
16 * limitations under the License.
17 *---------------------------------------------------------------------------
20 #include <vlib/vlib.h>
22 #include <vppinfra/vec.h>
23 #include <vppinfra/bitmap.h>
24 #include <vppinfra/hash.h>
25 #include <vppinfra/pool.h>
26 #include <vppinfra/clib.h>
27 #include <vlib/main.h>
29 #include "tcp_header_definitions.h"
30 #include "platform_common.h"
31 #include "spp_platform_trace_log.h"
33 #define WORD_SIZE sizeof(u32)
35 int temperature_read_blocked = 1;
37 spp_cnat_logger_tbl_t spp_cnat_logger_table[] =
46 { CNAT_NO_CONFIG_ERROR,
53 { CNAT_NO_VRF_RUN_ERROR,
60 { CNAT_NO_POOL_FOR_ANY_ERROR,
67 { CNAT_NO_PORT_FOR_ANY_ERROR,
74 { CNAT_BAD_INUSE_ANY_ERROR,
81 { CNAT_NOT_FOUND_ANY_ERROR,
88 { CNAT_INV_PORT_FOR_DIRECT_ERROR,
95 { CNAT_BAD_INUSE_DIRECT_ERROR,
102 { CNAT_NOT_FOUND_DIRECT_ERROR,
109 { CNAT_OUT_OF_PORT_LIMIT_ERROR,
116 { CNAT_MAIN_DB_CREATE_ERROR,
126 { CNAT_INDEX_MISMATCH_ERROR,
132 { CNAT_PACKET_DROP_ERROR,
139 { CNAT_INV_UNUSED_USR_INDEX,
142 {"invalid/unused user index"}
144 { CNAT_INVALID_VRFMAP_INDEX,
149 { CNAT_USER_OUT_OF_PORTS,
155 { CNAT_EXT_PORT_THRESH_EXCEEDED,
161 { CNAT_EXT_PORT_THRESH_NORMAL,
167 { CNAT_NO_EXT_PORT_AVAILABLE,
172 { CNAT_SESSION_THRESH_EXCEEDED,
178 { CNAT_SESSION_THRESH_NORMAL,
180 30, /* changed to 30 */
184 { WQE_ALLOCATION_ERROR,
186 180, /* changed to 180 */
191 60, /* changed to 60 */
195 { SYSMGR_PD_KEY_CREATION_ERROR,
200 { SYSMGR_PD_SHMEM_ID_ERROR,
205 { SYSMGR_PD_SHMEM_ATTACH_ERROR,
210 { OCTEON_CKHUM_SKIPPED,
212 60, /* changed to 60 */
226 { SPP_CTX_ALLOC_FAILED,
228 300, /* every 5 min */
231 { SPP_MAX_DISPATCH_REACHED,
248 { HA_INVALID_SEQ_OR_CONFIG_OR_TYPE,
251 {"seq-id or config option",
254 { NODE_CREATION_ERROR,
260 { CNAT_CLI_INVALID_INPUT,
268 { CNAT_DUMMY_HANDLER_HIT,
284 180, /* changed to 180 */
287 { CNAT_CMVX_TWSI_READ_WRITE_FAIL,
294 { CNAT_TEMP_SENSOR_TIMEOUT,
299 { CNAT_TEMP_SENSOR_DATA_MISMATCH,
305 { CNAT_TEMP_SENSOR_CONFIG_FAILED,
310 { HA_APP_NOT_RESPONDING,
316 { HA_DATA_PATH_TEST_FAILED,
321 { CNAT_WRONG_PORT_ALLOC_TYPE,
328 { CNAT_NEW_PORT_ALLOC_ERROR,
335 { CNAT_INVALID_INDEX_TO_FREE_PORT,
340 { CNAT_DELETE_DB_ENTRY_NO_PORTMAP,
345 { CNAT_MAIN_DB_LIMIT_ERROR,
350 { CNAT_USER_DB_LIMIT_ERROR,
355 { CNAT_FRAG_DB_ERROR,
368 #define LOG_TABLE_MAX_ENTRIES \
369 (sizeof(spp_cnat_logger_table)/sizeof(spp_cnat_logger_table[0]))
371 u32 error_code_timestamps[LOG_TABLE_MAX_ENTRIES];
372 spp_timer_t sensor_timer;
373 spp_trace_log_global_info_t spp_trace_log_global_info;
374 spp_global_counters_t spp_global_counters;
377 * Logging information structures
379 spp_trace_log_info_t spp_default_trace_log_info;
380 spp_trace_log_info_t *spp_trace_log_info_pool;
384 * The following 2 functions are temporary hacks until
385 * we have RTC support from the PD nodes
388 u32 spp_trace_log_get_sys_up_time_in_ms (void)
390 spp_node_main_vector_t *nmv;
393 nmv = spp_get_node_main_vectorized_inline();
395 sys_up_time = (u32) (nmv->ticks / nmv->ticks_per_ms);
397 return (sys_up_time);
400 u32 spp_trace_log_get_unix_time_in_seconds (void)
402 spp_node_main_vector_t *nmv;
405 nmv = spp_get_node_main_vectorized_inline();
407 unix_time = (u32) (nmv->ticks / nmv->ticks_per_second);
413 * edt: * * spp_trace_log_send_queued_pkt
415 * Tries to send a logging pkt that has been queued earlier
416 * because it could not be sent due to downstream constipation
418 * Argument: spp_trace_log_info_t *trace_logging_info
419 * structure that contains the packet context
422 void spp_trace_log_send_queued_pkt (spp_trace_log_info_t *trace_logging_info)
424 spp_node_t *output_node;
426 output_node = spp_get_nodes() +
427 spp_trace_log_global_info.spp_trace_log_disp_node_index;
429 if (PREDICT_TRUE(output_node->sf.nused < SPP_MAXDISPATCH)) {
431 * Move the logging context to output node
433 spp_dispatch_make_node_runnable(output_node);
434 output_node->sf.ctxs[output_node->sf.nused++] =
435 trace_logging_info->queued_logging_context;
438 * Context has been queued, it will be freed after the pkt
439 * is sent. Clear this from the logging_context_info structure
441 trace_logging_info->queued_logging_context = NULL;
445 * Can't do much, just return, may be we can send it later
447 spp_global_counters.spp_trace_log_downstream_constipation_count++;
452 * edt: * * spp_trace_log_send_pkt
454 * Tries to send a logging pkt. If the packet cannot be sent
455 * because of rewrite_output node cannot process it, queue
456 * it temporarily and try to send it later.
458 * Argument: spp_trace_log_info_t *trace_logging_info
459 * structure that contains the packet context
462 void spp_trace_log_send_pkt (spp_trace_log_info_t *trace_logging_info)
464 spp_node_t *output_node;
467 output_node = spp_get_nodes() +
468 spp_trace_log_global_info.spp_trace_log_disp_node_index;
470 if (PREDICT_TRUE(output_node->sf.nused < SPP_MAXDISPATCH)) {
472 * Move the logging context to output node
474 spp_dispatch_make_node_runnable(output_node);
475 output_node->sf.ctxs[output_node->sf.nused++] =
476 trace_logging_info->current_logging_context;
480 * Queue the context into the logging_info structure,
481 * We will try to send it later. Currently, we will
482 * restrict to only one context queued.
484 spp_global_counters.spp_trace_log_downstream_constipation_count++;
487 * Attach the current logging context which is full to the
488 * queued context list in trace_logging_info structure
490 trace_logging_info->queued_logging_context =
491 trace_logging_info->current_logging_context;
494 * Whether the context is queued or not, set the current context index
495 * to EMPTY, as the earlier context can no more be used to send
496 * more logging records.
500 trace_logging_info->current_logging_context = NULL;
504 * edt: * * spp_trace_log_send_pkt_always_success
506 * Tries to send a logging pkt. This cannot fail due to downstream
507 * constipation because we have already checked if the rewrite_output
508 * node can accept it.
510 * Argument: spp_trace_log_info_t *trace_logging_info
511 * structure that contains the packet context
513 * Argument: spp_node_t *output_node
514 * spp_node_t structure for rewrite_output node
517 void spp_trace_log_send_pkt_always_success (
518 spp_trace_log_info_t *trace_logging_info,
519 spp_node_t *output_node)
522 * At this point we either have a current or queued logging context
524 if (PREDICT_TRUE(trace_logging_info->current_logging_context != NULL)) {
526 output_node->sf.ctxs[output_node->sf.nused++] =
527 trace_logging_info->current_logging_context;
529 trace_logging_info->current_logging_context = NULL;
532 * For queued logging context
534 output_node->sf.ctxs[output_node->sf.nused++] =
535 trace_logging_info->queued_logging_context;
537 trace_logging_info->queued_logging_context = NULL;
541 * Move the logging context to output node
543 spp_dispatch_make_node_runnable(output_node);
548 * edt: * * spp_create_trace_log_context
550 * Tries to create a logging context with packet buffer
551 * to send a new logging packet
553 * Argument: spp_trace_log_info_t *trace_logging_info
554 * structure that contains the nfv9 logging info and will store
555 * the packet context as well.
558 void spp_create_trace_log_context (
559 spp_trace_log_info_t *trace_logging_info)
564 * If queued_logging_context_index is non-EMPTY, we already have a logging
565 * packet queued to be sent. First try sending this before allocating
566 * a new context. We can have only one active packet context per
567 * trace_logging_info structure
569 if (PREDICT_FALSE(trace_logging_info->queued_logging_context != NULL)) {
570 spp_trace_log_send_queued_pkt(trace_logging_info);
572 * If we cannot still send the queued pkt, just return
573 * Downstream Constipation count would have increased anyway
575 if (trace_logging_info->queued_logging_context != NULL) {
576 spp_global_counters.spp_trace_log_context_creation_deferred_count++;
583 * No context can be allocated, return silently
584 * calling routine will handle updating the error counters
586 if (spp_ctx_alloc(&ctx, 1) < 1) {
587 spp_global_counters.spp_trace_log_context_creation_fail_count++;
591 trace_logging_info->current_logging_context = ctx;
592 trace_logging_info->pkt_length = 0;
594 trace_logging_info->current_logging_context_timestamp =
595 spp_trace_log_get_sys_up_time_in_ms();
597 ctx->flags = SPP_CTX_END_OF_PACKET;
598 ctx->ru.tx.from_node = NODE_TRACE_BACKUP;
599 ctx->ru.tx.dst_ip_port_idx = EXT_TRACE_BACKUP_INDEX;
600 ctx->next_ctx_this_packet = (spp_ctx_t*) SPP_CTX_NO_NEXT_CTX;
601 ctx->current_header = &ctx->packet_data[SPP_TRACE_LOG_HDR_OFFSET];
602 ctx->current_length = 0;
604 trace_logging_info->log_record = 0;
605 trace_logging_info->total_record_count = 0;
606 trace_logging_info->next_data_ptr =
607 (u8 *) &ctx->packet_data[SPP_TRACE_LOG_HDR_OFFSET];
612 * edt: * * spp_trace_log_add_record_create
614 * Tries to create an add record to the NFV9 packet
616 * Argument: spp_trace_log_info_t *trace_logging_info
617 * structure that contains the nfv9 logging info and will store
618 * the packet context as well.
621 void spp_trace_log_add_record_create (spp_trace_log_info_t *trace_logging_info)
624 trace_logging_info->log_header =
625 (spp_trace_log_hdr_t *) (trace_logging_info->next_data_ptr);
628 * Initialize the number of traces recorded
630 trace_logging_info->log_header->num_traces =
631 spp_host_to_net_byte_order_32(0);
634 trace_logging_info->log_record =
635 (spp_trace_log_t *) (trace_logging_info->log_header + 1);
638 * Update the length of the total pkt
640 trace_logging_info->pkt_length +=
641 SPP_LOG_TRACE_HEADER_LENGTH;
644 * Set the data pointer beyond the trace header field
646 trace_logging_info->next_data_ptr =
647 (u8 *) (trace_logging_info->log_header + 1);
652 * edt: * * spp_trace_logger
654 * Tries to log spp/cnat event/errors
656 * Argument: u8 *error_code
659 * Argument: optional arguments
661 void spp_trace_logger (u16 error_code, u16 num_args, u32 *arg)
663 spp_trace_log_info_t *trace_logging_info = 0;
667 spp_trace_log_info_pool +
668 spp_trace_log_global_info.spp_log_pool_index[SPP_LOG_LTRACE];
670 if (PREDICT_FALSE(trace_logging_info->current_logging_context == NULL)) {
671 spp_create_trace_log_context(trace_logging_info);
674 * If still empty, return after increasing the count
676 if (PREDICT_FALSE(trace_logging_info->current_logging_context == NULL)) {
681 if (PREDICT_FALSE(trace_logging_info->log_record == NULL)) {
682 spp_trace_log_add_record_create(trace_logging_info);
686 * We should definitely have add_record now, no need to sanitize
688 trace_logging_info->log_record->error_code =
689 spp_host_to_net_byte_order_16(error_code);
690 trace_logging_info->log_record->num_args =
691 spp_host_to_net_byte_order_16(num_args);
693 for (i = 0; i < num_args; i++) {
694 trace_logging_info->log_record->arg[i] =
695 spp_host_to_net_byte_order_32(*(arg + i));
698 trace_logging_info->pkt_length += SPP_TRACE_LOG_RECORD_LENGTH + WORD_SIZE*num_args;
699 trace_logging_info->current_logging_context->current_length =
700 trace_logging_info->pkt_length;
701 trace_logging_info->total_record_count += 1;
703 trace_logging_info->next_data_ptr =
704 (u8 *) (trace_logging_info->next_data_ptr + WORD_SIZE + WORD_SIZE*num_args);
706 trace_logging_info->log_record =
707 (spp_trace_log_t *) (trace_logging_info->next_data_ptr);
710 * Initialize the number of traces recorded
712 trace_logging_info->log_header->num_traces =
713 spp_host_to_net_byte_order_32(trace_logging_info->total_record_count);
718 * If we have exceeded the packet length, let us send the
719 * packet now. There is buffer of additional bytes beyond
720 * max_pkt_length to ensure that the last add/delete record
721 * can be stored safely.
723 if (trace_logging_info->pkt_length >
724 trace_logging_info->max_length_minus_max_record_size) {
725 spp_trace_log_send_pkt(trace_logging_info);
731 * edt: * * spp_trace_log_timer_handler
733 * Timer handler for sending any pending NFV9 record
735 * Argument: spp_timer_t * timer_p
736 * Timer handler structure
739 void spp_trace_log_timer_handler (spp_timer_t * timer_p)
741 spp_node_t *output_node;
742 spp_trace_log_info_t *trace_logging_info = 0;
743 u32 current_timestamp = spp_trace_log_get_sys_up_time_in_ms();
746 output_node = spp_get_nodes() +
747 spp_trace_log_global_info.spp_trace_log_disp_node_index;
749 sf_nused = output_node->sf.nused;
751 pool_foreach (trace_logging_info, spp_trace_log_info_pool, ({
753 * Check if no more logging contexts can be queued
755 if (PREDICT_FALSE(sf_nused >= SPP_MAXDISPATCH)) {
760 * If there is a current logging context and timestamp
761 * indicates it is pending for long, send it out
762 * Also if there is a queued context send it out as well
764 if (trace_logging_info->queued_logging_context ||
765 (trace_logging_info->current_logging_context &&
767 trace_logging_info->current_logging_context_timestamp)
769 spp_trace_log_send_pkt_always_success(trace_logging_info,
776 spp_timer_in_n_ms_inline(1000); /* every 1 sec */
777 spp_timer_start(timer_p);
781 void spp_sensor_timer_handler (spp_timer_t * timer_p)
783 #ifdef TARGET_RODDICK
784 if (!temperature_read_blocked) {
785 Init_temperature_sensors();
786 read_octeon_sensors(TEMPERATURE_SENSOR_QUIET_MODE);
790 spp_timer_in_n_ms_inline(60000); /* every 1 sec */
791 spp_timer_start(timer_p);
795 void init_trace_log_buf_pool (void)
797 spp_trace_log_info_t *my_spp_log_info;
799 spp_log_type_t log_type;
802 * Init SPP logging info as needed, this will be done only once
804 spp_trace_log_init();
808 for (log_type = SPP_LOG_LTRACE; log_type < SPP_LOG_MAX; log_type++ ) {
809 /* Do we already have a map for this log type? */
810 pool_foreach (my_spp_log_info, spp_trace_log_info_pool, ({
811 if (my_spp_log_info->log_type == log_type) {
821 pool_get(spp_trace_log_info_pool, my_spp_log_info);
822 memset(my_spp_log_info, 0, sizeof(*my_spp_log_info));
825 * Make the current and head logging context indeices as EMPTY.
826 * When first logging happens, these get set correctly
828 my_spp_log_info->current_logging_context = NULL;
829 my_spp_log_info->queued_logging_context = NULL;
831 my_spp_log_info->log_type = log_type;
832 my_spp_log_info->max_length_minus_max_record_size =
833 SPP_TRACE_LOG_MAX_PKT_LENGTH;
835 spp_trace_log_global_info.spp_log_pool_index[log_type] =
836 my_spp_log_info - spp_trace_log_info_pool;
847 * has to be called at the init time
849 void spp_trace_log_init (void)
851 if (!spp_trace_log_global_info.spp_trace_log_init_done) {
853 #ifdef TARGET_RODDICK
854 spp_trace_log_global_info.spp_trace_log_disp_node_index =
855 spp_lookup_node_index("roddick_infra_l3_tx");
856 #elif defined(TARGET_BOOSTER)
857 spp_trace_log_global_info.spp_trace_log_disp_node_index =
858 spp_lookup_node_index("booster_infra_l3_tx");
860 ASSERT(spp_trace_log_global_info.spp_trace_log_disp_node_index != (u16)~0);
862 spp_trace_log_global_info.log_timer.cb_index =
863 spp_timer_register_callback(spp_trace_log_timer_handler);
864 spp_trace_log_global_info.log_timer.expires =
865 spp_timer_in_n_ms_inline(1000); /* every 1 sec */
866 spp_timer_start(&spp_trace_log_global_info.log_timer);
869 sensor_timer.cb_index =
870 spp_timer_register_callback(spp_sensor_timer_handler);
871 sensor_timer.expires =
872 spp_timer_in_n_ms_inline(60000); /* every 1 sec */
873 spp_timer_start(&sensor_timer);
876 spp_trace_log_global_info.spp_trace_log_init_done = 1;
879 * Set MSC ip_addr, port values
881 #ifdef TARGET_RODDICK
882 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].ipv4_address =
883 vpp_boot_params.msc_ip_address;
884 switch(vpp_boot_params.octeon_number) {
886 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
889 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
892 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
895 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
899 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].ipv4_address = 0x01020304;
900 dst_ipv4_port_table[EXT_TRACE_BACKUP_INDEX].port = 0x15BF;
906 void spp_printf (u16 error_code, u16 num_args, u32 *arg)
908 u32 current_timestamp;
909 spp_node_main_vector_t *nmv;
911 if (PREDICT_FALSE(error_code >= LOG_TABLE_MAX_ENTRIES))
913 /* printf("Error code invalid %d, %d, %d, %d\n",
914 error_code, LOG_TABLE_MAX_ENTRIES,
915 sizeof(spp_cnat_logger_table), sizeof(spp_cnat_logger_table[0]));
917 return; /* Should not happen */
920 nmv = spp_get_node_main_vectorized_inline();
921 current_timestamp = nmv->ticks / nmv->ticks_per_second;
923 /* Check if any further hashing is required */
925 if (PREDICT_FALSE(error_code == DUMP_PKT_IDX)) {
926 #ifdef TARGET_RODDICK || defined(TARGET_BOOSTER)
927 spp_trace_logger(error_code, num_args, arg);
931 printf("PKT DUMP :: ");
932 for (j = 0 ; j < num_args; j++) {
933 printf("0x%x ", arg[j]);
934 if (j == (num_args - 1)) {
939 } else if (PREDICT_TRUE((current_timestamp - error_code_timestamps[error_code]) >=
940 spp_cnat_logger_table[error_code].rate_limit_time)) {
941 /* update timestamp */
942 error_code_timestamps[error_code] = current_timestamp;
944 #ifdef TARGET_RODDICK || defined(TARGET_BOOSTER)
945 spp_trace_logger(error_code, num_args, arg);
949 for (j = 0 ; j < num_args; j++) {
950 printf("%s: %d ", spp_cnat_logger_table[error_code].param_name[j], arg[j]);
951 if (j == (num_args - 1)) {
959 #else /* TOBE_PORTEED */
960 void spp_trace_logger(u16 error_code, u16 num_args, u32 *arg)
965 void spp_trace_log_init(void)
970 void init_trace_log_buf_pool(void)
975 void spp_printf(u16 error_code, u16 num_args, u32 *arg)
980 inline u32 spp_trace_log_get_unix_time_in_seconds (void)
982 vlib_main_t *vlib_main;
984 vlib_main = vlib_get_main();
985 return(vlib_time_now((vlib_main_t *) vlib_main));
988 #endif /* TOBE_PORTED */