thetwom / toc2

Metronome app
GNU General Public License v3.0
144 stars 23 forks source link

Faulty playback after pressing pause and then pressing play again #60

Closed jorfus closed 1 year ago

jorfus commented 1 year ago

Hello!

When I press play having just started the app, the first note starts clicking really fast and erratic until I close the app. This seems the case every time I start the app now, whereas, some months ago, it seemed more rare.

If I instead swap out the first note at least once before pressing play it plays fine.

I use Android on a Xiaomi Redmi Note 9 Pro. I have the app through F-Droid. Everything appears up to date.

Thanks for the app!

thetwom commented 1 year ago

Hi, thanks a lot for reporting this bug. It is the first time, I hear of such behavior, but it sounds pretty annoying. I will try to check if there is any possible faulty initialization. But it might be difficult to find it without of your support. Could you maybe for a first investigation try to export the settings of a faulty startup (save the scene after startup and export it to a file)? Here a detailed list of how to export the file:

  1. Start you app
  2. Save the current settings by selecting the disc icon on the toolbar.
  3. Check if after pressing play, the issue occurs. If no, delete the scene (go to scenes-view e.g. be swiping to the left at the top region) and start again from point 1.
  4. After you successfully saved a "faulty" scene, go to the scenes view (I guess you have to restart) and export the settings to a file. (You might want to store existing scenes before, delete all "private" ones and then export the list with just the faulty scene)
  5. Provide the saved scenes file.

Maybe this can already give a hint of the incorrect startup.

Do you actually have the chance to export logcat files (don't do it right now, I would have to provide a special version with extra info)? Otherwise I would have to find other ways to get more debugging infos.

But maybe I find the bug before, so we don't need debugging info.

Best regards.

jorfus commented 1 year ago

Thank you, I would need to be provided the tools for exporting, but I just learnt something new.

Steps to reproduce:

  1. Have the metronome playing
  2. Press pause
  3. Press play again within a second or two of step 2

I repeated 2 and 3 a few times, and the result was as if an additional metronome started and kept playing each time, until I quit the app. So a cacophony of metronomes which cannot be paused!

The playing of the resulting added metronome seems sometimes normal, and it also seems at least one of them stops on pause.

I struggled getting it triggered on open this time, it might have happened once, but otherwise the steps above consistently trigger the behavior.

thetwom commented 1 year ago

Thanks for the additional info.

What do you mean with, "it seems an additional metronome is starting"? So, after pressing "pause", it stops? And then after pressing "play" again, it sounds as if several metronomes are playing?

The "exporting" steps described above can directly be done within the app. You don't need extra tools for it.

Can you tell me, which android version you are using?

Unfortunately, it is very difficult to find bugs, which don't reproduce well. I hope, we still can find the issue.

jorfus commented 1 year ago

I clarified my previous comment and your interpretation is correct. It's as if many metronomes are clicking.

After I have paused one successfully, but then pressed play again 'too soon' thereafter, a messed up metronome starts and won't quit.

Android version is 11 RKQ1.200826.002

thetwom commented 1 year ago

Thanks a lot for the further description. It almost seems as there are different issues, the startup issue and the one of playing instances not correctly shutting down. But who knows, maybe they are interconnected. Will look into the issue soon, hoping to be able to fix it, without more information. We will see :-).

jorfus commented 1 year ago

Now I cannot reproduce the behavior at all, even the one I saved as 'faulty' or even older scenes.

It's happened a lot, so perhaps it might have something to do with me having had the same scene loaded for a long time, or having had the app 'locked' from shutting down?

thetwom commented 1 year ago

Interesting, what do you mean with "locked from shutting down"? Did you do something specific here?

jorfus commented 1 year ago

Yes, it's a feature of my phone, and perhaps it isn't common, I've no clue, but when viewing all open apps one might mark them as locked from being closed when pressing to 'close all apps'.

On my phone the apps still disappear after a while of non-use, but when opened again they are again in that 'locked' state.

