@Override
public void run() {
if (recordUploadFailed) {
Logger.info(
LOG_TAG, "Previous record upload failed. Failing all records and not retrying.");
Exception ex = new Server11PreviousPostFailedException();
for (String guid : outgoingGuids) {
delegate.onRecordStoreFailed(ex, guid);
}
return;
}
if (outgoing == null || outgoing.size() == 0) {
Logger.debug(LOG_TAG, "No items: RecordUploadRunnable returning immediately.");
return;
}
URI u = serverRepository.collectionURI();
SyncStorageRequest request = new SyncStorageRequest(u);
request.delegate = this;
// We don't want the task queue to proceed until this request completes.
// Fortunately, BaseResource is currently synchronous.
// If that ever changes, you'll need to block here.
ByteArraysEntity body = getBodyEntity();
request.post(body);
}
@Override
public void stored() {
Logger.debug(LOG_TAG, "Record stored. Notifying.");
synchronized (storeSerializer) {
Logger.debug(LOG_TAG, "stored() took storeSerializer.");
counter++;
storeSerializer.notify();
Logger.debug(LOG_TAG, "stored() dropped storeSerializer.");
}
}
public void performNotify(final Throwable e) {
if (e != null) {
Logger.debug(LOG_TAG, "performNotify called with Throwable: " + e.getMessage());
} else {
Logger.debug(LOG_TAG, "performNotify called.");
}
if (!queue.offer(new Result(e))) {
// This could happen if performNotify is called multiple times (which is an error).
throw new MultipleNotificationsError();
}
}
/**
* Return the X-Weave-Timestamp header from <code>response</code>, or the current time if it is
* missing.
*
* <p><b>Warning:</b> this can cause the timestamp of <code>response</code> to cross domains (from
* server clock to local clock), which could cause records to be skipped on account of clock
* drift. This should never happen, because <i>every</i> server response should have a well-formed
* X-Weave-Timestamp header.
*
* @param response The <code>SyncStorageResponse</code> to interrogate.
* @return Normalized timestamp in milliseconds.
*/
public static long getNormalizedTimestamp(SyncStorageResponse response) {
long normalizedTimestamp = -1;
try {
normalizedTimestamp = response.normalizedWeaveTimestamp();
} catch (NumberFormatException e) {
Logger.warn(LOG_TAG, "Malformed X-Weave-Timestamp header received.", e);
}
if (-1 == normalizedTimestamp) {
Logger.warn(
LOG_TAG,
"Computing stand-in timestamp from local clock. Clock drift could cause records to be skipped.");
normalizedTimestamp = System.currentTimeMillis();
}
return normalizedTimestamp;
}
@Override
public void queueFilled() {
Logger.debug(LOG_TAG, "Queue filled.");
synchronized (monitor) {
this.stopEventually = true;
monitor.notify();
}
}
@Override
public void halt() {
Logger.debug(LOG_TAG, "Halting.");
synchronized (monitor) {
this.stopEventually = true;
this.stopImmediately = true;
monitor.notify();
}
}
private void consumerIsDone() {
long counterNow = this.counter;
Logger.info(
LOG_TAG,
"Consumer is done. Processed "
+ counterNow
+ ((counterNow == 1) ? " record." : " records."));
delegate.consumerIsDone(stopImmediately);
}
@Override
public void handleRequestSuccess(SyncStorageResponse response) {
Logger.debug(LOG_TAG, "Fetch done.");
removeRequestFromPending();
final long normalizedTimestamp = getNormalizedTimestamp(response);
Logger.debug(LOG_TAG, "Fetch completed. Timestamp is " + normalizedTimestamp);
// When we're done processing other events, finish.
workTracker.delayWorkItem(
new Runnable() {
@Override
public void run() {
Logger.debug(LOG_TAG, "Delayed onFetchCompleted running.");
// TODO: verify number of returned records.
delegate.onFetchCompleted(normalizedTimestamp);
}
});
}
@Override
protected boolean isEnabled() throws MetaGlobalException {
if (session == null || session.getContext() == null) {
return false;
}
boolean migrated = FennecControlHelper.isHistoryMigrated(session.getContext());
if (!migrated) {
Logger.warn(LOG_TAG, "Not enabling history engine since Fennec history is not migrated.");
}
return super.isEnabled() && migrated;
}
@Override
public void handleRequestError(final Exception ex) {
Logger.warn(LOG_TAG, "Got request error.", ex);
recordUploadFailed = true;
ArrayList<String> failedOutgoingGuids = outgoingGuids;
outgoingGuids = null; // Want to GC this ASAP.
for (String guid : failedOutgoingGuids) {
delegate.onRecordStoreFailed(ex, guid);
}
return;
}
public RecordUploadRunnable(
RepositorySessionStoreDelegate storeDelegate,
ArrayList<byte[]> outgoing,
ArrayList<String> outgoingGuids,
long byteCount) {
Logger.debug(
LOG_TAG,
"Preparing record upload for " + outgoing.size() + " records (" + byteCount + " bytes).");
this.outgoing = outgoing;
this.outgoingGuids = outgoingGuids;
this.byteCount = byteCount;
}
@Override
public void handleWBO(CryptoRecord record) {
workTracker.incrementOutstanding();
try {
delegate.onFetchedRecord(record);
} catch (Exception ex) {
Logger.warn(LOG_TAG, "Got exception calling onFetchedRecord with WBO.", ex);
// TODO: handle this better.
throw new RuntimeException(ex);
} finally {
workTracker.decrementOutstanding();
}
}
@Override
public void handleRequestError(final Exception ex) {
removeRequestFromPending();
Logger.warn(LOG_TAG, "Got request error.", ex);
// When we're done processing other events, finish.
workTracker.delayWorkItem(
new Runnable() {
@Override
public void run() {
Logger.debug(LOG_TAG, "Running onFetchFailed.");
delegate.onFetchFailed(ex, null);
}
});
}
@Override
public void storeDone() {
Logger.debug(LOG_TAG, "storeDone().");
synchronized (recordsBufferMonitor) {
flush();
// Do this in a Runnable so that the timestamp is grabbed after any upload.
final Runnable r =
new Runnable() {
@Override
public void run() {
synchronized (recordsBufferMonitor) {
final long end = uploadTimestamp.get();
Logger.debug(LOG_TAG, "Calling storeDone with " + end);
storeDone(end);
}
}
};
storeWorkQueue.execute(r);
}
}
public void performWait(int waitTimeoutInMillis, Runnable action) throws WaitHelperError {
Logger.debug(LOG_TAG, "performWait called.");
Result result = null;
try {
if (action != null) {
try {
action.run();
Logger.debug(LOG_TAG, "Action done.");
} catch (Exception ex) {
Logger.debug(LOG_TAG, "Performing action threw: " + ex.getMessage());
throw new InnerError(ex);
}
}
if (waitTimeoutInMillis < 0) {
result = queue.take();
} else {
result = queue.poll(waitTimeoutInMillis, TimeUnit.MILLISECONDS);
}
Logger.debug(LOG_TAG, "Got result from queue: " + result);
} catch (InterruptedException e) {
// We were interrupted.
Logger.debug(LOG_TAG, "performNotify interrupted with InterruptedException " + e);
final InterruptedError interruptedError = new InterruptedError();
interruptedError.initCause(e);
throw interruptedError;
}
if (result == null) {
// We timed out.
throw new TimeoutError(waitTimeoutInMillis);
} else if (result.error != null) {
Logger.debug(LOG_TAG, "Notified with error: " + result.error.getMessage());
// Rethrow any assertion with which we were notified.
InnerError innerError = new InnerError(result.error);
throw innerError;
}
// Success!
}
private void storeSerially(Record record) {
Logger.debug(LOG_TAG, "New record to store.");
synchronized (storeSerializer) {
Logger.debug(LOG_TAG, "storeSerially() took storeSerializer.");
Logger.debug(LOG_TAG, "Storing...");
try {
this.delegate.store(record);
} catch (Exception e) {
Logger.warn(LOG_TAG, "Got exception in store. Not waiting.", e);
return; // So we don't block for a stored() that never comes.
}
try {
Logger.debug(LOG_TAG, "Waiting...");
storeSerializer.wait();
} catch (InterruptedException e) {
// TODO
}
Logger.debug(LOG_TAG, "storeSerially() dropped storeSerializer.");
}
}
@Override
public void run() {
while (true) {
synchronized (monitor) {
Logger.debug(LOG_TAG, "run() took monitor.");
if (stopImmediately) {
Logger.debug(LOG_TAG, "Stopping immediately. Clearing queue.");
delegate.getQueue().clear();
Logger.debug(LOG_TAG, "Notifying consumer.");
consumerIsDone();
return;
}
Logger.debug(LOG_TAG, "run() dropped monitor.");
}
// The queue is concurrent-safe.
while (!delegate.getQueue().isEmpty()) {
Logger.debug(LOG_TAG, "Grabbing record...");
Record record = delegate.getQueue().remove();
// Block here, allowing us to process records
// serially.
Logger.debug(LOG_TAG, "Invoking storeSerially...");
this.storeSerially(record);
Logger.debug(LOG_TAG, "Done with record.");
}
synchronized (monitor) {
Logger.debug(LOG_TAG, "run() took monitor.");
if (stopEventually) {
Logger.debug(LOG_TAG, "Done with records and told to stop. Notifying consumer.");
consumerIsDone();
return;
}
try {
Logger.debug(LOG_TAG, "Not told to stop but no records. Waiting.");
monitor.wait(10000);
} catch (InterruptedException e) {
// TODO
}
Logger.debug(LOG_TAG, "run() dropped monitor.");
}
}
}
@Override
public void handleRequestSuccess(SyncStorageResponse response) {
Logger.trace(LOG_TAG, "POST of " + outgoing.size() + " records done.");
ExtendedJSONObject body;
try {
body = response.jsonObjectBody(); // jsonObjectBody() throws or returns non-null.
} catch (Exception e) {
Logger.error(LOG_TAG, "Got exception parsing POST success body.", e);
this.handleRequestError(e);
return;
}
// Be defensive when logging timestamp.
if (body.containsKey("modified")) {
Long modified = body.getTimestamp("modified");
if (modified != null) {
Logger.trace(
LOG_TAG, "POST request success. Modified timestamp: " + modified.longValue());
} else {
Logger.warn(
LOG_TAG, "POST success body contains malformed 'modified': " + body.toJSONString());
}
} else {
Logger.warn(
LOG_TAG, "POST success body does not contain key 'modified': " + body.toJSONString());
}
try {
JSONArray success = body.getArray("success");
if ((success != null) && (success.size() > 0)) {
Logger.trace(LOG_TAG, "Successful records: " + success.toString());
for (Object o : success) {
try {
delegate.onRecordStoreSucceeded((String) o);
} catch (ClassCastException e) {
Logger.error(LOG_TAG, "Got exception parsing POST success guid.", e);
// Not much to be done.
}
}
long normalizedTimestamp = getNormalizedTimestamp(response);
Logger.trace(LOG_TAG, "Passing back upload X-Weave-Timestamp: " + normalizedTimestamp);
bumpUploadTimestamp(normalizedTimestamp);
}
success = null; // Want to GC this ASAP.
ExtendedJSONObject failed = body.getObject("failed");
if ((failed != null) && (failed.object.size() > 0)) {
Logger.debug(LOG_TAG, "Failed records: " + failed.object.toString());
Exception ex = new Server11RecordPostFailedException();
for (String guid : failed.keySet()) {
delegate.onRecordStoreFailed(ex, guid);
}
}
failed = null; // Want to GC this ASAP.
} catch (UnexpectedJSONException e) {
Logger.error(LOG_TAG, "Got exception processing success/failed in POST success body.", e);
// TODO
return;
}
Logger.debug(LOG_TAG, "POST of " + outgoing.size() + " records handled.");
}