Add update logs to update-dialog.

[jdeanwallace]

Demo video.

Notes

1. Implementation note: If it's easier to stream the log through a websockets API, we can do that instead of using the existing /api/update GET API.

   I decided not to stream the update logs (via websockets) because it was easy enough to add the update logs to the /update API response.

2. "More details" only appears once there are update logs to display.

Fixes #496

---

This change is 

[mtlynch]

I think we should make the update logs a separate API endpoint.

Historically, we've had a lot of bugs on the version-to-version update UI flow because it's hard to test, so we should minimize complexity along that path. With the current implementation, the update flow would fail if the server failed to retrieve the update logs, which would be undesirable (the update itself would succeed but the UI flow would break).

My suggestion would be to either add a REST API endpoint or to add a socket.io API.

Also, in terms of UI, I think the user would want to have access to the logs the entire time. Can we keep the "More details" expander on the "Restarting" and "Update complete" views as well? I'd really love for the user to see the update logs when there's an error, but that complicates our error handling a lot, so we can punt on that for now.

I think it's a little surprising to see the expander appear suddenly. Can we have it visible as soon as the update starts, but its initial text reads Retrieving update logs from TinyPilot device?

[mtlynch]

Just peeking here, it'd be nice to be able to stream the writes to the frontend, but it's not worth the complexity of adding an additional privileged script to the backend.

If it's a choice between redundantly retrieving the full log on each file or adding an additional privileged script to maintain, I'd rather retrieve the full log.

[jdeanwallace]

Streaming the update logs via socketio was trickier than I expected. I have gotten it working, but I ran into some issues along the way.

The update logs are not written to its own dedicated file. We use the read-update-log script to extract the update logs on the fly. So in order to stream the live logs we'll need a new script, say stream-update-log, that does something like:

sudo journalctl -u tinypilot-updater --follow \
  | grep tinypilot-update-svc \
  | sed -E 's/^.*tinypilot-update-svc\[[0-9]+\]: //g'

which would write only the update logs to stdout as they happen. This means we'll need to stream the stdout of the above script via socketio. The problem is that reading from stdout is a blocking operation and our flask app is still written synchronously (i.e. not using async / awaits). For example the following code is blocking when there is nothing to read (yet) from stdout:

import subprocess
process = subprocess.Popen('tail -f test.txt'.split(), stderr=subprocess.STDOUT, stdout=subprocess.PIPE)
process.stdout.read() # This is blocking when there's no data to read yet.

