Docker compose up fails on m1 pro macBook

[SebastianKumor]

my setup is:
macBook pro m1 pro chip running macOS Ventura 13.5

this same code works fine on intel based macBook pro running mac os monterey 12.6.8

local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:00:48.527802Z DEBUG websocket{addr=172.18.0.4:45738}: proxy_controller/src/ws_routes.rs:220: Connecting to the SC2 process: "ws://sc2_controller:9110/sc2api", "sc2_controller:9110" local-play-bootstrap-main-sc2_controller-1 | Listening on: 0.0.0.0:9110 local-play-bootstrap-main-sc2_controller-1 | Startup Phase 3 complete. Ready for commands. local-play-bootstrap-main-sc2_controller-1 | Listening on: 0.0.0.0:9024 local-play-bootstrap-main-sc2_controller-1 | Startup Phase 3 complete. Ready for commands. local-play-bootstrap-main-sc2_controller-1 | ConnectHandler: Request from 172.18.0.5:34256 accepted local-play-bootstrap-main-sc2_controller-1 | ReadyHandler: 172.18.0.5:34256 ready local-play-bootstrap-main-sc2_controller-1 | ConnectHandler: Request from 172.18.0.5:39958 accepted local-play-bootstrap-main-sc2_controller-1 | ReadyHandler: 172.18.0.5:39958 ready local-play-bootstrap-main-bot_controller1-1 | 2023-08-11T18:01:17.703929Z DEBUG bot_controller/src/main.rs:101: response generated in 35.083147516s local-play-bootstrap-main-bot_controller2-1 | 2023-08-11T18:01:17.703949Z DEBUG bot_controller/src/main.rs:101: response generated in 35.083204224s local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:01:17.770992Z ERROR common/src/api/api_reference/mod.rs:228: ResponseError(ResponseContent { status: 400, api_error_message: ApiErrorMessage { error: "Could not find port for started process" } }) local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:01:17.781346Z ERROR common/src/api/api_reference/mod.rs:228: ResponseError(ResponseContent { status: 400, api_error_message: ApiErrorMessage { error: "Could not find port for started process" } }) local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:01:17.782231Z ERROR proxy_controller/src/match_scheduler/mod.rs:209: Failed to start bot 1: error in response: status code 400 Bad Request local-play-bootstrap-main-proxy_controller-1 | Error:ApiErrorMessage { error: "Could not find port for started process" } local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:01:17.790022Z INFO proxy_controller/src/match_scheduler/mod.rs:244: AiArenaGameResult { match_id: 1, bot1_avg_step_time: None, bot1_tags: None, bot2_avg_step_time: None, bot2_tags: None, result: InitializationError, game_steps: 0 } local-play-bootstrap-main-proxy_controller-1 | 2023-08-11T18:01:17.790698Z INFO proxy_controller/src/match_scheduler/mod.rs:245: Match finished in 35.275604267s

docker on my m1 macbook.

Edit: I am attaching all the logs:

1. Basic bot
   2023-08-13T17:32:42.505859Z DEBUG bot_controller/src/main.rs:129: listening on 0.0.0.0:8081 2023-08-13T17:32:42.678156Z DEBUG bot_controller/src/main.rs:98: started POST /terminate_all 2023-08-13T17:32:42.680139Z DEBUG bot_controller/src/main.rs:101: response generated in 1.980833ms 2023-08-13T17:32:42.748929Z DEBUG bot_controller/src/main.rs:98: started POST /start 2023-08-13T17:32:42.753934Z DEBUG start_bot{start_bot=StartBot { bot_name: "basic_bot", bot_type: Python, opponent_id: "2", player_num: One, match_id: 2, process_key: 9141, should_download: false }}: bot_controller/src/routes.rs:165: Bot log dir exists 2023-08-13T17:32:42.755373Z DEBUG start_bot{start_bot=StartBot { bot_name: "basic_bot", bot_type: Python, opponent_id: "2", player_num: One, match_id: 2, process_key: 9141, should_download: false }}: bot_controller/src/routes.rs:170: Bot log path: "/logs/basic_bot/stderr.log" 2023-08-13T17:32:42.756842Z DEBUG start_bot{start_bot=StartBot { bot_name: "basic_bot", bot_type: Python, opponent_id: "2", player_num: One, match_id: 2, process_key: 9141, should_download: false }}: bot_controller/src/routes.rs:182: Log files created: "/logs/basic_bot/stderr.log" 2023-08-13T17:32:42.762665Z DEBUG start_bot{start_bot=StartBot { bot_name: "basic_bot", bot_type: Python, opponent_id: "2", player_num: One, match_id: 2, process_key: 9141, should_download: false }}: bot_controller/src/routes.rs:255: Starting bot with command cd "/bots/basic_bot" && "python" "run.py" "--GamePort" "8080" "--LadderServer" "172.18.0.5" "--StartPort" "8080" "--OpponentId" "2" 2023-08-13T17:33:17.844581Z DEBUG bot_controller/src/main.rs:101: response generated in 35.094008142s 2023-08-13T17:33:17.859798Z DEBUG bot_controller/src/main.rs:98: started GET /download/bot/basic_bot/log 2023-08-13T17:33:17.861181Z DEBUG download_bot_log{bot_name="basic_bot"}: bot_controller/src/routes.rs:358: Log path: "/logs/basic_bot/stderr.log" 2023-08-13T17:33:17.863161Z DEBUG bot_controller/src/main.rs:98: started GET /download/bot/basic_bot/data 2023-08-13T17:33:17.865260Z DEBUG bot_controller/src/main.rs:101: response generated in 5.463417ms 2023-08-13T17:33:17.965321Z DEBUG bot_controller/src/main.rs:101: response generated in 102.151125ms 2023-08-13T17:33:18.025487Z DEBUG bot_controller/src/main.rs:98: started GET /download/controller_log 2023-08-13T17:33:18.028060Z DEBUG bot_controller/src/main.rs:101: response generated in 2.575708ms 2023-08-13T17:33:18.120662Z DEBUG bot_controller/src/main.rs:98: started POST /terminate_all 2023-08-13T17:33:18.121166Z DEBUG bot_controller/src/main.rs:101: response generated in 507.625µs 2023-08-13T17:33:28.167266Z DEBUG bot_controller/src/main.rs:98: started POST /shutdown 2023-08-13T17:33:28.169417Z INFO shutdown: common/src/api/process.rs:184: Shutdown request received. Terminating all running processes 2023-08-13T17:33:28.172135Z INFO shutdown: common/src/api/process.rs:192: Shutting down... 2023-08-13T17:33:28.177039Z DEBUG bot_controller/src/main.rs:101: response generated in 9.7765ms

2. loser bot
   2023-08-13T17:32:39.558676Z DEBUG bot_controller/src/main.rs:129: listening on 0.0.0.0:8082 2023-08-13T17:32:42.678311Z DEBUG bot_controller/src/main.rs:98: started POST /terminate_all 2023-08-13T17:32:42.680165Z DEBUG bot_controller/src/main.rs:101: response generated in 1.844375ms 2023-08-13T17:32:42.749842Z DEBUG bot_controller/src/main.rs:98: started POST /start 2023-08-13T17:32:42.754857Z DEBUG start_bot{start_bot=StartBot { bot_name: "loser_bot", bot_type: Python, opponent_id: "1", player_num: Two, match_id: 2, process_key: 9605, should_download: false }}: bot_controller/src/routes.rs:165: Bot log dir exists 2023-08-13T17:32:42.756116Z DEBUG start_bot{start_bot=StartBot { bot_name: "loser_bot", bot_type: Python, opponent_id: "1", player_num: Two, match_id: 2, process_key: 9605, should_download: false }}: bot_controller/src/routes.rs:170: Bot log path: "/logs/loser_bot/stderr.log" 2023-08-13T17:32:42.758121Z DEBUG start_bot{start_bot=StartBot { bot_name: "loser_bot", bot_type: Python, opponent_id: "1", player_num: Two, match_id: 2, process_key: 9605, should_download: false }}: bot_controller/src/routes.rs:182: Log files created: "/logs/loser_bot/stderr.log" 2023-08-13T17:32:42.762520Z DEBUG start_bot{start_bot=StartBot { bot_name: "loser_bot", bot_type: Python, opponent_id: "1", player_num: Two, match_id: 2, process_key: 9605, should_download: false }}: bot_controller/src/routes.rs:255: Starting bot with command cd "/bots/loser_bot" && "python" "run.py" "--GamePort" "8080" "--LadderServer" "172.18.0.5" "--StartPort" "8080" "--OpponentId" "1" 2023-08-13T17:33:17.822073Z DEBUG bot_controller/src/main.rs:101: response generated in 35.070562099s 2023-08-13T17:33:17.860687Z DEBUG bot_controller/src/main.rs:98: started GET /download/bot/loser_bot/log 2023-08-13T17:33:17.861932Z DEBUG download_bot_log{bot_name="loser_bot"}: bot_controller/src/routes.rs:358: Log path: "/logs/loser_bot/stderr.log" 2023-08-13T17:33:17.864123Z DEBUG bot_controller/src/main.rs:98: started GET /download/bot/loser_bot/data 2023-08-13T17:33:17.866335Z DEBUG bot_controller/src/main.rs:101: response generated in 5.649583ms 2023-08-13T17:33:17.965596Z DEBUG bot_controller/src/main.rs:101: response generated in 101.468833ms 2023-08-13T17:33:18.025496Z DEBUG bot_controller/src/main.rs:98: started GET /download/controller_log 2023-08-13T17:33:18.028062Z DEBUG bot_controller/src/main.rs:101: response generated in 2.584292ms 2023-08-13T17:33:18.120681Z DEBUG bot_controller/src/main.rs:98: started POST /terminate_all 2023-08-13T17:33:18.121160Z DEBUG bot_controller/src/main.rs:101: response generated in 483.959µs 2023-08-13T17:33:28.169808Z DEBUG bot_controller/src/main.rs:98: started POST /shutdown 2023-08-13T17:33:28.172700Z INFO shutdown: common/src/api/process.rs:184: Shutdown request received. Terminating all running processes 2023-08-13T17:33:28.184600Z INFO shutdown: common/src/api/process.rs:192: Shutting down... 2023-08-13T17:33:28.186004Z DEBUG bot_controller/src/main.rs:101: response generated in 16.21475ms

