Giter Club home page Giter Club logo

Comments (14)

ksiyuan avatar ksiyuan commented on June 17, 2024 1

It 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.

from alda.

ksiyuan avatar ksiyuan commented on June 17, 2024 1

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024 1

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.

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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!

from alda.

ksiyuan avatar ksiyuan commented on June 17, 2024

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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.)

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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:

  • Start your own player process in very verbose mode (alda-player -vv run) and hard-code the REPL server to use specifically that player process, or
  • Hard-code it so that Alda starts all player processes in very verbose mode.

from alda.

ksiyuan avatar ksiyuan commented on June 17, 2024

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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 the managePlayers 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.

from alda.

ksiyuan avatar ksiyuan commented on June 17, 2024

  1. 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 the managePlayers 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:

  1. The server thinks that the player process is unreachable. i.e. ping signal timed out
  2. The server thinks that the player process no longer exists for unknown reason
  3. Manual shutdown the player

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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. 🤔

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.

from alda.

ksiyuan avatar ksiyuan commented on June 17, 2024

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

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.

from alda.

daveyarwood avatar daveyarwood commented on June 17, 2024

I think this is fixed now in Alda 2.2.2.

If anyone continues to see this behavior, please let us know!

from alda.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.