So instead of reading from stdout directly, I thought I could write stdout to an in-memory text stream (i.e. io.StringIO), but subprocess.Popen require the "file" to have an actual fileno (which StringIO doesn't have).

So I ended up writing stdout to a real tempfile then streaming the contents of the tempfile to the frontend via socketio.

Overall the solution isn't very elegant and I'm no longer sure this is the direction we want to continue in. So I'm just checking in here.

[jdeanwallace]

If it's a choice between redundantly retrieving the full log on each file or adding an additional privileged script to maintain, I'd rather retrieve the full log.

Ah okay I see, thanks for the guidance on this.

[mtlynch]

I have one idea before we simplify to just sending the full log.

Could we have a separate thread / process that repeatedly calls read-update-log, caches the output, and sends only the delta over the socket channel? This thread could exit when the update process is no longer running.

If that sounds interesting, play around with that for up to four hours. If it doesn't look like it's leading anywhere or it seems like it's going to be too much complexity, let's just fall back to a simple implementation that sends the full log on each request.

[jdeanwallace]

Could we have a separate thread / process that repeatedly calls read-update-log, caches the output, and sends only the delta over the socket channel? This thread could exit when the update process is no longer running.

Based on this feedback, I've done the following:

1. Linked the while loop that repeatedly calls read-update-log to the lifetime of the open socket connection.
2. The output is cached in the flask user session. Source.
3. The delta is calculated by removing the common prefix from the output and only sending the new logs over the socket channel. Source.

The reason why I use the flask session instead of a variable on the namespace instance is because the namespace is a global variable. So changing anything on the namespace, changes it for all socketio clients :/

This PR is still a rough PoC. Demo video.

[mtlynch]

Cool, that looks like a good direction to me.

[jdeanwallace]

Update

This PR is now ready for a review. Demo video.

Notes

1. I wasn't sure what the best way was to design the /updateLogs socketio API. The current approach is:

   1. The client establishes a socketio connection with the server
   2. The client emits a read event.
   3. The server keeps sending read_response events every 500ms (if there is new update logs)
   4. The client disconnects the socketio connection to stop receiving events.

   The idea behind this approach was to treat the /updateLogs namespace like a file handler. You open the connection, you read from it, then you close the connection.

2. The code feels a bit messy, but I'm not sure why exactly 🤔

3. This feature took longer than I expected. I went over the initial sizing by ~7hours 😬

[mtlynch]

@jotaen - Can you review?

This feature took longer than I expected. I went over the initial sizing by ~7hours 😬

I think this actually went as planned, in terms of how our bug sizing goes. You were checking in as you went, so I had a sense of how difficult it would be.

Maybe one thing we can change in the future is to explicitly say during development that the size needs to be bumped up or the task needs to be scoped down. I'll upgrade to a large now.

[jotaen4tinypilot]

I think the general approach is cool, since it’s fairly lightweight both in terms of LOC and bandwidth. I’ve tested on the device, and it appears to work for me.

The code feels a bit messy, but I'm not sure why exactly 🤔

I’d see a possibility for improvement by restructuring a few things, for which I left some suggestions.

Reviewable status: 0 of 5 files reviewed, 10 unresolved discussions (waiting on @jdeanwallace and @jotaen)

---

app/update_logs.py, line 7 at r4 (raw file):

import eventlet
import flask_socketio
from flask import session

I think we usually try to avoid importing objects from modules selectively, so we should change to import flask and then do flask.session below.

---

app/update_logs.py, line 45 at r4 (raw file):

class Namespace(flask_socketio.Namespace):

I would probably put this class directly into socket_api.py. On the one hand it’s not really related to the other socket endpoints, on the other we also have one big api.py file with all the things. Currently, I see more value in keeping all external APIs grouped and being consistent with that, at the expense of bigger files.

I’d leave the read function here, though, so that we have a separation between API layer and core logic. That actually would be structurally similar to how we do it in api.py and the underlying modules (e.g. debug_logs.py).

---

app/update_logs.py, line 71 at r4 (raw file):

            logs = read()
            # Determine where the current logs overlap with the previous logs
            common_logs = os.path.commonprefix(

We could consider putting this logic into a separate function, like determine_new_logs or the like. Even if it’s not fancy logic, we could write a test for it then.

Cool idea to reuse commonprefix, btw.: it first seemed a bit odd to me that it’s from os.path, but on the other hand it does exactly what we want.

---

app/update_logs.py, line 77 at r4 (raw file):

            if new_logs:
                flask_socketio.emit('read_response', new_logs)
                session['update_logs']['prev_logs'] = logs

This part might be problematic, because as far as I understand sessions in Flask are persisted in cookies. So we are potentially serializing the entire log output and sending it as a cookie to the client. This doesn’t happen actually and I’m not sure what the reason is – maybe it’s because session['update_logs'] is a dict (not a primitive) and we are performing a deep update within that dict; therefore Flask might not notice that we have updated the session data and doesn’t flag the session cookie for resending.

I’d be worried that this approach might potentially lead to problems down the line. As an idea, we could have an internal dictionary with { uuid : prev_logs } or the like, and then we only store the id in the session?

Also, I found your explanation why the session is involved here in the first place quite helpful, so I suggest to put it as comment in the code. (It wasn’t immediately obvious to me from reading the code alone.)

---

app/update_logs.py, line 78 at r4 (raw file):

                flask_socketio.emit('read_response', new_logs)
                session['update_logs']['prev_logs'] = logs
            eventlet.sleep(0.5)

Just a thought here: in Pro, we have a module threads.py in order to hide the fact that Flask uses eventlet under the hood. While the use-case there is actually a bit different, I was still wondering whether it’d make sense to keep eventlet encapsulated, because it’s actually an implementation detail. Not sure, though – might also be too much. What do you think?

---

app/templates/custom-elements/update-dialog.html, line 51 at r4 (raw file):

    }

    #update-container .logs {

I think it would be worth to share a common style with the debug logs here to enforce visual consistency. I’d think something along the lines of:

/* style.css */

.logs-output {
      /* Note: don’t forget to also add the monospace class when using this class. */
      padding: 0.25rem 0.5rem;
      background-color: white;
      border: 1px solid var(--brand-metallic-dark);
      user-select: text;
      text-align: left;
      overflow-y: scroll;
      white-space: pre-wrap;
}

That would leave us with a local class that only contains the specific sizing and flex stuff.

---

app/templates/custom-elements/update-dialog.html, line 107 at r4 (raw file):

    <details>
      <summary>More details</summary>

I would add top-margin: 1.5rem here to separate the details section a bit more from the spinner.

---

app/templates/custom-elements/update-dialog.html, line 108 at r4 (raw file):

    <details>
      <summary>More details</summary>
      <div class="logs"></div>

Can we add the monospace class here? I think that’d make sense for the log output, we also use it for the debug logs. (Unfortunately, we can’t mix it into the logs class directly, since we don’t use SASS/LESS.)

---

app/templates/custom-elements/update-dialog.html, line 258 at r4 (raw file):

          // Initilize a Socket on the "/updateLogs" namespace and
          // automatically establish a connection.
          const socket = io("/updateLogs");

As an idea, I think the readability could benefit if we wrapped the socket logic into its own class. That would make the consumer code here read more abstract, and we probably also wouldn’t need the comments anymore. Roughly like so:

const updateLogsStreamer = new UpdateLogsStreamer();
updateLogsStreamer.onNewLogText(text => {/*...*/});
updateLogsStreamer.start();
updateLogsStreamer.stop();

We could even consider putting this into a separate place then, like controllers.js for example. In the other web components, we don’t depend on the backend directly (e.g. specific routes), but we are going via the controllers. (Not sure whether controllers.js would be the best place, though, because our main socket also doesn’t live there.)

---

app/templates/custom-elements/update-dialog.html, line 262 at r4 (raw file):

          socket.on("read_response", (text) => {
            this.shadowRoot.querySelector(
              "#update-container .logs"

Bit of a nitpick: I’d personally prefer using an id attribute when targeting specific (single) DOM nodes. We can also save the element in this.elements to avoid looking it up repeatedly. (No significant performance win admittedly, more general habit.)

[jotaen4tinypilot]

Another thought on the session actually: I was wondering, maybe it’s fine to just store the logs in a shared variable? In practice there should only be one update happening at a time anyway. (But maybe I’m missing something?)

[jdeanwallace]

Thanks for the feedback. I've reworked the code based on the suggestions. Demo video.

Reviewable status: 0 of 5 files reviewed, 9 unresolved discussions (waiting on @jotaen and @jotaen4tinypilot)

---

app/update_logs.py, line 7 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

I think we usually try to avoid importing objects from modules selectively, so we should change to import flask and then do flask.session below.

Done. This was removed in the refactor.

---

app/update_logs.py, line 45 at r4 (raw file):

I would probably put this class directly into socket_api.py.

Generally I would agree, but because this functionality is contained within a class, it doesn't look the same as the rest of the functions in socket_api.py. If we look at socket_api.py as just a place to register event listeners, then I would argue that simply registering this namespace here is enough to point the programmer to the right spot.

---

app/update_logs.py, line 71 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

We could consider putting this logic into a separate function, like determine_new_logs or the like. Even if it’s not fancy logic, we could write a test for it then.

Cool idea to reuse commonprefix, btw.: it first seemed a bit odd to me that it’s from os.path, but on the other hand it does exactly what we want.

Done.

---

app/update_logs.py, line 77 at r4 (raw file):
Yeah using the flask session was a bit of a hack because I wasn't too sure if we wanted each client to be able to stream logs individually (i.e. multiple read-update-log processes) or only allow one stream at a time.

Based on your other comment:

maybe it’s fine to just store the logs in a shared variable? In practice there should only be one update happening at a time anyway

I've reworked the way we stream the update logs by only allowing a single stream at a time while also broadcasting to all connected clients. This means that even if you do have multiple browser tabs open for the same TinyPilot device, there's only one "process" streaming the update logs to all socket clients. Kind of an edge case, but I'm glad we resolved this. Thanks!

---

app/update_logs.py, line 78 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

Just a thought here: in Pro, we have a module threads.py in order to hide the fact that Flask uses eventlet under the hood. While the use-case there is actually a bit different, I was still wondering whether it’d make sense to keep eventlet encapsulated, because it’s actually an implementation detail. Not sure, though – might also be too much. What do you think?

Yeah I think the use-case it very much the same now (i.e. don't block my thread). I'll port this over in another PR.

---

app/templates/custom-elements/update-dialog.html, line 51 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

I think it would be worth to share a common style with the debug logs here to enforce visual consistency. I’d think something along the lines of:

/* style.css */

.logs-output {
      /* Note: don’t forget to also add the monospace class when using this class. */
      padding: 0.25rem 0.5rem;
      background-color: white;
      border: 1px solid var(--brand-metallic-dark);
      user-select: text;
      text-align: left;
      overflow-y: scroll;
      white-space: pre-wrap;
}

That would leave us with a local class that only contains the specific sizing and flex stuff.

Awesome, thanks!

---

app/templates/custom-elements/update-dialog.html, line 107 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

I would add top-margin: 1.5rem here to separate the details section a bit more from the spinner.

Done. I went with 1rem because it seemed a bit too far when the timer is displayed.

---

app/templates/custom-elements/update-dialog.html, line 108 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

Can we add the monospace class here? I think that’d make sense for the log output, we also use it for the debug logs. (Unfortunately, we can’t mix it into the logs class directly, since we don’t use SASS/LESS.)

Done.

---

app/templates/custom-elements/update-dialog.html, line 258 at r4 (raw file):

Previously, jotaen4tinypilot wrote…

As an idea, I think the readability could benefit if we wrapped the socket logic into its own class. That would make the consumer code here read more abstract, and we probably also wouldn’t need the comments anymore. Roughly like so:

const updateLogsStreamer = new UpdateLogsStreamer();
updateLogsStreamer.onNewLogText(text => {/*...*/});
updateLogsStreamer.start();
updateLogsStreamer.stop();

We could even consider putting this into a separate place then, like controllers.js for example. In the other web components, we don’t depend on the backend directly (e.g. specific routes), but we are going via the controllers. (Not sure whether controllers.js would be the best place, though, because our main socket also doesn’t live there.)

Great idea! I've also reworked the socket API to match this interface. I think the code looks much cleaner now.

---

app/templates/custom-elements/update-dialog.html, line 262 at r4 (raw file):
I like the this.elements approach. I've made use of it here.

I’d personally prefer using an id attribute when targeting specific (single) DOM nodes.

I agree with this in the context on the entire DOM. But when we're managing different states (i.e. updating, restarting, finished, etc.) I don't want to pollute the global namespace with state specific IDs. This means that the next programmer doesn't need to worry about naming conflicts when adding a new state.

[jotaen4tinypilot]

👍 Cool, the code looks all good to me. I’ve also tested on the device again.

Reviewed 3 of 5 files at r2, 6 of 6 files at r5.
Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @jdeanwallace and @jotaen)

---

app/update_logs.py, line 45 at r4 (raw file):

Previously, jdeanwallace (Jason Wallace) wrote…

I would probably put this class directly into socket_api.py.

Generally I would agree, but because this functionality is contained within a class, it doesn't look the same as the rest of the functions in socket_api.py. If we look at socket_api.py as just a place to register event listeners, then I would argue that simply registering this namespace here is enough to point the programmer to the right spot.

Fair point about the registering, I’m good with it either way.

---

app/update_logs.py, line 77 at r4 (raw file):

Previously, jdeanwallace (Jason Wallace) wrote…

Yeah using the flask session was a bit of a hack because I wasn't too sure if we wanted each client to be able to stream logs individually (i.e. multiple read-update-log processes) or only allow one stream at a time.

Based on your other comment:

maybe it’s fine to just store the logs in a shared variable? In practice there should only be one update happening at a time anyway

I've reworked the way we stream the update logs by only allowing a single stream at a time while also broadcasting to all connected clients. This means that even if you do have multiple browser tabs open for the same TinyPilot device, there's only one "process" streaming the update logs to all socket clients. Kind of an edge case, but I'm glad we resolved this. Thanks!

It’s good that you had identified that edge case anyway, I wouldn’t have thought of it at all, admittedly. Considering all the constellations, your current solution feels like the best compromise to me.

---

app/update_logs.py, line 78 at r4 (raw file):

Previously, jdeanwallace (Jason Wallace) wrote…

Yeah I think the use-case it very much the same now (i.e. don't block my thread). I'll port this over in another PR.

Ok, cool!

---

app/static/css/style.css, line 102 at r5 (raw file):

}

.logs-output {

Note to self: reuse this class in <error-dialog> for the details box. (I’m working on some general layout things this sprint, so I’ve taken note and will refactor there later.)

---

app/static/js/updatelogs.js, line 12 at r5 (raw file):

  }

  onNewLogs(fn) {

I think a comment would be cool to understand the required signature of fn.

---

app/templates/custom-elements/update-dialog.html, line 107 at r4 (raw file):

Previously, jdeanwallace (Jason Wallace) wrote…

Done. I went with 1rem because it seemed a bit too far when the timer is displayed.

👍

---

app/templates/custom-elements/update-dialog.html, line 262 at r4 (raw file):

Previously, jdeanwallace (Jason Wallace) wrote…

I like the this.elements approach. I've made use of it here.

I’d personally prefer using an id attribute when targeting specific (single) DOM nodes.

I agree with this in the context on the entire DOM. But when we're managing different states (i.e. updating, restarting, finished, etc.) I don't want to pollute the global namespace with state specific IDs. This means that the next programmer doesn't need to worry about naming conflicts when adding a new state.

Yeah, I think it’s a bit of a blurry line anyway between classes and ids, so all good from my side.

---

app/templates/custom-elements/update-dialog.html, line 111 at r5 (raw file):

<script src="/js/util/poll.js"></script>
<script src="/js/updatelogs.js"></script>

Ah sorry, I forgot to ping you on this PR. So we should add this import to index.html (pro tip: in the right lexicographic order 😆 )

The poll.js import will go away once you update your branch with master.

[jdeanwallace]

Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @jdeanwallace)

---

app/static/js/updatelogs.js, line 12 at r5 (raw file):

Previously, jotaen4tinypilot wrote…

I think a comment would be cool to understand the required signature of fn.

Done.

---

app/templates/custom-elements/update-dialog.html, line 111 at r5 (raw file):

Previously, jotaen4tinypilot wrote…

Ah sorry, I forgot to ping you on this PR. So we should add this import to index.html (pro tip: in the right lexicographic order 😆 )

The poll.js import will go away once you update your branch with master.

Done.