Improve logging around message sending and processing.

This commit is contained in:
Greyson Parrelli
2021-09-15 12:24:42 -04:00
committed by Alex Hart
parent cdf8e4e1ed
commit 1031a4e96c
3 changed files with 24 additions and 23 deletions

View File

@@ -385,6 +385,7 @@ public class SignalServiceMessageSender {
EnvelopeContent envelopeContent = EnvelopeContent.encrypted(content, ContentHint.IMPLICIT, Optional.of(groupId));
long timestamp = System.currentTimeMillis();
Log.d(TAG, "[" + timestamp + "] Sending SKDM to " + recipients.size() + " recipients.");
return sendMessage(recipients, getTargetUnidentifiedAccess(unidentifiedAccess), timestamp, envelopeContent, false, null, null);
}
@@ -1520,6 +1521,7 @@ public class SignalServiceMessageSender {
CancelationSignal cancelationSignal)
throws IOException
{
Log.d(TAG, "[" + timestamp + "] Sending to " + recipients.size() + " recipients.");
enforceMaxContentSize(content);
long startTime = System.currentTimeMillis();
@@ -1551,7 +1553,7 @@ public class SignalServiceMessageSender {
Log.w(TAG, e);
results.add(SendMessageResult.identityFailure(recipient, ((UntrustedIdentityException) e.getCause()).getIdentityKey()));
} else if (e.getCause() instanceof UnregisteredUserException) {
Log.w(TAG, "Found unregistered user.");
Log.w(TAG, "[" + timestamp + "] Found unregistered user.");
results.add(SendMessageResult.unregisteredFailure(recipient));
} else if (e.getCause() instanceof PushNetworkException) {
Log.w(TAG, e);
@@ -1586,7 +1588,7 @@ public class SignalServiceMessageSender {
}
}
Log.d(TAG, "Completed send to " + recipients.size() + " recipients in " + (System.currentTimeMillis() - startTime) + " ms, with an average time of " + Math.round(average) + " ms per send.");
Log.d(TAG, "[" + timestamp + "] Completed send to " + recipients.size() + " recipients in " + (System.currentTimeMillis() - startTime) + " ms, with an average time of " + Math.round(average) + " ms per send.");
return results;
}
@@ -1611,7 +1613,7 @@ public class SignalServiceMessageSender {
OutgoingPushMessageList messages = getEncryptedMessages(socket, recipient, unidentifiedAccess, timestamp, content, online);
if (content.getContent().isPresent() && content.getContent().get().getSyncMessage() != null && content.getContent().get().getSyncMessage().hasSent()) {
Log.d(TAG, "[" + timestamp + "] Sending a sent sync message to devices: " + messages.getDevices());
Log.d(TAG, "[sendMessage][" + timestamp + "] Sending a sent sync message to devices: " + messages.getDevices());
}
if (cancelationSignal != null && cancelationSignal.isCanceled()) {
@@ -1623,20 +1625,20 @@ public class SignalServiceMessageSender {
SendMessageResponse response = new MessagingService.SendResponseProcessor<>(messagingService.send(messages, Optional.absent()).blockingGet()).getResultOrThrow();
return SendMessageResult.success(recipient, messages.getDevices(), false, response.getNeedsSync() || store.isMultiDevice(), System.currentTimeMillis() - startTime, content.getContent());
} catch (WebSocketUnavailableException e) {
Log.i(TAG, "[sendMessage] Pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
Log.i(TAG, "[sendMessage][" + timestamp + "] Pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
} catch (IOException e) {
Log.w(TAG, e);
Log.w(TAG, "[sendMessage] Pipe failed, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
Log.w(TAG, "[sendMessage][" + timestamp + "] Pipe failed, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
}
} else if (unidentifiedAccess.isPresent()) {
try {
SendMessageResponse response = new MessagingService.SendResponseProcessor<>(messagingService.send(messages, unidentifiedAccess).blockingGet()).getResultOrThrow();
return SendMessageResult.success(recipient, messages.getDevices(), true, response.getNeedsSync() || store.isMultiDevice(), System.currentTimeMillis() - startTime, content.getContent());
} catch (WebSocketUnavailableException e) {
Log.i(TAG, "[sendMessage] Unidentified pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
Log.i(TAG, "[sendMessage][" + timestamp + "] Unidentified pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
} catch (IOException e) {
Log.w(TAG, e);
Log.w(TAG, "[sendMessage] Unidentified pipe failed, falling back...");
Log.w(TAG, "[sendMessage][" + timestamp + "] Unidentified pipe failed, falling back...");
}
}
@@ -1688,11 +1690,11 @@ public class SignalServiceMessageSender {
throws IOException, UntrustedIdentityException, NoSessionException, InvalidKeyException, InvalidRegistrationIdException
{
if (recipients.isEmpty()) {
Log.w(TAG, "[sendGroupMessage] Empty recipient list!");
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Empty recipient list!");
return Collections.emptyList();
}
Preconditions.checkArgument(recipients.size() == unidentifiedAccess.size(), "Unidentified access mismatch!");
Preconditions.checkArgument(recipients.size() == unidentifiedAccess.size(), "[" + timestamp + "] Unidentified access mismatch!");
Map<UUID, UnidentifiedAccess> accessByUuid = new HashMap<>();
Iterator<SignalServiceAddress> addressIterator = recipients.iterator();
@@ -1712,7 +1714,7 @@ public class SignalServiceMessageSender {
.map(SignalServiceAddress::new)
.collect(Collectors.toList());
if (needsSenderKey.size() > 0) {
Log.i(TAG, "[sendGroupMessage] Need to send the distribution message to " + needsSenderKey.size() + " addresses.");
Log.i(TAG, "[sendGroupMessage][" + timestamp + "] Need to send the distribution message to " + needsSenderKey.size() + " addresses.");
SenderKeyDistributionMessage message = getOrCreateNewGroupSession(distributionId);
List<Optional<UnidentifiedAccessPair>> access = needsSenderKey.stream()
.map(r -> {
@@ -1733,11 +1735,11 @@ public class SignalServiceMessageSender {
store.markSenderKeySharedWith(distributionId, successAddresses);
Log.i(TAG, "[sendGroupMessage] Successfully sent sender keys to " + successes.size() + "/" + needsSenderKey.size() + " recipients.");
Log.i(TAG, "[sendGroupMessage][" + timestamp + "] Successfully sent sender keys to " + successes.size() + "/" + needsSenderKey.size() + " recipients.");
int failureCount = results.size() - successes.size();
if (failureCount > 0) {
Log.w(TAG, "[sendGroupMessage] Failed to send sender keys to " + failureCount + " recipients. Sending back failed results now.");
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Failed to send sender keys to " + failureCount + " recipients. Sending back failed results now.");
List<SendMessageResult> trueFailures = results.stream()
.filter(r -> !r.isSuccess())
@@ -1785,29 +1787,29 @@ public class SignalServiceMessageSender {
SendGroupMessageResponse response = new MessagingService.SendResponseProcessor<>(messagingService.sendToGroup(ciphertext, joinedUnidentifiedAccess, timestamp, online).blockingGet()).getResultOrThrow();
return transformGroupResponseToMessageResults(targetInfo.devices, response, content);
} catch (WebSocketUnavailableException e) {
Log.i(TAG, "[sendGroupMessage] Pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
Log.i(TAG, "[sendGroupMessage][" + timestamp + "] Pipe unavailable, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
} catch (IOException e) {
Log.w(TAG, "[sendGroupMessage] Pipe failed, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Pipe failed, falling back... (" + e.getClass().getSimpleName() + ": " + e.getMessage() + ")");
}
try {
SendGroupMessageResponse response = socket.sendGroupMessage(ciphertext, joinedUnidentifiedAccess, timestamp, online);
return transformGroupResponseToMessageResults(targetInfo.devices, response, content);
} catch (GroupMismatchedDevicesException e) {
Log.w(TAG, "[sendGroupMessage] Handling mismatched devices.", e);
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Handling mismatched devices.", e);
for (GroupMismatchedDevices mismatched : e.getMismatchedDevices()) {
SignalServiceAddress address = new SignalServiceAddress(UuidUtil.parseOrThrow(mismatched.getUuid()), Optional.absent());
handleMismatchedDevices(socket, address, mismatched.getDevices());
}
} catch (GroupStaleDevicesException e) {
Log.w(TAG, "[sendGroupMessage] Handling stale devices.", e);
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Handling stale devices.", e);
for (GroupStaleDevices stale : e.getStaleDevices()) {
SignalServiceAddress address = new SignalServiceAddress(UuidUtil.parseOrThrow(stale.getUuid()), Optional.absent());
handleStaleDevices(address, stale.getDevices());
}
}
Log.w(TAG, "[sendGroupMessage] Attempt failed (i = " + i + ")");
Log.w(TAG, "[sendGroupMessage][" + timestamp + "] Attempt failed (i = " + i + ")");
}
throw new IOException("Failed to resolve conflicts after " + RETRY_COUNT + " attempts!");