Here I corrected from the mistake of using the term 'shut down'. Sorry if that confused things at all, and thanks for your ardent bug hunting!

thetwom commented 1 year ago

I had a quick look at the critical places of the app, but at the moment I can't find or imagine anything which would trigger such strange effects. But obviously you managed to trigger such a behavior, so there must be something I don't understand. Maybe it is really something that only occurs if the app is open for a very long time.

I will keep my eyes open, hopefully I will find the root cause at some time. Please let me know when you observe any strange behavior again (I guess you will, since such issues mostly come back after some time ;-).

jorfus commented 1 year ago

Alright, thank you, and I'll make sure to be mindful of the issue as I use the app from here on!

jorfus commented 1 year ago

I'm sorry, I forgot about this for a bit.

There are three 'faulties' at the bottom, two of which are the same beat, but I did mess about with the volume gauges for the individual beats just before I managed to trigger the behavior in the case of 'faulty three'. However, for all three scenes, the behavior was finally triggered by the same steps as per above description.

Triggering the behavior on the very first press of play after opening the app might never have happened, but rather, somehow, I had gotten the wrong idea before I started thinking more carefully about the issue.

It's pausing and then pressing play again too soon that triggers it somewhat regularly.

I hope it's not a problem that some other saved scenes are included.

'faulty three' is the last one I saved, just before exporting. I think with the first of these I had followed your instructions exactly, but I'll be trying again later with just a single scene saved while really making sure I follow your testing instructions without error.

Sorry for the bit of messiness and wall of text! metronome.txt

thetwom commented 1 year ago

Thanks for the providing the further descriptions and the file. Don't worry about messiness or much text :-).

So the first strange thing is, that the file is empty. Did you actually use the feature of exporting and importing scenes before? If yes, was is working?

Based on your description, that the issue seems rather to be "pressing play too soon after pausing", the exported files won't really help to find the issue. It rather seems to be a issue with threads, that the previous "player" was not cancelled correctly. What I don't understand, why after pausing it starts playing again, together with a "new" one, so that it sounds as there are two (or more) metronomes playing at the same time.

Did the issue actually reappear? I wonder if I could "instrument" a version with extra log messages, such that I can get a bit more insights. But it would also mean, that you would have to extract the system logs (logcat). And at the moment I am not yet sure, what the easiest way is. And also if you would be willing to spend this extra time to find the cause of the problem.

thetwom commented 1 year ago

or is it possible, that when you pause and start the metronome quickly, that it actually never stops, but just a new one is starting?

jorfus commented 1 year ago

Darn, I think my browser messed something up, because the file isn't empty when I check it on my phone or desktop. Let me see what I can do...

The file above should be good now.

jorfus commented 1 year ago

Ok, I finished reading your comment, and just to clarify one thing, the behavior happens at pressing play, not at pressing pause.

So, if you have the metronome playing just fine, then press pause, then press play again, only 'too soon' after you paused, then the behavior is triggered. It seems possible one won't notice it yet, because sometimes the metronome plays as expected, but on pausing yet again at this point, the metronome won't stop.

When I have repeated the steps of pausing and playing this way many times in a row, I've ended up with an additional metronome playing each time.

It seems that on pausing, one of the metronomes might stop. Perhaps that is a 'correct' one; one which you would have expected to start playing after you last pressed pause. As the playback is often super-chaotic even with one 'sticky metronome' having been triggered though, it is sometimes hard to detect if one or more than one might stop playing after several have been triggered.

I'd be happy to look into the logcat biz. I have triggered the behavior as recently as last night, and with each of the 'faulty scenes' provided I did as well, though I was sometimes unable to when I set out to produce that log. I haven't had time to go through your instructions again more carefully, but I will as I use the app quite a bit.

Let me just add quickly that this isn't a really annoying issue for me, as it's fairly quick to quick-fix the issue when it occurs as per my original post, although it'd be cool to get it fixed of course. Glad to oblige!

