imjasonh/esp32
1
0
Fork 0
mirror of https://github.com/imjasonh/esp32 synced 2026-07-08 08:25:02 +00:00
Code Activity

docs: reorganise into docs/, fold logs-plan + monitoring-plan into observability.md

Browse source 
- New `docs/observability.md`: descriptive (present-tense) write-up
  of the Cloud Logging + Cloud Monitoring pipelines as currently
  shipped. Replaces the historical `logs-plan.md` + `monitoring-plan.md`
  planning docs.
- New `docs/setup.md`: prerequisites, first flash, day-to-day Make
  targets, and the optional GCP setup (lifted out of the README so the
  README can stay terse). Includes the Python 3.12-shim explanation
  from the old `notes.txt`.
- Move `ota.md` → `docs/ota.md`.
- Move `eink-plan.md` → `docs/eink-plan.md`. Per-feature plans still
  use the `<feature>-plan.md` name; once shipped they get rewritten
  in present tense alongside the other docs.
- Delete `logs-plan.md`, `monitoring-plan.md`, `notes.txt`. Their
  user-facing content is now in `docs/setup.md`; their LLM-relevant
  bits (architectural rationale, partition-table CMake quirk, Python
  shim, no-LED, `make` conventions, NVS key length cap) are in
  `CLAUDE.md`.
- Trim `README.md` to a top-level overview + links into `docs/`.
- Update internal cross-references (Makefile, ota.md, eink-plan.md,
  tools/provision/src/main.rs doc-comment).

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Jason Hall 2026-05-03 08:30:43 -04:00
parent dbe679d6ea
commit 7e32f6decb
11 changed files with 621 additions and 790 deletions
Download patch file Download diff file Expand all files Collapse all files

348
docs/observability.md Normal file
View file

