[NO ISSUE][OTH] Logging Fixes
- user model changes: no
- storage format changes: no
- interface changes: no
Details:
- Log exception when closing sockets quietly at trace level.
- Fix replication logging levels.
- Fix RemoteLogsNotifier thread name.
Change-Id: I210900a410a18144c22fd5af928151b7e7c4bfbd
Reviewed-on: https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/15983
Reviewed-by: Murtadha Hubail <mhubail@apache.org>
Reviewed-by: Michael Blow <mblow@apache.org>
Integration-Tests: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Tested-by: Murtadha Hubail <mhubail@apache.org>
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/logging/RemoteLogsNotifier.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/logging/RemoteLogsNotifier.java
index 58025fc..80bb3c8 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/logging/RemoteLogsNotifier.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/logging/RemoteLogsNotifier.java
@@ -57,7 +57,7 @@
@Override
public void run() {
final String nodeId = appCtx.getServiceContext().getNodeId();
- Thread.currentThread().setName(nodeId + RemoteLogsNotifier.class.getSimpleName());
+ Thread.currentThread().setName(RemoteLogsNotifier.class.getSimpleName() + ":" + nodeId);
while (!Thread.currentThread().isInterrupted()) {
try {
final RemoteLogRecord logRecord = remoteLogsQ.take();
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/IndexReplicationManager.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/IndexReplicationManager.java
index 48eb8e3..063709a 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/IndexReplicationManager.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/IndexReplicationManager.java
@@ -38,7 +38,6 @@
import org.apache.hyracks.api.exceptions.HyracksDataException;
import org.apache.hyracks.api.replication.IReplicationJob;
import org.apache.hyracks.storage.am.lsm.common.api.ILSMIndexReplicationJob;
-import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
@@ -153,7 +152,7 @@
if (!replicationJobsQ.isEmpty()) {
return;
}
- LOGGER.log(Level.INFO, "No pending replication jobs. Closing connections to replicas");
+ LOGGER.trace("no pending replication jobs; closing connections to replicas");
for (ReplicationDestination dest : destinations) {
dest.getReplicas().stream().map(PartitionReplica.class::cast).forEach(PartitionReplica::close);
}
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/ReplicationChannel.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/ReplicationChannel.java
index ba770cd..6c6a10a 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/ReplicationChannel.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/management/ReplicationChannel.java
@@ -129,21 +129,21 @@
+ getRemoteAddress() + ")");
try {
if (socketChannel.requiresHandshake() && !socketChannel.handshake()) {
- LOGGER.warn("failed to complete handshake");
+ LOGGER.warn("failed to complete handshake with {}", this::getRemoteAddress);
return;
}
socketChannel.getSocketChannel().configureBlocking(true);
- LOGGER.debug("reading replication worker initial request");
+ LOGGER.trace("reading replication worker initial request");
ReplicationRequestType requestType = ReplicationProtocol.getRequestType(socketChannel, inBuffer);
- LOGGER.debug("got request type: {}", requestType);
+ LOGGER.trace("got request type: {}", requestType);
while (requestType != ReplicationRequestType.GOODBYE) {
handle(requestType);
- LOGGER.debug("handled request type: {}", requestType);
+ LOGGER.trace("handled request type: {}", requestType);
requestType = ReplicationProtocol.getRequestType(socketChannel, inBuffer);
- LOGGER.debug("got request type: {}", requestType);
+ LOGGER.trace("got request type: {}", requestType);
}
} catch (Exception e) {
- LOGGER.warn("Unexpected error during replication.", e);
+ LOGGER.warn("unexpected error during replication.", e);
} finally {
NetworkUtil.closeQuietly(socketChannel);
}
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/DeleteFileTask.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/DeleteFileTask.java
index 1e93228..92e4989 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/DeleteFileTask.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/DeleteFileTask.java
@@ -60,7 +60,7 @@
((PersistentLocalResourceRepository) appCtx.getLocalResourceRepository())
.invalidateResource(replicaRes.getRelativePath().toString());
}
- LOGGER.info(() -> "Deleted file: " + localFile.getAbsolutePath());
+ LOGGER.debug(() -> "Deleted file: " + localFile.getAbsolutePath());
} else {
LOGGER.warn(() -> "Requested to delete a non-existing file: " + localFile.getAbsolutePath());
}
@@ -85,6 +85,11 @@
}
}
+ @Override
+ public String toString() {
+ return "DeleteFileTask{" + "file='" + file + '\'' + '}';
+ }
+
public static DeleteFileTask create(DataInput input) throws IOException {
return new DeleteFileTask(input.readUTF());
}
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/PartitionResourcesListTask.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/PartitionResourcesListTask.java
index 82ec601..0f5949e 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/PartitionResourcesListTask.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/messaging/PartitionResourcesListTask.java
@@ -67,7 +67,6 @@
LOGGER.debug("got partition {} files ({})", partition, partitionFiles.size());
final PartitionResourcesListResponse response = new PartitionResourcesListResponse(partition,
partitionReplicatedResources, partitionFiles, appCtx.getReplicaManager().isPartitionOrigin(partition));
- LOGGER.debug("partition {} files list to requester", partition);
ReplicationProtocol.sendTo(worker.getChannel(), response, worker.getReusableBuffer());
LOGGER.debug("sent partition {} files list to requester", partition);
}
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/FileSynchronizer.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/FileSynchronizer.java
index 73fca9c..0e27a51 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/FileSynchronizer.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/FileSynchronizer.java
@@ -58,7 +58,7 @@
String masterNode = appCtx.getReplicaManager().isPartitionOrigin(replica.getIdentifier().getPartition())
? appCtx.getServiceContext().getNodeId() : null;
ReplicateFileTask task = new ReplicateFileTask(file, filePath.getFile().length(), metadata, masterNode);
- LOGGER.debug("attempting to replicate {} to replica {}", task, replica);
+ LOGGER.trace("attempting {} to replica {}", task, replica);
ReplicationProtocol.sendTo(replica, task);
// send the file itself
try (RandomAccessFile fromFile = new RandomAccessFile(filePath.getFile(), "r");
@@ -66,6 +66,7 @@
NetworkingUtil.sendFile(fileChannel, channel);
}
ReplicationProtocol.waitForAck(replica);
+ LOGGER.debug("completed {} to replica {}", task, replica);
} catch (IOException e) {
throw new ReplicationException(e);
}
@@ -74,8 +75,10 @@
public void delete(String file) {
try {
final DeleteFileTask task = new DeleteFileTask(file);
+ LOGGER.trace("attempting {} from replica {}", task, replica);
ReplicationProtocol.sendTo(replica, task);
ReplicationProtocol.waitForAck(replica);
+ LOGGER.debug("completed {} from replica {}", task, replica);
} catch (IOException e) {
throw new ReplicationException(e);
}
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaFilesSynchronizer.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaFilesSynchronizer.java
index 809b7a6..5d217a4 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaFilesSynchronizer.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaFilesSynchronizer.java
@@ -70,9 +70,9 @@
if (!deltaRecovery) {
deletePartitionFromReplica(partition);
}
- LOGGER.debug("getting replica files");
+ LOGGER.trace("getting replica files");
PartitionResourcesListResponse replicaResourceResponse = getReplicaFiles(partition);
- LOGGER.debug("got replica files");
+ LOGGER.trace("got replica files");
Map<ResourceReference, Long> resourceReferenceLongMap = getValidReplicaResources(
replicaResourceResponse.getPartitionReplicatedResources(), replicaResourceResponse.isOrigin());
// clean up files for invalid resources (deleted or recreated while the replica was down)
@@ -81,11 +81,10 @@
final PersistentLocalResourceRepository localResourceRepository =
(PersistentLocalResourceRepository) appCtx.getLocalResourceRepository();
final IReplicationStrategy replicationStrategy = appCtx.getReplicationManager().getReplicationStrategy();
- LOGGER.debug("clean up replica invalid files");
final Set<String> masterFiles =
localResourceRepository.getPartitionReplicatedFiles(partition, replicationStrategy).stream()
.map(StoragePathUtil::getFileRelativePath).collect(Collectors.toSet());
- LOGGER.debug("got master partition files");
+ LOGGER.trace("got master partition files");
// exclude from the replica files the list of invalid deleted files
final Set<String> replicaFiles = new HashSet<>(replicaResourceResponse.getFiles());
replicaFiles.removeAll(deletedReplicaFiles);
@@ -131,13 +130,12 @@
}
private void deleteInvalidFiles(List<String> files) {
- LOGGER.debug("deleting replica invalid files");
final FileSynchronizer sync = new FileSynchronizer(appCtx, replica);
// sort files to ensure index metadata files starting with "." are deleted last
files.sort(String::compareTo);
Collections.reverse(files);
- LOGGER.info("deleting {}", files);
files.forEach(sync::delete);
+ LOGGER.debug("completed invalid files deletion");
}
private long getResourceMasterValidSeq(ResourceReference rr) throws HyracksDataException {
@@ -174,7 +172,7 @@
}
}
if (!invalidFiles.isEmpty()) {
- LOGGER.info("will delete the following files from replica {}", invalidFiles);
+ LOGGER.debug("will delete the following files from replica {}", invalidFiles);
deleteInvalidFiles(new ArrayList<>(invalidFiles));
}
return invalidFiles;
diff --git a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaSynchronizer.java b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaSynchronizer.java
index 7130e07..459ff01 100644
--- a/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaSynchronizer.java
+++ b/asterixdb/asterix-replication/src/main/java/org/apache/asterix/replication/sync/ReplicaSynchronizer.java
@@ -50,7 +50,7 @@
LOGGER.debug("starting replica sync process for replica {}", replica);
Object partitionLock = appCtx.getReplicaManager().getPartitionSyncLock(replica.getIdentifier().getPartition());
synchronized (partitionLock) {
- LOGGER.debug("acquired partition replica lock");
+ LOGGER.trace("acquired partition replica lock");
final ICheckpointManager checkpointManager = appCtx.getTransactionSubsystem().getCheckpointManager();
try {
// suspend checkpointing datasets to prevent async IO operations while sync'ing replicas
diff --git a/hyracks-fullstack/hyracks/hyracks-ipc/src/main/java/org/apache/hyracks/ipc/sockets/SslSocketChannel.java b/hyracks-fullstack/hyracks/hyracks-ipc/src/main/java/org/apache/hyracks/ipc/sockets/SslSocketChannel.java
index fc379fb..9e052f8 100644
--- a/hyracks-fullstack/hyracks/hyracks-ipc/src/main/java/org/apache/hyracks/ipc/sockets/SslSocketChannel.java
+++ b/hyracks-fullstack/hyracks/hyracks-ipc/src/main/java/org/apache/hyracks/ipc/sockets/SslSocketChannel.java
@@ -102,7 +102,7 @@
inAppData.limit(0);
}
} else if (bytesRead < 0) {
- LOGGER.debug("received EOF; transferredBytes Bytes: {}", transferredBytes);
+ LOGGER.trace("received EOF; transferred bytes: {}", transferredBytes);
handleEndOfStreamQuietly();
return -1;
}
@@ -195,7 +195,7 @@
new SslHandshake(this).handshake();
} catch (Exception e) {
// ignore exceptions on best effort graceful close handshake
- LOGGER.debug("ssl socket close handshake failed", e);
+ LOGGER.trace("ssl socket close handshake failed", e);
} finally {
socketChannel.close();
}
@@ -243,7 +243,8 @@
close();
}
} catch (Exception e) {
- LOGGER.warn("failed to close socket gracefully", e);
+ // ignore close exception since we are closing quietly
+ LOGGER.trace("failed to close socket gracefully", e);
}
}