jorfus commented 1 year ago

I'll just leave another quick note, namely that I am more confident now that the behavior occurs after the app has been left running too long.

I left the app running in the background, but not playing, some hours today, and after that the steps above triggered it first try.

Before I left the app running like that I had reinstalled the app, but then failed to trigger the behavior despite many tries.

thetwom commented 1 year ago

Thanks for the many more details. Based on your description it seems that it really is no problem of startup values, and also the file you provided does not show any suspicious things. So you do not have to try to "capture" more faulty scenes anymore. But thanks a lot for providing this!

From your description it seems that really something very unexpected is happening. I carefully checked if there might be any threads running, which are not cancelled correctly, but failed to find anything yet. Also, the app starts a background job which keeps the metronome playing while it is in the background (possibly there is happening something weird, since the system can cancel jobs when the app is in the background and not doing anything, but all this should be handled by the app). But also here, I cannot find inconsistencies.

So I will also open the app now on my phone and see if I can trigger the same behavior. I will also try to provide app version which writes extra info to the system logs. But in this case, we have to find a good way, how you can access the logcat (this is not app specific, but you would have to access the system logs of you phone).

It might take some days for me to provide this special version with extra logs.

Thanks a lot for all your help. I really hope we can find out what is going on (and then fixing it :-).

jorfus commented 1 year ago

No sweat! I'm a noob programmer myself and, so far, I don't mind assisting in a bit of bug hunting on the side.

In this case I consider it a perfectly decent pastime.

thetwom commented 1 year ago

Thanks again, for offering your help. Sorry, that it will take a few more days until I find time create a version with extra logs.

jorfus commented 1 year ago

At your leisure!

thetwom commented 1 year ago

I finally added some logs and put the package here: v4.6.0-instrumented. I guess, you have to deinstall a previous version from google play or fdroid first, since the signing keys are different.

The biggest difficulty is to capture the info of the logcat:

Not sure what operation system you are on. If you are using windows, I unfortunately cannot test getting the logcat. On Linux I could try to write down the single steps which work for me.

Sorry, that this is not so easy. I could understand if it is to much efforts for you to set it up. But if you would provide the info, at least there is some hope to get some insights about the issue.

jorfus commented 1 year ago

Hello, thanks for the instructions, and I'll be checking all of this out fairly soon, I reckon!

thetwom commented 1 year ago

No hurry, take your time.

jorfus commented 1 year ago

Here's a log filtered on Metronome:V stdout_metronome.txt

The problem was consistently triggered several times during this log, where the effect I got was that the first note started playing erratically on each press of play. However, it did not seem to 'stick' or 'duplicate', i.e. the metronome did stop playing every time I pressed pause.

The first time it happened since I installed this version of the metronome I was unfortunately not logging, but triggered the metronome to start playing by mistake via my Bluetooth headphone controls. So that time the problem was triggered on a play after no quick pause/play steps, as I hadn't been trying for a few minutes at least. Immediately after the accidental triggering, I paused the metronome and went to start logging.

Hope it helps, but if you need more log info, just let me know how to better filter the log, or I might just send you a complete log privately.

thetwom commented 1 year ago

Thanks a lot for the logs! This is really great support from your side!

So, we are back to the first problem you described :-). The filtering you applied looks just fine. It really seems that the player is started many times, but the reason is not clear to me, yet. I hope I will find time very soon to have a closer look. Maybe I will ask you again for more logs with a further instrumented version. But lets see.

thetwom commented 1 year ago

Ok, I had a second look at your logs. Something is wildly starting and stopping the metronome player. Unfortunately the logs don't reveal the cause. I added more log messages in hope that it will reveal the missing piece: v4.6.0-instrumented2. If you have more patience with me, it would be great if you could install the version and sending the logcats taken while the issue occured (exactly the same way you did it).

It is interesting that you mention, that the bluetooth device was first starting the metronome. I never really tested this functionality. I also looked at the corresponding code, and possibly, something unintended is happening here (even if not using bluetooth).

