- Problem summary.
My app triggers audio messages based on BT data that it receives from sensors. It receives the data at 200Hz (once every 5ms). In order to test without having to wait for data from these sensors, I have developed a simulator (part of my program running on android) that reads recorded sensor data from a file and plays them back at the same speed as the sensors would normally send the data to the phone (this code uses a lot of multitasking and scheduling to get the timing right).
The audio messages are played with the java MediaPlayer. Sometimes, the played audio is interrupted based on the incoming data, with a mediaplayer.stop(). I then use prepare() to get it ready to start playing the next time this is required by the data.
The issue is that after the prepare() call, spurious onCompletion calls sometimes occur and I do not understand how they are triggered / how to get rid of them.
- Expected and actual results.
I have a CMediaPlayer class as follows:
public class CMediaPlayer extends MediaPlayer {
private String name;
private Activity act;
private Cue cue;
public Long startedAt;
public CMediaPlayer (Activity act, Cue rc,
String audioFileName, String audioSet,
String audioFileExtension, String mpName,
MediaPlayer.OnCompletionListener cListen,
MediaPlayer.OnPreparedListener pListen) {
super();
if (checkAndroidPermission(act, Manifest.permission.READ_EXTERNAL_STORAGE)) {
if (audioFileExists(act, audioFileName + audioSet)) {
init(act, rc, mpName);
String fullFileName = Environment.getExternalStorageDirectory().getPath() + "/" + PHONE_AUDIO_DIR + "/" +
audioFileName + audioSet + audioFileExtension;
makeStartReady(fullFileName, cListen, pListen);
} else {
Log.e(act.getString(R.string.app_name), audioFileName + audioSet + " file not found under /" + PHONE_AUDIO_DIR + " directory!");
}
} else {
Log.e(act.getString(R.string.app_name), " Missing READ_EXTERNAL_STORAGE permission for this app.");
}
}
private void init(Activity act, Cue rc, String name) {
this.name = name;
this.act = act;
this.cue = rc;
this.startedAt = 0L;
}
private void makeStartReady(String fileName, MediaPlayer.OnCompletionListener cListen, MediaPlayer.OnPreparedListener pListen) {
try {
setDataSource(fileName);
prepare();
setOnCompletionListener(cListen);
setOnPreparedListener(pListen);
setVolume(1.0f,1.0f);
} catch (Exception e) {
Log.e(act.getString(R.string.app_name), fileName + " file not found under /" + PHONE_AUDIO_DIR + " directory!");
e.printStackTrace();
}
}
public void prepare(Activity act, String msg) {
try {
this.prepare();
} catch (Exception e) {
Log.e(act.getString(R.string.app_name), msg + " failed!");
e.printStackTrace();
}
}
public void setOnCompletionListener(OnCompletionListener listener) {
super.setOnCompletionListener(listener);
}
public String getName() {
return name;
}
public void startCMP() {
this.startedAt = this.cue.mState.counter.cur;
cue.mState.callBackDebugLine(name + ".startCMP(" + this.startedAt + ")");
try {
super.start();
} catch (Exception e) {
Log.e(act.getString(R.string.app_name), "cannot start " + name + e.toString());
if (cue != null) cue.mState.callBackDebugLine("cannot start " + name);
}
}
public void stopCMP() {
if (isPlaying()) {
stop();
if (cue != null) cue.mState.callBackDebugLine(name + ".stopCMP(" + this.startedAt + ")");
try {
prepare();
} catch (Exception e) {
Log.e(act.getString(R.string.app_name), name + ".prepareAsync() failed!");
e.printStackTrace();
}
}
}
public void closeCMP() {
cue.mState.callBackDebugLine( name + ".closeCMP()");
reset();
release();
}
}
The onPreparedListener looks like this:
(MediaPlayer mp) -> {
if (mState.debugWriter != null)
addDebugLine(mState, ((CMediaPlayer)mp).getName() + ".onPrepared");
((CMediaPlayer)mp).startedAt = -1L;
});
Starting audio with startCMP() and stopping it with stopCMP() works correctly (ie, the onPrepared listener is called and nothing more) when my onCompletionListener looks like this:
(MediaPlayer mp) -> {
addDebugLine(mState, ((CMediaPlayer)mp).getName() + ".onCompletion "); // + ((CMediaPlayer)mp).startedAt);
},
addDebugLine writes debug information to a csv file for analysis after running the program as follows:
public static void addDebugLine(WalkState ws, String label) {
Date now = new Date();
try {
ws.debugWriter.append(Common.formattedNow("HH_mm_ss_SSS") + ","
+ (now.getTime() - ws.startTime) + "," + ws.counter.cur
+ "," + (ws.counter.cur-ws.counter.start) * 5
+ "," + label + "\n");
} catch (IOException e) {
Log.d(mCtx.getString(R.string.app_name), "exception in addDebugLine");
e.printStackTrace();
}
}
When the onCompletion listener is modified as
(MediaPlayer mp) -> {
addDebugLine(mState, ((CMediaPlayer)mp).getName() + ".onCompletion ") + ((CMediaPlayer)mp).startedAt);
},
(the only difference is that a Long is appended to the message that is passed to addDebugLine) then it is called multiple times after the onPrepared is called. The output in the debug csv file (with the name of the MediaPlayer equal to "dangerStart") looks like this:
09_59_44_176,34515,6866,34330,dangerStart.onCompletion -1
09_59_44_177,34516,6866,34330,dangerStart.onCompletion -1
09_59_44_177,34516,6866,34330,dangerStart.onCompletion -1
The first string on each line is the phone time, the 2nd string (actually a Long) the time since start of the program, the 3rd is the counter of the hardware that transmits data to the phone. Each increase by 1 on this counter represents 5ms.
The failure happens in two different ways: it can happen after a stopCMP() call (and after onPrepared()), or even just after a startCMP() when no stopCMP() has been called and long before normal completion of the audio. This happens shortly (like 15ms) after the call to startCMP() and long before actual completion of the audio (which lasts approx 5.2s).
So, this output means that the mediaPlayer with name dangerStart calls onCompletion 3x in a very short time period (roughly 1 ms). As per the media player state diagram (https://developer.android.com/reference/android/media/MediaPlayer#StateDiagram), this should not happen.
With this one set of data, adding the Long to the addDebugLine message results in the effect described. With other sets of data, this is not the case and the multiple onCompletion calls may happen without having expanded the addDebugLine message. I have quite a few datapoints but cannot find any rhyme or reason behind them.
I would hope to find what goes wrong with this data set and then to test the solution on the other data sets to confirm this really fixes the problem in general.