I've created a little test-setup to play around with the savegames-api. In this setup, I run the same app (which has been configured for use with the savedgames-api in the developer console) on two different devices, and connect to the games-api using the same user-account. I can then (roughly) simultaneously start a sequence of actions (saving/loading the game state using the savedgames-api), and print the state as seen by the two devices. For details, please refer to the code at the end of this post.
In this setup I use a manual conflict resolution that always returns the largest value. I now simultaneously write "1" from one device, and "2" from the other, and then, a few seconds later, load the current state on both devices. I would expect the final state on both devices to always be "2" (i.e. the larger of the two values, according to the conflict resolution strategy). Sometimes, everything works as expected (i.e. I see state "2" on both devices), quite regularly I also get "1" on one, and "2" on the other device (which is wrong, but at mostly resolves at the next load on the device that saw "1"), and sometimes, I also get "1" as the loaded state on both devices (in that situation, the state "2" seems to be lost forever).
Note that this last situation (state is lost forever), might result in quite angry users if they buy something using in-app-payments (which is reflected in the state), and then at some point that state just gets lost due to buggy syncing.
The corresponding logcat output looks as follows:
Different results at first load (fixes at second load):
=======================================================
Device1:
04-27 10:58:05.149: V/SyncTestActivity(32369): Own entries.size: 4
04-27 10:58:06.149: V/SyncTestActivity(32369): (1001) performAction: LOAD [device=1, tMs=1000, data=null, delay=0]
04-27 10:58:08.089: V/SyncTestActivity(32369): (2941) loaded: ''
04-27 10:58:21.149: V/SyncTestActivity(32369): (16000) performAction: SAVE [device=1, tMs=16000, data=1, delay=0]
04-27 10:58:22.159: D/BlockingSyncer(32369): loaded before saving:
04-27 10:58:22.159: D/SyncTestActivity(32369): merging and 1
04-27 10:58:22.159: D/BlockingSyncer(32369): merged with local data before saving: 1.0
04-27 10:58:22.619: V/SyncTestActivity(32369): (17474) saved: '1.0'
04-27 10:58:41.149: V/SyncTestActivity(32369): (36000) performAction: LOAD [device=1, tMs=36000, data=null, delay=0]
04-27 10:58:42.129: V/SyncTestActivity(32369): (36982) loaded: '1.0'
04-27 10:59:01.149: V/SyncTestActivity(32369): (56001) performAction: LOAD [device=1, tMs=56000, data=null, delay=0]
04-27 10:59:03.569: V/SyncTestActivity(32369): (58425) loaded: '2.0'
04-27 10:59:03.579: V/SyncTestActivity(32369): (58430) done
Device2:
04-27 10:58:05.128: V/SyncTestActivity(15276): Own entries.size: 4
04-27 10:58:06.132: V/SyncTestActivity(15276): (1002) performAction: LOAD [device=2, tMs=1000, data=null, delay=0]
04-27 10:58:07.253: V/SyncTestActivity(15276): (2124) loaded: ''
04-27 10:58:21.132: V/SyncTestActivity(15276): (16000) performAction: SAVE [device=2, tMs=16000, data=2, delay=0]
04-27 10:58:22.347: D/BlockingSyncer(15276): loaded before saving:
04-27 10:58:22.351: D/SyncTestActivity(15276): merging and 2
04-27 10:58:22.355: D/BlockingSyncer(15276): merged with local data before saving: 2.0
04-27 10:58:23.015: V/SyncTestActivity(15276): (17884) saved: '2.0'
04-27 10:58:41.128: V/SyncTestActivity(15276): (36000) performAction: LOAD [device=2, tMs=36000, data=null, delay=0]
04-27 10:58:45.390: D/BlockingSyncer(15276): conflict detected
04-27 10:58:45.429: D/SyncTestActivity(15276): merging 1.0 and 2.0
04-27 10:58:49.203: V/SyncTestActivity(15276): (44067) loaded: '2.0'
04-27 10:59:01.128: V/SyncTestActivity(15276): (56000) performAction: LOAD [device=2, tMs=56000, data=null, delay=0]
04-27 10:59:02.417: V/SyncTestActivity(15276): (57288) loaded: '2.0'
04-27 10:59:02.460: V/SyncTestActivity(15276): (57328) done
Different results at first load (does not fix at second load):
==============================================================
Device1:
04-27 11:44:18.199: V/SyncTestActivity(2714): Own entries.size: 4
04-27 11:44:19.199: V/SyncTestActivity(2714): (999) performAction: LOAD [device=1, tMs=1000, data=null, delay=0]
04-27 11:44:21.399: V/SyncTestActivity(2714): (3200) loaded: ''
04-27 11:44:34.199: V/SyncTestActivity(2714): (16000) performAction: SAVE [device=1, tMs=16000, data=1, delay=0]
04-27 11:44:35.049: D/BlockingSyncer(2714): loaded before saving:
04-27 11:44:35.049: D/SyncTestActivity(2714): merging and 1
04-27 11:44:35.049: D/BlockingSyncer(2714): merged with local data before saving: 1.0
04-27 11:44:35.509: V/SyncTestActivity(2714): (17312) saved: '1.0'
04-27 11:44:46.199: V/SyncTestActivity(2714): (27999) performAction: LOAD [device=1, tMs=28000, data=null, delay=0]
04-27 11:44:47.099: V/SyncTestActivity(2714): (28896) loaded: '1.0'
04-27 11:44:58.199: V/SyncTestActivity(2714): (40000) performAction: LOAD [device=1, tMs=40000, data=null, delay=0]
04-27 11:44:59.329: V/SyncTestActivity(2714): (41127) loaded: '1.0'
04-27 11:44:59.329: V/SyncTestActivity(2714): (41129) done
Device2:
04-27 11:44:18.148: V/SyncTestActivity(18064): Own entries.size: 4
04-27 11:44:19.148: V/SyncTestActivity(18064): (1000) performAction: LOAD [device=2, tMs=1000, data=null, delay=0]
04-27 11:44:25.445: V/SyncTestActivity(18064): (7295) loaded: ''
04-27 11:44:34.152: V/SyncTestActivity(18064): (16001) performAction: SAVE [device=2, tMs=16000, data=2, delay=0]
04-27 11:44:36.144: D/BlockingSyncer(18064): loaded before saving:
04-27 11:44:36.156: D/SyncTestActivity(18064): merging and 2
04-27 11:44:36.171: D/BlockingSyncer(18064): merged with local data before saving: 2.0
04-27 11:44:37.214: V/SyncTestActivity(18064): (19066) saved: '2.0'
04-27 11:44:46.167: V/SyncTestActivity(18064): (28020) performAction: LOAD [device=2, tMs=28000, data=null, delay=0]
04-27 11:44:52.429: D/BlockingSyncer(18064): conflict detected
04-27 11:44:52.457: D/SyncTestActivity(18064): merging 1.0 and 2.0
04-27 11:44:56.949: V/SyncTestActivity(18064): (38798) loaded: '2.0'
04-27 11:44:58.152: V/SyncTestActivity(18064): (40001) performAction: LOAD [device=2, tMs=40000, data=null, delay=0]
04-27 11:44:59.371: V/SyncTestActivity(18064): (41220) loaded: '2.0'
04-27 11:44:59.414: V/SyncTestActivity(18064): (41266) done
Both wrong
==========
Device1:
04-27 12:10:36.689: V/SyncTestActivity(2714): Own entries.size: 4
04-27 12:10:37.689: V/SyncTestActivity(2714): (1000) performAction: LOAD [device=1, tMs=1000, data=null, delay=0]
04-27 12:10:38.379: V/SyncTestActivity(2714): (1695) loaded: ''
04-27 12:10:52.689: V/SyncTestActivity(2714): (15999) performAction: SAVE [device=1, tMs=16000, data=1, delay=0]
04-27 12:10:53.479: D/BlockingSyncer(2714): loaded before saving:
04-27 12:10:53.479: D/SyncTestActivity(2714): merging and 1
04-27 12:10:53.479: D/BlockingSyncer(2714): merged with local data before saving: 1.0
04-27 12:10:54.009: V/SyncTestActivity(2714): (17326) saved: '1.0'
04-27 12:11:04.689: V/SyncTestActivity(2714): (27999) performAction: LOAD [device=1, tMs=28000, data=null, delay=0]
04-27 12:11:05.759: V/SyncTestActivity(2714): (29070) loaded: '1.0'
04-27 12:11:16.689: V/SyncTestActivity(2714): (40000) performAction: LOAD [device=1, tMs=40000, data=null, delay=0]
04-27 12:11:17.629: V/SyncTestActivity(2714): (40939) loaded: '1.0'
04-27 12:11:17.629: V/SyncTestActivity(2714): (40940) done
Device2:
04-27 12:10:36.824: V/SyncTestActivity(1561): Own entries.size: 4
04-27 12:10:37.824: V/SyncTestActivity(1561): (1000) performAction: LOAD [device=2, tMs=1000, data=null, delay=0]
04-27 12:10:41.664: V/SyncTestActivity(1561): (4820) loaded: ''
04-27 12:10:52.824: V/SyncTestActivity(1561): (16000) performAction: SAVE [device=2, tMs=16000, data=2, delay=0]
04-27 12:10:55.507: D/BlockingSyncer(1561): loaded before saving:
04-27 12:10:55.507: D/SyncTestActivity(1561): merging and 2
04-27 12:10:55.507: D/BlockingSyncer(1561): merged with local data before saving: 2.0
04-27 12:10:55.933: V/SyncTestActivity(1561): (19109) saved: '2.0'
04-27 12:11:04.824: V/SyncTestActivity(1561): (28000) performAction: LOAD [device=2, tMs=28000, data=null, delay=0]
04-27 12:11:08.753: V/SyncTestActivity(1561): (31929) loaded: '1.0'
04-27 12:11:16.824: V/SyncTestActivity(1561): (40001) performAction: LOAD [device=2, tMs=40000, data=null, delay=0]
04-27 12:11:19.167: V/SyncTestActivity(1561): (42343) loaded: '1.0'
04-27 12:11:19.167: V/SyncTestActivity(1561): (42344) done
The code for my tests can be found in the following two files:
Activity:
public class SyncTestActivity extends Activity {
private static final String TAG = SyncTestActivity.class.getSimpleName();
private enum Action {
SAVE, LOAD
}
private static class Entry {
public final int deviceId;
public final int timeMs;
public final Action action;
public final String data;
public final int readToWriteDelay;
private Entry(int deviceId, int timeMs, Action action, String data, int readToWriteDelay) {
this.deviceId = deviceId;
this.timeMs = timeMs;
this.action = action;
this.data = data;
this.readToWriteDelay = readToWriteDelay;
}
public static Entry load(int deviceId, int timeS) {
return new Entry(deviceId, timeS, Action.LOAD, null, 0);
}
public static Entry save(int deviceId, int timeS, String data, int readToWriteDelay) {
return new Entry(deviceId, timeS, Action.SAVE, data, readToWriteDelay);
}
@Override
public String toString() {
return action + " [device=" + deviceId + ", tMs=" + timeMs + ", data=" + data
+ ", delay=" + readToWriteDelay + "]";
}
}
public interface Callback<T> {
void done(T result);
}
public interface ConflictResolver {
byte[] resolveConflict(byte[] bytes1, byte[] bytes2);
}
public interface IsSyncer {
void load(Callback<byte[]> callback);
void save(byte[] data, int readToWriteDelay, Callback<byte[]> callback);
}
private final static ConflictResolver CONFLICT_RESOLVER = new ConflictResolver() {
@Override
public byte[] resolveConflict(byte[] bytes1, byte[] bytes2) {
try {
String s1 = new String(bytes1, "UTF-8");
String s2 = new String(bytes2, "UTF-8");
Log.d(TAG, "merging " + s1 + " and " + s2);
double d1 = toDouble(s1);
double d2 = toDouble(s2);
return Double.toString(Math.max(d1, d2)).getBytes("UTF-8");
} catch (UnsupportedEncodingException e) {
throw new RuntimeException(e);
}
}
private double toDouble(String s) {
return s.isEmpty() ? 0 : Double.parseDouble(s);
}
};
@SuppressLint("SimpleDateFormat")
private final static SimpleDateFormat df = new SimpleDateFormat("HH:mm:ss.SSS");
private EditText editDeviceId;
private Button start;
private Button stop;
private Button reset;
private TextView output;
private List<Entry> entries;
private StringBuilder sb = new StringBuilder();
private GameHelper gameHelper;
private IsSyncer syncer;
private IsSyncer resetter;
private AsyncTask<Void, Void, Void> asyncTask;
private Long startTimeMs;
public SyncTestActivity() {
entries = createEntries();
}
private List<Entry> createEntries() {
List<Entry> entries = new ArrayList<Entry>();
int t = 1000;
entries.add(Entry.load(1, t));
entries.add(Entry.load(2, t));
t += 15 * 1000;
entries.add(Entry.save(1, t, "1", 0));
entries.add(Entry.save(2, t, "2", 0));
t += 12 * 1000;
entries.add(Entry.load(1, t));
entries.add(Entry.load(2, t));
t += 12 * 1000;
entries.add(Entry.load(1, t));
entries.add(Entry.load(2, t));
return entries;
}
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_synctest);
editDeviceId = (EditText) findViewById(R.id.device_id);
start = (Button) findViewById(R.id.start);
stop = (Button) findViewById(R.id.stop);
reset = (Button) findViewById(R.id.reset);
output = (TextView) findViewById(R.id.output);
start.setOnClickListener(new OnClickListener() {
@Override
public void onClick(View v) {
start();
}
});
stop.setOnClickListener(new OnClickListener() {
@Override
public void onClick(View v) {
stop();
}
});
reset.setOnClickListener(new OnClickListener() {
@Override
public void onClick(View v) {
reset();
}
});
initSocial();
}
private void initSocial() {
GameHelperListener signInListener = new GameHelperListener() {
@Override
public void onSignInSucceeded() {
Log.v(TAG, "signed in");
}
@Override
public void onSignInFailed() {
Log.v(TAG, "signin failed");
}
};
gameHelper = new GameHelper(this, GameHelper.CLIENT_GAMES | GameHelper.CLIENT_APPSTATE
| GameHelper.CLIENT_SNAPSHOT);
gameHelper.enableDebugLog(true);
gameHelper.setup(signInListener);
gameHelper.onStart(this);
GoogleApiClient apiClient = gameHelper.getApiClient();
syncer = new BlockingSyncer(apiClient, CONFLICT_RESOLVER);
resetter = new BlockingSyncer(apiClient, null);
}
private void start() {
logState();
if (!gameHelper.getApiClient().isConnected()) {
Toast.makeText(this, "Not connected", Toast.LENGTH_LONG).show();
return;
}
int deviceId;
try {
deviceId = Integer.parseInt(editDeviceId.getText().toString());
} catch (NumberFormatException e) {
Toast.makeText(this, "Please enter a valid device-id", Toast.LENGTH_LONG).show();
return;
}
final List<Entry> ownEntries = getOwnEntries(deviceId);
Log.v(TAG, "Own entries.size: " + ownEntries.size());
if (ownEntries.isEmpty()) {
Toast.makeText(this, "No entries", Toast.LENGTH_LONG).show();
return;
}
start(ownEntries);
}
private void start(final List<Entry> ownEntries) {
final long startTime = System.nanoTime();
startTimeMs = startTime / (long)1e6;
asyncTask = new AsyncTask<Void, Void, Void>() {
@Override
protected Void doInBackground(Void... params) {
processEntries(ownEntries, startTime);
return null;
}
};
asyncTask.execute();
}
private void processEntries(final List<Entry> ownEntries, final long startTime) {
for (int i = 0; i < ownEntries.size(); i++) {
if (isAborted()) {
break;
}
Entry entry = ownEntries.get(i);
long entryTime = entry.timeMs * (long)1e6 + startTime;
long now = System.nanoTime();
long sleepMs = (entryTime - now) / (long)1e6;
try {
Thread.sleep(sleepMs);
} catch (InterruptedException e) {
Log.w(TAG, e);
break;
} catch (IllegalArgumentException e) {
Log.v(TAG, "sleepMs: " + sleepMs);
throw e;
}
performAction(entry);
}
append("done");
startTimeMs = null;
}
private boolean isAborted() {
if (asyncTask != null) {
return asyncTask.isCancelled();
}
return false;
}
private void logState() {
Log.v(TAG, "isSignedIn: "+ gameHelper.isSignedIn());
Log.v(TAG, "isConnected: "+ gameHelper.getApiClient().isConnected());
Log.v(TAG, "isConnecting: "+ gameHelper.isConnecting());
Log.v(TAG, "isConnecting: "+ gameHelper.getApiClient().isConnecting());
}
private void performAction(final Entry entry) {
append("performAction: " + entry);
if (entry.action == Action.LOAD) {
performLoad();
} else if (entry.action == Action.SAVE) {
performSave(entry);
}
}
private void performSave(Entry entry) {
syncer.save(convertToBytes(entry.data), entry.readToWriteDelay, new Callback<byte[]>() {
@Override
public void done(byte[] data) {
append("saved: '" + convertToString(data) + "'");
}
});
}
private void performLoad() {
syncer.load(new Callback<byte[]>() {
@Override
public void done(byte[] data) {
append("loaded: '" + convertToString(data) + "'");
}
});
}
private void append(String string) {
string = timeOffsetString() + string;
Log.v(TAG, string);
sb.append(df.format(new Date()) + ": " + string + "\n");
update();
}
private String timeOffsetString() {
if (startTimeMs == null) {
return "";
}
long nowMs = System.nanoTime() / (long)1e6;
return "(" + (nowMs - startTimeMs) + ") ";
}
private void update() {
runOnUiThread(new Runnable() {
@Override
public void run() {
output.setText(sb.toString());
}
});
}
private List<Entry> getOwnEntries(int deviceId) {
List<Entry> result = new ArrayList<Entry>();
for (Entry entry: entries) {
if (entry.deviceId == deviceId) {
result.add(entry);
}
}
return result;
}
private void stop() {
logState();
if (!gameHelper.getApiClient().isConnected()) {
Toast.makeText(this, "Not connected", Toast.LENGTH_LONG).show();
return;
}
if (asyncTask != null) {
asyncTask.cancel(true);
}
}
private void reset() {
sb.setLength(0);
append("deleting (writing default-instance)...");
// it seems delete is buggy (loads can later fail for a while)
new AsyncTask<Void, Void, Void>() {
@Override
protected Void doInBackground(Void... params) {
resetter.save(convertToBytes(""), 0,
new Callback<byte[]>() {
@Override
public void done(byte[] data) {
append("deletion done. saved: '" + convertToString(data) + "'");
}
});
return null;
}
}.execute();
append("user: " + Games.Players.getCurrentPlayer(gameHelper.getApiClient()).getDisplayName());
}
@Override
protected void onActivityResult(int request, int response, Intent data) {
super.onActivityResult(request, response, data);
gameHelper.onActivityResult(request, response, data);
}
private static String convertToString(byte[] data) {
try {
return new String(data, "UTF-8");
} catch (UnsupportedEncodingException e) {
throw new RuntimeException(e);
}
}
private static byte[] convertToBytes(String data) {
try {
return data.getBytes("UTF-8");
} catch (UnsupportedEncodingException e) {
throw new RuntimeException(e);
}
}
}
Cloud-save logic:
public class BlockingSyncer implements IsSyncer {
private final static String TAG = BlockingSyncer.class.getSimpleName();
private final static int MAX_RETRIES = 5;
private final static String NAME = "savegame";
private final GoogleApiClient client;
private final ConflictResolver conflictResolver;
private final int resolutionPolicy;
public BlockingSyncer(GoogleApiClient client, ConflictResolver conflictResolver) {
this.client = client;
this.conflictResolver = conflictResolver;
this.resolutionPolicy = conflictResolver == null ? Snapshots.RESOLUTION_POLICY_MOST_RECENTLY_MODIFIED
: Snapshots.RESOLUTION_POLICY_MANUAL;
}
@Override
public void load(Callback<byte[]> callback) {
OpenSnapshotResult openResult = getResolvedOpenResult();
try {
byte[] data = openResult.getSnapshot().getSnapshotContents().readFully();
callback.done(data);
} catch (IOException e) {
throw new RuntimeException(e);
}
}
private OpenSnapshotResult getResolvedOpenResult() {
OpenSnapshotResult result = Games.Snapshots.open(client, NAME, true, resolutionPolicy).await();
int retryCount = 0;
while (!result.getStatus().isSuccess() && retryCount++ < MAX_RETRIES) {
if (result.getStatus().getStatusCode() != GamesStatusCodes.STATUS_SNAPSHOT_CONFLICT) {
throw new IllegalStateException("Unexpected status code: "
+ result.getStatus().getStatusCode());
}
if (conflictResolver == null) {
throw new IllegalStateException("Conflict despite automatic conflict resolution");
}
Log.d(TAG, "conflict detected");
result.getResolutionSnapshotContents().writeBytes(mergeData(result));
String snapshotId = result.getSnapshot().getMetadata().getSnapshotId();
checkState(result.getConflictingSnapshot().getMetadata().getSnapshotId().equals(snapshotId));
result = Games.Snapshots.resolveConflict(client, result.getConflictId(), snapshotId,
SnapshotMetadataChange.EMPTY_CHANGE, result.getResolutionSnapshotContents()).await();
}
if (!result.getStatus().isSuccess()) {
throw new IllegalStateException("Couldn't resolve conflicts");
}
return result;
}
private byte[] mergeData(OpenSnapshotResult result) {
checkState(conflictResolver != null);
try{
byte[] d1 = result.getSnapshot().getSnapshotContents().readFully();
byte[] d2 = result.getConflictingSnapshot().getSnapshotContents().readFully();
return conflictResolver.resolveConflict(d1, d2);
} catch (IOException e) {
throw new RuntimeException(e);
}
}
@Override
public void save(byte[] data, int readToWriteDelay, Callback<byte[]> callback) {
OpenSnapshotResult result = getResolvedOpenResult();
try {
byte[] loaded = result.getSnapshot().getSnapshotContents().readFully();
Log.d(TAG, "loaded before saving: " + new String(loaded));
if (conflictResolver != null) {
data = conflictResolver.resolveConflict(loaded, data);
}
Log.d(TAG, "merged with local data before saving: " + new String(data));
// just for testing
try {
Thread.sleep(readToWriteDelay);
} catch (InterruptedException e) {
Log.w(TAG, e);
return;
}
result.getSnapshot().getSnapshotContents().writeBytes(data);
CommitSnapshotResult commitResult = Games.Snapshots.commitAndClose(client, result.getSnapshot(), SnapshotMetadataChange.EMPTY_CHANGE).await();
if (!commitResult.getStatus().isSuccess()) {
throw new IllegalStateException("failed to commit: " + commitResult.getStatus());
}
callback.done(data);
} catch (IOException e) {
throw new RuntimeException(e);
}
}
private void checkState(boolean state) {
if (!state) {
throw new IllegalStateException();
}
}
}
228 Dec 7, 2021
3 May 26, 2021
234 Nov 14, 2022
1.3k Dec 27, 2022
1.8k Nov 10, 2022
89 Nov 21, 2022
0 Nov 29, 2021
60 Oct 11, 2022
20.2k Dec 31, 2022
7.6k Dec 30, 2022
5.7k Dec 22, 2022
4.6k Dec 18, 2022
2k Jan 3, 2023
1.9k Dec 30, 2022
1.1k Nov 10, 2022
2k Dec 31, 2022