I did adapt a bit of code regarding possible issues. So, it is possible that the issue does not reappear in the new version (but I don't really think it is solved ...). It would have been more strategic by me to NOT trying to improve things before having found the issue, but on the other side, I am trying to keep the iterations as few as possible ...

jorfus commented 1 year ago

Well, I'll gladly try this out as well!

I thought I could tell the thing was stopping and starting crazily from looking at the logs myself, but I wasn't sure, haha.

The funny thing about the Bluetooth controls on the headphones is that, when I use them to resume playing whatever media app I paused last, the metronome app seems to always be the recipient of that input instead of the expected app, and so it starts playing. So I have to close the metronome app for the controls to work properly for the other ones.

At least it's happened many, many times, so really it is interesting in light of what you just wrote.

I have also wondered whether having other audio-playing apps running in the background at the same time, switching between them etc might be triggering the actual issue of this thread, rather than simply leaving the metronome app running like that for a long time.

thetwom commented 1 year ago

ok, so the bluetooth-controls should be something I should have a further look at. The behavior you are describing seems to be rather annoying :-). I actually wonder how other apps are dealing with this. E.g. if there are two audio apps, playing sound at the same time .. which will react to the bluetooth controls? Maybe I should just try to react to bluetooth control, if the metronome is in foreground?

Interesting point of yours regarding other audio-playing apps, which possibly could trigger the issue. I would not expect this, but who knows. As said, the metronome listens to signals from outside (as bluetooth controls), and who knows, maybe this framework is not working as I am currently expecting, especially since this is not tested at all by myself.

Interesting that the bluetooth issue was never raised before. I wonder if it is device dependent. Or it is just not used much ...

jorfus commented 1 year ago

Just to be clear, I have only noticed the Bluetooth behavior rather than tested it, but will keep it in mind from now on. So, also, it hasn't been super-annoying enough for me to freak out over it, but who knows about others, of course, lol.

But I suppose I might as well create a separate issue for that then, soon as I've made sure I haven't been hallucinating the entire biz.

Been enjoying being able to help out at all, by the way. Code's the stuff!

jorfus commented 1 year ago

stdout_metronome.txt

Hello again, I believe the same exact situation occurred this time, only I wasn't using the Bluetooth headphones. Also, I opened the app just now after not having used it for a few days.

I opened it, the 'app lock' had been on since last time I used the metronome, and at the first press of play the problem occurred. I reopened the app, plugged in to do some logging, and the 'pause, play, pause' steps reproduced the problem reliably. However, as were the case last time, the metronome stayed quiet while paused.

thetwom commented 1 year ago

Thanks a lot for the further logs. So far everything works as expected but only the player (i. e. the audio mixer) is started too often. Unfortunately, it does still not tell why. However, based on your logs, I could at least find the only remaining possibility, which can cause the issue. I was not seeing this before, so it does not tell more infos in the logs.

Can I ask you again for sending me updated logs with this new version: v4.6.0-instrumented3? I really hope, that this finally gives some insight, what is happening.

jorfus commented 1 year ago

stdout_metronome.txt

Ok, this log ended up a bit longer.

I'd been listening to a podcast for a while, paused with the Bluetooth headset controls, and when I used them to press play again, the metronome started playing instead, only with fine behavior. I couldn't trigger the bug until I switched back to play the podcast, and then the metronome again.

I'm not a hundred percent sure when I started logging, but if needed, you might hopefully come up with questions through which I'll be able to clarify what was going on.

thetwom commented 1 year ago

Perfect, this log finally explains your described behavior. The app asks the system how large the audio buffers should be and somehow the system does not report consistent results. And each time that something changes, the app restarts playing (these restarts are actually intended, so that we can react to audio rerouting, e.g. when you connect a bluetooth speaker). I will have to see, how to achieve a more robust behavior here.

