HTTP Server stops responding with NTP

[pppTec]

I am trying to get the HTTP server working together with the NTP and MQTT services. I am using ESP-IDF 5.2. However, I am struggling to get it working stable. I thought I got NTP and HTTP server running together stable, so I moved on to MQTT, but as soon as the MQTT service is trying to connect to the broker while the HTTP server was serving a page, the HTTP server stops responding after a while. The only solution is to perform a reset of the ESP32-S2 at the moment. Therefore, I removed the MQTT service/task in order to finishing the NTP sync feature, but apparently it gives the same problem. It seems that when the NTP server is trying to connect to the server and the HTTP server is serving pages, it may get stuck and unresponsive. I'm not sure whether this is caused due to the NTP syncing or just because the NTP task is interrupting the webserver in some way. The webserver gives this error then:

W (662507) httpd_txrx: httpd_sock_err: error in send : 11
W (662517) httpd_uri: httpd_uri: uri handler execution failed

Here's an outline of what I currently have (leaving out MQTT for now):

- ESP32-S2 Wifi set to work as Wifi hotspot and connects to user defined access point with internet
- HTTP server from ESP-IDF with priority 6
- NTP sync task running at priority 1
- I have 2 other tasks running at priority 24 and 1 respectively. Without the NTP task everything works fine, however.

Here's the code to start the HTTP server:

Code: Select all

