diff --git a/cwmp.c b/cwmp.c index 172ee80..0cedc7f 100644 --- a/cwmp.c +++ b/cwmp.c @@ -189,15 +189,23 @@ int cwmp_get_retry_interval(struct cwmp *cwmp, bool heart_beat) static int cwmp_rpc_cpe_handle_message(struct session *session, struct rpc *rpc_cpe) { - if (xml_prepare_msg_out(session)) + CWMP_LOG(DEBUG, "entry func: %s, line: %d", __FUNCTION__, __LINE__); + if (xml_prepare_msg_out(session)) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } - if (rpc_cpe_methods[rpc_cpe->type].handler(session, rpc_cpe)) + if (rpc_cpe_methods[rpc_cpe->type].handler(session, rpc_cpe)) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } - if (xml_set_cwmp_id_rpc_cpe(session)) + if (xml_set_cwmp_id_rpc_cpe(session)) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); return 0; } @@ -257,6 +265,7 @@ void check_firewall_restart_state() int cwmp_schedule_rpc(struct cwmp *cwmp, struct session *session) { + CWMP_LOG(DEBUG, "entry func: %s, line: %d", __FUNCTION__, __LINE__); struct list_head *ilist; struct rpc *rpc_acs, *rpc_cpe; @@ -328,6 +337,7 @@ int cwmp_schedule_rpc(struct cwmp *cwmp, struct session *session) CWMP_LOG(INFO, "Send the %s%s message to the ACS", rpc_cpe_methods[rpc_cpe->type].name, (rpc_cpe->type != RPC_CPE_FAULT) ? "Response" : ""); if (xml_send_message(cwmp, session, rpc_cpe) || thread_end) goto retry; + CWMP_LOG(INFO, "Send done"); MXML_DELETE(session->tree_out); cwmp_session_rpc_destructor(rpc_cpe); @@ -359,6 +369,7 @@ end: MXML_DELETE(session->tree_out); http_client_exit(); xml_exit(); + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); return session->error; } @@ -460,6 +471,7 @@ int run_session_end_func(void) static void cwmp_schedule_session(struct cwmp *cwmp) { + CWMP_LOG(DEBUG, "entry func: %s, line: %d", __FUNCTION__, __LINE__); int t; struct timespec time_to_wait = { 0, 0 }; bool retry = false; @@ -480,6 +492,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) CWMP_LOG(INFO, "Waiting the next session"); if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); pthread_mutex_unlock(&(cwmp->mutex_session_send)); return; } @@ -487,6 +500,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) pthread_cond_timedwait(&(cwmp->threshold_session_send), &(cwmp->mutex_session_send), &time_to_wait); if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); pthread_mutex_unlock(&(cwmp->mutex_session_send)); return; } @@ -498,6 +512,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) if (cwmp->session_status.last_status == SESSION_FAILURE) { cwmp_config_load(cwmp); if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); pthread_mutex_unlock(&mutex_heartbeat_session); pthread_mutex_unlock(&(cwmp->mutex_session_send)); return; @@ -516,6 +531,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) cwmp_prepare_value_change(cwmp); clean_list_value_change(); if ((error = cwmp_move_session_to_session_send(cwmp, session))) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); CWMP_LOG(EMERG, "FATAL error in the mutex process in the session scheduler!"); exit(EXIT_FAILURE); } @@ -540,6 +556,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) CWMP_LOG(INFO, "End session"); if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); event_remove_all_event_container(session, RPC_SEND); run_session_end_func(); cwmp_session_destructor(session); @@ -551,6 +568,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) if (session->error == CWMP_RETRY_SESSION && (!list_empty(&(session->head_event_container)) || (list_empty(&(session->head_event_container)) && cwmp->cwmp_cr_event == 0))) { cwmp_config_load(cwmp); if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); event_remove_all_event_container(session, RPC_SEND); run_session_end_func(); cwmp_session_destructor(session); @@ -586,6 +604,7 @@ static void cwmp_schedule_session(struct cwmp *cwmp) pthread_mutex_unlock(&mutex_heartbeat_session); pthread_mutex_unlock(&(cwmp->mutex_session_send)); } + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); } static void check_exit_timer_expiry(struct uloop_timeout *timeout) @@ -640,7 +659,9 @@ static void *thread_uloop_run(void *v __attribute__((unused))) static void *thread_http_cr_server_listen(void *v __attribute__((unused))) { + CWMP_LOG(DEBUG, "entry func: %s, line: %d", __FUNCTION__, __LINE__); http_server_listen(); + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); return NULL; } diff --git a/datamodel_interface.c b/datamodel_interface.c index 7543497..df98a27 100755 --- a/datamodel_interface.c +++ b/datamodel_interface.c @@ -387,24 +387,24 @@ int cwmp_get_leaf_value(char *leaf, char **value) size_t llen; if (leaf == NULL || value == NULL) { - CWMP_LOG(INFO, "Empty parameter/value in arguments") + CWMP_LOG(INFO, "Empty parameter/value in arguments"); return FAULT_CPE_INVALID_ARGUMENTS; } llen = strlen(leaf); if (llen == 0) { - CWMP_LOG(INFO, "Empty parameter in arguments") + CWMP_LOG(INFO, "Empty parameter in arguments"); return FAULT_CPE_INVALID_ARGUMENTS; } if (leaf[llen - 1] == '.') { - CWMP_LOG(INFO, "Non-leaf parameter parameter") + CWMP_LOG(INFO, "Non-leaf parameter parameter"); return FAULT_CPE_INVALID_ARGUMENTS; } cwmp_get_single_parameter_value(leaf, &dm_param); if (dm_param.name == NULL) { - CWMP_LOG(INFO, "Fault in getting the parameter %s", leaf) + CWMP_LOG(INFO, "Fault in getting the parameter %s", leaf); return FAULT_CPE_INTERNAL_ERROR; } diff --git a/download.c b/download.c index 7e73fe6..93c4862 100644 --- a/download.c +++ b/download.c @@ -261,6 +261,7 @@ int cwmp_launch_download(struct download *pdownload, char *download_file_name, e if (cwmp_check_image() == 0) { long int file_size = get_file_size(FIRMWARE_UPGRADE_IMAGE); if (file_size > flashsize) { + CWMP_LOG(ERROR, "download %s failed: file size %ld > flash size %ld", __FUNCTION__, file_size, flashsize); error = FAULT_CPE_DOWNLOAD_FAIL_FILE_CORRUPTED; remove(FIRMWARE_UPGRADE_IMAGE); goto end_download; @@ -269,6 +270,7 @@ int cwmp_launch_download(struct download *pdownload, char *download_file_name, e goto end_download; } } else { + CWMP_LOG(ERROR, "download %s, failed in cwmp_check_image", __FUNCTION__); error = FAULT_CPE_DOWNLOAD_FAIL_FILE_CORRUPTED; remove(FIRMWARE_UPGRADE_IMAGE); } diff --git a/http.c b/http.c index c906767..9f15bb7 100644 --- a/http.c +++ b/http.c @@ -35,12 +35,15 @@ char *fc_cookies = "/tmp/icwmp_cookies"; void http_set_timeout(void) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); if (curl) curl_easy_setopt(curl, CURLOPT_CONNECTTIMEOUT, 1); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } int http_client_init(struct cwmp *cwmp) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); char *dhcp_dis = NULL; char *acs_var_stat = NULL; @@ -55,12 +58,14 @@ int http_client_init(struct cwmp *cwmp) free(acs_var_stat); FREE(dhcp_dis); FREE(url); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; } } else { if (CWMP_STRLEN(url) == 0 || icwmp_asprintf(&http_c.url, "%s", url) == -1) { FREE(dhcp_dis); FREE(url); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; } } @@ -68,6 +73,7 @@ int http_client_init(struct cwmp *cwmp) if (url == NULL || icwmp_asprintf(&http_c.url, "%s", url) == -1) { FREE(dhcp_dis); FREE(url); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; } } @@ -76,15 +82,17 @@ int http_client_init(struct cwmp *cwmp) if (dhcp_dis) free(dhcp_dis); - CWMP_LOG(INFO, "ACS url: %s", http_c.url); + CWMP_LOG(INFO, "#### ACS url: %s", http_c.url); /* TODO debug ssl config from freecwmp*/ curl_global_init(CURL_GLOBAL_SSL); curl_glob_init = true; curl = curl_easy_init(); - if (!curl) + if (!curl) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } bool v6_enable = global_bool_param_read(&cwmp->conf.ipv6_enable); if (v6_enable) { @@ -100,11 +108,13 @@ int http_client_init(struct cwmp *cwmp) cwmp_uci_set_value("cwmp", "acs", "ip_version", (tmp == 1) ? "4" : "6"); } + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return 0; } void http_client_exit(void) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); icwmp_free(http_c.url); if (http_c.header_list) { @@ -122,37 +132,46 @@ void http_client_exit(void) curl_global_cleanup(); curl_glob_init = false; } + + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } static size_t http_get_response(void *buffer, size_t size, size_t rxed, char **msg_in) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); char *c = NULL; - CWMP_LOG(INFO, "HTTP CURL handler function"); + CWMP_LOG(INFO, "#### HTTP CURL handler function"); if (msg_in == NULL) { - CWMP_LOG(ERROR, "msg_in is null"); + CWMP_LOG(ERROR, "#### msg_in is null"); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return 0; } if (buffer == NULL) { - CWMP_LOG(ERROR, "Buffer is null"); + CWMP_LOG(ERROR, "#### Buffer is null"); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return 0; } if (cwmp_asprintf(&c, "%s%.*s", *msg_in, (int)(size * rxed), (char *)buffer) == -1) { FREE(*msg_in); + CWMP_LOG(ERROR, "#### asprintf failed"); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; } FREE(*msg_in); *msg_in = c; + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return size * rxed; } int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char **msg_in) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); unsigned char buf[sizeof(struct in6_addr)]; int tmp = 0; CURLcode res; @@ -163,16 +182,22 @@ int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char ** http_c.header_list = NULL; http_c.header_list = curl_slist_append(http_c.header_list, "User-Agent: iopsys-cwmp"); - if (!http_c.header_list) + if (!http_c.header_list) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } http_c.header_list = curl_slist_append(http_c.header_list, "Content-Type: text/xml"); - if (!http_c.header_list) + if (!http_c.header_list) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } if (global_bool_param_read(&cwmp->conf.http_disable_100continue)) { http_c.header_list = curl_slist_append(http_c.header_list, "Expect:"); - if (!http_c.header_list) + if (!http_c.header_list) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; + } } curl_easy_setopt(curl, CURLOPT_URL, http_c.url); global_string_param_read(&cwmp->conf.acs_userid, &temp); @@ -227,6 +252,7 @@ int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char ** FREE(temp); global_string_param_read(&cwmp->conf.interface, &temp); + CWMP_LOG(DEBUG, "#### func: %s, line: %d interface %s", __FUNCTION__, __LINE__, temp); curl_easy_setopt(curl, CURLOPT_INTERFACE, temp); FREE(temp); *msg_in = (char *)calloc(1, sizeof(char)); @@ -238,9 +264,9 @@ int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char ** if (len) { if (errbuf[len - 1] == '\n') errbuf[len - 1] = '\0'; - CWMP_LOG(ERROR, "libcurl: (%d) %s", res, errbuf); + CWMP_LOG(ERROR, "#### 1-libcurl: (%d) %s", res, errbuf); } else { - CWMP_LOG(ERROR, "libcurl: (%d) %s", res, curl_easy_strerror(res)); + CWMP_LOG(ERROR, "#### 2-libcurl: (%d) %s", res, curl_easy_strerror(res)); } } @@ -271,7 +297,7 @@ int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char ** curl_easy_getinfo(curl, CURLINFO_RESPONSE_CODE, &http_code); if (http_code == 204) { - CWMP_LOG(INFO, "Receive HTTP 204 No Content"); + CWMP_LOG(INFO, "#### Receive HTTP 204 No Content"); } if (http_code == 415) { @@ -291,6 +317,7 @@ int http_send_message(struct cwmp *cwmp, char *msg_out, int msg_out_len, char ** if (res) goto error; + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d success", __FUNCTION__, __LINE__); return 0; error: @@ -299,20 +326,24 @@ error: curl_slist_free_all(http_c.header_list); http_c.header_list = NULL; } + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d error", __FUNCTION__, __LINE__); return -1; } void http_success_cr(void) { - CWMP_LOG(INFO, "Connection Request thread: add connection request event in the queue"); + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); + CWMP_LOG(INFO, "#### Connection Request thread: add connection request event in the queue"); pthread_mutex_lock(&(cwmp_main.mutex_session_queue)); cwmp_add_event_container(&cwmp_main, EVENT_IDX_6CONNECTION_REQUEST, ""); pthread_mutex_unlock(&(cwmp_main.mutex_session_queue)); pthread_cond_signal(&(cwmp_main.threshold_session_send)); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } static void http_cr_new_client(int client, bool service_available) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); FILE *fp = NULL; char buffer[BUFSIZ] = {0}; char auth_digest_buffer[BUFSIZ] = {0}; @@ -324,21 +355,20 @@ static void http_cr_new_client(int client, bool service_available) char *temp = NULL; char *username = NULL; char *password = NULL; + fd_set rfds; + struct timeval tv; + int line_no = 0; + int status = 0; + + CWMP_LOG(INFO, "#### Received a new CR from ACS, service_available: %d", service_available); - CWMP_LOG(INFO, "Received a new CR from ACS, service_available: %d", service_available); - fp = fdopen(client, "r+"); - if (fp == NULL) { - CWMP_LOG(INFO, "Failed to open client socket"); - service_available = false; - goto http_end; - } global_string_param_read(&cwmp_main.conf.cpe_userid, &username); global_string_param_read(&cwmp_main.conf.cpe_passwd, &password); memset(auth_digest_buffer, 0, BUFSIZ); if (!username || !password) { // if we dont have username or password configured proceed with connecting to ACS - CWMP_LOG(INFO, "Failed to get acs username and password"); + CWMP_LOG(INFO, "#### Failed to get acs username and password"); service_available = false; goto http_end; } @@ -346,12 +376,36 @@ static void http_cr_new_client(int client, bool service_available) global_string_param_read(&cwmp_main.conf.connection_request_path, &temp); snprintf(cr_http_get_head, sizeof(cr_http_get_head), "GET %s HTTP/1.1", temp); FREE(temp); - while (fgets(buffer, sizeof(buffer), fp)) { + CWMP_LOG(INFO, "#### HTTP Head: (%s)", cr_http_get_head); + + tv.tv_sec = 5; //TODO config + tv.tv_usec = 0; + FD_ZERO(&rfds); + FD_SET(client, &rfds); + + status = select(client+1, &rfds, NULL, NULL, &tv); + if (status <= 0) { + CWMP_LOG(INFO, "#### TIMEOUT occured or select failed"); + goto http_end; + } + + fp = fdopen(client, "r+"); + if (fp == NULL) { + CWMP_LOG(INFO, "Failed to open client socket"); + goto http_end; + } + + while ((fgets(buffer, sizeof(buffer), fp) != NULL) && (line_no < 50)) { if (buffer[0] == '\r' || buffer[0] == '\n') { /* end of http request (empty line) */ break; } + if (line_no == 0 && (strstr(buffer, "GET ") == NULL || strstr(buffer, "HTTP/1.1") == NULL)) { + CWMP_LOG(INFO, "#### GET or HTTP/1.1 not found at 1st line"); + break; + } + if (strstr(buffer, "GET ") != NULL && strstr(buffer, "HTTP/1.1") != NULL) { // check if extra url parameter then ignore extra params int j = 0; @@ -377,11 +431,15 @@ static void http_cr_new_client(int client, bool service_available) strip_lead_trail_char(buffer, '\n'); strip_lead_trail_char(buffer, '\r'); + CWMP_LOG(INFO, "#### BUFFER: (%s)", buffer); if (!strncasecmp(buffer, "Authorization: Digest ", strlen("Authorization: Digest "))) { auth_digest_checked = true; CWMP_STRNCPY(auth_digest_buffer, buffer, BUFSIZ); } + + line_no++; } + if (!service_available || !method_is_get) { goto http_end; } @@ -398,15 +456,20 @@ static void http_cr_new_client(int client, bool service_available) http_end: FREE(username); FREE(password); + + if (fp) { + fflush(fp); + } + if (!service_available || !method_is_get) { - CWMP_LOG(WARNING, "Receive Connection Request: Return 503 Service Unavailable"); + CWMP_LOG(WARNING, "#### Receive Connection Request: Return 503 Service Unavailable"); if (fp) { fputs("HTTP/1.1 503 Service Unavailable\r\n", fp); fputs("Connection: close\r\n", fp); fputs("Content-Length: 0\r\n", fp); } } else if (auth_status) { - CWMP_LOG(INFO, "Receive Connection Request: success authentication"); + CWMP_LOG(INFO, "#### Receive Connection Request: success authentication"); if (fp) { fputs("HTTP/1.1 200 OK\r\n", fp); fputs("Connection: close\r\n", fp); @@ -414,7 +477,7 @@ http_end: } http_success_cr(); } else if (internal_error) { - CWMP_LOG(WARNING, "Receive Connection Request: Return 500 Internal Error"); + CWMP_LOG(WARNING, "#### Receive Connection Request: Return 500 Internal Error"); if (fp) { fputs("HTTP/1.1 500 Internal Server Error\r\n", fp); fputs("Connection: close\r\n", fp); @@ -422,7 +485,7 @@ http_end: } } else { - CWMP_LOG(WARNING, "Receive Connection Request: Return 401 Unauthorized"); + CWMP_LOG(WARNING, "#### Receive Connection Request: Return 401 Unauthorized"); if (fp) { fputs("HTTP/1.1 401 Unauthorized\r\n", fp); fputs("Connection: close\r\n", fp); @@ -434,10 +497,12 @@ http_end: fputs("\r\n", fp); fclose(fp); } + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } void http_server_init(void) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); struct sockaddr_in6 server = { 0 }; unsigned short cr_port; unsigned short prev_cr_port = (unsigned short)global_int_param_read(&cwmp_main.conf.connection_request_port); @@ -446,21 +511,24 @@ void http_server_init(void) cr_port = (unsigned short)global_int_param_read(&cwmp_main.conf.connection_request_port); unsigned short i = (DEFAULT_CONNECTION_REQUEST_PORT == cr_port) ? 1 : 0; //Create socket - if (thread_end) + if (thread_end) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return; + } cwmp_main.cr_socket_desc = socket(AF_INET6, SOCK_STREAM, 0); if (cwmp_main.cr_socket_desc == -1) { - CWMP_LOG(ERROR, "Could not open server socket for Connection Requests, Error no is : %d, Error description is : %s", errno, strerror(errno)); + CWMP_LOG(ERROR, "#### Could not open server socket for Connection Requests, Error no is : %d, Error description is : %s", errno, strerror(errno)); sleep(1); continue; } + CWMP_LOG(DEBUG, "#### sock_fd: %d", cwmp_main.cr_socket_desc); fcntl(cwmp_main.cr_socket_desc, F_SETFD, fcntl(cwmp_main.cr_socket_desc, F_GETFD) | FD_CLOEXEC); int reusaddr = 1; if (setsockopt(cwmp_main.cr_socket_desc, SOL_SOCKET, SO_REUSEADDR, &reusaddr, sizeof(int)) < 0) { - CWMP_LOG(WARNING, "setsockopt(SO_REUSEADDR) failed"); + CWMP_LOG(WARNING, "#### setsockopt(SO_REUSEADDR) failed"); } //Prepare the sockaddr_in structure @@ -468,16 +536,18 @@ void http_server_init(void) server.sin6_addr = in6addr_any; for (;; i++) { - if (thread_end) + if (thread_end) { + CWMP_LOG(DEBUG, "exit func: %s, line: %d", __FUNCTION__, __LINE__); return; + } server.sin6_port = htons(cr_port); //Bind if (bind(cwmp_main.cr_socket_desc, (struct sockaddr *)&server, sizeof(server)) < 0) { //print the error message - CWMP_LOG(ERROR, "Could not bind server socket on the port %d, Error no is : %d, Error description is : %s", cr_port, errno, strerror(errno)); + CWMP_LOG(ERROR, "#### Could not bind server socket on the port %d, Error no is : %d, Error description is : %s", cr_port, errno, strerror(errno)); cr_port = DEFAULT_CONNECTION_REQUEST_PORT + i; - CWMP_LOG(INFO, "Trying to use another connection request port: %d", cr_port); + CWMP_LOG(INFO, "#### Trying to use another connection request port: %d", cr_port); continue; } break; @@ -492,11 +562,13 @@ void http_server_init(void) connection_request_port_value_change(&cwmp_main, cr_port); } - CWMP_LOG(INFO, "Connection Request server initiated with the port: %d", cr_port); + CWMP_LOG(INFO, "#### Connection Request server initiated with the port: %d", cr_port); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } void http_server_listen(void) { + CWMP_LOG(DEBUG, "#### entry func: %s, line: %d", __FUNCTION__, __LINE__); int c; int cr_request = 0; time_t restrict_start_time = 0; @@ -508,12 +580,14 @@ void http_server_listen(void) //Accept and incoming connection c = sizeof(struct sockaddr_in); do { - if (thread_end) + if (thread_end) { + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); return; + } int client_sock = accept(cwmp_main.cr_socket_desc, (struct sockaddr *)&client, (socklen_t *)&c); if (client_sock < 0) { - CWMP_LOG(ERROR, "Could not accept connections for Connection Requests!"); + CWMP_LOG(ERROR, "#### Could not accept connections for Connection Requests! Error: %d", errno); shutdown(cwmp_main.cr_socket_desc, SHUT_RDWR); http_server_init(); listen(cwmp_main.cr_socket_desc, 3); @@ -522,6 +596,7 @@ void http_server_listen(void) continue; } + CWMP_LOG(DEBUG, "#### accepted socket %d", client_sock); bool service_available; time_t current_time; @@ -535,10 +610,12 @@ void http_server_listen(void) if (cr_request > CONNECTION_REQUEST_RESTRICT_REQUEST) { restrict_start_time = current_time; service_available = false; - CWMP_LOG(WARNING, "CR count %d exceeded max %d, SKIPPED", cr_request, CONNECTION_REQUEST_RESTRICT_REQUEST); + CWMP_LOG(WARNING, "#### CR count %d exceeded max %d, SKIPPED", cr_request, CONNECTION_REQUEST_RESTRICT_REQUEST); } } http_cr_new_client(client_sock, service_available); close(client_sock); + CWMP_LOG(DEBUG, "#### Client socket %d closed", client_sock); } while (1); + CWMP_LOG(DEBUG, "#### exit func: %s, line: %d", __FUNCTION__, __LINE__); } diff --git a/test/files/usr/libexec/rpcd/rpc-sys b/test/files/usr/libexec/rpcd/rpc-sys index b525dbb..4778d2e 100755 --- a/test/files/usr/libexec/rpcd/rpc-sys +++ b/test/files/usr/libexec/rpcd/rpc-sys @@ -18,6 +18,10 @@ case "$1" in ;; upgrade_start) cat /tmp/rpc_sys.data 2>/dev/null + sleep 10 + supervisorctl stop icwmpd + sleep 5 + supervisorctl start icwmpd ;; esac ;; diff --git a/test/script/verify_custom_notifications.sh b/test/script/verify_custom_notifications.sh index 95bd980..7fd547e 100755 --- a/test/script/verify_custom_notifications.sh +++ b/test/script/verify_custom_notifications.sh @@ -26,7 +26,7 @@ sleep 5 check_cwmp_status supervisorctl stop icwmpd - +sleep 5 check_valgrind_xml notif1=`uci -c /etc/icwmpd get cwmp_notifications.@notifications[0].active | grep "Device.Users."` diff --git a/test/script/verify_download_method.sh b/test/script/verify_sw_download_method.sh similarity index 94% rename from test/script/verify_download_method.sh rename to test/script/verify_sw_download_method.sh index 2f81637..a30104e 100755 --- a/test/script/verify_download_method.sh +++ b/test/script/verify_sw_download_method.sh @@ -22,9 +22,7 @@ fi [ -f "/etc/icwmpd/dm_enabled_notify" ] && rm /etc/icwmpd/dm_enabled_notify remove_icwmp_log echo "Restarting icwmpd in order to apply the new firmware" >> ./funl-test-debug.log -supervisorctl stop icwmpd >> ./funl-test-debug.log -check_valgrind_xml -supervisorctl start icwmpd >> ./funl-test-debug.log +sleep 20 check_cwmp_status sleep 5 diff --git a/xml.c b/xml.c index 7c6c4ea..ec3ecc8 100644 --- a/xml.c +++ b/xml.c @@ -134,6 +134,7 @@ void xml_exit(void) int xml_send_message(struct cwmp *cwmp, struct session *session, struct rpc *rpc) { + CWMP_LOG(INFO, "#### %s start ####", __FUNCTION__); char *s, *msg_out = NULL, *msg_in = NULL; char c[512]; int msg_out_len = 0, f, r = 0; @@ -146,6 +147,7 @@ int xml_send_message(struct cwmp *cwmp, struct session *session, struct rpc *rpc } if (session->tree_out) { + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); unsigned char *zmsg_out; msg_out = mxmlSaveAllocString(session->tree_out, MXML_NO_CALLBACK); if (msg_out == NULL) { @@ -153,9 +155,13 @@ int xml_send_message(struct cwmp *cwmp, struct session *session, struct rpc *rpc return -1; } + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); CWMP_LOG_XML_MSG(DEBUG, msg_out, XML_MSG_OUT); + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); if (compression != COMP_NONE) { + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); if (zlib_compress(msg_out, &zmsg_out, &msg_out_len, compression)) { + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); return -1; } FREE(msg_out); @@ -163,6 +169,7 @@ int xml_send_message(struct cwmp *cwmp, struct session *session, struct rpc *rpc } else { msg_out_len = msg_out ? strlen(msg_out) : 0; } + CWMP_LOG(INFO, "#### %s line: %d ####", __FUNCTION__, __LINE__); } while (1) { f = 0; @@ -223,11 +230,13 @@ int xml_send_message(struct cwmp *cwmp, struct session *session, struct rpc *rpc end: FREE(msg_out); FREE(msg_in); + CWMP_LOG(INFO, "#### %s return ####", __FUNCTION__); return 0; error: FREE(msg_out); FREE(msg_in); + CWMP_LOG(INFO, "#### %s return ####", __FUNCTION__); return -1; }