Anyhow, I am still a bit puzzled about this behavior. If you are willing to give me more insight here, I would post another version with even more logs soon (have to see, when I find time).

But apart from that, thanks already for the great support! This really helped to understand where the problem is, such that I can hopefully find a good fix.

jorfus commented 1 year ago

Cool beans, and I'm glad I could be of help. Sounds to my ears it might be a somewhat trickyish problem underneath, then.

Whatever the case, best of luck with things for the time being!

thetwom commented 1 year ago

Ok, I guess (and hope) that the bug fix is only changing two characters ... however, as said I would be interested to (hopefully) one last time, get some logs of the buggy version. So, if you still have the patience, here would be a version with more logs: v4.6.0-instrumented4

I would be interested in the logs, ones captured, while everything is running fine, and once captured during the buggy behavior.

If you have enough with sending logs (or alternatively after having captured the requested logs :-), then you can directly try the (hopefully) fixed version: v4.6.1-rc1

Thanks again for your great help! Sometimes it is really difficult to track down bugs if you can't reproduce them on the own device.

jorfus commented 1 year ago

stdout_metronome.txt

Here, I: Started logging Pressed played on the metronome, and it played fine Paused the metronome Switched over to listen to a podcast for a few minutes Stopped the podcast Switched back to the metronome and pressed play, whereupon it played fine Paused the metronome to then quickly press play again, and it went bonkers as per the bug Switched to task manager and side-swiped the metronome app to close it Stopped logging

thetwom commented 1 year ago

Hi, thanks a lot for really taking the time and sending me these logs. Sounds as in the meantime you know quite well how to trigger the bug :-).

I really wonder, why this works at all ... throughout the whole logs the inconsistency is visible. I will try to have a deeper look into it later, maybe I can understand better what is going on.

However, now is the time, where you could switch the fixed version. I really hope, that this is working. I was pretty confident, but now, that I see, that the problem should have occurred all the time, I am a bit hesitant :-).

jorfus commented 1 year ago

Alright, no sweat, and it'll be interesting to see how the fixed version fares👍

thetwom commented 1 year ago

I had a second look on your logs. In contrast to the first quick look, the behavior can be explained. A bit odd behavior though, but otherwise the issue would not have been so rare :-). Still, lets see if the rc1 really solves the issue ...

jorfus commented 1 year ago

Hello, I've been using the metronome about daily over the past week at least, and without issue! The only, very slight, oddity that occurs sometimes is that the first note plays twice in quick succession when play is first pressed, but that is it, and it's barely even an issue for the user, obviously.

I simply used the metronome some of the time, and actively tried to cause the issue to occur some of the time.

Perhaps it's time to close this as fixed?

thetwom commented 1 year ago

Thanks a lot for the further testing. I am glad that the issue is fixed now. Thanks a lot for your support and patience!!!

Of course I wonder, why the app plays the first note twice, so if you have the time, maybe you can capture the logs one day with the version you are currently using. Maybe it gives already a hint. But as you say, this is not so urgent or important.

