Skip to content

Commit e81f256

Browse files
rjeberhardrjeberhard
committed
Improve logging
1 parent 068bde0 commit e81f256

File tree

6 files changed

+148
-53
lines changed

6 files changed

+148
-53
lines changed

‎src/main/java/oracle/kubernetes/operator/Main.java

Lines changed: 54 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -992,11 +992,11 @@ private static Step scaleDownIfNecessary(DomainPresenceInfo info, Collection<Str
992992
}
993993

994994
private static class ManagedServerUpIteratorStep extends Step {
995-
private final Iterator<ServerStartupInfo> it;
995+
private final Collection<ServerStartupInfo> c;
996996

997997
public ManagedServerUpIteratorStep(Collection<ServerStartupInfo> c, Step next) {
998998
super(next);
999-
this.it = c.iterator();
999+
this.c = c;
10001000
}
10011001

10021002
@Override
@@ -1005,8 +1005,7 @@ public NextAction apply(Packet packet) {
10051005
Map<String, StepAndPacket> rolling = new ConcurrentHashMap<>();
10061006
packet.put(ProcessingConstants.SERVERS_TO_ROLL, rolling);
10071007

1008-
while (it.hasNext()) {
1009-
ServerStartupInfo ssi = it.next();
1008+
for (ServerStartupInfo ssi : c) {
10101009
Packet p = packet.clone();
10111010
p.put(ProcessingConstants.SERVER_SCAN, ssi.serverConfig);
10121011
p.put(ProcessingConstants.CLUSTER_SCAN, ssi.clusterConfig);
@@ -1015,6 +1014,28 @@ public NextAction apply(Packet packet) {
10151014
startDetails.add(new StepAndPacket(bringManagedServerUp(ssi, null), p));
10161015
}
10171016

1017+
if (LOGGER.isFineEnabled()) {
1018+
DomainPresenceInfo info = packet.getSPI(DomainPresenceInfo.class);
1019+
1020+
Domain dom = info.getDomain();
1021+
DomainSpec spec = dom.getSpec();
1022+
1023+
Collection<String> runningList = new ArrayList<>();
1024+
for (Map.Entry<String, ServerKubernetesObjects> entry : info.getServers().entrySet()) {
1025+
ServerKubernetesObjects sko = entry.getValue();
1026+
if (sko != null && sko.getPod() != null) {
1027+
runningList.add(entry.getKey());
1028+
}
1029+
}
1030+
LOGGER.fine("Running servers for domain with UID: " + spec.getDomainUID() + ", running list: " + runningList);
1031+
1032+
Collection<String> serverList = new ArrayList<>();
1033+
for (ServerStartupInfo ssi : c) {
1034+
serverList.add(ssi.serverConfig.getName());
1035+
}
1036+
LOGGER.fine("Starting or validating servers for domain with UID: " + spec.getDomainUID() + ", server list: " + serverList);
1037+
}
1038+
10181039
if (startDetails.isEmpty()) {
10191040
return doNext(packet);
10201041
}
@@ -1032,6 +1053,19 @@ public NextAction apply(Packet packet) {
10321053
@SuppressWarnings("unchecked")
10331054
Map<String, StepAndPacket> rolling = (Map<String, StepAndPacket>) packet.get(ProcessingConstants.SERVERS_TO_ROLL);
10341055

1056+
if (LOGGER.isFineEnabled()) {
1057+
DomainPresenceInfo info = packet.getSPI(DomainPresenceInfo.class);
1058+
1059+
Domain dom = info.getDomain();
1060+
DomainSpec spec = dom.getSpec();
1061+
1062+
Collection<String> rollingList = Collections.emptyList();
1063+
if (rolling != null) {
1064+
rollingList = rolling.keySet();
1065+
}
1066+
LOGGER.fine("Rolling servers for domain with UID: " + spec.getDomainUID() + ", rolling list: " + rollingList);
1067+
}
1068+
10351069
if (rolling == null || rolling.isEmpty()) {
10361070
return doNext(packet);
10371071
}
@@ -1041,22 +1075,34 @@ public NextAction apply(Packet packet) {
10411075
}
10421076

10431077
private static class ServerDownIteratorStep extends Step {
1044-
private final Iterator<Map.Entry<String, ServerKubernetesObjects>> it;
1078+
private final Collection<Map.Entry<String, ServerKubernetesObjects>> c;
10451079

10461080
public ServerDownIteratorStep(Collection<Map.Entry<String, ServerKubernetesObjects>> serversToStop, Step next) {
10471081
super(next);
1048-
this.it = serversToStop.iterator();
1082+
this.c = serversToStop;
10491083
}
10501084

10511085
@Override
10521086
public NextAction apply(Packet packet) {
10531087
Collection<StepAndPacket> startDetails = new ArrayList<>();
10541088

1055-
while (it.hasNext()) {
1056-
Map.Entry<String, ServerKubernetesObjects> entry = it.next();
1089+
for (Map.Entry<String, ServerKubernetesObjects> entry : c) {
10571090
startDetails.add(new StepAndPacket(new ServerDownStep(entry.getKey(), entry.getValue(), null), packet));
10581091
}
10591092

1093+
if (LOGGER.isFineEnabled()) {
1094+
DomainPresenceInfo info = packet.getSPI(DomainPresenceInfo.class);
1095+
1096+
Domain dom = info.getDomain();
1097+
DomainSpec spec = dom.getSpec();
1098+
1099+
Collection<String> stopList = new ArrayList<>();
1100+
for (Map.Entry<String, ServerKubernetesObjects> entry : c) {
1101+
stopList.add(entry.getKey());
1102+
}
1103+
LOGGER.fine("Stopping servers for domain with UID: " + spec.getDomainUID() + ", stop list: " + stopList);
1104+
}
1105+
10601106
if (startDetails.isEmpty()) {
10611107
return doNext(packet);
10621108
}

‎src/main/java/oracle/kubernetes/operator/logging/LoggingFormatter.java

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
import java.text.SimpleDateFormat;
1616
import java.util.Date;
1717
import java.util.HashMap;
18+
import java.util.LinkedHashMap;
1819
import java.util.List;
1920
import java.util.Map;
2021
import java.util.logging.Formatter;
@@ -98,7 +99,7 @@ public String format(LogRecord record) {
9899
}
99100
}
100101
String level = record.getLevel().getLocalizedName();
101-
Map<String, Object> map = new HashMap<>();
102+
Map<String, Object> map = new LinkedHashMap<>();
102103
long rawTime = record.getMillis();
103104
final String dateString = dateFormat.format(new Date(rawTime));
104105
long thread = Thread.currentThread().getId();

‎src/main/java/oracle/kubernetes/operator/work/Engine.java

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,10 @@ public Fiber createFiber() {
116116
return new Fiber(this);
117117
}
118118

119+
Fiber createChildFiber(Fiber parent) {
120+
return new Fiber(this, parent);
121+
}
122+
119123
private class DaemonThreadFactory implements ThreadFactory {
120124
final AtomicInteger threadNumber = new AtomicInteger(1);
121125
final String namePrefix;

‎src/main/java/oracle/kubernetes/operator/work/Fiber.java

Lines changed: 63 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,6 @@
1616
import java.util.concurrent.locks.Condition;
1717
import java.util.concurrent.locks.ReentrantLock;
1818
import java.util.function.Consumer;
19-
import java.util.logging.Level;
2019

2120
import oracle.kubernetes.operator.logging.LoggingFacade;
2221
import oracle.kubernetes.operator.logging.LoggingFactory;
@@ -56,6 +55,7 @@ public final class Fiber implements Runnable, Future<Void>, ComponentRegistry {
5655
private Packet packet;
5756

5857
public final Engine owner;
58+
private final Fiber parent;
5959

6060
/**
6161
* Is this thread suspended? 0=not suspended, 1=suspended.
@@ -148,7 +148,12 @@ public interface ExitCallback {
148148
private static final ExitCallback PLACEHOLDER = () -> {};
149149

150150
Fiber(Engine engine) {
151+
this(engine, null);
152+
}
153+
154+
Fiber(Engine engine, Fiber parent) {
151155
this.owner = engine;
156+
this.parent = parent;
152157
id = iotaGen.incrementAndGet();
153158

154159
// if this is run from another fiber, then we naturally inherit its context
@@ -175,6 +180,10 @@ public void start(Step stepline, Packet packet, CompletionCallback completionCal
175180
this.completionCallback = completionCallback;
176181
this.applyThrowable = null;
177182

183+
if (LOGGER.isFineEnabled()) {
184+
LOGGER.fine("{0} started", new Object[] { getName() });
185+
}
186+
178187
if (status.get() == NOT_COMPLETE) {
179188
owner.addRunnable(this);
180189
}
@@ -213,20 +222,25 @@ public void resume(Packet resumePacket) {
213222
*/
214223
public void resume(Packet resumePacket, CompletionCallback callback) {
215224
if (status.get() == NOT_COMPLETE) {
225+
226+
if (LOGGER.isFineEnabled()) {
227+
LOGGER.fine("{0} resumed", new Object[] { getName() });
228+
}
229+
216230
lock.lock();
217231
try {
218232
if (callback != null) {
219233
setCompletionCallback(callback);
220234
}
221-
if (LOGGER.isLoggable(Level.FINE)) {
222-
LOGGER.fine("{0} resuming. Will have suspendedCount={1}", new Object[] { getName(), suspendedCount - 1 });
235+
if (LOGGER.isFinerEnabled()) {
236+
LOGGER.finer("{0} resuming. Will have suspendedCount={1}", new Object[] { getName(), suspendedCount - 1 });
223237
}
224238
packet = resumePacket;
225239
if (--suspendedCount == 0) {
226240
owner.addRunnable(this);
227241
} else {
228-
if (LOGGER.isLoggable(Level.FINE)) {
229-
LOGGER.fine("{0} taking no action on resume because suspendedCount != 0: {1}",
242+
if (LOGGER.isFinerEnabled()) {
243+
LOGGER.finer("{0} taking no action on resume because suspendedCount != 0: {1}",
230244
new Object[] { getName(), suspendedCount });
231245
}
232246
}
@@ -245,6 +259,11 @@ public void terminate(Throwable t, Packet packet) {
245259
if (t == null) {
246260
throw new IllegalArgumentException();
247261
}
262+
263+
if (LOGGER.isFineEnabled()) {
264+
LOGGER.fine("{0} terminated", new Object[] { getName() });
265+
}
266+
248267
lock.lock();
249268
try {
250269
if (suspendedCount <= 0) {
@@ -263,7 +282,7 @@ public void terminate(Throwable t, Packet packet) {
263282
* @return Child fiber
264283
*/
265284
public Fiber createChildFiber() {
266-
Fiber child = owner.createFiber();
285+
Fiber child = owner.createChildFiber(this);
267286

268287
synchronized (this) {
269288
if (children == null) {
@@ -289,6 +308,10 @@ public boolean cancel(boolean mayInterrupt) {
289308
return false;
290309
}
291310

311+
if (LOGGER.isFineEnabled()) {
312+
LOGGER.fine("{0} cancelled", new Object[] { getName() });
313+
}
314+
292315
// synchronized(this) is used as Thread running Fiber will be holding lock
293316
synchronized (this) {
294317
if (mayInterrupt) {
@@ -375,13 +398,15 @@ public Void get(long timeout, TimeUnit unit) throws InterruptedException, Execut
375398
private boolean suspend(Holder<Boolean> isRequireUnlock, Consumer<Fiber> onExit) {
376399
suspendedCount++;
377400

378-
if (LOGGER.isLoggable(Level.FINE)) {
379-
LOGGER.fine("{0} suspending. Will have suspendedCount={1}", new Object[] { getName(), suspendedCount });
401+
if (LOGGER.isFinerEnabled()) {
402+
LOGGER.finer("{0} suspending. Will have suspendedCount={1}", new Object[] { getName(), suspendedCount });
380403
if (suspendedCount > 1) {
381-
LOGGER.fine(
404+
LOGGER.finer(
382405
"WARNING - {0} suspended more than resumed. Will require more than one resume to actually resume this fiber.",
383406
getName());
384407
}
408+
} else if (LOGGER.isFineEnabled()) {
409+
LOGGER.fine("{0} suspending", new Object[] { getName() });
385410
}
386411

387412
if (onExit != null) {
@@ -457,6 +482,11 @@ public void run() {
457482
// Trigger exitCallback
458483
synchronized (this) {
459484
if (exitCallback != null && exitCallback != PLACEHOLDER) {
485+
486+
if (LOGGER.isFineEnabled()) {
487+
LOGGER.fine("{0} invoking exit callback", new Object[] { getName() });
488+
}
489+
460490
exitCallback.onExit();
461491
}
462492
exitCallback = PLACEHOLDER;
@@ -474,7 +504,7 @@ private void completionCheck() {
474504
// throwable
475505
int s = status.get();
476506
if (s == CANCELLED || (s == NOT_COMPLETE && (applyThrowable != null || (next == null && suspendedCount == 0)))) {
477-
if (LOGGER.isLoggable(Level.FINE)) {
507+
if (LOGGER.isFineEnabled()) {
478508
LOGGER.fine("{0} completed", getName());
479509
}
480510
boolean isDone = status.compareAndSet(NOT_COMPLETE, DONE);
@@ -507,8 +537,8 @@ private boolean doRun(Step next) {
507537
// currentThread is protected by the monitor for this fiber so
508538
// that it is accessible to cancel() even when the lock is held
509539
currentThread = Thread.currentThread();
510-
if (LOGGER.isLoggable(Level.FINE)) {
511-
LOGGER.fine("Thread entering _doRun(): {0}", currentThread);
540+
if (LOGGER.isFinerEnabled()) {
541+
LOGGER.finer("Thread entering _doRun(): {0}", currentThread);
512542
}
513543

514544
old = currentThread.getContextClassLoader();
@@ -535,8 +565,8 @@ private boolean doRun(Step next) {
535565
// tracks this state
536566
Thread thread = Thread.currentThread();
537567
thread.setContextClassLoader(old);
538-
if (LOGGER.isLoggable(Level.FINE)) {
539-
LOGGER.fine("Thread leaving _doRun(): {0}", thread);
568+
if (LOGGER.isFinerEnabled()) {
569+
LOGGER.finer("Thread leaving _doRun(): {0}", thread);
540570
}
541571
}
542572
} finally {
@@ -563,8 +593,8 @@ private boolean _doRun(Holder<Boolean> isRequireUnlock) {
563593
return false;
564594
}
565595

566-
if (LOGGER.isLoggable(Level.FINE)) {
567-
LOGGER.fine("{0} {1}.apply({2})", new Object[] { getName(), next,
596+
if (LOGGER.isFinerEnabled()) {
597+
LOGGER.finer("{0} {1}.apply({2})", new Object[] { getName(), next,
568598
packet != null ? "Packet@" + Integer.toHexString(packet.hashCode()) : "null" });
569599
}
570600

@@ -576,8 +606,8 @@ private boolean _doRun(Holder<Boolean> isRequireUnlock) {
576606
return false;
577607
}
578608

579-
if (LOGGER.isLoggable(Level.FINE)) {
580-
LOGGER.fine("{0} returned with {1}", new Object[] { getName(), na });
609+
if (LOGGER.isFineEnabled()) {
610+
LOGGER.fine("{0} {1} returned with {2}", new Object[] { getName(), next, na });
581611
}
582612

583613
// If resume is called before suspend, then make sure
@@ -615,7 +645,17 @@ private boolean isReady() {
615645
}
616646

617647
private String getName() {
618-
return "engine-" + owner.id + "fiber-" + id;
648+
StringBuilder sb = new StringBuilder();
649+
if (parent != null) {
650+
sb.append(parent.getName());
651+
sb.append("-child-");
652+
} else {
653+
sb.append("engine-");
654+
sb.append(owner.id);
655+
sb.append("-fiber-");
656+
}
657+
sb.append(id);
658+
return sb.toString();
619659
}
620660

621661
@Override
@@ -666,6 +706,10 @@ public boolean cancelAndExitCallback(boolean mayInterrupt, ExitCallback exitCall
666706
// Mark fiber as cancelled, if not already done
667707
status.compareAndSet(NOT_COMPLETE, CANCELLED);
668708

709+
if (LOGGER.isFineEnabled()) {
710+
LOGGER.fine("{0} cancelled", new Object[] { getName() });
711+
}
712+
669713
synchronized (this) {
670714
if (currentThread != null) {
671715
if (mayInterrupt) {

‎src/main/java/oracle/kubernetes/operator/work/NextAction.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -132,10 +132,10 @@ public Packet getPacket() {
132132
@Override
133133
public String toString() {
134134
StringBuilder buf = new StringBuilder();
135-
buf.append(super.toString()).append(" [");
135+
buf.append('[');
136136
buf.append("kind=").append(kind).append(',');
137137
buf.append("next=").append(next).append(',');
138-
buf.append("packet=").append(packet != null ? packet.toString() : null).append(',');
138+
buf.append("packet=").append(packet != null ? packet.toString() : null).append(']');
139139
return buf.toString();
140140
}
141141
}

0 commit comments

Comments
 (0)