webdev daemon should use app.progress instead of daemon.logMessage for build progress

[DanTup]

Currently webdev daemon writes all build progress as daemon.logMessage events. Many of these would work better as app.progress events since they're already used to show nice progress notifications when building Flutter apps.

For example, here's a webdev daemon build:

[9:30:35 AM]: <== [{"event":"daemon.connected","params":{"version":"0.4.2","pid":18674}}]
[9:30:36 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Connecting to the build daemon..."}}]
[9:30:37 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script..."}}]
[9:30:37 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script completed, took 366ms"}}]
[9:30:37 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[9:30:37 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Starting daemon..."}}]
[9:30:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Initializing inputs"}}]
[9:30:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Reading cached asset graph..."}}]
[9:30:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Reading cached asset graph completed, took 368ms"}}]

And here's a Flutter build:

[9:09:12 AM]: <== [{"event":"daemon.connected","params":{"version":"0.4.2","pid":14493}}]
[9:09:12 AM]: <== [{"event":"app.start","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","deviceId":"1DD6786B-37D4-4355-AA15-B818A87A18B4","directory":"/Users/dantup/Dev/Google/flutter/examples/flutter_gallery","supportsRestart":true,"launchMode":"run"}}]
[9:09:12 AM]: <== Launching lib/main.dart on iPhone XS Max in debug mode...
[9:09:16 AM]: <== [{"event":"app.progress","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","id":"0","progressId":null,"message":"Running Xcode build..."}}]
[9:09:21 AM]: <== [{"event":"app.progress","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","id":"0","progressId":null,"finished":true}}]
[9:09:21 AM]: <== Xcode build done.                                            4.8s
[9:09:26 AM]: <== [{"event":"app.debugPort","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","port":52628,"wsUri":"ws://127.0.0.1:52628/ws","baseUri":"file:///Users/dantup/Library/Developer/CoreSimulator/Devices/1DD6786B-37D4-4355-AA15-B818A87A18B4/data/Containers/Data/Application/504526A6-634C-4B7B-B6B5-22DE55D3FE3F/tmp/flutter_gallerybZpreZ/flutter_gallery/"}}]
[9:09:27 AM]: <== [{"event":"app.progress","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","id":"1","progressId":null,"message":"Syncing files to device iPhone XS Max..."}}]
[9:09:30 AM]: <== [{"event":"app.progress","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459","id":"1","progressId":null,"finished":true}}]
[9:09:30 AM]: <== [{"event":"app.started","params":{"appId":"f7f9f43e-4003-4e5f-aff2-f97b7d8e5459"}}]

In VS Code, daemon.logMessage isn't currently surfaced anywhere (though I'll fix this, and make it work similar to Flutter's non-JSON stdout output, going to the debug console), but the app.progress notifications are used to show the progress of a build/launch in a progress notification:

If we could change webdev daemon's progress notifications (all the ones that appear twice, the second one with "Completed" on the end) to app.progress, then we'd get the same sort of build notifications for webdev without additional work.

[devoncarew]

+1 for using the app.progress when we can. In IntelliJ, pairs of app.progress and app.progress (with finished == true) will cause a progress UI element to show - this gives the user a good sense of what's happening during longer tasks.

[grouma]

This is unfortunately a little tricky. We don't have the appId while the application is building. The appId is a hash of the entrypoint which is only provided when the application is loaded. This isn't easy to change for a number of reasons. I can however tie into the build_daemon protocol and listen for build start and end events and create a corresponding app.progress event for each. Thoughts?

[devoncarew]

We'll only every have one app I suspect - webdev serve --machine will just launch chrome and run the app? If so, we could just use a hard-coded id (web-app-1).

[devoncarew]

And re: progress events - we'd want to prefer fewer, more course grained events rather than lots of separate, short events. These will show up as progress bars in the IDE, and we won't want a dozen different progress events to flash by, each taking 100ms.

[DanTup]

@grouma Running against the latest changes I'm not seeing any app.progress events. My log is from the daemon. Any ideas?

Also - looking at the code change, I think the progress IDs for the build complete/failed events should have finished: true and the same progressId as the start build (this will be our signal to remove the UI progress indicator for the build progress).

[8:06:27 AM]: <== [{"event":"daemon.connected","params":{"version":"0.4.2","pid":7252}}]
[8:06:27 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Connecting to the build daemon..."}}]
[8:06:28 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script..."}}]
[8:06:28 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script completed, took 399ms"}}]
[8:06:28 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:28 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Starting daemon..."}}]
[8:06:29 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script..."}}]
[8:06:29 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Generating build script completed, took 114ms"}}]
[8:06:29 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:29 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Creating build script snapshot......"}}]
[8:06:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Creating build script snapshot... completed, took 9.5s"}}]
[8:06:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:39 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Starting daemon..."}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Initializing inputs"}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Building new asset graph..."}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Building new asset graph completed, took 1.6s"}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Checking for unexpected pre-existing outputs...."}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"BuildDefinition: Checking for unexpected pre-existing outputs. completed, took 1ms"}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"build_runner: Setting up file watchers..."}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"build_runner: Setting up file watchers completed, took 3ms"}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":""}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Serving DevTools at http://localhost:50444\n"}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Starting resource servers..."}}]
[8:06:41 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Serving `web` on http://localhost:50434\n"}}]
[8:06:42 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Registering build targets..."}}]
[8:06:42 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Starting initial build..."}}]
[8:06:42 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"About to build [web]..."}}]
[8:06:42 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Build: Running build..."}}]
[8:06:44 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 1.1s elapsed, 202/206 actions completed."}}]
[8:06:45 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 2.2s elapsed, 563/567 actions completed."}}]
[8:06:46 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 3.3s elapsed, 653/692 actions completed."}}]
[8:06:47 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 4.4s elapsed, 658/694 actions completed."}}]
[8:06:48 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 5.5s elapsed, 671/702 actions completed."}}]
[8:06:49 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 6.6s elapsed, 679/709 actions completed."}}]
[8:06:50 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 7.7s elapsed, 686/722 actions completed."}}]
[8:06:51 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 8.8s elapsed, 695/728 actions completed."}}]
[8:06:52 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 9.8s elapsed, 698/734 actions completed."}}]
[8:06:53 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 10.9s elapsed, 702/734 actions completed."}}]
[8:06:54 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 12.0s elapsed, 705/734 actions completed."}}]
[8:06:55 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 13.0s elapsed, 710/736 actions completed."}}]
[8:06:57 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 14.1s elapsed, 712/736 actions completed."}}]
[8:06:58 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 15.2s elapsed, 713/736 actions completed."}}]
[8:06:59 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 16.3s elapsed, 715/736 actions completed."}}]
[8:07:00 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 17.4s elapsed, 719/736 actions completed."}}]
[8:07:01 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 18.5s elapsed, 722/736 actions completed."}}]
[8:07:02 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 19.5s elapsed, 722/736 actions completed."}}]
[8:07:03 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 20.5s elapsed, 723/736 actions completed."}}]
[8:07:04 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 21.6s elapsed, 725/736 actions completed."}}]
[8:07:05 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 22.6s elapsed, 725/736 actions completed."}}]
[8:07:06 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 23.7s elapsed, 732/736 actions completed."}}]
[8:07:07 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 24.7s elapsed, 733/736 actions completed."}}]
[8:07:08 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 25.8s elapsed, 733/736 actions completed."}}]
[8:07:09 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 26.9s elapsed, 733/736 actions completed."}}]
[8:07:10 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 27.9s elapsed, 733/736 actions completed."}}]
[8:07:11 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 29.0s elapsed, 733/736 actions completed."}}]
[8:07:12 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 30.0s elapsed, 733/736 actions completed."}}]
[8:07:14 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 31.1s elapsed, 733/736 actions completed."}}]
[8:07:15 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 32.2s elapsed, 733/736 actions completed."}}]
[8:07:16 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 33.3s elapsed, 733/736 actions completed."}}]
[8:07:17 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 34.3s elapsed, 734/736 actions completed."}}]
[8:07:18 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Heartbeat: 35.3s elapsed, 1971/1971 actions completed."}}]
[8:07:18 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Build: Running build completed, took 35.6s\n"}}]
[8:07:18 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Build: Caching finalized dependency graph..."}}]
[8:07:18 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Build: Caching finalized dependency graph completed, took 215ms\n"}}]
[8:07:18 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Build: Succeeded after 35.8s with 627 outputs (3446 actions)\n"}}]
[8:07:20 AM]: <== [{"event":"daemon.logMessage","params":{"level":"INFO","message":"Debug service listening on ws://localhost:50519\n"}}]
[8:07:20 AM]: <== [{"event":"app.start","params":{"appId":"kVKCUVlm/g7DpX4AxYGNGQ==","directory":"/Users/dantup/Dev/Google/xxx/examples/hello_world","deviceId":"chrome","launchMode":"run"}}]
[8:07:20 AM]: <== [{"event":"app.started","params":{"appId":"kVKCUVlm/g7DpX4AxYGNGQ=="}}]
[8:07:20 AM]: <== [{"event":"app.debugPort","params":{"appId":"kVKCUVlm/g7DpX4AxYGNGQ==","port":50519,"wsUri":"ws://localhost:50519"}}]

[grouma]

Should we still use build.started as the progressId? I'll add finished: true. Note that you are not getting progress events for the initial build due to the issues I outlined above. However, for any subsequent build you'll get them. Just modify a file to trigger the build.

[DanTup]

Should we still use build.started as the progressId?

The ID doesn't matter to the clients - all we do is assume that for any given progressId we get, that later we'll get the same ID with finished:true, without caring about the specific value.

Note that you are not getting progress events for the initial build due to the issues I outlined above

Oh sorry :) I re-read above though and I'm not sure what this relates to though. Do you mean the comment about appId? If so, I think just hard-coding anything is fine as Devon suggested.

The initial build is really slow for me, and currently gives no indication of progress if the Debug Console isn't visible. Could we possibly send an app.progress alongside the daemon.connected event, and then "finish" it just before app.start or something? (we could otherwise spawn a progress indicator right at the start and close it when we get debugPort or something - though it'd be a bit webdev specific).

[grouma]

The problem is that building a top level directory doesn't necessarily imply that only one application is built. For example you can have multiple applications under your web directory. This makes me hesitant to create a fake appId. As an alternative, can we provide build progress events without an appId? That way we can provide a progress event for the initial build.

[DanTup]

For example you can have multiple applications under your web directory. This makes me hesitant to create a fake appId

If there are multiple apps, what will happen here - will you sent multiple app.starts and multiple app.debugPorts? VS Code doesn't currently expect that - it assumes only a single app will launch. I think appId is a bit of a hangover from when the original daemon (now "the device daemon") handled launching (@devoncarew may be able to confirm).

As an alternative, can we provide build progress events without an appId?

For VS Code, I think this would work fine (though I also think it'd just be the same as hard-coding a string for all appIds). I'm not sure about IntelliJ though.

Let me know how multiple apps will work with this, as there might be more work to do in the clients if the daemon isn't just handling a single app.

[grouma]

If there are multiple apps, what will happen here - will you sent multiple app.starts and multiple app.debugPorts?

The first app to be loaded will get the app.start event. Other apps to be loaded will be ignored. This touches on an issue that was brought up earlier today. The user can manually refresh the browser. Should we be sending new app.start events for those?

Let me know how multiple apps will work with this, as there might be more work to do in the clients if the daemon isn't just handling a single app.

Multiple apps are supported with webdev serve and works as one would expect. You can open devtools connected to each one. Since this infrastructure is mostly reused for the daemon side of things, that's why we run into issues. We don't have the appId until the application is built and loaded. As mentioned above, only the first application loaded will work with the daemon.