Closed elydpg closed 2 years ago
Thanks for reporting this. I've also seen this happen from time to time and have been meaning to fix it. Will dig in when I can!
Hello, I want to solve this issue but have stuck for a while. This bug doesn't always happen on my computer, but it happens more frequently as the fragment gets longer. I might be totally wrong but is it possible that this have something to do with race condition? Any thought would be appreciated.
I have only a fuzzy understanding of how this might be happening. The first thing I would check is whether the "stop" message is making it to the player process. If you run alda -v2 stop
(with verbosity level 2 or higher), you can see the INFO logs that show the "stop" messages being sent from the client to each player process. So that's one thing to check -- is the player process that's currently playing included in the list of player processes that the client is sending the "stop" message to?
Another thing to check is whether the player process is actually receiving the "stop" message and processing it right away. You can run a player process in the foreground in "very verbose" mode by running alda-player -vv run
. Note the three-letter ID at the beginning of each log message. You can then use alda play -i xxx
(where xxx
is the ID of your player process) to send "play" and "stop" messages.
I was playing around with this just now, and here is some the of output of the player process while I ran alda play -i iqt -c "piano: c*100"
and then alda stop -i iqt
in another terminal:
iqt INFO 2022-04-13 20:42:01 StateManager.cleanUpStaleStateFiles:72 - Cleaning up stale files in /home/dave/.cache/alda/state/players...
iqt INFO 2022-04-13 20:42:01 StateManager.cleanUpStaleStateFiles:72 - Cleaning up stale files in /home/dave/.cache/alda/state/repl-servers...
iqt INFO 2022-04-13 20:42:01 Main.run:77 - Starting receiver, listening on port 38447...
iqt INFO 2022-04-13 20:42:01 MidiEngine.<init>:276 - Initializing MIDI sequencer...
iqt INFO 2022-04-13 20:42:01 MidiEngine.<init>:281 - Initializing MIDI synthesizer...
iqt TRACE 2022-04-13 20:42:04 MidiEngine.invoke:367 - current offset: 0.0
<elided for brevity>
iqt INFO 2022-04-13 20:42:06 Main.run:90 - Starting player...
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/patch [0, 0]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /system/tempo [0, 120.0]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/volume [0, 100]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/panning [0, 64]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/note [0, 60, 500, 450, 69]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/note [500, 60, 500, 450, 69]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/note [1000, 60, 500, 450, 69]
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /track/1/midi/note [1500, 60, 500, 450, 69]
<elided for brevity>
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /system/play []
iqt TRACE 2022-04-13 20:42:08 Parser.parse:223 - /system/shutdown [59950]
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:402 - ----
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:403 - [PLAY]
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:404 - {}
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:405 - [io.alda.player.TempoEvent@3b894c60, io.alda.player.ShutdownEvent@3e211469]
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:406 - {1=[io.alda.player.MidiPatchEvent@530be808, io.alda.player.MidiVolumeEvent@2fab5168, io.alda.player.MidiPanningEvent@1f4e9f31, io.alda.player.MidiNoteEvent@3390db8, io.alda.player.MidiNoteEvent@f7eee7f, io.alda.player.MidiNoteEvent@7aabdee9, io.alda.player.MidiNoteEvent@1177619a, io.alda.player.MidiNoteEvent@5ae8eac1, io.alda.player.MidiNoteEvent@221dfaf5, io.alda.player.MidiNoteEvent@6e524c9, io.alda.player.MidiNoteEvent@2cb4ee3e, io.alda.player.MidiNoteEvent@3117b78b, io.alda.player.MidiNoteEvent@7c90290e, io.alda.player.MidiNoteEvent@537c8939, io.alda.player.MidiNoteEvent@58325876, io.alda.player.MidiNoteEvent@54150714, io.alda.player.MidiNoteEvent@29308cc1, io.alda.player.MidiNoteEvent@1eb2ed9f, io.alda.player.MidiNoteEvent@5409f7d7, io.alda.player.MidiNoteEvent@28d877e5, io.alda.player.MidiNoteEvent@5a3b0bb, io.alda.player.MidiNoteEvent@cf46b85, io.alda.player.MidiNoteEvent@17589283, io.alda.player.MidiNoteEvent@7c54a8d2, io.alda.player.MidiNoteEvent@64eae98b, io.alda.player.MidiNoteEvent@4bed1ed0, io.alda.player.MidiNoteEvent@18f251a4, io.alda.player.MidiNoteEvent@41396850, io.alda.player.MidiNoteEvent@722c774d, io.alda.player.MidiNoteEvent@5114ec46, io.alda.player.MidiNoteEvent@5b61f8b1, io.alda.player.MidiNoteEvent@51907065, io.alda.player.MidiNoteEvent@4097f305, io.alda.player.MidiNoteEvent@3697418d, io.alda.player.MidiNoteEvent@62e7839e, io.alda.player.MidiNoteEvent@3026c4ff, io.alda.player.MidiNoteEvent@4f560625, io.alda.player.MidiNoteEvent@43c1ad6b, io.alda.player.MidiNoteEvent@1d643dfe, io.alda.player.MidiNoteEvent@1be31391, io.alda.player.MidiNoteEvent@64fb59e6, io.alda.player.MidiNoteEvent@2a9f0ae7, io.alda.player.MidiNoteEvent@16a85987, io.alda.player.MidiNoteEvent@15d4bf58, io.alda.player.MidiNoteEvent@2b5ee06d, io.alda.player.MidiNoteEvent@79c40fd3, io.alda.player.MidiNoteEvent@2df4150d, io.alda.player.MidiNoteEvent@1d6a5194, io.alda.player.MidiNoteEvent@416b87dc, io.alda.player.MidiNoteEvent@1808a2b5, io.alda.player.MidiNoteEvent@155990c4, io.alda.player.MidiNoteEvent@5af0950a, io.alda.player.MidiNoteEvent@47b8bcef, io.alda.player.MidiNoteEvent@1a78b3a7, io.alda.player.MidiNoteEvent@43fedf9c, io.alda.player.MidiNoteEvent@1df84a2c, io.alda.player.MidiNoteEvent@1fa5d2b8, io.alda.player.MidiNoteEvent@409fbf60, io.alda.player.MidiNoteEvent@75289ad0, io.alda.player.MidiNoteEvent@2a5e1773, io.alda.player.MidiNoteEvent@1b5f2092, io.alda.player.MidiNoteEvent@2606e826, io.alda.player.MidiNoteEvent@17c9182c, io.alda.player.MidiNoteEvent@4d766029, io.alda.player.MidiNoteEvent@2f4f92a5, io.alda.player.MidiNoteEvent@3e9918b2, io.alda.player.MidiNoteEvent@614e6f35, io.alda.player.MidiNoteEvent@1f472c1d, io.alda.player.MidiNoteEvent@4c4e5fea, io.alda.player.MidiNoteEvent@3ae48259, io.alda.player.MidiNoteEvent@284165f7, io.alda.player.MidiNoteEvent@ec08326, io.alda.player.MidiNoteEvent@304f2c1b, io.alda.player.MidiNoteEvent@2e278601, io.alda.player.MidiNoteEvent@d6a30ef, io.alda.player.MidiNoteEvent@7395bd7, io.alda.player.MidiNoteEvent@4edf90df, io.alda.player.MidiNoteEvent@5cda008b, io.alda.player.MidiNoteEvent@6baeb7, io.alda.player.MidiNoteEvent@4dc1aa8e, io.alda.player.MidiNoteEvent@7f2a9281, io.alda.player.MidiNoteEvent@73780bb7, io.alda.player.MidiNoteEvent@2e3b0d79, io.alda.player.MidiNoteEvent@6eee47ea, io.alda.player.MidiNoteEvent@45fb6e2c, io.alda.player.MidiNoteEvent@766de097, io.alda.player.MidiNoteEvent@cb7be6, io.alda.player.MidiNoteEvent@1c06ad02, io.alda.player.MidiNoteEvent@2923aa0, io.alda.player.MidiNoteEvent@1be21b3d, io.alda.player.MidiNoteEvent@402d57ec, io.alda.player.MidiNoteEvent@69ea8c56, io.alda.player.MidiNoteEvent@7abeecf1, io.alda.player.MidiNoteEvent@710e3b68, io.alda.player.MidiNoteEvent@5bb69092, io.alda.player.MidiNoteEvent@66832f8e, io.alda.player.MidiNoteEvent@6b578ecb, io.alda.player.MidiNoteEvent@6b823db2, io.alda.player.MidiNoteEvent@45f1250, io.alda.player.MidiNoteEvent@7b5fb20a, io.alda.player.MidiNoteEvent@2c295a7c, io.alda.player.MidiNoteEvent@56bc8de6, io.alda.player.MidiNoteEvent@2a8dd8f3]}
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:407 - {}
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:408 - {}
iqt TRACE 2022-04-13 20:42:08 Player.applyUpdates:409 - ----
iqt TRACE 2022-04-13 20:42:08 MidiEngine.setTempo:224 - Setting tempo to 120.0 BPM at offset: 0
iqt DEBUG 2022-04-13 20:42:08 MidiEngine.scheduleShutdown:271 - Scheduling shutdown for 59950
iqt DEBUG 2022-04-13 20:42:08 Player.invoke:346 - TRACK 1: startOffset is 0
iqt DEBUG 2022-04-13 20:42:08 Player.invoke:349 - eraBefore: 0; eraAfter: 0
iqt TRACE 2022-04-13 20:42:08 MidiEngine.note:432 - channel 0: scheduling note from 0 to 450
iqt TRACE 2022-04-13 20:42:08 MidiEngine.note:432 - channel 0: scheduling note from 500 to 950
iqt TRACE 2022-04-13 20:42:08 MidiEngine.note:432 - channel 0: scheduling note from 1000 to 1450
iqt TRACE 2022-04-13 20:42:08 MidiEngine.note:432 - channel 0: scheduling note from 1500 to 1950
<elided for brevity>
iqt TRACE 2022-04-13 20:42:08 MidiEngine.invoke:367 - PLAYING; current offset: 0.0
iqt DEBUG 2022-04-13 20:42:09 MidiEngine.meta:334 - Received Set Tempo meta event
iqt TRACE 2022-04-13 20:42:09 MidiEngine.invoke:367 - PLAYING; current offset: 7.8125
iqt TRACE 2022-04-13 20:42:09 MidiEngine.invoke:367 - PLAYING; current offset: 507.8125
iqt TRACE 2022-04-13 20:42:10 MidiEngine.invoke:367 - PLAYING; current offset: 1007.8125
iqt TRACE 2022-04-13 20:42:10 MidiEngine.invoke:367 - PLAYING; current offset: 1511.71875
iqt DEBUG 2022-04-13 20:42:11 MidiEngine.meta:291 - Received CONTINUE meta event
iqt TRACE 2022-04-13 20:42:11 MidiEngine.invoke:367 - PLAYING; current offset: 2011.71875
iqt TRACE 2022-04-13 20:42:11 MidiEngine.invoke:367 - PLAYING; current offset: 2511.71875
iqt DEBUG 2022-04-13 20:42:12 MidiEngine.meta:291 - Received CONTINUE meta event
iqt TRACE 2022-04-13 20:42:12 MidiEngine.invoke:367 - PLAYING; current offset: 3011.71875
iqt TRACE 2022-04-13 20:42:12 MidiEngine.invoke:367 - PLAYING; current offset: 3515.625
iqt TRACE 2022-04-13 20:42:13 Parser.parse:223 - /system/stop []
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:402 - ----
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:403 - [STOP]
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:404 - {}
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:405 - []
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:406 - {}
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:407 - {}
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:408 - {}
iqt TRACE 2022-04-13 20:42:13 Player.applyUpdates:409 - ----
iqt TRACE 2022-04-13 20:42:13 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:13 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:14 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:14 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:15 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:15 MidiEngine.invoke:367 - current offset: 3914.0625
iqt TRACE 2022-04-13 20:42:16 MidiEngine.invoke:367 - current offset: 3914.0625
I wasn't able to reproduce the issue this way, but maybe the issue has something to do with the Alda REPL. Maybe if there were some way that you could run a player process in the foreground and then force your REPL server to use it, and then see if you can reproduce the issue? (This might require some manual adjustments in the code to hard-code the REPL server to talk to your specific player process.)
Oh yeah! I forgot that player logs are written to disk!
If you run your REPL in verbose mode, you can see which player process it's sending messages to:
$ alda -v2 repl
nREPL server started on port 38483 on host localhost - nrepl://localhost:38483
Apr 13 20:49:33 INF repl/server.go:331 > Request received. decodedRequest={"id":"e13fe104-e22c-41d5-adf5-66b4963ae694","op":"clone"}
Apr 13 20:49:33 INF repl/server.go:82 > Sending response. data={"id":"e13fe104-e22c-41d5-adf5-66b4963ae694","new-session":"d57ca5c6-12c7-4136-8ff2-122ec0803f8e","status":["done"]}
Apr 13 20:49:33 INF repl/client.go:980 > Started nREPL session. sessionID=d57ca5c6-12c7-4136-8ff2-122ec0803f8e
Apr 13 20:49:33 INF repl/server.go:331 > Request received. decodedRequest={"id":"834f7ab1-de0d-4107-bba8-7396a09d9c24","op":"describe","session":"d57ca5c6-12c7-4136-8ff2-122ec0803f8e"}
Apr 13 20:49:33 INF repl/server.go:82 > Sending response. data={"id":"834f7ab1-de0d-4107-bba8-7396a09d9c24","ops":{"clone":{},"describe":{},"eval":{},"eval-and-play":{},"export":{},"instruments":{},"load":{},"new-score":{},"replay":{},"score-ast":{},"score-data":{},"score-events":{},"score-text":{},"stop":{}},"session":"d57ca5c6-12c7-4136-8ff2-122ec0803f8e","status":["done"],"versions":{"alda":{"version-string":"2.2.1"}}}
Apr 13 20:49:33 INF repl/client.go:997 > Alda REPL server version version={"version-string":"2.2.1"}
โโโโโโ โโโ โโโโโโโ โโโโโโ
โโโโโโโโโโโ โโโโโโโโโโโโโโโโ
โโโโโโโโโโโ โโโ โโโโโโโโโโโ
โโโโโโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโ โโโ
โโโ โโโโโโโโโโโโโโโโโโ โโโ โโโ
Client version: 2.2.1
Server version: 2.2.1
Type :help for a list of available commands.
Starting player processes...
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
Apr 13 20:49:34 INF system/process_management.go:452 > Spawned player process.
alda> piano: c
Apr 13 20:49:35 INF repl/server.go:331 > Request received. decodedRequest={"code":"piano: c","id":"b867df38-148b-4486-987a-2a8feb3f7a19","op":"eval-and-play","session":"d57ca5c6-12c7-4136-8ff2-122ec0803f8e"}
Apr 13 20:49:41 INF repl/player_management.go:159 > Found player process. player={"Expiry":1649897730259,"ID":"ihm","Port":39411,"ReadError":null,"State":"ready"}
Apr 13 20:49:41 INF parser/parser.go:1105 > Parsed input. filepath= took="89.606ยตs"
Apr 13 20:49:41 INF repl/server.go:627 > Sending OSC messages to player. player={"Expiry":1649897730259,"ID":"ihm","Port":39411,"ReadError":null,"State":"ready"}
Apr 13 20:49:41 INF repl/server.go:82 > Sending response. data={"id":"b867df38-148b-4486-987a-2a8feb3f7a19","session":"d57ca5c6-12c7-4136-8ff2-122ec0803f8e","status":["done"]}
In this case, the ID of the player process the REPL server chose is ihm
. Then I can follow the logs of that player process like this:
$ tail -F ~/.cache/alda/logs/alda-player.log | grep ihm
ihm INFO 2022-04-13 20:49:41 Main.run:90 - Starting player...
The only problem is, the logs that I really want to see are at the TRACE level, and those aren't showing up in the log file because when Alda launches player processes, they only log at the INFO level.
So I think to investigate further, you would either need to:
alda-player -vv run
) and hard-code the REPL server to use specifically that player process, orIt seems like the stop message was sent to the wrong player process when the error occurs.
$ alda -v2 repl
nREPL server started on port 34387 on host localhost - nrepl://localhost:34387
Apr 14 16:40:55 INF repl/server.go:331 > Request received. decodedRequest={"id":"37ea7784-9ed8-4b47-a9fd-408baefb40a0","op":"clone"}
Apr 14 16:40:55 INF repl/server.go:82 > Sending response. data={"id":"37ea7784-9ed8-4b47-a9fd-408baefb40a0","new-session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4","status":["done"]}
Apr 14 16:40:55 INF repl/client.go:982 > Started nREPL session. sessionID=2357cb7c-4a41-437f-b0e3-34e186dd6fc4
Apr 14 16:40:55 INF repl/server.go:331 > Request received. decodedRequest={"id":"8b36baa4-c077-4e60-9678- 901632ae6150","op":"describe","session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4"}
Apr 14 16:40:55 INF repl/server.go:82 > Sending response. data={"id":"8b36baa4-c077-4e60-9678-901632ae6150","ops": {"clone":{},"describe":{},"eval":{},"eval-and-play":{},"export":{},"instruments":{},"load":{},"new-score":{},"replay":{},"score-ast": {},"score-data":{},"score-events":{},"score-text":{},"stop":{}},"session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4","status": ["done"],"versions":{"alda":{"version-string":"2.2.0"}}}
Apr 14 16:40:55 INF repl/client.go:999 > Alda REPL server version version={"version-string":"2.2.0"}
โโโโโโ โโโ โโโโโโโ โโโโโโ
โโโโโโโโโโโ โโโโโโโโโโโโโโโโ
โโโโโโโโโโโ โโโ โโโโโโโโโโโ
โโโโโโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโ โโโ
โโโ โโโโโโโโโโโโโโโโโโ โโโ โโโ
Client version: 2.2.0
Server version: 2.2.0
Type :help for a list of available commands.
Apr 14 16:40:56 INF system/process_management.go:452 > Spawned player process.
Apr 14 16:40:56 INF system/process_management.go:452 > Spawned player process.
Apr 14 16:40:56 INF repl/player_management.go:160 > Found player process. player= {"Expiry":1649969262155,"ID":"wsc","Port":40395,"ReadError":null,"State":"ready"}
alda> piano: c*100
Apr 14 16:40:59 INF repl/server.go:331 > Request received. decodedRequest={"code":"piano: c*100","id":"cb0cf7f4-3a01- 4aea-a4ba-b71ca34cca6e","op":"eval-and-play","session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4"}
Apr 14 16:40:59 INF parser/parser.go:1127 > Parsed input. filepath= took="48.102ยตs"
Apr 14 16:40:59 INF repl/server.go:627 > Sending OSC messages to player. player= {"Expiry":1649969278286,"ID":"wsc","Port":40395,"ReadError":null,"State":"active"}
Apr 14 16:40:59 INF repl/server.go:82 > Sending response. data={"id":"cb0cf7f4-3a01-4aea-a4ba- b71ca34cca6e","session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4","status":["done"]}
Apr 14 16:41:00 INF repl/player_management.go:160 > Found player process. player={"Expiry":1649969357028,"ID":"ycd","Port":39269,"ReadError":null,"State":"ready"}
alda> :stop
Apr 14 16:41:05 INF repl/server.go:331 > Request received. decodedRequest={"id":"91cc80a5-491c-4711-af9f- 3039f479c0a6","op":"stop","session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4"}
Apr 14 16:41:05 INF repl/server.go:521 > Sending "stop" message to player process. player= {"Expiry":1649969378530,"ID":"ycd","Port":39269,"ReadError":null,"State":"active"}
Apr 14 16:41:05 INF repl/server.go:82 > Sending response. data={"id":"91cc80a5-491c-4711-af9f- 3039f479c0a6","session":"2357cb7c-4a41-437f-b0e3-34e186dd6fc4","status":["done"]}
Apr 14 16:41:08 INF system/process_management.go:452 > Spawned player process.
Apr 14 16:41:13 INF repl/player_management.go:160 > Found player process. player= {"Expiry":1649969199709,"ID":"mqk","Port":36729,"ReadError":null,"State":"ready"}
The score piano: c*100
was sent to player wsc
, after which a new player called ycd
was spawned (I don't know why). The stop
message was then sent to the player process with id ycd
, not wsc
. I think that's why it doesn't work.
This is another try in which the error didn't occur
Starting player processes...
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:14 INF system/process_management.go:452 > Spawned player process.
Apr 14 17:09:19 INF repl/player_management.go:160 > Found player process. player={"Expiry":1649971071161,"ID":"pqv","Port":39399,"ReadError":null,"State":"ready"}
alda> piano: c*100
Apr 14 17:09:34 INF repl/server.go:331 > Request received. decodedRequest={"code":"piano: c*100","id":"baed2a6b-e12a-4cc3-a128-b1d53bf27e82","op":"eval-and-play","session":"6f143990-1abc-4aac-9ba3-240c9eb0b4f3"}
Apr 14 17:09:34 INF parser/parser.go:1127 > Parsed input. filepath= took="182.46ยตs"
Apr 14 17:09:34 INF repl/server.go:627 > Sending OSC messages to player. player={"Expiry":1649971090018,"ID":"pqv","Port":39399,"ReadError":null,"State":"active"}
Apr 14 17:09:34 INF repl/server.go:82 > Sending response. data={"id":"baed2a6b-e12a-4cc3-a128-b1d53bf27e82","session":"6f143990-1abc-4aac-9ba3-240c9eb0b4f3","status":["done"]}
alda> :stop
Apr 14 17:10:02 INF repl/server.go:331 > Request received. decodedRequest={"id":"17c69704-d963-4bb9-b704-96124c04f7f2","op":"stop","session":"6f143990-1abc-4aac-9ba3-240c9eb0b4f3"}
Apr 14 17:10:02 INF repl/server.go:521 > Sending "stop" message to player process. player={"Expiry":1649971140790,"ID":"pqv","Port":39399,"ReadError":null,"State":"active"}
Apr 14 17:10:02 INF repl/server.go:82 > Sending response. data={"id":"17c69704-d963-4bb9-b704-96124c04f7f2","session":"6f143990-1abc-4aac-9ba3-240c9eb0b4f3","status":["done"]}
Only one player process pqv
was spawned, both the OSC message and the stop message are sent to the same player pqv
. Therefore the player process stops as expected.
Although I don't why extra player process were spawned, maybe sending stop
message to all existing player process when :stop
is invoked in REPL
can solve this problem? Just like what alda stop
does:
alda -v2 stop
Stopping playback.
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971833116,"ID":"aqz","Port":42209,"ReadError":null,"State":"ready"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971721559,"ID":"feq","Port":44563,"ReadError":null,"State":"active"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971894775,"ID":"han","Port":44411,"ReadError":null,"State":"active"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649972013972,"ID":"ndu","Port":41353,"ReadError":null,"State":"active"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971747132,"ID":"njt","Port":45195,"ReadError":null,"State":"active"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971741704,"ID":"sfu","Port":46869,"ReadError":null,"State":"ready"}
Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971954707,"ID":"xyr","Port":33191,"ReadError":null,"State":"ready"}
This seems to explain why the bug report said: "issuing an alda stop or alda shutdown command seems to be the only way to stop the playback." Because alda stop
shut down all the player while :stop
in REPL
only shut down one player process which may not be the correct player.
Thanks for posting these logs, they are helpful! I think you're definitely onto something here.
I looked through the code for a while and I did find and fix one problem just now where we were relying on an outdated error message: https://github.com/alda-lang/alda/commit/2ffdb23f12486398310bf871e403038bae68be10
But I think that's unrelated to this issue, based on the logs above.
Here is my current understanding of the issue:
managePlayers
that runs in a loop and continuously checks that the server has a designated player process that it will use for playback.:new
command to start a new score), we shut down the current player process and the managePlayers
background loop replaces it with a new one. This corresponds with the "Found player process" log messages you were seeing above.Although I don't why extra player process were spawned, maybe sending
stop
message to all existing player process when:stop
is invoked inREPL
can solve this problem? Just like whatalda stop
does:alda -v2 stop Stopping playback. Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971833116,"ID":"aqz","Port":42209,"ReadError":null,"State":"ready"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971721559,"ID":"feq","Port":44563,"ReadError":null,"State":"active"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971894775,"ID":"han","Port":44411,"ReadError":null,"State":"active"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649972013972,"ID":"ndu","Port":41353,"ReadError":null,"State":"active"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971747132,"ID":"njt","Port":45195,"ReadError":null,"State":"active"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971741704,"ID":"sfu","Port":46869,"ReadError":null,"State":"ready"} Apr 14 17:23:45 INF cmd/stop.go:76 > Sent "stop" message to player process. player={"Expiry":1649971954707,"ID":"xyr","Port":33191,"ReadError":null,"State":"ready"}
This seems to explain why the bug report said: "issuing an alda stop or alda shutdown command seems to be the only way to stop the playback." Because
alda stop
shut down all the player while:stop
inREPL
only shut down one player process which may not be the correct player.
I think that would probably fix this issue, but it's not exactly the behavior that I think we want.
When you run alda stop
, by default, it will send a "stop" message to every known player process. If you include a -i/--player-id
or -p/--port
option, it will send a "stop" message to a specific player process.
In a REPL session, we know which player is currently active, and we have the ability to stop that specific player process, so it would be better to do that. Otherwise, we would potentially stop other players that maybe the user might want to still be playing.
To better illustrate my point: try starting 2 separate alda repl
sessions in 2 different terminals. In one of them, enter piano: c*100
, and in the other, enter trumpet: g*100
. You should hear a piano and trumpet playing simultaneously. Now run :stop
in just one of them. Now you should hear only the piano, or only the trumpet.
Thanks for posting these logs, they are helpful! I think you're definitely onto something here.
I looked through the code for a while and I did find and fix one problem just now where we were relying on an outdated error message: 2ffdb23
But I think that's unrelated to this issue, based on the logs above.
Here is my current understanding of the issue:
- There is a asynchronous background thread (goroutine) called
managePlayers
that runs in a loop and continuously checks that the server has a designated player process that it will use for playback.- If something goes wrong with the current player process, or if a "reset" is needed (e.g. when you run the
:new
command to start a new score), we shut down the current player process and themanagePlayers
background loop replaces it with a new one. This corresponds with the "Found player process" log messages you were seeing above.- For some reason, sometimes the player process is getting "unset" right after playing some input, and a new player process is selected, even though that previous player process is still actively playing, and should still be the active player process for that REPL session.
After reading the code I found three situations in which unsetPlayer
is invoked:
We can disregard situation 3 because I didn't manually shut down the player. For condition 2, I think it's more likely caused by the system/hardware than by the program. I assume that's an exceptional error expected to happen rarely. Therefore, I think the most likely cause is condition 1, which means the ping signal the server sends to the player timed out. My initial thought is to make the pingTimeout
longer and check whether the error still exists.
That sounds reasonable, but the weird thing is that it should be logging "Player process unreachable" in situation 1, but I don't see that in the logs you posted above. :thinking:
I have another theory that's kind of strange, but I guess it's possible. I searched for server.player =
and I see that in addition to inside of unsetPlayer
, there are a couple of other places where we are setting the current player process, and I wonder if maybe in one of those places, we are inadvertently setting server.player
to a PlayerState struct with a zero value for the port?
I'm thinking of these lines of code, in particular.
Maybe a good next step would be to add some debug logging in all of the places where we are setting server.player
, so that we can better understand how/why it is is ending up getting unset.
I changed the function hasPlayer
so that it checks whether server.player
is not an empty struct instead of only checking if server.player.Port
is equal to 0. After that it seems the issue never comes out on my computer but I don't know the exact reason. Besides, to give user a choice to shut down all player process, I added another repl command called stopall
which shut down all player process while didn't change the original stop
command so that the user can choose whether to shut down the current player or simply shut down everything if something wrong happens. I leave the pingTimeout
unchanged because after testing changing that doesn't have an effect.
Ooh, this is getting interesting! I think maybe the issue is in ReadPlayerStates, a function that we use to check the JSON "player state files" in the cache directory (e.g. ~/.cache/alda/state/players
) and return a list of PlayerState structs that reflect the current state of Alda player processes.
I wrote that function in a bit of a hacky way in that it always returns a PlayerState struct for each of the state files, even if the file is in a weird state (e.g. the file was created, but not yet written to). I believe in a situation like that, we end up with an otherwise "zero value" struct, except that ID and ReadError are set. Port would be 0 in that case, which could explain the behavior that we're seeing.
I suspect that this is an issue, because I've noticed that if I watch the output of alda ps
, often times, a ReadError will be visible for a split second while a player process is starting.
There must be a better way that we could handle that. Maybe if there is a read error, we should just log it and then not add the PlayerState to the list, i.e. we ignore that player process.
I think this is fixed now in Alda 2.2.2.
If anyone continues to see this behavior, please let us know!
๐ Bug report ๐
Description
The REPL
:stop
command simply fails to function when an overly long segment is played. More specifically, the:stop
command simply fails after the first 2 seconds for certain sufficiently long segments (usually around 45 seconds or longer). Quitting the repl and issuing analda stop
oralda shutdown
command seems to be the only way to stop the playback.Steps to Reproduce
piano: c*100
into the repl:stop
command.Expected Behavior
The segment stops playing.
Actual Behavior
The segment fails to stop playing.
Environment
Windows 10, PowerShell, alda 2.0.6