@ -0,0 +1,348 @@
# Observability — current state
The firmware ships structured `tracing` events to **Google Cloud
Logging** and periodic chip-health snapshots to **Google Cloud
Monitoring**. Both are opt-in per device: without a `[gcp]` block in
`provisioning.toml`, the firmware boots normally and emits to serial
only.
One service account, one private key, one cached access token covers
both APIs (the JWT requests `logging.write` + `monitoring.write`
scopes; the cached bearer is shared between the two sender threads).
## Architecture
```
┌──────────────────── ESP32 ────────────────────┐ ┌──── GCP ─────┐
│ │ │ │
│ tracing event ──┐ │ │ │
│ (any module) ├─▶ ring buffer ──▶ cloud_log │ HTTPS │ Logging │
│ tracing event ──┘ (256 entries) thread │────────▶│ /v2/ │
│ drop-oldest │ │ entries: │
│ │ │ write │
│ │ │ │
│ metrics thread ─ snapshot heap/stack/wifi/... │ HTTPS │ Monitoring │
│ (every N s) build CreateTimeSeries │────────▶│ /v3/.../ │
│ │ │ timeSeries │
│ │ │ │
│ gcp_auth: shared TokenProvider │ HTTPS │ oauth2 │
│ - mints multi-scope JWT │────────▶│ /token │
│ - caches bearer for ~1h │ │ │
│ │ │ │
└────────────────────────────────────────────────┘ └──────────────┘
```
## Modules
| File | What it owns |
|------|--------------|
| `src/gcp_auth.rs` | `TokenProvider` (multi-scope JWT mint + bearer cache), `ShortHttpsLock`, `OtaDownloadGuard`, shared HTTPS / time / base64url helpers, `device_mac()`. |
| `src/cloud_log.rs` | `GcpConfig` NVS load, `LogEntry`, `LogQueue` (bounded ring buffer), `CloudLogLayer` (tracing subscriber), sender thread that POSTs to `logging.googleapis.com`. |
| `src/metrics.rs` | Per-task `TaskHandle_t` registry, snapshot collector (FFI calls into ESP-IDF), sender thread that POSTs to `monitoring.googleapis.com`. |
## Auth
The `TokenProvider` mints a single OAuth2 access token covering both
APIs:
```
JWT claims.scope = "https://www.googleapis.com/auth/logging.write
https://www.googleapis.com/auth/monitoring.write"
```
Standard service-account flow: build header + claims, base64url-encode,
sign with the SA's RSA private key (RS256), POST to
`oauth2.googleapis.com/token`, cache the returned `access_token` for
its `expires_in` minus a 5-minute safety margin.
The cache lives in a `Mutex<Option<CachedToken>>` inside the provider;
`get_or_refresh()` returns the bearer directly on hit, mints under the
lock on miss. cloud_log + metrics share an `Arc<TokenProvider>` so
neither pays for its own RSA sign.
## Cloud Logging
### Capture
`CloudLogLayer` is a `tracing_subscriber::Layer`. Every emitted event:
- Severity mapped: `TRACE`/`DEBUG → DEBUG`, `INFO → INFO`, `WARN →
WARNING`, `ERROR → ERROR`.
- Wall-clock timestamp from `SystemTime::now()` if NTP has synced
(anything before 2020-01-01 is treated as not-yet-synced → entry
goes without a timestamp; Cloud Logging assigns server-side time).
- All structured fields captured into `serde_json::Map`.
- Pushed onto a 256-entry bounded queue. When full, oldest is dropped
and a counter is bumped; the next entry pushed carries
`dropped_before` so readers can spot lossy windows in the cloud.
- The layer's own module path (`esp32_blinky::cloud_log`),
`esp32_blinky::metrics`, and `esp32_blinky::gcp_auth` are
**excluded** from capture — otherwise the senders' own tracing
calls would land on the queue they're draining and create a tight
feedback loop.
The layer composes with `EspLogger`, so events still print to serial
in addition to being queued.
### Sender thread
Background pthread, ~32 KB stack. Wakes every 5 s (or backoff if the
last POST failed):
1. Skip the cycle if `OTA_DOWNLOAD_IN_PROGRESS` is set (see "Heap
budget" below).
2. Drain up to 50 entries from the queue.
3. Acquire `ShortHttpsLock` (serialises against metrics + OTA short
fetches).
4. `auth.get_or_refresh()` — may transparently mint a token.
5. POST to `https://logging.googleapis.com/v2/entries:write`.
6. Drop the lock.
On 4xx/5xx the batch is dropped (rather than re-queued) — long outages
otherwise grow the queue unboundedly. Drop count is surfaced on the
next entry pushed.
### Schema
```json
{
"logName": "projects/<project-id>/logs/esp32-firmware",
"resource": {
"type": "generic_node",
"labels": {
"project_id": "<project-id>",
"location": "global",
"namespace": "esp32",
"node_id": "<chip-mac>"
}
},
"entries": [
{
"severity": "INFO",
"timestamp": "2026-05-02T19:45:00Z",
"jsonPayload": {
"message": "ota: boot summary",
"module": "esp32_blinky::ota",
"fw_version": "abc1234",
"fw": "abc1234",
"repo": "ghcr.io/imjasonh/esp32",
"tag": "latest",
"poll_secs": 60,
"last_digest":"sha256:..."
}
}
]
}
```
Single `logName` for both app + OTA; `jsonPayload.module` lets
queries split by component:
```
jsonPayload.module="esp32_blinky::ota" AND jsonPayload.fw_version="abc1234"
```
## Cloud Monitoring
### Snapshot
Every `metrics_interval_secs` (default 300, NVS-tunable, 0 disables
the thread entirely), `metrics::collect()` reads:
| Metric type (`custom.googleapis.com/esp32/…`) | Source | Unit | Kind |
|-----------------------------------------------|---------------------------------------------------------|------|-------|
| `free_heap` | `esp_get_free_heap_size()` | By | GAUGE |
| `free_heap_internal` | `heap_caps_get_free_size(MALLOC_CAP_INTERNAL)` | By | GAUGE |
| `min_free_heap` | `esp_get_minimum_free_heap_size()` (water-mark / boot) | By | GAUGE |
| `largest_free_block` | `heap_caps_get_largest_free_block(MALLOC_CAP_DEFAULT)` | By | GAUGE |
| `stack_hwm` *(label `task`)* | `uxTaskGetStackHighWaterMark` per published task | By | GAUGE |
| `wifi_rssi` | `esp_wifi_sta_get_ap_info().rssi` | dBm | GAUGE |
| `wifi_channel` | …`.primary` | 1 | GAUGE |
| `cpu_freq_mhz` | `CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ` | MHz | GAUGE |
| `uptime_secs` | `esp_timer_get_time() / 1_000_000` | s | GAUGE |
| `nvs_used_entries` | `nvs_get_stats().used_entries` | 1 | GAUGE |
| `nvs_free_entries` | …`.free_entries` | 1 | GAUGE |
| `cloud_log_queue_depth` | `LogQueue::stats().0` | 1 | GAUGE |
| `cloud_log_dropped_total` | lifetime drop counter on `LogQueue` | 1 | GAUGE |
`stack_hwm` carries a `task` label (`main` / `ota` / `cloud_log` /
`metrics`) so all four series chart on one graph. Each thread
publishes its own `TaskHandle_t` via
`metrics::publish_self(&handles::<NAME>)` at the top of its run loop;
`metrics::collect()` reads the FFI handle out of an `AtomicUsize` (0 =
unpublished, field omitted from the snapshot).
Note: ESP-IDF Xtensa `StackType_t = uint8_t`, so
`uxTaskGetStackHighWaterMark` returns **bytes** (not "words" as
upstream FreeRTOS docs say). No multiplication.
### Sender thread
Background pthread, ~16 KB stack. Wakes every `metrics_interval_secs`:
1. Skip the cycle if `OTA_DOWNLOAD_IN_PROGRESS`.
2. `collect()` — pure FFI, no allocations beyond the snapshot struct.
3. Acquire `ShortHttpsLock`.
4. `auth.get_or_refresh()`.
5. POST one `CreateTimeSeries` request containing all ~16 series in a
single body to `monitoring.googleapis.com/v3/projects/<id>/timeSeries`.
Cloud Monitoring auto-creates `MetricDescriptor`s on first write;
no separate provisioning step on the GCP side.
### Schema
```json
{
"timeSeries": [
{
"metric": {
"type": "custom.googleapis.com/esp32/free_heap",
"labels": { "fw_version": "abc1234" }
},
"resource": {
"type": "generic_node",
"labels": {
"project_id": "<project-id>",
"location": "global",
"namespace": "esp32",
"node_id": "<chip-mac>"
}
},
"metricKind": "GAUGE",
"valueType": "INT64",
"points": [
{ "interval": { "endTime": "2026-05-02T22:30:00Z" },
"value": { "int64Value": "182456" } }
]
}
]
}
```
`fw_version` rides on every metric as a **metric label** (resource
labels can't carry it — `generic_node` has a fixed schema). Adding
new label keys to an existing `MetricDescriptor` is forbidden by Cloud
Monitoring; if the fleet's running fw doesn't match the descriptor
schema you'll see HTTP 500 on the POST. Migration in that case is
manual:
```bash
TOKEN=$(gcloud auth print-access-token)
URL='https://monitoring.googleapis.com/v3/projects/<id>/metricDescriptors'
for m in $(curl -sG "$URL" -H "Authorization: Bearer $TOKEN" \
--data-urlencode 'filter=metric.type=starts_with("custom.googleapis.com/esp32/")' \
| jq -r '.metricDescriptors[].type'); do
curl -s -X DELETE "$URL/$m" -H "Authorization: Bearer $TOKEN"
done
```
This deletes all historical points for those metrics. There's no
in-place schema migration in Cloud Monitoring.
## Heap budget + serialization
Each TLS handshake on this chip allocates ~25–35 KB of mbedtls
context. With cloud_log + metrics + OTA each potentially holding a
TLS session, the worst case is three concurrent handshakes pinning
~90 KB — past the heap budget, producing
`MBEDTLS_ERR_SSL_ALLOC_FAILED` (-0x7F00).
Three knobs work together to keep this in budget:
1. **mbedtls config** (`sdkconfig.defaults.in`):
- `CONFIG_MBEDTLS_DYNAMIC_BUFFER` — I/O buffers grow as needed,
freed between handshakes (vs. pinned 16+16 KB).
- `CONFIG_MBEDTLS_DYNAMIC_FREE_CONFIG_DATA` — frees handshake
config struct after handshake.
- `CONFIG_MBEDTLS_DYNAMIC_FREE_CA_CERT` — frees the CA bundle
after handshake; re-attached on the next handshake.
- `CONFIG_MBEDTLS_SSL_KEEP_PEER_CERTIFICATE=n` — drops the parsed
peer cert after handshake (~3–5 KB/session). We don't reuse
sessions or do mutual TLS.
2. **Short HTTPS serialised** (`gcp_auth::ShortHttpsLock`): cloud_log
POST + metrics POST + OTA's manifest fetch + sig-bundle fetch all
take this `Mutex<()>` at their call sites. Held *at the call site*
(not inside `http_post`) so token mints inside `get_or_refresh()`
are covered by the caller's lock — std `Mutex` isn't reentrant.
OTA's poll_once releases between phases (token+manifest, then
verify which is CPU-only, then sig bundle) so cloud_log/metrics
aren't blocked behind ~2 s of pure-Rust X.509/ECDSA work.
3. **OTA download pause** (`gcp_auth::OTA_DOWNLOAD_IN_PROGRESS`):
`ota::download_and_apply` flips this `AtomicBool` true via an RAII
guard for the duration of the multi-second blob download (which
intentionally **does not** take `ShortHttpsLock` — it'd otherwise
block per-5-s log flushes for tens of seconds). cloud_log + metrics
check the flag at the top of each cycle and skip — but don't
drain — when set. Entries accumulate in the bounded queue and
flush in one batched POST after the download finishes.
Even with all three, peak heap during a 2-way concurrent TLS
(OTA + cloud_log handshake on top of OTA's held-open download) was
historically tight — the gate in #3 is what made downloads reliably
complete.
## Provisioning (NVS)
Optional `[gcp]` block in `provisioning.toml` (see
`provisioning.toml.example`):
```toml
[gcp]
project_id = "..."
sa_email = "esp32-logger@my-project.iam.gserviceaccount.com"
sa_key_id = "abc123..." # `private_key_id` from the SA JSON key
sa_key_pem = "gcp-sa-key.pem" # path; tool reads + embeds the bytes
min_severity = "info" # debug / info / warn / error; default info
metrics_interval_secs = 300 # 0 disables metrics; cloud_log keeps running
```
NVS keys (15-char limit):
| ns | key | type | notes |
|-----|----------------|------|----------------------------------------------------|
| gcp | project_id | str | GCP project (logs + metrics land in) |
| gcp | sa_email | str | service-account email |
| gcp | sa_key_id | str | private-key id (JWT `kid` header) |
| gcp | sa_key_pem | blob | RSA private key, PKCS#8 PEM (~1.7 KB) |
| gcp | min_severity | u8 | 0=TRACE..4=ERROR; default 2=INFO |
| gcp | metric_intvl | u32 | metrics snapshot interval in seconds; default 300 |
Missing the namespace entirely or any of the four required string/blob
fields disables both pipelines. Missing optional fields fall back to
defaults.
The OTA-distributed firmware contains no GCP secrets — the SA key
lives in NVS and is written via USB by `make provision`.
## Concerns / known limitations
- **NVS unencrypted**: anyone with physical access can dump the SA
key. Mitigation is strict scoping (only `logging.logWriter` +
`monitoring.metricWriter`, on a logs-tolerant project). Real fix is
Flash Encryption + Secure Boot v2; deferred (see [`ota.md`](ota.md)
Future work).
- **Wi-Fi outages**: the cloud_log queue is bounded at 256 entries.
Long offline periods are lossy; drops are surfaced via
`dropped_before` on subsequent entries.
- **Metric descriptor sticky labels**: see "Schema" above. Adding a
new metric label key requires a one-time descriptor delete.
- **CPU freq metric is build-time**: `esp_clk_cpu_freq` isn't in the
esp-idf-svc bindings, so we report the configured default. Becomes
inaccurate if/when `CONFIG_PM_ENABLE` is turned on.
## Future work
- **Per-task CPU runtime stats** via `vTaskGetRunTimeStats` — needs
`CONFIG_FREERTOS_USE_TRACE_FACILITY=y` + `CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y`.
- **Light-sleep stats** once `esp_pm_*` is adopted — pairs with
modem-sleep work for power telemetry.
- **External power telemetry** (INA219/INA226 over I2C) — would warrant its own plan.
- **Pre-declared MetricDescriptors** with units + descriptions for nicer Cloud Monitoring UI.
- **Alerting policies** as Terraform / `gcloud alpha monitoring` resources, checked in.
- **Cumulative metrics with `startTime`** for proper rate aggregation
(drops/sec, polls/sec) instead of GAUGE snapshots of running totals.
- **OIDC instead of SA key** — would remove the key-leak concern, but
ESP32 has no source of a usable OIDC token today.