Order of lines in output is occasionally different than actual order

[madebydavid]

Description

I am doing some testing on the build servers and noticed that when logging the build directly the order of the lines in the output is different.

Expected output

Exporting Godot project to iOS....
Godot Engine v4.5.beta5.official.c81fd6c51 - https://godotengine.org

[   0% ] first_scan_filesystem | Started Project initialization (5 steps)
[   0% ] first_scan_filesystem | Scanning file structure...
[  16% ] first_scan_filesystem | Loading global class names...
[  33% ] first_scan_filesystem | Verifying GDExtensions...
[  50% ] first_scan_filesystem | Creating autoload scripts...
[  66% ] first_scan_filesystem | Initializing plugins...
[  83% ] first_scan_filesystem | Starting file scan...
[ DONE ] first_scan_filesystem

[   0% ] _update_scan_actions | Started Scanning actions... (19 steps)
[   0% ] _update_scan_actions | favicon-512.png
[   5% ] _update_scan_actions | icon.svg
[  10% ] _update_scan_actions | shipthis_adaptive_background_432x432.png
[  15% ] _update_scan_actions | shipthis_adaptive_foreground_432x432.png
[  20% ] _update_scan_actions | shipthis_main_192x192.png
[  25% ] _update_scan_actions | favicon-512.png
[  30% ] _update_scan_actions | icon.svg
[  35% ] _update_scan_actions | shipthis_29@2x.png
[  40% ] _update_scan_actions | shipthis_29@3x.png
[  45% ] _update_scan_actions | shipthis_40@2x.png
[  50% ] _update_scan_actions | shipthis_40@3x.png
[  55% ] _update_scan_actions | shipthis_60@2x.png
[  60% ] _update_scan_actions | shipthis_60@3x.png
[  65% ] _update_scan_actions | shipthis_76.png
[  70% ] _update_scan_actions | shipthis_76@2x.png
[  75% ] _update_scan_actions | shipthis_83_5@2x.png
[  80% ] _update_scan_actions | shipthis_appstore.png
[  85% ] _update_scan_actions | cube.blend
[  90% ] _update_scan_actions | icon.svg
[ DONE ] _update_scan_actions

Actual output

Exporting Godot project to iOS....
Godot Engine v4.5.beta5.official.c81fd6c51 - https://godotengine.org

[   0% ] first_scan_filesystem | Started Project initialization (5 steps)
[   0% ] first_scan_filesystem | Scanning file structure...
[  33% ] first_scan_filesystem | Verifying GDExtensions...
[   0% ] _update_scan_actions | favicon-512.png
[  16% ] first_scan_filesystem | Loading global class names...

[  83% ] first_scan_filesystem | Starting file scan...
[  66% ] first_scan_filesystem | Initializing plugins...
[  75% ] _update_scan_actions | shipthis_83_5@2x.png
[  15% ] _update_scan_actions | shipthis_adaptive_foreground_432x432.png
[  50% ] first_scan_filesystem | Creating autoload scripts...
[  10% ] _update_scan_actions | shipthis_adaptive_background_432x432.png

[ DONE ] first_scan_filesystem
[  60% ] _update_scan_actions | shipthis_60@3x.png
[  40% ] _update_scan_actions | shipthis_29@3x.png
[ DONE ] _update_scan_actions
[  90% ] _update_scan_actions | icon.svg
[  85% ] _update_scan_actions | cube.blend
[   0% ] _update_scan_actions | Started Scanning actions... (19 steps)
[  80% ] _update_scan_actions | shipthis_appstore.png
[  20% ] _update_scan_actions | shipthis_main_192x192.png
[  25% ] _update_scan_actions | favicon-512.png
[  30% ] _update_scan_actions | icon.svg
[  55% ] _update_scan_actions | shipthis_60@2x.png
[  45% ] _update_scan_actions | shipthis_40@2x.png
[  50% ] _update_scan_actions | shipthis_40@3x.png
[  35% ] _update_scan_actions | shipthis_29@2x.png
[  70% ] _update_scan_actions | shipthis_76@2x.png
[  65% ] _update_scan_actions | shipthis_76.png
[   5% ] _update_scan_actions | icon.svg

[madebydavid]

Working on some backend changes for this - adding an internal "sequence" to the log messages and refactoring how the agent sends the buffer to the API

[madebydavid]

The backend changes seem to be working a lot better:

Could not find version of build tools that matches Target SDK, using 33.0.2
[   0% ] first_scan_filesystem | Started Project initialization (5 steps)
[   0% ] first_scan_filesystem | Scanning file structure...
[  16% ] first_scan_filesystem | Loading global class names...
[  33% ] first_scan_filesystem | Verifying GDExtensions...
[  50% ] first_scan_filesystem | Creating autoload scripts...
[  66% ] first_scan_filesystem | Initializing plugins...
[  83% ] first_scan_filesystem | Starting file scan...
[ DONE ] first_scan_filesystem

[   0% ] update_scripts_classes | Started Registering global classes... (4 steps)
[   0% ] update_scripts_classes | 
[  20% ] update_scripts_classes | 
[  40% ] update_scripts_classes | 
[  60% ] update_scripts_classes | 
[ DONE ] update_scripts_classes

[   0% ] _update_scan_actions | Started Scanning actions... (31 steps)
[   0% ] _update_scan_actions | enemyFlyingAlt_1.png
[   3% ] _update_scan_actions | enemyFlyingAlt_2.png
[   6% ] _update_scan_actions | enemySwimming_1.png
[   9% ] _update_scan_actions | enemySwimming_2.png
[  12% ] _update_scan_actions | enemyWalking_1.png
[  15% ] _update_scan_actions | enemyWalking_2.png
[  18% ] _update_scan_actions | gameover.wav
[  21% ] _update_scan_actions | House In a Forest Loop.ogg
[  25% ] _update_scan_actions | playerGrey_up1.png
[  28% ] _update_scan_actions | playerGrey_up2.png
[  31% ] _update_scan_actions | playerGrey_walk1.png
[  34% ] _update_scan_actions | playerGrey_walk2.png
[  37% ] _update_scan_actions | favicon-512.png
[  40% ] _update_scan_actions | icon.svg
[  43% ] _update_scan_actions | shipthis_adaptive_background_432x432.png

[madebydavid]

My testing has been with the --follow mode which console.logs the lines as soon as received - when running without the follow mode, there is a sort which is being applied in src/utils/hooks/useJobLogTail.ts

// When received from the server the logs are not guaranteed to be in order
function getSortedJobLogs(logs: JobLogEntry[]) {
  // TODO: sort by the "sequence" field when it exists
  return logs.sort((a, b) => a.sentAt.toMillis() - b.sentAt.toMillis())
}

I added that TODO - I think we should expose the sequence to the cli and sort on that. I think we should be safe to add a new field without breaking old versions of the cli - but I will test this.