pebble/src/fw/kernel/pulse_logging.c

/*
 * 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 "pulse_logging.h"

#include "logging_private.h"
#include "pebble_tasks.h"

#include "console/pulse.h"
#include "console/pulse_protocol_impl.h"
#include "kernel/events.h"

#include "mcu/interrupts.h"
#include "mcu/privilege.h"
#include "util/attributes.h"
#include "util/circular_buffer.h"
#include "util/math.h"
#include "util/string.h"

#include "FreeRTOS.h"
#include "task.h"

#include <ctype.h>

//! This is the format for a PULSEv2 log message when sent out over the wire.
typedef struct PACKED MessageContents {
  uint8_t message_type;
  char src_filename[16];
  char log_level_char;
  unsigned char task_char;
  uint64_t time_ms;
  uint16_t line_number;
  //! Not null-terminated message contents
  char message[128];
} MessageContents;

typedef struct PACKED {
  uint64_t timestamp_ms;
  uint8_t log_level;
} BufferedLogInfo;

//! For ISR contexts, we can't write log message directly. Instead we write them to this
//! circular buffer and flush them out when the ISR is completed.
static CircularBuffer s_isr_log_buffer;

//! Underlying storage for s_isr_log_buffer
static uint8_t s_isr_log_buffer_storage[256];


static uint64_t prv_get_timestamp_ms(void) {
  time_t time_s;
  uint16_t time_ms;
  rtc_get_time_ms(&time_s, &time_ms);
  return ((uint64_t) time_s * 1000) + time_ms;
}

static size_t prv_serialize_log_header(MessageContents *contents,
                                       uint8_t log_level, uint64_t timestamp_ms, PebbleTask task,
                                       const char *src_filename, uint16_t src_line_number) {
  contents->message_type = 1; // Text

  // Log the log level and the current task+privilege level
  contents->log_level_char = pbl_log_get_level_char(log_level);
  contents->task_char = pebble_task_get_char(task);
  if (mcu_state_is_privileged()) {
    contents->task_char = toupper(contents->task_char);
  }

  contents->time_ms = timestamp_ms;

  // Obtain the filename
  strncpy(contents->src_filename, GET_FILE_NAME(src_filename), sizeof(contents->src_filename));

  // Obtain the line number
  contents->line_number = src_line_number;

  return offsetof(MessageContents, message);
}


//! Serialize a message into contents, returning the number of bytes used.
static size_t prv_serialize_log(MessageContents *contents,
                                uint8_t log_level, uint64_t timestamp_ms, PebbleTask task,
                                const char *src_filename, uint16_t src_line_number,
                                const char *message) {

  prv_serialize_log_header(contents, log_level, timestamp_ms, task,
                           src_filename, src_line_number);

  // Write the actual log message.
  strncpy(contents->message, message, sizeof(contents->message));

  size_t payload_length = MIN(sizeof(MessageContents),
                              offsetof(MessageContents, message) + strlen(message));

  return payload_length;
}

static void prv_send_pulse_packet(uint8_t log_level, const char *src_filename,
                                  uint16_t src_line_number, const char *message) {
  MessageContents *contents = pulse_push_send_begin(PULSE_PROTOCOL_LOGGING);

  const size_t payload_length = prv_serialize_log(
      contents, log_level, prv_get_timestamp_ms(), pebble_task_get_current(),
      src_filename, src_line_number, message);

  pulse_push_send(contents, payload_length);
}


static bool prv_isr_buffer_read_and_consume(void *buffer, size_t read_length) {
  portENTER_CRITICAL();

  const bool result = circular_buffer_copy(&s_isr_log_buffer, buffer, read_length);
  if (result) {
    circular_buffer_consume(&s_isr_log_buffer, read_length);
  }

  portEXIT_CRITICAL();

  return result;
}


static void prv_event_cb(void *data) {
  while (true) {
    // No need to worry about reading a partial message here, we write messages to the circular
    // buffer while disabling interrupts the whole time.

    uint32_t log_length;
    if (!prv_isr_buffer_read_and_consume(&log_length, sizeof(log_length))) {
      // No more messages to read if we can't read a length
      break;
    }

    if (log_length == sizeof(uint32_t)) {
      // We dropped a message, log a message to that effect

      MessageContents *contents = pulse_push_send_begin(PULSE_PROTOCOL_LOGGING);

      const size_t payload_length = prv_serialize_log(
          contents, LOG_LEVEL_ERROR, prv_get_timestamp_ms(), PebbleTask_Unknown,
          "", 0, "ISR Message Dropped!");

      pulse_push_send(contents, payload_length);
    } else {
      BufferedLogInfo log_info;
      prv_isr_buffer_read_and_consume(&log_info, sizeof(log_info));

      MessageContents *contents = pulse_push_send_begin(PULSE_PROTOCOL_LOGGING);

      const size_t header_length = prv_serialize_log_header(
          contents, log_info.log_level, log_info.timestamp_ms, PebbleTask_Unknown, "", 0);

      const size_t message_length = log_length - sizeof(uint32_t) - sizeof(BufferedLogInfo);
      prv_isr_buffer_read_and_consume(&contents->message, message_length);

      pulse_push_send(contents, header_length + message_length);
    }
  }
}

static void prv_enqueue_log_message(uint8_t log_level, const char *message) {
  const bool buffer_was_empty = (circular_buffer_get_read_space_remaining(&s_isr_log_buffer) == 0);

  // Need to prevent other interrupts from corrupting the log buffer while we're writing to it
  portENTER_CRITICAL();

  if (circular_buffer_get_write_space_remaining(&s_isr_log_buffer) < sizeof(uint32_t)) {
    // Completely out of space, can't do anything.
    portEXIT_CRITICAL();
    return;
  }

  const size_t message_length = MIN(strlen(message), 128);
  const uint32_t required_space = sizeof(uint32_t) + sizeof(BufferedLogInfo) + message_length;

  if (circular_buffer_get_write_space_remaining(&s_isr_log_buffer) < required_space) {
    // Not enough space for the full message, just write an empty message with only the length
    // word to indicate we're dropping the message.
    const uint32_t insufficient_space_length = sizeof(uint32_t);
    circular_buffer_write(&s_isr_log_buffer,
                          &insufficient_space_length, sizeof(insufficient_space_length));
  } else {
    circular_buffer_write(&s_isr_log_buffer, &required_space, sizeof(required_space));

    const BufferedLogInfo log_info = {
      .timestamp_ms = prv_get_timestamp_ms(),
      .log_level = log_level
    };
    circular_buffer_write(&s_isr_log_buffer, &log_info, sizeof(log_info));

    circular_buffer_write(&s_isr_log_buffer, message, message_length);
  }

  if (buffer_was_empty) {
    PebbleEvent e = {
      .type = PEBBLE_CALLBACK_EVENT,
      .callback = {
        .callback = prv_event_cb
      }
    };
    event_put_isr(&e);
  }

  portEXIT_CRITICAL();
}

void pulse_logging_init(void) {
  circular_buffer_init(&s_isr_log_buffer,
                       s_isr_log_buffer_storage, sizeof(s_isr_log_buffer_storage));
}

void pulse_logging_log(uint8_t log_level, const char* src_filename,
                       uint16_t src_line_number, const char* message) {
  if (portIN_CRITICAL() || mcu_state_is_isr() ||
      xTaskGetSchedulerState() == taskSCHEDULER_SUSPENDED) {
    // We're in a state where we can't immediately send the message, save it to an internal buffer
    // instead for later sending.
    prv_enqueue_log_message(log_level, message);
  } else {
    // Send the log line inline
    prv_send_pulse_packet(log_level, src_filename, src_line_number, message);
  }
}

void pulse_logging_log_buffer_flush(void) {
  prv_event_cb(NULL);
}

void pulse_logging_log_sync(uint8_t log_level, const char *src_filename,
                            uint16_t src_line_number, const char *message) {
  // Send the log line inline, even if we're in a critical section or ISR
  prv_send_pulse_packet(log_level, src_filename, src_line_number, message);
}

void *pulse_logging_log_sync_begin(
    uint8_t log_level, const char *src_filename, uint16_t src_line_number) {
  MessageContents *contents = pulse_push_send_begin(PULSE_PROTOCOL_LOGGING);
  prv_serialize_log_header(contents, log_level, prv_get_timestamp_ms(),
                           pebble_task_get_current(), src_filename,
                           src_line_number);
  contents->message[0] = '\0';
  return contents;
}

void pulse_logging_log_sync_append(void *ctx, const char *message) {
  MessageContents *contents = ctx;
  strncat(contents->message, message, sizeof(contents->message));
}

void pulse_logging_log_sync_send(void *ctx) {
  MessageContents *contents = ctx;
  size_t payload_length = MIN(
      sizeof(MessageContents),
      offsetof(MessageContents, message) + strlen(contents->message));
  pulse_push_send(contents, payload_length);
}