[FR] Websockets for logging, streaming cadence, power, etc

[bau-sec]

Is your feature request related to a problem? Please describe.
For the debug info page, the javascript refreshes debug info every second or so. I'm envisioning a dashboard that is similar to the debug info page, but it displays current cadence, power, connected devices, think a bike computer basically. This would be useful riding outside of zwift or similar apps. To make something like that work well, websockets would be nice. Rather than refreshing every second which can create lag between when the measurement was taken and when we actually read it on the refresh, it would be nice to have websockets allowing the SS2K to push out the measurement as soon as it happens.

This would also be nice for logging since the log message can be pushed out immediately rather than cached to a buffer waiting for a client to pull it down.

Describe the solution you'd like
If we switch to ESPAsyncWebServer (https://github.com/me-no-dev/ESPAsyncWebServer) we'd get websockets and server side events to handle this scenario.

Describe alternatives you've considered
Just leaving it the way it is w/ the client webpage making requests every second or so to refresh data

Additional context
I was thinking about starting a branch to swap our Webserver.h calls to use ESPAsyncWebServer, but wanted to gauge interested before going down that path. I'd probably wait until the native testing PR was in since that's a big reorg.

[kadaan]

@bau-sec This would be great. We would love to use websockets and the AsyncWebServer. There have been issues in the past getting the AsyncWebServer and NimBLE-Arduino working well together.

I think this could fit in well with the new logging changes I have in the "Improved Logging" PR.

Here is an example of someone doing websockets for debug logging: https://github.com/ayushsharma82/WebSerial

[bau-sec]

@bau-sec This would be great. We would love to use websockets and the AsyncWebServer. There have been issues in the past getting the AsyncWebServer and NimBLE-Arduino working well together.

I think this could fit in well with the new logging changes I have in the "Improved Logging" PR.

Here is an example of someone doing websockets for debug logging: https://github.com/ayushsharma82/WebSerial

I threw some stuff together to start experimenting w/ ESPAsyncWebServer in PR #178. So far it runs on the ESP, but I haven't tried to ride w/ it yet or connect to bluetooth devices. Do you remember what the issues were combining ESPAsyncWebServer with NimBLE?

[kadaan]

You will get some nice crashes. Search on NimBLE-Arduino and ESPAsyncWebServer and you will find some mention for sure. Sorry, I don’t have the links handy.

[doudar]

Is your feature request related to a problem? Please describe.
For the debug info page, the javascript refreshes debug info every second or so. I'm envisioning a dashboard that is similar to the debug info page, but it displays current cadence, power, connected devices, think a bike computer basically. This would be useful riding outside of zwift or similar apps. To make something like that work well, websockets would be nice. Rather than refreshing every second which can create lag between when the measurement was taken and when we actually read it on the refresh, it would be nice to have websockets allowing the SS2K to push out the measurement as soon as it happens.

This would also be nice for logging since the log message can be pushed out immediately rather than cached to a buffer waiting for a client to pull it down.

Describe the solution you'd like
If we switch to ESPAsyncWebServer (https://github.com/me-no-dev/ESPAsyncWebServer) we'd get websockets and server side events to handle this scenario.

Describe alternatives you've considered
Just leaving it the way it is w/ the client webpage making requests every second or so to refresh data

Additional context
I was thinking about starting a branch to swap our Webserver.h calls to use ESPAsyncWebServer, but wanted to gauge interested before going down that path. I'd probably wait until the native testing PR was in since that's a big reorg.

It's an awesome Idea. I've just hit big roadblocks in the past with Async. :(

We could do it all with Bluetooth.

Just have to write a bunch of multi platform client apps :) Unfortunately this doesn't work on mobile devices (apple) yet:
https://web.dev/bluetooth/

https://balenalabs-incubator.github.io/balena-web-ble/

I guess there is this:
https://apps.apple.com/us/app/bluefy-web-ble-browser/id1492822055

That really might not be a horriBLE solution if someone wanted to check it out.

[doudar]

@bau-sec , @h2zero has mentioned that there's a chance this may now work with the latest NimBLE and arduino-framework commits if you're interested in trying again.

[h2zero]

It's wishful thinking, but worth a go. If I had a quick way to test it I would try it out but that might not work for this repo. I sadly gave up on async long ago for much the same reasons @doudar did, it's just too hard to get stable and the dev is too busy to address the issues. Recent updates of IDF and Arduino might provide some relief though if anyone is interested in testing.

[bau-sec]

I commented on the PR too, but I'll take a look this weekend, should be pretty quick to see the state of things w/ the arduino and NimBLE updates.

[doudar]

@bau-sec , have you had been able to check into this at all?

[MarkusSchneider]

For logging UDP could be an alternative way to submit messages. I've used UDP in another Arduino project for logging together with https://github.com/couchcoding/Logbert.
If you think this is worth a look, I can try to add it to SmartSpin2k logging.

[doudar]

We’ve freed up a bunch more memory with the latest arduino updates. Give it a go if you’d like. Sounds promising!

[doudar]

As of 12/31/2021, it appears there is still an issue in arduino core preventing stability when using both BLE and asyncTcp simultaneously.

[doudar]

@MarkusSchneider , I think we are starting to have occasional issues with ISR's not getting recognized (shifter presses) over time as the WiFI radio gets bogged down with too much traffic from logging.

Thinking about this, I'm seeing two options:

1. See if there's some better way for the html to get logging information that would be dual purpose. Like websockets...Are we sure there's no way for a browser to access a raw TCP port? I think that answer is no but it might be worth looking into.
2. If we still need to send out via UDP and the webpage, maybe we should look at shutting down UDP logging for X seconds if logging is being requested via the http server.

Thoughts?

[MarkusSchneider]

I confirm, a unique interface for all use case (logging, status apps, html logging) would be the best.
Udp Logging is only useful for debugging or to record status information. I can implement an option to enable / disable udp logging.
In the long term we can go away from http polling and upd and use web sockets. But depending on the number of consumers web sockets could also be expensive. But with web sockets we can create several channels e.g. logging, ERG Date, ...

[doudar]

I love the UDP logging btw, it's leaps better the the HTML logging for recording a whole session, but if you just want to glance at the log quickly, the HTML log is very easy.

[doudar]

I confirm, a unique interface for all use case (logging, status apps, html logging) would be the best. Udp Logging is only useful for debugging or to record status information. I can implement an option to enable / disable udp logging. In the long term we can go away from http polling and upd and use web sockets. But depending on the number of consumers web sockets could also be expensive. But with web sockets we can create several channels e.g. logging, ERG Date, ...

!!!!!! It looks like maybe this library implements websockets without having to use asynctcp library! (but also allows the use of async in the future if it becomes stable with BLE).
https://github.com/Links2004/arduinoWebSockets

[doudar]

I confirm, a unique interface for all use case (logging, status apps, html logging) would be the best. Udp Logging is only useful for debugging or to record status information. I can implement an option to enable / disable udp logging. In the long term we can go away from http polling and upd and use web sockets. But depending on the number of consumers web sockets could also be expensive. But with web sockets we can create several channels e.g. logging, ERG Date, ...

In our potential release testing tonight, one of the users reported having the same issues as you while UDP logging was enabled. BLE kept timing out and disconnecting. I think it's because the logging stream is so steady that it's not allowing breaks between for BLE communication. I think we may be able to use bursts of UDP logging with a buffer like you mentioned previously. I believe @kadaan already had a solution for that, which we currently use in the http debugging interface. It's here:

SmartSpin2k/src/SS2KLog.cpp

Line 17 in a6220ed

const std::string DebugInfo::get_and_clear_logs() { return DebugInfo::INSTANCE.get_and_clear_logs_internal(); }

and here:

SmartSpin2k/src/SS2KLog.cpp

Lines 33 to 41 in a6220ed

	const std::string DebugInfo::get_and_clear_logs_internal() {
	if (xSemaphoreTake(logBufferMutex, 0) == pdTRUE) {
	const std::string debugLog = std::string(logBuffer, logBufferLength);
	logBufferLength = 0;
	logBuffer[0] = '\0';
	xSemaphoreGive(logBufferMutex);
	SS2K_LOGD(DEBUG_INFO_LOG_TAG, "Log buffer read %d bytes and cleared", logBufferLength);
	return debugLog;
	}

We would just need to use that and direct the logs to the UDP logger on a specified interval. I think the best place would be here:

SmartSpin2k/src/Main.cpp

Lines 156 to 161 in a6220ed

	if ((millis() - intervalTimer) > 10000) { // add check here for when to restart WiFi
	// maybe if in STA mode and 8.8.8.8 no ping return?
	// ss2k.restartWifi();
	intervalTimer = millis();
	}

Just modify the timer value to every 2 seconds or something. Currently that timer isn't being used, but I plan to expand that to check for wifi connectivity.

[MarkusSchneider]

Your solution will also ensure that BLE task is no longer blocked by udp-logging because main task will do that in background 👍.
I think the synchronous sending insed BLE task is the main problem and the frequent logging.

[MarkusSchneider]

I would prefer to use a queue

SmartSpin2k/src/BLE_Client.cpp

Line 518 in a6220ed

bool SpinBLEAdvertisedDevice::enqueueData(uint8_t *data, size_t length) {

instead of using a shared memory buffer.

The semaphore in the buffer will block adding log messages if the messages are processed and the caller must wait or the message is rejected.

A queue decouples writing and reading completely.

[doudar]

I'm open to either, I wanted to make sure that you knew the other option was available as well.

At some point we would want messages to be dropped, but we currently serve 15k webpages without issue so we are probably restricted more by esp32's memory.

If you turn on the stack debug, you'll want to look at the "best block" for an idea on how much we have to work with.

[doudar]

@MarkusSchneider , new branch https://github.com/doudar/SmartSpin2k/tree/websockets-no-async has an infant implementation of websockets working for the html debug. So far, it works really slick. I haven't ride tested it yet and there's a lot that would need to be converted over (like for userConfig and rtConfig). Also not sure how to get these out into something like Logbert yet.

[MarkusSchneider]

Hi Anthony,
I did a deeper look at the logging implementation and I think we should implement a strategy pattern for the log sinks.

We can then define and enable different logging strategies by creating an instance of a logger.
Interface could looks like:
class ILogAppender { public: virtual void Log(const char* message) = 0; };

In SSKLog

SmartSpin2k/src/SS2KLog.cpp

Lines 72 to 82 in a6220ed

	void ss2k_log_writev(esp_log_level_t level, const char *format, va_list args) {
	esp_log_writev(level, SS2K_LOG_TAG, format, args);
	if (userConfig.getUdpLogEnabled()) {
	UdpLogger::log(format, args);
	}
	#if DEBUG_LOG_BUFFER_SIZE > 0
	DebugInfo::append_logv(format, args);
	#endif // DEBUG_LOG_BUFFER_SIZE > 0
	}

Push the log message to a Queue or MessageBuffer (I don't know what kind of buffer is better for sending strings).

In the main.cpp register/create the appender and in the main-loop, read all messages from queue or message-buffer and loop over the log-appenders to write messages to sink.

Advantages

• decoupled creating of log message and sending (send runs in main task, not blocking worker task)
• Unique interface to all log appender, no code change in SSK2Log for new appender

Disadvantages

• Can not send log messages at startup (before main loop is running). Can solved by implementing serial logging inside of SSKLog.ss2k_log_writev as default.

What do you think?

[doudar]

I’m all for it, and agree that it should reduce the issues we’re having with logging. Startup messages will probably always have to be gathered via serial, or made less verbose.

Speaking of verbosity, I wonder if there’s a way to reduce characters transmitted while retaining information and readability.

Such as, sending all common constants in the logging data (such as the log tags) to the client at startup and then encoding them to a single uint8_t, then decoding them for display on the client. Probably too complex and may introduce more issues though.

Along this same line, we could reduce verbosity by utilizing log levels more and making the log level run time selectable via the interface. If websockets prove stable, they would be perfect for this as we could specify log level by the web socket constructor on the client.

[MarkusSchneider]

we can gzip the messages. But then we have to build owner own log monitor with the unzip functionality.
If we move the processing of the log messages into the main loop, logging should no longer block task.

[doudar]

^^ I’m reading that the websocket protocol supports text compression on the fly. Maybe that small library we have supports it (I doubt it). Also, I edited the comment above with more information ^^

[doudar]

Nice @MarkusSchneider ! I see your updates to that branch. I'm going to ride test it ASAP and see if we're stable.

Looks awesome!

[doudar]

This should be merged with Wahoo Dircon as it’s an established protocol for sending FTMS data via udp. The issue I have is that the mdns library needs to be modified and it’s part of the IDF so it needs to be compiled into our own version of arduino-core