Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

REPL :stop command fails for overly long segments #404

Closed
elydpg opened this issue Oct 22, 2021 · 14 comments
Closed

REPL :stop command fails for overly long segments #404

elydpg opened this issue Oct 22, 2021 · 14 comments
Labels
Projects

Comments

@elydpg
Copy link
Contributor

elydpg commented Oct 22, 2021

🐞 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 an alda stop or alda shutdown command seems to be the only way to stop the playback.

Steps to Reproduce

  1. Run the alda repl
  2. Enter piano: c*100 into the repl
  3. Wait for a couple of seconds. After the first four or five notes, issue a :stop command.

Expected Behavior

The segment stops playing.

Actual Behavior

The segment fails to stop playing.

Environment

Windows 10, PowerShell, alda 2.0.6

@elydpg elydpg added the bug label Oct 22, 2021
@daveyarwood
Copy link
Member

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!

@daveyarwood daveyarwood added this to Discussion in Alda via automation Oct 24, 2021
@daveyarwood daveyarwood moved this from Discussion to Up for Grabs in Alda Oct 24, 2021
@ksiyuan
Copy link

ksiyuan commented Apr 13, 2022

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.

@daveyarwood
Copy link
Member

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

@daveyarwood
Copy link
Member

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.

@ksiyuan
Copy link

ksiyuan commented Apr 14, 2022

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.

@ksiyuan
Copy link

ksiyuan commented Apr 14, 2022

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.

@ksiyuan
Copy link

ksiyuan commented Apr 14, 2022

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.

@daveyarwood
Copy link
Member

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.

@daveyarwood
Copy link
Member

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.

@ksiyuan
Copy link

ksiyuan commented Apr 16, 2022

  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.

@daveyarwood
Copy link
Member

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.

@ksiyuan
Copy link

ksiyuan commented Apr 16, 2022

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.

@daveyarwood
Copy link
Member

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.

ksiyuan pushed a commit to ksiyuan/alda that referenced this issue Apr 16, 2022
Changed function `hasPlayer`
Add a new REPL command `stopall` that stops all player process
ksiyuan pushed a commit to ksiyuan/alda that referenced this issue Apr 17, 2022
Adding check when the server.player is set, if the new player/updated state has port = 0, leave the current server.player unchanged.

If there is a read error in ReadPlayerStates, return nil and the read error instead of  including any player states
daveyarwood added a commit that referenced this issue Apr 17, 2022
#404 REPL :stop command fails for overly long segments
@daveyarwood
Copy link
Member

I think this is fixed now in Alda 2.2.2.

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

Alda automation moved this from Up for Grabs to Done Apr 17, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
Alda
  
Done
Development

No branches or pull requests

3 participants