3. proxy controller:
   2023-08-13T17:32:39.369031Z INFO proxy_controller/src/match_scheduler/mod.rs:34: Arena Client started 2023-08-13T17:32:39.381611Z DEBUG proxy_controller/src/main.rs:143: listening on 0.0.0.0:8080 2023-08-13T17:32:39.611188Z INFO proxy_controller/src/match_scheduler/mod.rs:64: Waiting for controllers to become ready 2023-08-13T17:32:42.688270Z INFO proxy_controller/src/match_scheduler/mod.rs:111: Starting Game - Round 0 2023-08-13T17:32:42.688615Z INFO proxy_controller/src/match_scheduler/mod.rs:112: basic_bot vs loser_bot 2023-08-13T17:32:42.688906Z INFO proxy_controller/src/match_scheduler/mod.rs:117: Sending start requests to SC2 2023-08-13T17:32:42.717052Z DEBUG proxy_controller/src/match_scheduler/mod.rs:125: SC2-1 Response: StartResponse { status: Success, status_reason: "", port: 9141, process_key: 9141 } 2023-08-13T17:32:42.717401Z DEBUG proxy_controller/src/match_scheduler/mod.rs:126: SC2-2 Response: StartResponse { status: Success, status_reason: "", port: 9605, process_key: 9605 } 2023-08-13T17:32:42.746658Z DEBUG proxy_controller/src/match_scheduler/mod.rs:161: Starting bots 2023-08-13T17:32:46.068649Z DEBUG websocket{addr=172.18.0.4:58642}: proxy_controller/src/ws_routes.rs:41: Connection from 172.18.0.4:58642 2023-08-13T17:32:46.070011Z DEBUG websocket{addr=172.18.0.4:58642}: proxy_controller/src/ws_routes.rs:46: Got free SC2 URL: Some(SC2Url { host: "sc2_controller", port: 9141, is_allocated: true }) 2023-08-13T17:32:46.070410Z DEBUG websocket{addr=172.18.0.4:58642}: proxy_controller/src/ws_routes.rs:220: Connecting to the SC2 process: "ws://sc2_controller:9141/sc2api", "sc2_controller:9141" 2023-08-13T17:32:46.071483Z DEBUG websocket{addr=172.18.0.2:52074}: proxy_controller/src/ws_routes.rs:41: Connection from 172.18.0.2:52074 2023-08-13T17:32:46.071769Z DEBUG websocket{addr=172.18.0.2:52074}: proxy_controller/src/ws_routes.rs:46: Got free SC2 URL: Some(SC2Url { host: "sc2_controller", port: 9605, is_allocated: true }) 2023-08-13T17:32:46.072030Z DEBUG websocket{addr=172.18.0.2:52074}: proxy_controller/src/ws_routes.rs:220: Connecting to the SC2 process: "ws://sc2_controller:9605/sc2api", "sc2_controller:9605" 2023-08-13T17:33:17.847834Z ERROR common/src/api/api_reference/mod.rs:228: ResponseError(ResponseContent { status: 400, api_error_message: ApiErrorMessage { error: "Could not find port for started process" } }) 2023-08-13T17:33:17.848799Z ERROR common/src/api/api_reference/mod.rs:228: ResponseError(ResponseContent { status: 400, api_error_message: ApiErrorMessage { error: "Could not find port for started process" } }) 2023-08-13T17:33:17.849355Z ERROR proxy_controller/src/match_scheduler/mod.rs:209: Failed to start bot 1: error in response: status code 400 Bad Request Error:ApiErrorMessage { error: "Could not find port for started process" } 2023-08-13T17:33:17.850030Z INFO proxy_controller/src/match_scheduler/mod.rs:244: AiArenaGameResult { match_id: 2, bot1_avg_step_time: None, bot1_tags: None, bot2_avg_step_time: None, bot2_tags: None, result: InitializationError, game_steps: 0 } 2023-08-13T17:33:17.850437Z INFO proxy_controller/src/match_scheduler/mod.rs:245: Match finished in 35.160833308s 2023-08-13T17:33:28.163927Z DEBUG common/src/api/api_reference/mod.rs:116: Calling shutdown endpoint api="BotController" url="http://bot_controller1:8081/shutdown" 2023-08-13T17:33:28.165720Z DEBUG common/src/api/api_reference/mod.rs:116: Calling shutdown endpoint api="BotController" url="http://bot_controller2:8082/shutdown" 2023-08-13T17:33:28.167586Z DEBUG common/src/api/api_reference/mod.rs:116: Calling shutdown endpoint api="SC2Controller" url="http://sc2_controller:8083/shutdown"

