/* * Copyright 2024 Google LLC * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include "applib/data_logging.h" #include "util/uuid.h" #include "process_management/pebble_process_md.h" #include "services/normal/filesystem/pfs.h" #include "services/normal/filesystem/flash_translation.h" #include "services/common/comm_session/protocol.h" #include "services/common/comm_session/session.h" #include "services/common/comm_session/session_send_buffer.h" #include "services/common/comm_session/session_transport.h" #include "services/normal/data_logging/data_logging_service.h" #include "services/normal/data_logging/dls_private.h" #include "services/normal/data_logging/dls_list.h" #include "services/normal/data_logging/dls_storage.h" #include "services/common/regular_timer.h" #include "system/logging.h" #include "system/passert.h" #include "util/legacy_checksum.h" #include "util/list.h" #include "util/math.h" #include "util/size.h" #include "util/string.h" #include "clar.h" // Stubs #include "fake_app_manager.h" #include "fake_pebble_tasks.h" #include "fake_system_task.h" #include "fake_spi_flash.h" #include "fake_session.h" #include "fake_new_timer.h" #include "fake_pbl_malloc.h" #include "fake_rtc.h" #include "stubs_analytics.h" #include "stubs_bt_lock.h" #include "stubs_hexdump.h" #include "stubs_logging.h" #include "stubs_mutex.h" #include "stubs_passert.h" #include "stubs_prompt.h" #include "stubs_rand_ptr.h" #include "stubs_serial.h" #include "stubs_sleep.h" #include "stubs_syscall_internal.h" #include "stubs_task_watchdog.h" #include "stubs_reboot_reason.h" #include #include #include "FreeRTOS.h" #include "timers.h" TickType_t xTaskGetTickCount(void) { return 1337; } #include "kernel/memory_layout.h" const MpuRegion* memory_layout_get_app_region(void) { return NULL; } bool memory_layout_is_buffer_in_region(const MpuRegion *region, const void *buf, size_t length) { return true; } // We can't include all of stubs_process_manager because it conflicts with fake_app_manager.h bool process_manager_send_event_to_process(PebbleTask task, PebbleEvent* e) { return true; } // ------------------------------------------------------------------------------------ // Comm session fake support void data_logging_protocol_msg_callback(CommSession *session, const uint8_t *data, size_t length); static CommSession *s_session; static DataLoggingSendDataMessage s_prev_send_data_hdr; static uint8_t s_prev_send_data[COMM_MAX_OUTBOUND_PAYLOAD_SIZE]; static uint32_t s_prev_send_data_bytes; static void prv_transport_sent_data_cb(uint16_t endpoint_id, const uint8_t* data, unsigned int data_length) { PBL_LOG(LOG_LEVEL_INFO, "Received %d bytes of data from watch", data_length); if (data_length >= sizeof(s_prev_send_data_hdr)) { memcpy(&s_prev_send_data_hdr, data, sizeof(s_prev_send_data_hdr)); data_length -= sizeof(s_prev_send_data_hdr); data += sizeof(s_prev_send_data_hdr); if (data_length > 0) { s_prev_send_data_bytes = data_length; memcpy(s_prev_send_data, data, data_length); } else { s_prev_send_data_bytes = 0; } } } // ---------------------------------------------------------------------------------------- // Setup static void prv_init_fake_flash(void) { fake_spi_flash_init(0, 0x1000000); pfs_init(false); pfs_format(false /* write erase headers */); PBL_LOG(LOG_LEVEL_INFO, "\nFile system size: %d, avail: %d", (int)pfs_get_size(), (int)get_available_pfs_space()); } // ---------------------------------------------------------------------------------------- // fill a buffer, return it's CRC32 static uint32_t prv_get_random_buffer(uint8_t **buf, unsigned int size) { uint8_t *temp = calloc(size, sizeof(uint8_t)); for (unsigned int i = 0; i < size; i++) { temp[i] = (uint8_t)(rand() % 10); } *buf = temp; return legacy_defective_checksum_memory(temp, size); } // ---------------------------------------------------------------------------------------- static void prv_data_log_chain(DataLoggingSessionRef logging_session, uint8_t *buf, int item_size, int num_items) { int num_bytes = item_size * num_items; while (num_bytes > 0) { unsigned int chunk_size; if (item_size > DLS_SESSION_MAX_BUFFERED_ITEM_SIZE) { // Must be unbuffered chunk_size = item_size; } else { chunk_size = MIN(num_bytes, DLS_SESSION_MAX_BUFFERED_ITEM_SIZE); chunk_size -= (chunk_size % item_size); } PBL_ASSERTN(chunk_size <= num_bytes); data_logging_log(logging_session, buf, chunk_size / item_size); fake_system_task_callbacks_invoke_pending(); buf += chunk_size; num_bytes -= chunk_size; } } // ---------------------------------------------------------------------------------------- static void prv_check_session_data(DataLoggingSessionRef logging_session, uint32_t crc, unsigned int num_bytes) { uint8_t buffer[num_bytes]; uint32_t read_bytes = dls_test_read(logging_session, buffer, num_bytes); cl_assert(read_bytes == num_bytes); uint32_t session_crc = legacy_defective_checksum_memory(buffer, num_bytes); cl_assert(crc == session_crc); dls_test_consume(logging_session, num_bytes); cl_assert(dls_test_get_num_bytes(logging_session) == 0); } // ---------------------------------------------------------------------------------------- // log some random data, return its crc32 static uint32_t prv_log_random_data(DataLoggingSessionRef logging_session, int item_size, int num_items) { PBL_LOG(LOG_LEVEL_INFO, "Logging %d bytes", item_size * num_items); uint8_t *random_buf; uint32_t random_crc = prv_get_random_buffer(&random_buf, item_size * num_items); prv_data_log_chain(logging_session, random_buf, item_size, num_items); free (random_buf); return (random_crc); } // ---------------------------------------------------------------------------------------- static void prv_log_consume_random(DataLoggingSessionRef logging_session, int item_size, int num_items) { uint32_t random_crc = prv_log_random_data(logging_session, item_size, num_items); prv_check_session_data(logging_session, random_crc, item_size * num_items); } // ---------------------------------------------------------------------------------------- void test_data_logging__initialize(void) { regular_timer_init(); prv_init_fake_flash(); stub_pebble_tasks_set_current(PebbleTask_KernelBackground); dls_clear(); dls_init(); fake_system_task_callbacks_invoke_pending(); // Create the system comm session //Transport *transport = (Transport *) ~0; //s_session = comm_session_open(transport, &s_transport_imp, // TransportDestinationSystem); fake_comm_session_init(); Transport *transport = fake_transport_create(TransportDestinationSystem, NULL, prv_transport_sent_data_cb); s_session = fake_transport_set_connected(transport, true /* connected */); } // ---------------------------------------------------------------------------------------- void test_data_logging__cleanup(void) { regular_timer_deinit(); fake_comm_session_cleanup(); } // ---------------------------------------------------------------------------------------- void test_data_logging__log_consume(void) { DataLoggingSessionRef logging_sessions[10]; const int item_size = 1; // Create sessions for (int i = 0; i < 10; i++) { logging_sessions[i] = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); } // Log Consume for (int i = 0; i < 10; i++) { prv_log_consume_random(logging_sessions[i], item_size, rand() % 12345); } } // ---------------------------------------------------------------------------------------- void test_data_logging__log_consume_non_buffered(void) { DataLoggingSessionRef logging_sessions[10]; Uuid system_uuid = UUID_SYSTEM; // Test that we can log items > DLS_SESSION_MAX_BUFFERED_ITEM_SIZE when non-buffered const int item_size = 2 * DLS_SESSION_MAX_BUFFERED_ITEM_SIZE; // Create sessions for (int i = 0; i < 10; i++) { logging_sessions[i] = (DataLoggingSessionRef)dls_create(i, DATA_LOGGING_BYTE_ARRAY, item_size, false /*buffered*/, false /*resume*/, &system_uuid); cl_assert(logging_sessions[i]); } // Log Consume for (int i = 0; i < 10; i++) { prv_log_consume_random(logging_sessions[i], item_size, rand() % 16); } } // ---------------------------------------------------------------------------------------- void test_data_logging__log_consume_large_items(void) { DataLoggingSessionRef logging_sessions[10]; int item_size[10]; // Create sessions for (int i = 0; i < 10; i++) { item_size[i] = 50 + (rand() % 250); logging_sessions[i] = data_logging_create(i, DATA_LOGGING_BYTE_ARRAY, item_size[i], false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); } // Log Consume for (int i = 0; i < 10; i++) { prv_log_consume_random(logging_sessions[i], item_size[i], rand() % 123); } } // ---------------------------------------------------------------------------------------- // Test writing and consuming so much that we are forced to reallocate the file partway // through void test_data_logging__log_realloc(void) { DataLoggingSessionRef logging_sessions[5]; const int item_size = 1; // Create sessions for (int i = 0; i < 5; i++) { logging_sessions[i] = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); } // Log Consume for (int i = 0; i < 5; i++) { // Each write is 1/8 to 1/4 of the initial file size. int num_bytes = DLS_FILE_INIT_SIZE_BYTES/8 + (rand() % DLS_FILE_INIT_SIZE_BYTES/8); // By doing 16 loops, we are sure to cycle through the allocated file size at least twice. for (int j=0; j<16; j++) { prv_log_consume_random(logging_sessions[i], item_size, num_bytes); } } } // ---------------------------------------------------------------------------------------- // Filling up the file system. We should be limited to creating DLS_MAX_DATA_BYTES worth // of storage void test_data_logging__fill_quota(void) { const int item_size = 1; const int num_sessions = 5; DataLoggingSessionRef logging_sessions[DLS_MAX_NUM_SESSIONS]; // Create sessions for (int i = 0; i < num_sessions; i++) { logging_sessions[i] = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); } // This should fill up the file system int bytes_per_session = 2 * DLS_TOTAL_STORAGE_BYTES / num_sessions; for (int i = 0; i < num_sessions; i++) { prv_log_random_data(logging_sessions[i], item_size, bytes_per_session); } // Check the total capacity, it should be no more than DLS_TOTAL_STORAGE_BYTES, but close // to DLS_MAX_DATA_BYTES int total_bytes = 0; for (int i = 0; i < num_sessions; i++) { uint32_t size = dls_test_get_num_bytes(logging_sessions[i]); PBL_LOG(LOG_LEVEL_INFO, "Size of session %d: %d", i, size); total_bytes += size; } PBL_LOG(LOG_LEVEL_INFO, "total bytes: %d", total_bytes); cl_assert(total_bytes < DLS_TOTAL_STORAGE_BYTES); // We should still be able to create more sessions up to the max for (int i = num_sessions; i < DLS_MAX_NUM_SESSIONS; i++) { logging_sessions[i] = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); prv_log_random_data(logging_sessions[i], item_size, DLS_FILE_INIT_SIZE_BYTES); } // Check the total capacity, it should still be no more than DLS_TOTAL_STORAGE_BYTES. total_bytes = 0; for (int i = 0; i < num_sessions; i++) { uint32_t size = dls_test_get_num_bytes(logging_sessions[i]); PBL_LOG(LOG_LEVEL_INFO, "Size of session %d: %d", i, size); total_bytes += size; } PBL_LOG(LOG_LEVEL_INFO, "total bytes: %d", total_bytes); cl_assert(total_bytes < DLS_TOTAL_STORAGE_BYTES); } // ---------------------------------------------------------------------------------------- // Test logging a LOT of data. void test_data_logging__large_session(void) { const int item_size = DLS_ENDPOINT_MAX_PAYLOAD; DataLoggingSessionRef logging_session; Uuid system_uuid = UUID_SYSTEM; logging_session = (DataLoggingSessionRef)dls_create(0, DATA_LOGGING_BYTE_ARRAY, item_size, false /*buffered*/, false /*resume*/, &system_uuid); cl_assert(logging_session); fake_system_task_callbacks_invoke_pending(); // We should be able to create a really large session. int num_bytes = DLS_MAX_DATA_BYTES/2; int num_items = num_bytes / item_size; cl_assert(num_bytes > 0); prv_log_consume_random(logging_session, item_size, num_items); } // ---------------------------------------------------------------------------------------- void test_data_logging__interleave(void) { DataLoggingSessionRef logging_sessions[10]; uint32_t crcs[10]; uint8_t *buf[10]; uint32_t buf_size[10]; uint32_t bytes_left[10]; const int item_size = 1; for (int i = 0; i < 10; i++) { logging_sessions[i] = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_sessions[i]); fake_system_task_callbacks_invoke_pending(); buf_size[i] = bytes_left[i] = rand() % (50 * 300); crcs[i] = prv_get_random_buffer(&(buf[i]), buf_size[i]); } bool did_some = true; while (did_some) { did_some = false; for (int i = 0; i < 10; i++) { unsigned int nb = rand() % 300; nb = MIN(nb, bytes_left[i]); if (!nb) { continue; } did_some = true; prv_data_log_chain(logging_sessions[i], buf[i], item_size, nb); bytes_left[i] -= nb; buf[i] += nb; } } for (int i = 0; i < 10; i++) { prv_check_session_data(logging_sessions[i], crcs[i], buf_size[i]); } } // ---------------------------------------------------------------------------------------- static void prv_do_recovery_test(int num_sessions) { unsigned int num_bytes[num_sessions]; uint32_t crcs[num_sessions]; const int item_size = 1; // Log some random data for (int i = 0; i < num_sessions; i++) { DataLoggingSessionRef logging_session = data_logging_create(i, DATA_LOGGING_UINT, item_size, false); cl_assert(logging_session); num_bytes[i] = rand() % 12345; crcs[i] = prv_log_random_data(logging_session, item_size, num_bytes[i]); } // Clear the logging sessions from RAM dls_list_remove_all(); DataLoggingSessionRef logging_session = dls_list_get_next(NULL); cl_assert(logging_session == NULL); // Reset regular timer. dls_init() will add the same timer info again regular_timer_deinit(); regular_timer_init(); // Rebuild the list from flash dls_init(); fake_system_task_callbacks_invoke_pending(); // Check the sessions for (int i = 0; i < num_sessions; i++) { logging_session = dls_list_get_next(logging_session); cl_assert(logging_session != NULL); uint32_t tag = dls_test_get_tag(logging_session); prv_check_session_data(logging_session, crcs[tag], num_bytes[tag]); } logging_session = dls_list_get_next(logging_session); cl_assert(logging_session == NULL); } void test_data_logging__recover_one(void) { prv_do_recovery_test(1); } void test_data_logging__recover_five(void) { prv_do_recovery_test(5); } // ---------------------------------------------------------------------------------------- //! Try passing garbage pointers to sessions to data logging functions. void test_data_logging__invalid_session_garbage(void) { uint32_t data[] = { 1, 2, 3 }; // Make sure logging to bogus sessions does the right thing. cl_assert_equal_i(data_logging_log(0, data, ARRAY_LENGTH(data)), DATA_LOGGING_INVALID_PARAMS); cl_assert_equal_i(data_logging_log(&data, data, ARRAY_LENGTH(data)), DATA_LOGGING_INVALID_PARAMS); // Make sure closing invalid sessions doesn't crash. It's defined to be a no-op data_logging_finish(0); data_logging_finish(&data); } // ---------------------------------------------------------------------------------------- //! Try using sessions after we've closed them. void test_data_logging__invalid_session_use_after_close(void) { uint32_t data[] = { 1, 2, 3 }; DataLoggingSessionRef session = data_logging_create(0x1234, DATA_LOGGING_UINT, 4, false); cl_assert(session); fake_system_task_callbacks_invoke_pending(); data_logging_finish(session); fake_system_task_callbacks_invoke_pending(); // Log to the session after it's closed. cl_assert_equal_i(data_logging_log(session, data, ARRAY_LENGTH(data)), DATA_LOGGING_INVALID_PARAMS); // Finish the session again without a crash. data_logging_finish(0); } // ---------------------------------------------------------------------------------------- //! Try passing invalid params to data_logging_log void test_data_logging__invalid_params(void) { uint32_t data[] = { 1, 2, 3 }; DataLoggingSessionRef session = data_logging_create(0x1234, DATA_LOGGING_UINT, 4, false); cl_assert(session); fake_system_task_callbacks_invoke_pending(); // Log to the session after it's closed. cl_assert_equal_i(data_logging_log(session, NULL, 4), DATA_LOGGING_INVALID_PARAMS); cl_assert_equal_i(data_logging_log(NULL, data, ARRAY_LENGTH(data)), DATA_LOGGING_INVALID_PARAMS); // Finish the session without a crash data_logging_finish(0); } // ---------------------------------------------------------------------------------------- // Test emptying the session using dls_private_send_session static void prv_endpoint_test(bool buffered, const int item_size, const int num_items) { DataLoggingSessionRef logging_session; // Create session Uuid system_uuid = UUID_SYSTEM; const PebbleProcessMd *md = sys_process_manager_get_current_process_md(); const Uuid *uuid; if (buffered) { uuid = &md->uuid; } else { uuid = &system_uuid; } logging_session = (DataLoggingSessionRef)dls_create(0, DATA_LOGGING_BYTE_ARRAY, item_size, buffered, false /*resume*/, uuid); cl_assert(logging_session); fake_system_task_callbacks_invoke_pending(); // This sends the open session request out the transport fake_comm_session_process_send_next(); // Generate the received ack from the phone endpoint CommSession *session = comm_session_get_system_session(); uint8_t ack_data[] = { ~DLS_ENDPOINT_CMD_MASK | DataLoggingEndpointCmdAck, dls_test_get_session_id(logging_session)}; data_logging_protocol_msg_callback(session, ack_data, 2); fake_system_task_callbacks_invoke_pending(); // Log the data uint32_t random_crc = prv_log_random_data(logging_session, item_size, num_items); // Finish up the session so that all data gets sent out the endpoint data_logging_finish(logging_session); // --------------------------------------------------------------------------- // Consume it using the method used by the data logging endpoint const int buf_size = num_items * item_size; uint8_t *rcv_buffer = calloc(num_items, item_size); PBL_ASSERTN(rcv_buffer); uint32_t rcv_bytes = 0; s_prev_send_data_bytes = 0; dls_private_send_session(logging_session, true /*empty*/); const int items_per_send = (COMM_MAX_OUTBOUND_PAYLOAD_SIZE - sizeof(DataLoggingSendDataMessage)) / item_size; const int num_sends = num_items / items_per_send; for (int i = 0; i < num_sends + 5; i++) { // This sends a chunk out and it should show up in our prv_transport_sent_data_cb callback fake_comm_session_process_send_next(); cl_assert(s_prev_send_data_bytes <= buf_size - rcv_bytes); memcpy(rcv_buffer + rcv_bytes, s_prev_send_data, s_prev_send_data_bytes); rcv_bytes += s_prev_send_data_bytes; s_prev_send_data_bytes = 0; // Provide acknowledgement from phone, this should trigger another dls_private_send_session data_logging_protocol_msg_callback(session, ack_data, 2); fake_system_task_callbacks_invoke_pending(); } // Verify the received data uint32_t session_crc = legacy_defective_checksum_memory(rcv_buffer, rcv_bytes); cl_assert(random_crc == session_crc); // Free buffer free(rcv_buffer); } // ---------------------------------------------------------------------------------------- // Test using the endpoint to empty the session void test_data_logging__send_session_1(void) { prv_endpoint_test(true /*buffered*/, 1, 1000); } // ---------------------------------------------------------------------------------------- // Test using the endpoint to empty a session using large item sizes void test_data_logging__send_session_large(void) { prv_endpoint_test(false /*buffered*/, DLS_ENDPOINT_MAX_PAYLOAD, 20); } // ---------------------------------------------------------------------------------------- // Test using the endpoint to empty a session using medium item sizes void test_data_logging__send_session_medium(void) { prv_endpoint_test(true /*buffered*/, 90, 20); } // ---------------------------------------------------------------------------------------- // Test using the endpoint to empty a session using small item sizes. The item size of 19 // exposes issue PBL-21331 void test_data_logging__send_session_small(void) { prv_endpoint_test(true /*buffered*/, 19, 45); }