#1693 The transport starts or stops by itself
Occasionally, the transport starts or stops by itself. Currently, I do not know the circumstances, except that it is relatively rare.
* Starting by itself has occurred on more than one occasion when opening a session
* Ending by itself has occurred at some random point in the composition when I am not touching the keyboard
"Use JACK transport" is set to true, so stopping might be related to an incoming event and starting to some old queued event. Unfortunately, in the logs there appears to be no way to distinguish between when the transport is started/stopped in RG or when it is via a JACK client. In both cases, the start and stop appear as follows:
Start:
[AudioPlayQueue] This tends to be the last thing you'll see on a normal exit.
[SequencerThread] run(): Sequencer status changed from 0 to 1
Stop
[SequencerThread] run() - Stopped
[SequencerThread] run(): Sequencer status changed from 1 to 0
Can the logging code be updated to identify the source of the two events, at least between in or outside RG?
Before we add logging, can you confirm/set the following preferences...
Of course, this might turn off something you are using, so make sure that whichever external transport control you usually use is still working. If not, turn on the appropriate one, or go through them one at a time to figure out which one you are using.
The above settings will disable all external transport controls. That might solve the problem. It should at least reduce the number of places we need to look.
The following was on:
MIDI > General > Accept Transport CCs (116-118): onI don't need the keyboard to send any changes to RG most of the time, so I have now turned that off and can leave it that way.
I wasn't touching the keyboard or my computer when the transport stops occurred...RG was simply sending MIDI to the keyboard. I was definitely opening a session when the transport immediately started though. Both seem to imply it has nothing to do with the keyboard.
The other settings were off except JACK which I do use, and turning it off is impractical. However, when the problem occurred, there were no other JACK clients around, although I leave "Use JACK transport" on so I don't have to remember to switch it on and off as JACK clients come and go.
It will take some time to determine if the CCs change is the culprit, because the issue is rare and I cannot make it happen on demand. I was hoping to see something unexpected in the logs which I could report. I saw nothing for a false start on opening a session, and I will have to wait for a sudden stop to check the logs in that case.
I got lucky, or unlucky, depending on one's point of view, and two occurrences of this issue occurred in close proximity today, one of which I've not seen before.
Description:
1. RG was playing MIDI and suddenly stopped, which is why I opened this bug. It actually moves the transport back as far as it would go i.e. the start of the composition in this case
2. I decided to check whether the flags had been set according to my last post, and while the preferences window was open, RG started by itself and immediately stopped within the first beat of the first measure from where it had previously moved (by itself) but the transport was not moved back to the start this time
I removed the repetitive "Profiling points" sections below, but have it here should you need it. The pattern of start and stop, which I do myself, is seen twice below. Then there is a section which mentions defaultAudioEditor even though I didn't touch audacity and there are no audio tracks. It might have occurred when I opened the preferences section to go to the MIDI section though, otherwise it's the same as the previous start/stop sections.
After mentioning audacity there is a "Stopped" which might be related to the start before audacity. After that ,there is a "Stopped" again with no corresponding sign of a start prior to it and no mention of the status changing from 1 to 0 as per previous entries after it which seems odd and it never repeated "Stopped" previous to that?
How familiar are you with switching branches in git? I have some logging, but I'd like to keep it out of master. I was thinking of pushing a
bug1693branch so I can make a mess while we work on this and not touch master.I'm not sure if this is what you mean, but for master I visit the following URL with the various branches, including master which I have used exclusively so far:
https://sourceforge.net/p/rosegarden/git/ci/master/tree/I see a number of branches there e.g. fr462-ted (and I wonder who that could be? :-)). If you are planning to have bug1693 show up at some level in that left navigation bar along with is associated "Download Snapshot" link then for me it will be no different than getting master...I just need that zip file to tie into the build.
While on the build subject, I should mention that I have noticed that master has new LV2 plugin support, although not in a stable release yet i.e. warnings show up during recent master builds that those plugins will not work. I don't use the LV2, but it's probably a good idea to build with it when reporting bugs, especially if it will appear in stable by default...one never knows when the presence or absence of code will make a difference. Obviously, the RG code dependencies page cannot be updated until an official release, so is there a link which mentions which LV2 package dependencies are recommended for a debian RG build? Or perhaps you can just post that information here?
I added some logging and pushed my branch:
https://sourceforge.net/p/rosegarden/git/ci/bug1693/tree/
Logging is only enabled for a debug build.
Logging has been added for UI play/stop and for JACK play/stop. Search for "bug1693" in the output to find the logging.
The downloaded code with start/stop logging works perfectly. It's now just a matter of waiting for the bug to reappear. Today, I went through the same, usual steps I carried when I opened this bug...and nothing. It bowed out with its randomness at turning up.
The old adage "Bugs know when they are being hunted" sprang to mind. However, now it's caught between its pleasure of tripping me up and its extinction.
No sign of this issue as yet. I even turned on "Accept Transport CCs" again since that was originally on when the bug occurred. Yet nothing with the same sessions doing the same thing for a week. There's an outside chance that something else changed in master (as a side effect) hence fixing the bug, but there is no way to be certain.
I'll keep this version for another week at least, since it's the only one with the debugging.
I've been waiting unsuccessfully for RG to unexpectedly start or stop play on its own since the new debug statements were added. I don't normally watch RG logs. The plan was to see the issue and then check the log. I was about to abandon the logging branch to move on to test sourceforge master, when I noticed a JACK error (I rarely get them):
I have seen this before for JACK clients, possibly even RG, but mostly when opening and closing windows. I thought I should double check the RG log and found the following:
That last line with bug1693 was followed by 1,475 identical lines and after those:
This happened again further down in the log with another session, but that had 1,716 identical lines. Without the repeated lines, the log entries are identical to similar sections of the log for other sessions. Also note that there were two occurrences of this issue in the RG log, but only one occurrence of the JACK error, so the JACK error may not be related...it just got my attention.
Unfortunately, I am not sure which sessions triggered this or whether those sessions always trigger this cascade. But I can find out by remaining on the bug1693 branch for a few more days and this time actually tailing the RG log. I have just enough screen real estate to notice lines like that whizzing by.
Do you think this is a problem with the implementation of the debugging statement itself? If so, then we can close this bug report as no longer reproducible i.e. RG has not started or stopped unexpectedly since I moved to this branch.
Tailing the log has revealed some more bizarre behavior, although there is no way to tell if it's just the debug statement implementation. And on this occasion I did not get the thousands of lines mentioned in the last post.
NB: the following option should be true:
Edit/Preferences/General/Use JACK transportFirst, a normal sequence after opening a session:
Here the slotPlay() occurs when the Enter button (Play) is engaged. Nothing odd here, but I later noticed the following for the next session opened, and every session after that i.e. an extra jackSynCallback() on opening an rg file. And note, that line is the one which occurred thousands for times in the last post, but for no apparent reason.
Unexpected log entry:
To make matters worse, for all of the following actions, a new log entry occurs every time, even though nothing is actually started.
all cause a log line:
[JackDriver] jackSyncCallback(): bug1693 Starting playback due to JACK transportIt's possible that the previous thousands of entries are also caused by something else that RG does normally, but which did not occur on this occasion.
It took a while to figure out why this did not occur for the first session opened. Although you can start/stop as desired in the first session and not get that log entry, it's not until you let the composition run to its end by itself. That is when the new bug statements start occurring, and will do so for all of the circumstances above until RG is restarted. However, on allowing any composition to end naturally, the behavior returns. The other way to stop the behavior is to set "Use JACK transport to false.
It's true that none of this actually causes RG to start/stop a session by itself, as it did when the bug was first opened, but the cause of the above needs to be explained to be sure it is not related. Unexplained JACK related transport behavior is definitely around according to the logs.
The bug1693 logging is not intended to diagnose any issue other than the spurious starts/stops. The wording of the message is imprecise as it was only intended to help figure out where the spurious starts/stops are coming from. It will be issued for all sorts of other situations as well. It's only useful at the moment when a spurious start/stop occurs. Unfortunately it might be so noisy that it is useless at that moment. Hopefully it's good enough.
The repeating messages are being caused by JACK. It calls rg over and over. This is normal.
The xruns are typical of a system that is bogged down. Given that JACK is calling rg over and over, and we've added logging that is also coming out over and over, this is likely bogging JACK down and causing xruns which may causes glitches in audio track playback. It's normal. It may cause trouble if you are doing a final mixdown, so be sure to do that with a less experimental branch.
I've rebased the bug1693 branch so that it has all the latest fixes. Feel free to grab a new snapshot and see if you can get the spurious start/stop to occur.
I've not seen a single start/stop glitch since I moved first to the [bug1693] branch to look for the problem, and then back to [2f2c01]. It might have been related to a master branch I was using at that time. As a matter of fact, I should have added the problem master ID when I opened this bug...at least I could have gone back to it to check.
I will work with the re-based bug1693. The logging alone did not cause any xruns as far I know. I only get those when I am actively opening and closing windows with multiple JACK clients around. But I'll watch for any increase in them this time.
Related
Commit: [2f2c01]
I thought RG stopped by itself immediately after I had hit the Enter key to play, but I could not be certain...NB the playback cursor was still at the start when I looked. I checked the logs and noticed that the logs did not mention anything about my stopping via the UI:
At first I assumed it must have stopped by itself. However, when I started and intentionally stopped RG, I got the same result as above. In other words the logging was not providing the necessary information to distinguish between whether the user requested the stop or whether some other event caused it. In fact, the logs contain no evidence that I ever stopped RG at all.
But looking at the wording i.e. "pressed on the UI", I got suspicious and repeated the above exercise using the mouse to click the start and stop transport buttons:
It became clear that the logging does not appear to be tied to stop when the Enter key is pressed, although it does log when the Enter key is pressed to play. I tend to toggle the Enter key for start/stop since it is far easier than messing around with the mouse. If that one log entry for stop via Enter key was present we would have had an answer. As it stands, there is no way to tell. Perhaps I didn't fully press the Enter key on this occasion?
Prior to opening this bug, the mysterious starting and stopping happened a number of times, sometimes multiple times on the same day...but only for a particular short range of the master branch. It might well be gone by now leaving today as a coincidence...I was even planning to add a post to that effect. So, it's up to you whether you wish to fix that last crucial stop via Enter key or to close the bug as unable to reproduce...almost.
Just as an addendum, and as per my last post, I've seen no xruns which might be due to this extra logging.
So, finally RG can apparently start by itself after all, although the actual cause is still not clear.
As mentioned earlier in this post, normally the "button pressed on the UI" message turns up when I hit the Enter key to start play:
While I had emacs open check the logs, and RG was not doing anything, I heard MIDI output on the keyboard and knew RG had started. I reopened the logs to check for new entries. Notice that there is no evidence of a button being pressed this time.
Obviously RG received some signal to do so, although current logging does not show it. I suspect since the JACK transport is involved, it may be related to that even though there are no other JACK clients running on my system...emacs can't be one as far as I know and its usage at the time is probably coincidental...I had no other applications running., and RG was doing nothing at that time.
Just before the above, or very close to that time, I saw the following in the JACK log:
which coincided with the thousands of the following lines in the RG log, as reported earlier in this post:
[JackDriver] jackSyncCallback(): bug1693 Starting playback due to JACK transportI think those multiple lines occurred shortly before RG started by itself, but without timestamps there is no way to know. Also, although I'm not sure when it occurred, the rosegarden log (stdout) was corrupted and contained screens of the following (presumably unprintable) characters.
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0I have now turned on JACK verbose logging, and notice that I do get extra information in the RG log itself as well as the JACK log, which was not appearing before e.g: in RG's log there are positional information requests in between the multiple line outputs:
So now I will have to wait for the next occurrence of this issue and see if there is any extra information in between the multiple line outputs or close to when RG actually starts or stops by itself.
A long post, but can't be helped. Based on observation, I am guessing that this problem occurs when RG is allowed to play a composition to its end without user intervention. After that, no matter what session is opened, that RG instance's log entries are different from then on until it is restarted. In addition, I think it is also responsible for RG randomly starting or stopping by itself for any session after that point because the RG/JACK interaction is different.
For this post:
Normal means that no prior session has been allowed to play and run to its composition end.
Abnormal is when one session is opened, allowed to play to its end, and after that another session is opened.
NORMAL
Normal RG Log session opening:
Normal RG Log start:
Normal RG Log stop:
Normal JACK Log session opening:
Normal JACK Log start
Normal JACK Log stop:
ABNORMAL
RG still does not start by itself all the time, but during this abnormal section, there are extra jackSyncCallback which an earlier post describes as harmless in this case. Ignoring those makes some the same as for the normal case.
Abnormal RG Log session opening:
As for normal, barring extra jackSyncCallbacks
Abormal RG Log start:
As for normal, barring extra jackSyncCallbacks
Abormal RG Log stop:
As for normal, barring extra jackSyncCallbacks
Abormal JACK Log session opening:
Abormal JACK Log start
The first five entries in the normal section are missing and there is no references for frame = 0?
Abormal JACK Log stop:
As for normal, barring extra jackSyncCallbacks
RG OPEN AND START BY ITSELF
Abnormal RG open, which includes the self start:
There is no indication of how RG was started...only that reference to the jackSyncCallback, which appears in the abnormal sections even without the self start.
Abnormal JACK Log when RG starts by itself:
This is completely different, and was not present in normal or abnormal sessions without a self start. It doesn't look like much, but I have noticed that the "transport starting ==> rolling fSyncTimeLeft" in my logs is ALWAYS 1721, as per all entries shown above, and also for ALL entries in logs I've seen so far. Here it has changed to 1710. Those repeated CheckAllRolling also never occurred before. There is no mention of frame = 0, which is also the case for abnormal sections as well.
Conclusion
As mentioned in an earlier post, RG logging changes permanently when I allow the session to start and let it run until it stops by itself, as opposed to stopping it manually before the composition END. Now it appears that JACK output also changes permanently with respect to what appears when a session is opened.
Although this is no proof of a cause of the self start, I should mention that when the composition ends by itself, it is odd that JACK is not informed that anything has happened to the transport. When the user stops RG manually, JACK is made aware that has happened. Why wouldn't the same thing occur when RG stops at the end of the composition?
Although it may be just the location of the bug1693 debugging statements, but the only seen in the RG log when the composition ends naturally is:
And with no corresponding JACK logs for that ending, it seems odd especially since JACK may itself need to de-allocate resources or clean up based on transport positional information, or whether the transport is still rolling or not? And although I don't rely on it, I assume other JACK clients would like to know when and where the RG transport stopped? But that too is just a guess and open to discussion.
Comment or opinions?
The debug logging that I put in was intended only to determine where a spurious stop or start was originating. Nothing more.
Some of this rings a bell. I think we decided that rg would not send a JACK transport stop when rg performed an end-of-composition auto-stop. The reason was that this could cause a fatal stop to a session on another part of the system. E.g. ardour might be recording and needs to capture the rest of the performance. rg only sends JACK transport stop if the user presses the stop button.
Let us know what the logging shows when you encounter a spurious start or stop.
I understand the logging limitations on your part, but your logging provides all of the necessary information based on my last post.
If you have a reason for not letting JACK know of the composition end stop, then obviously nothing can be done about it. I must point out that my guess...a total guess...is that when JACK is not told of the transport stop at the end of composition, the SyncTimeout, fSyncTimeout, etc might be affected i.e. at some point the timeout will occur and perhaps that causes the transport status to change back in RG, if not also for any client.
I should also mention that on days when this mysterious start/stop occurs, I execute a number of short sessions one after the other for about an hour or so, each running to composition end. I only get this issue at some point in one of those sessions. It doesn't always occur in the same place or session either, but I vaguely feel like it's around the half way mark. I don't know what that "rolling fSyncTimeLeft = 1721" means, but if that were seconds, then that would be half hour? Well...it's just guess work.
As for logging the spurious start/stop, you must have missed it in that really long post :-) I don't want to make this post long too, so it's the Heading "RG OPEN AND START BY ITSELF" i.e spurious that I open an RG session and immediately it starts playing, and the two subsections show RG's log and JACK's log at that time, and added I comments about those entries and how they differ from previous ones in that same post. If you have a specific question let me know.
I hesitate to add another post when you've probably got enough information, but the direction I am guessing in is the following: When RG specifically tells JACK that the transport has started and is rolling, and fails to notify JACK that it has stopped simply because it is the end of a composition, then on some occasions when a new session is started, JACK broadcasts that the transport is still rolling, RG picks that up when the the new session opens and immediately does what it should do i.e. plays the composition as though some other JACK client started the transport. In other words RG did not start by itself, it was instructed to do that by the remnants of the last session closed?
I can't come up with a scenario which will allow me to test that here because it rarely happen, but you may be able to see if that is happening.