esp_err_t start_rest_server(const char *base_path)
{
    if (server != NULL)
    {
        ESP_LOGE(REST_TAG, "Server already started");
        return ESP_FAIL;
    }

    REST_CHECK(base_path, "wrong base path", err);
    rest_server_context_t *rest_context = calloc(1, sizeof(rest_server_context_t));
    REST_CHECK(rest_context, "No memory for rest context", err);
    strlcpy(rest_context->base_path, base_path, sizeof(rest_context->base_path));

    

    server = NULL;
    httpd_config_t config = HTTPD_DEFAULT_CONFIG();
    config.max_uri_handlers = 18;
    config.task_priority = tskIDLE_PRIORITY+6;
    config.uri_match_fn = httpd_uri_match_wildcard;
    config.lru_purge_enable = true;

    ESP_LOGI(REST_TAG, "Starting HTTP Server");
    REST_CHECK(httpd_start(&server, &config) == ESP_OK, "Start server failed", err_start);
    
    // Then follow a bunch of endpoint registrations...
    
     return ESP_OK;
err_start:
    free(rest_context);
err:
    return ESP_FAIL;

Here's the code for serving general pages (all files are served from the flash memory):

Code: Select all

static esp_err_t rest_common_get_handler(httpd_req_t *req)
{
    char filepath[FILE_PATH_MAX];

    rest_server_context_t *rest_context = (rest_server_context_t *)req->user_ctx;
    strlcpy(filepath, rest_context->base_path, sizeof(filepath));
    if (req->uri[strlen(req->uri) - 1] == '/') {
        strlcat(filepath, "/index.html", sizeof(filepath));
    } else {
        strlcat(filepath, req->uri, sizeof(filepath));
    }

    size_t buf_len = httpd_req_get_url_query_len(req);
    #ifdef DEBUG_REST_SERVER
    ESP_LOGI(REST_TAG, "Query length %d, filepath %d", buf_len, strlen(filepath));
    #endif

    
    if (buf_len > 0)
    {
        strlcpy(filepath, filepath, strlen(filepath)-buf_len);
    }
    // ESP_LOGI("REST", "URI: %s", filepath);
    if (strncmp(filepath, rest_context->base_path, strlen(filepath) - 1) == 0)
    {
        strlcat(filepath, "index.html", sizeof(filepath));
    }

    int fd = open(filepath, O_RDONLY, 0);
    if (fd == -1) {
        // ESP_LOGE(REST_TAG, "Failed to open file : %s", filepath);
        if (CHECK_FILE_EXTENSION(filepath, ".js"))
        {
            strlcat(filepath, ".gz", sizeof(filepath));
        }
        // ESP_LOGE(REST_TAG, "Trying %s", filepath);
        fd = open(filepath, O_RDONLY, 0);

        if (fd == -1)
        {
            /* Respond with 500 Internal Server Error */
            httpd_resp_send_err(req, HTTPD_500_INTERNAL_SERVER_ERROR, "Failed to read existing file");
            return ESP_FAIL;
        }
    }

    set_content_type_from_file(req, filepath);

    if (CHECK_FILE_EXTENSION(filepath, ".gz"))
    {
        httpd_resp_set_hdr(req, "Content-Encoding", "gzip");
    }

    if (CHECK_FILE_EXTENSION(filepath, ".json")){
            httpd_resp_set_type(req, "text/json");
    }

    if (CHECK_FILE_EXTENSION(filepath, ".py") )
    {
         // Extract the filename from the filepath
        const char *filename = strrchr(filepath, '/');
        if (filename) // Check if the '/' character was found
        {
            filename++; // Move past the '/' to the start of the actual filename
        }
        else
        {
            filename = filepath; // No '/' found, the whole path is the filename
        }

        // Set the HTTP headers
        httpd_resp_set_hdr(req, "Content-Type", "application/octet-stream");

        // Create a buffer for the Content-Disposition header
        char content_disposition[256]; // Adjust size as needed
        snprintf(content_disposition, sizeof(content_disposition), "attachment; filename=\"%s\"", filename);

        // Set the Content-Disposition header with the actual filename
        httpd_resp_set_hdr(req, "Content-Disposition", content_disposition);
    }

    char *chunk = rest_context->scratch;
    ssize_t read_bytes;
    do {
        /* Read file in chunks into the scratch buffer */
        read_bytes = read(fd, chunk, SCRATCH_BUFSIZE);
        if (read_bytes == -1) {
             ESP_LOGE(REST_TAG, "Failed to read file : %s", filepath);
        } else if (read_bytes > 0) {
            /* Send the buffer contents as HTTP response chunk */
            if (httpd_resp_send_chunk(req, chunk, read_bytes) != ESP_OK) {
                close(fd);
                ESP_LOGE(REST_TAG, "File sending failed!");
                /* Abort sending file */
                httpd_resp_sendstr_chunk(req, NULL);
                /* Respond with 500 Internal Server Error */
                httpd_resp_send_err(req, HTTPD_500_INTERNAL_SERVER_ERROR, "Failed to send file");
                return ESP_FAIL;
            }
        }
    } while (read_bytes > 0);
    /* Close file after sending complete */
    close(fd);
    #ifdef DEBUG_REST_SERVER
    ESP_LOGI(REST_TAG, "File sending complete");
    #endif
    /* Respond with an empty chunk to signal HTTP response completion */
    httpd_resp_send_chunk(req, NULL, 0);
    return ESP_OK;
}

And the NTP task code:

Code: Select all

static const char *TAG = "NTP_SYNC";
uint8_t allowSyncDuringLogging = 1;

// #define SYNC_INTERVAL_MS (24 * 60 * 60 * 1000) // 24 hours
#define SYNC_INTERVAL_MS (10 * 1000) // 10 seconds

static TimerHandle_t sync_timer;
extern EventGroupHandle_t s_connection_event_group;
extern EventGroupHandle_t wifi_event_group;

void sync_timer_callback(TimerHandle_t xTimer)
{
    xEventGroupSetBits(s_connection_event_group, NTP_SYNC_TRIGGER_BIT);
}

esp_err_t ntp_task_init()
{
    // Create the sync timer
    sync_timer = xTimerCreate("SyncTimer", pdMS_TO_TICKS(SYNC_INTERVAL_MS), pdTRUE, (void *)0, sync_timer_callback);
    if (sync_timer == NULL)
    {
        ESP_LOGE(TAG, "Failed to create sync timer");
        return ESP_FAIL;
    }
    else
    {
        if (xTimerStart(sync_timer, 0) != pdPASS)
        {
            ESP_LOGE(TAG, "Failed to start sync timer");
            return ESP_FAIL;
        }
    }

    return ESP_OK;

}
    
void ntp_time_sync_task(void *pvParameters)
{
        ESP_LOGI(TAG, "Starting NTP time sync");
        if (ntp_task_init() != ESP_OK)
        {
            ESP_LOGE(TAG, "Error initializing NTP sync!");
            vTaskDelete(NULL);
        }

        esp_sntp_config_t config = ESP_NETIF_SNTP_DEFAULT_CONFIG("pool.ntp.org");
        config.start = false;
        // Wait for time to be set
        time_t now = 0;
        esp_err_t ret; 

        int retry = 0;
        const int retry_count = 6;
        uint8_t restartLogging = 0;

        esp_netif_sntp_init(&config);

    while (1)
    {
        // wait for ntp sync trigger to be set
        EventBits_t bits = xEventGroupWaitBits(s_connection_event_group, NTP_SYNC_TRIGGER_BIT, pdTRUE, pdFALSE, portMAX_DELAY);  

        retry = 0;
        esp_netif_sntp_start(); 

        while (1) 
        {
            // retrieve the status Wifi bit immediately
            EventBits_t wifiBits = xEventGroupWaitBits(wifi_event_group, WIFI_CONNECTED_BIT, pdFALSE, pdFALSE, 0);
            
            if((wifiBits & WIFI_CONNECTED_BIT) == 0)
            {
                ESP_LOGW(TAG, "Not connected to WiFi AP. Cannot perform NTP time sync");
                break;
            }

            ESP_LOGI(TAG, "Syncing time...");
            ret = esp_netif_sntp_sync_wait(15000 / portTICK_PERIOD_MS);

            if ( ret == ESP_ERR_TIMEOUT  && (++retry < retry_count) )
            {
                ESP_LOGI(TAG, "Timeout. retrying... (%d/%d)", retry, retry_count);
            } else if ( ret == ESP_OK) {
                // Time retrieved
                time(&now);
                // set time

                

                uint64_t recvTime = (uint64_t)now * 1000LL;
                settings_set_timestamp((uint64_t)recvTime);
               
        
                ESP_LOGI(TAG, "NTP sync succesfull");
                break;

            
                //localtime_r(&now, &timeinfo);
            } else {
        
                ESP_LOGI(TAG, "Failed to retieve time");
                break;
            }            
        }
        
    }
}

Where the wifi_event_group is set in another file, which sets the WIFI_CONNECTED_BIT when the ESP32-S2 is connected to an Access Point. If a client connects to the ESP32-S2 Station it's not set.

The LWIP task is running at prio 18. Here's an example output:

Code: Select all

I (245206) LOGGER: Received task: 9
D (245206) httpd_txrx: httpd_recv_with_opt: received length = 128
D (245216) httpd_parse: read_block: received HTTP request block size = 128
D (245226) httpd_parse: cb_header_value: processing value = //192.168.4.1/index.html?page=log
D (245236) httpd_parse: cb_header_field: processing field = Accept-Encoding
D (245246) httpd_parse: cb_header_value: processing value = gzip, deflate
D (245256) httpd_parse: cb_header_field: processing field = Accept-Language
D (245266) httpd_parse: cb_header_value: processing value = en-US,en;q=0.9,nl;q=0.8,de-DE;q=0.7,de;q=0.6
D (245276) httpd_parse: parse_block: parsed block size = 360
D (245286) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245296) httpd_txrx: httpd_recv_with_opt: received length = 4
D (245306) httpd_parse: read_block: received HTTP request block size = 4
D (245316) httpd_parse: cb_header_value: processing value = 
D (245326) httpd_parse: cb_headers_complete: bytes read     = 391
D (245336) httpd_parse: cb_headers_complete: content length = 0
D (245346) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:3 posted to loop 0x3ffdd664
D (245346) httpd_parse: pause_parsing: paused
D (245356) httpd_parse: cb_no_body: message complete
D (245356) httpd_parse: httpd_parse_req: parsing complete
D (245356) httpd_uri: httpd_uri: request for /view.css with type 1
D (245366) httpd_uri: httpd_find_uri_handler: [0] = /ajax/calibrate
D (245376) httpd_uri: httpd_find_uri_handler: [1] = /ajax/formatSdcard
D (245386) httpd_uri: httpd_find_uri_handler: [2] = /ajax/getDefaultConfig
D (245396) httpd_uri: httpd_find_uri_handler: [3] = /ajax/getConfig
D (245406) httpd_uri: httpd_find_uri_handler: [4] = /ajax/getValues
D (245416) httpd_uri: httpd_find_uri_handler: [5] = /ajax/getRawAdc
D (245426) httpd_uri: httpd_find_uri_handler: [6] = /ajax/getStatus
D (245436) httpd_uri: httpd_find_uri_handler: [7] = /ajax/setTime
D (245446) httpd_uri: httpd_find_uri_handler: [8] = /ajax/setConfig
D (245456) httpd_uri: httpd_find_uri_handler: [9] = /ajax/loggerStop
D (245466) httpd_uri: httpd_find_uri_handler: [10] = /ajax/loggerStart
D (245476) httpd_uri: httpd_find_uri_handler: [11] = /ajax/sdcardUnmount
D (245486) httpd_uri: httpd_find_uri_handler: [12] = /ajax/getFileList/*
D (245496) httpd_uri: httpd_find_uri_handler: [13] = /fwupdate/*
D (245506) httpd_uri: httpd_find_uri_handler: [14] = /ajax/reboot
D (245516) httpd_uri: httpd_find_uri_handler: [15] = /upload/*
D (245526) httpd_uri: httpd_find_uri_handler: [16] = /delete/*
D (245536) httpd_uri: httpd_find_uri_handler: [17] = /*
D (245536) httpd_txrx: httpd_send_all: sent = 69
D (245536) httpd_txrx: httpd_send_all: sent = 2
D (245536) httpd_txrx: httpd_send_all: sent = 6
I (244666) NTP_SYNC: NTP sync succesfull
D (245556) httpd_txrx: httpd_send_all: sent = 9691
D (245556) httpd_txrx: httpd_send_all: sent = 2
D (245556) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:6 posted to loop 0x3ffdd664
D (245556) httpd_txrx: httpd_send_all: sent = 3
D (245566) httpd_txrx: httpd_send_all: sent = 2
D (245566) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:6 posted to loop 0x3ffdd664
D (245566) httpd_sess: httpd_sess_process: httpd_req_delete
D (245586) httpd_sess: httpd_sess_process: success
D (245586) httpd: httpd_server: processing listen socket 54
D (245596) httpd: httpd_accept_conn: newfd = 60
D (245596) httpd_sess: httpd_sess_new: fd = 60
D (245596) httpd_sess: httpd_sess_new: active sockets: 4
D (245596) httpd: httpd_accept_conn: complete
D (245596) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:2 posted to loop 0x3ffdd664
D (245596) httpd: httpd_server: doing select maxfd+1 = 61
D (245606) httpd: httpd_process_session: processing socket 60
D (245616) httpd_sess: httpd_sess_process: httpd_req_new
D (245616) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245626) httpd_txrx: httpd_recv_with_opt: received length = 128
D (245636) httpd_parse: read_block: received HTTP request block size = 128
D (245646) httpd_parse: cb_url: message begin
D (245646) httpd_parse: cb_url: processing url = /logo.png
D (245646) httpd_parse: verify_url: received URI = /logo.png
D (245656) httpd_parse: cb_header_field: headers begin
D (245656) httpd_txrx: httpd_unrecv: length = 104
D (245656) httpd_parse: pause_parsing: paused
D (245656) httpd_parse: cb_header_field: processing field = Host
D (245666) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245676) httpd_txrx: httpd_recv_with_opt: pending length = 104
D (245686) httpd_parse: read_block: received HTTP request block size = 104
D (245696) httpd_parse: continue_parsing: skip pre-parsed data of size = 5
D (245706) httpd_parse: continue_parsing: un-paused
D (245706) httpd_parse: cb_header_value: processing value = 192.168.4.1
D (245716) httpd_parse: cb_header_field: processing field = Connection
I (245726) LOGGER: Received task: 9
D (245726) httpd_parse: cb_header_value: processing value = keep-alive
D (245736) httpd_parse: cb_header_field: processing field = User-Agent
D (245746) httpd_parse: cb_header_value: processing value = Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWe
D (245756) httpd_parse: parse_block: parsed block size = 104
D (245766) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245776) httpd_txrx: httpd_recv_with_opt: received length = 128
D (245786) httpd_parse: read_block: received HTTP request block size = 128
D (245796) httpd_parse: cb_header_value: processing value = bKit/537.36 (KHTML, like Gecko) Chrome/126.0.0.0 Safari/537.36 Edg/126.0.0.0
D (245806) httpd_parse: cb_header_field: processing field = DNT
D (245816) httpd_parse: cb_header_value: processing value = 1
D (245826) httpd_parse: cb_header_field: processing field = Accept
D (245836) httpd_parse: cb_header_value: processing value = image/avif,image/webp,image/apng,i
D (245846) httpd_parse: parse_block: parsed block size = 232
D (245856) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245866) httpd_txrx: httpd_recv_with_opt: received length = 128
D (245876) httpd_parse: read_block: received HTTP request block size = 128
D (245886) httpd_parse: cb_header_value: processing value = mage/svg+xml,image/*,*/*;q=0.8
D (245896) httpd_parse: cb_header_field: processing field = Referer
D (245906) httpd_parse: cb_header_value: processing value = http://192.168.4.1/index.html?page=log
D (245916) httpd_parse: cb_header_field: processing field = Accept-Encoding
D (245926) httpd_parse: cb_header_value: processing value = gzip, deflate
D (245936) httpd_parse: cb_header_field: processing field = Accept-Language
D (245946) httpd_parse: parse_block: parsed block size = 360
D (245956) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (245966) httpd_txrx: httpd_recv_with_opt: received length = 50
D (245976) httpd_parse: read_block: received HTTP request block size = 50
D (245986) httpd_parse: cb_header_field: processing field = 
D (245996) httpd_parse: cb_header_value: processing value = en-US,en;q=0.9,nl;q=0.8,de-DE;q=0.7,de;q=0.6
D (246006) httpd_parse: cb_headers_complete: bytes read     = 437
D (246016) httpd_parse: cb_headers_complete: content length = 0
D (246026) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:3 posted to loop 0x3ffdd664
D (246026) httpd_parse: pause_parsing: paused
D (246036) httpd_parse: cb_no_body: message complete
D (246036) httpd_parse: httpd_parse_req: parsing complete
D (246036) httpd_uri: httpd_uri: request for /logo.png with type 1
D (246046) httpd_uri: httpd_find_uri_handler: [0] = /ajax/calibrate
D (246056) httpd_uri: httpd_find_uri_handler: [1] = /ajax/formatSdcard
D (246066) httpd_uri: httpd_find_uri_handler: [2] = /ajax/getDefaultConfig
D (246076) httpd_uri: httpd_find_uri_handler: [3] = /ajax/getConfig
D (246086) httpd_uri: httpd_find_uri_handler: [4] = /ajax/getValues
D (246096) httpd_uri: httpd_find_uri_handler: [5] = /ajax/getRawAdc
D (246106) httpd_uri: httpd_find_uri_handler: [6] = /ajax/getStatus
D (246116) httpd_uri: httpd_find_uri_handler: [7] = /ajax/setTime
D (246126) httpd_uri: httpd_find_uri_handler: [8] = /ajax/setConfig
D (246136) httpd_uri: httpd_find_uri_handler: [9] = /ajax/loggerStop
D (246146) httpd_uri: httpd_find_uri_handler: [10] = /ajax/loggerStart
D (246156) httpd_uri: httpd_find_uri_handler: [11] = /ajax/sdcardUnmount
D (246166) httpd_uri: httpd_find_uri_handler: [12] = /ajax/getFileList/*
D (246176) httpd_uri: httpd_find_uri_handler: [13] = /fwupdate/*
D (246186) httpd_uri: httpd_find_uri_handler: [14] = /ajax/reboot
D (246196) httpd_uri: httpd_find_uri_handler: [15] = /upload/*
D (246206) httpd_uri: httpd_find_uri_handler: [16] = /delete/*
D (246216) httpd_uri: httpd_find_uri_handler: [17] = /*
D (246226) httpd_txrx: httpd_send_all: sent = 70
D (246226) httpd_txrx: httpd_send_all: sent = 2
D (246226) httpd_txrx: httpd_send_all: sent = 6
I (246246) LOGGER: Received task: 9
I (246766) LOGGER: Received task: 9
I (247286) LOGGER: Received task: 9
I (247806) LOGGER: Received task: 9
I (248336) LOGGER: Received task: 9
I (248856) LOGGER: Received task: 9
I (249376) LOGGER: Received task: 9
I (249896) LOGGER: Received task: 9
I (250416) LOGGER: Received task: 9
I (250936) LOGGER: Received task: 9
I (251446) LOGGER: Received task: 9
I (251966) LOGGER: Received task: 9
D (252056) httpd_txrx: httpd_send_all: sent = 5736
D (252436) esp_netif_lwip: check: remote, if=0x400b1e64 fn=0x4012ac78
D (252446) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (252456) NTP_SYNC: Syncing time...
I (252456) SETTINGS: Incoming timestamp: 1721222534000, outgoing 1721222534
I (252466) SETTINGS: System time set 
I (252466) SETTINGS: Current system time: 1721222534, 2024-07-17 13:22:14
I (252476) LOGGER: Received task: 3
I (252546) LOGGER: Received task: 5
I (253726) LOGGER: Received task: 9
I (254256) LOGGER: Received task: 9
I (254476) NTP_SYNC: NTP sync succesfull
I (254776) LOGGER: Received task: 9
I (255296) LOGGER: Received task: 9
I (255816) LOGGER: Received task: 9
I (256336) LOGGER: Received task: 9
I (256856) LOGGER: Received task: 9
W (257056) httpd_txrx: httpd_sock_err: error in send : 11
D (257066) httpd_txrx: httpd_send_all: error in send_fn
E (257066) esp-rest: File sending failed!
I (257376) LOGGER: Received task: 9
I (257896) LOGGER: Received task: 9
I (258416) LOGGER: Received task: 9
I (258936) LOGGER: Received task: 9
I (259456) LOGGER: Received task: 9
I (259976) LOGGER: Received task: 9

The part "LOGGER: Received task: 9" comes from the task with priority 24. I also checked the heap memory, but there's plenty available. In the past I used to have similar issues withtout the NTP task, but the configuration

Code: Select all

 config.lru_purge_enable = true;

resolved that. But no more. Any help is welcome.

Thanks!

Edit: I noticed that when the HTTP server stops responding, the NTP sync does not connect to the server anymore either after a while, even though it is still connected to the AP.

[pppTec]

Is there anyone who can help me maybe?

[MicroController]

the wifi_event_group is set in another file, which sets the WIFI_CONNECTED_BIT when the ESP32-S2 is connected to an Access Point

Does that 'other file' also clear the WIFI_CONNECTED_BIT in the event group if/when the AP connection drops?

[pppTec]

In the end I solved this issue by disabling the UART over USB port and putting compiling options to performance. So definitely some timing issues.