Improve startup logs

[sdirix]

Theia provides a number of startup related logging, e.g.

root INFO configured all backend app contributions
root INFO Backend PluginDeployerContribution.initialize: 1.0 ms [Finished 0.676 s after backend start]
root INFO Backend WebviewBackendSecurityWarnings.initialize: 0.7 ms [Finished 0.676 s after backend start]
root INFO Backend HostedPluginLocalizationService.initialize: 0.7 ms [Finished 0.676 s after backend start]
root INFO Backend MiniBrowserBackendSecurityWarnings.initialize: 0.6 ms [Finished 0.676 s after backend start]
root INFO Backend HostedPluginReader.initialize: 0.6 ms [Finished 0.676 s after backend start]
root WARN Backend PluginLocalizationServer.initialize took longer than the expected maximum 50 milliseconds: 62.8 ms [Finished 0.686 s after backend start]
root INFO configured all backend app contributions
root INFO Backend WebsocketEndpoint.onStart: 1.2 ms [Finished 0.703 s after backend start]
root INFO Theia app listening on http://127.0.0.1:3000.
root INFO Backend DefaultWorkspaceServer.onStart: 37.9 ms [Finished 0.741 s after backend start]
root INFO Finished starting backend application: 0.0 ms [Finished 0.754 s after backend start]
root INFO Resolve plugins list: 113.1 ms [Finished 0.818 s after backend start]
root INFO Deploy plugins list: 308.2 ms [Finished 1.013 s after backend start]
[...]
root INFO Start frontend contributions: 184.9 ms [Finished 1.599 s after frontend start]
root INFO Changed application state from 'init' to 'started_contributions'.
root INFO Changed application state from 'started_contributions' to 'attached_shell'.
root INFO >>> Restoring the layout state...
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Waiting for backend deployment: 36.6 ms [Finished 1.634 s after frontend start]
root INFO [hosted-plugin: 3808251] PLUGIN_HOST(3808251) starting instance
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Sync of 99 plugins: 429.1 ms [Finished 2.063 s after frontend start]
root INFO <<< The layout has been successfully restored.
root INFO Initialize the workbench layout: 1285.9 ms [Finished 2.895 s after frontend start]
root INFO Changed application state from 'attached_shell' to 'initialized_layout'.
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Loading plugin contributions
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Load contributions of 99 plugins: 148.8 ms [Finished 3.054 s after frontend start]
root WARN Frontend EditorPreviewTreeDecorator.onDidInitializeLayout took longer than the expected maximum 100 milliseconds: 150.3 ms [Finished 3.054 s after frontend start]
root INFO Frontend application start: 2640.5 ms [Finished 201.409 s after backend start]
root INFO Replace loading indicator with ready workbench UI (animation): 1066.3 ms [Finished 4.132 s after frontend start]
root INFO Changed application state from 'initialized_layout' to 'ready'.
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Starting plugins.
root INFO [51cb1c8c-2d6e-4b2f-8712-a99d784b70b7] Start of 99 plugins: 2707.6 ms [Finished 5.810 s after frontend start]

It would be good to work on the improvements of the logging:

• There is no log message in the backend startup before the backend application is constructed
• The "configuration" steps in the backend startup are not individually measured
• The message "after backend start" is not self-explanatory. It means after the node process was started.
  • The same with the "after frontend start" logs.
• We have log messages like this: root INFO Finished starting backend application: 0.0 ms [Finished 0.754 s after backend start] in which we just log something without doing work, so measuring time like 0.0ms just provides confusion. We should clearly separate between pure log messages and logs describing a process
• After "finished starting backend application" more log messages are emitted, because startup kicks off some async processes, especially plugin loading. This should be self-explanatory, by adjusting the message.
  • The same happens in the frontend application and should be adjusted too.
• We should offer a way for extensions to automatically log their startup work they perform outside of the blocking thread. For example each configure, initialize and onStart could optionally return a Promise instead of being void, with the promise being resolved once they are actually finished. This would allow to track the overall startup work and emit a marker once the backend/frontend actually settled.
• There is no log message in the frontend startup before the frontend application start is called. At least a log message at construction time and ideally one before would nice to have to track these times too.
• There are no log messages regarding the Electron process at all. We should have the same logs like in frontend/backend startup too.

[cdamus]

I have an interest in these improvements. Happy to work on a contribution of a fix.