4. sc2 controller:
   2023-08-13T17:32:39.559031Z DEBUG sc2_controller/src/main.rs:116: listening on 0.0.0.0:8083 2023-08-13T17:32:42.678338Z DEBUG sc2_controller/src/main.rs:89: started POST /terminate_all 2023-08-13T17:32:42.680231Z DEBUG sc2_controller/src/main.rs:92: response generated in 1.898292ms 2023-08-13T17:32:42.691873Z DEBUG sc2_controller/src/main.rs:89: started POST /start 2023-08-13T17:32:42.699827Z DEBUG sc2_controller/src/main.rs:89: started POST /start 2023-08-13T17:32:42.714853Z DEBUG sc2_controller/src/main.rs:92: response generated in 22.961125ms 2023-08-13T17:32:42.714850Z DEBUG sc2_controller/src/main.rs:92: response generated in 15.013584ms 2023-08-13T17:32:42.718945Z DEBUG sc2_controller/src/main.rs:89: started GET /find_map/DragonScalesAIE 2023-08-13T17:32:42.745524Z DEBUG sc2_controller/src/main.rs:92: response generated in 26.576625ms 2023-08-13T17:33:18.120702Z DEBUG sc2_controller/src/main.rs:89: started POST /terminate_all 2023-08-13T17:33:18.121616Z DEBUG common/src/api/process.rs:119: Terminating procs with on port 9605 2023-08-13T17:33:23.136129Z DEBUG common/src/api/process.rs:119: Terminating procs with on port 9141 2023-08-13T17:33:28.146014Z DEBUG sc2_controller/src/main.rs:92: response generated in 10.025253879s 2023-08-13T17:33:28.169651Z DEBUG sc2_controller/src/main.rs:89: started POST /shutdown 2023-08-13T17:33:28.172015Z INFO shutdown: common/src/api/process.rs:184: Shutdown request received. Terminating all running processes 2023-08-13T17:33:28.184148Z INFO shutdown: common/src/api/process.rs:192: Shutting down... 2023-08-13T17:33:28.186259Z DEBUG sc2_controller/src/main.rs:92: response generated in 16.607917ms

[SebastianKumor]

@lladdy hello, I am making some more tests. I have now running the same version of macOS (13.5.1) on both intel and m1 based mac and the only difference I can see is the architecture warning in docker. The intel version works fine and the m1 fails with the same error

[lladdy]

I'm not able to troubleshoot this myself because I don't have access to a mac.

You could attempt to specify the platform in the docker compose for each service and see if that makes a difference?
If it does, we can update this repo with the change.
References:
https://stackoverflow.com/questions/68434301/docker-compose-run-with-specified-platform
https://stackoverflow.com/questions/69708866/how-to-make-docker-compose-work-on-m1-chip

[SebastianKumor]

@lladdy I will try to look into it more on the weekend, thanks for help

[lladdy]

@SebastianKumor did you have any luck with this?

[SebastianKumor]

@lladdy sorry was a bit busy with other things but I will get back to it next week