I will make the changes official in a few days (it's already in the master now, but I will test it a bit further before releasing it). When the release is available, we can close the issue. Up the then, lets leave it open to keep it visible (in case others have similar issues).

jorfus commented 1 year ago

Very good, and I'll happily log the remaining oddity, for sure. I do believe it used to occur before as well, but might have been overshadowed by the more major issue.

I'll get back to you later!

jorfus commented 1 year ago

stdout_metronome.txt

alright, it took me a few tries but here it happened first thing on pressing play, having left the app in the background and using other audio apps before trying again

thetwom commented 1 year ago

Thanks for sending me this info. It indeed shows what is happening. The app is setting up the player, but very shortly after this, the system reports that the audio routing changed and we better use larger buffer sizes, so the app recreates and restarts the player.

This is the similar issue as we had before, but not that severe anymore since the app can now deal with inconsistent system infos to a certain extent.

It seems difficult to solve this issue. We could just ignore the system request for larger buffers, but I fear this can affect the playback (e.g. audible cracks could appear). We could also be conservative and just use larger buffers firsthand, but this affects the latency (if you change settings, it lags more behind).

I am wondering , why your system is actually reporting changes on the audio routing. As far as I know, this normally happens when you e.g. plug in earphones, or if you connect some bluetooth device while playing. Maybe you are willing to install this version: v4.6.0-instrumented5 and try to provide another log? It will print some audio device info to the logs, when the system reports changes. Not sure, if this really gives much info. As before, feel free to ignore this request. It seems that we are at very device specific issues here and it is more out of my interest about the reasons (with small hopes that there is something I can fix :-).

jorfus commented 1 year ago

I'll try this as well, no prob.

Considering what you just wrote, it might be useful to know that I do switch between three different audio outputs, including just the phone, several times most days. Bluetooth headphones and a Bluetooth electric piano are the two other ones I use.

I could test more carefully to see if switching output devices, or perhaps simply using Bluetooth devices at all, might have something to do with it too.

jorfus commented 1 year ago

metronome_HD450BT.txt metronome_phone.txt

I think I've learnt a couple of things. With the bluetooth headphones (first file), the problem seems to be triggered after I have changed the scene, in particular if I've removed notes and also switched the type of note. With the phone speaker file, I failed to trigger it entirely, as far as I noticed.

Funnily though, it seemed as if I had to;

  1. Remove some notes
  2. Press play
  3. Press pause
  4. Switch out a note type
  5. Press play

What I mostly ended up doing was to switch between the two note types on the upper right, since, after some trying, that seemed to consistently trigger the problem. I can't remember noticing it being triggered after I'd added notes or switched between any other notes, though that's all uncertain.

thetwom commented 1 year ago

Thanks a lot for trying. For now I guess, that it has nothing to do with removed notes, since also the logs tell us other things as cause but still an interesting information.

It seems that there are no surprising switches of audio devices, though I should have written the device info more often. Maybe you could try again with this version? v4.6.0-instrumented6. Sorry, I should have thought about this before.

But what can be seen from the logs, is that the system really reports very different required buffer sizes (and this mainly with bluetooth connected). I looked again, how others find the buffer size and all use the same strategy. I tend to accepting the issue as it is but opening a new issue to keep it documented. The problem at the moment is, that I don't have enough insights on how the different functions should really behave. Is it a bug of the system of your specific device? Am I expecting something from the system, which I actually cannot expect? Questions I unfortunately cannot answer with 100% confidence.

Anyway, thanks again for your great support! As said, maybe you find time to try one last time. As long as this shows nothing completely new and unexpected I guess I don't need more logs ;-)

jorfus commented 1 year ago

metronome_HD450BT.txt metronome_HD450BT_2.txt metronome_HD450BT_3.txt metronome_HD450BT_4.txt

This ended up a few files, but they aren't very lengthy. I tried logging while doing some of the things I did before, like switching between apps, simply playing and pausing etc.

I think I only triggered the bug three or so times through these documents.

thetwom commented 1 year ago

Thanks a lot. It seems that at least the system always reports the same device. Maybe it is worth a try to only recreate the player if the routing device changes. I will try to create another test version soon. No need to send more logs in this case, only checking if there are no cracks while playing ... and if the double beats at the beginning are gone.

jorfus commented 1 year ago

Btw, I think I did noticed in one log that it rerouted every time I pressed play. I dunno what's what so much ofc, but that struck me as a bit odd.

I have had the occasional note somewhere suddenly, on one loop only, sound weird, quieter and a bit distorted while nothing else was happening. It's in one of the logs where I left it playing for a few minutes.

It might be worth noting that these headphones will go into a standby state after some number of seconds, causing a slight delay when some audio starts to come through. I think this causes the software sending the audio to be delayed as well, such that visuals don't get out of sync with the audio.

So far I haven't managed to trigger this latter issue when using headphones through my electric piano, though the original issue of this thread did occur as often using that setup.