Skip to content

Commit

Permalink
Browse files Browse the repository at this point in the history
Merge pull request #77 from stephenc/jenkins-41517
[JENKINS-41517] More consistent logging
  • Loading branch information
stephenc committed Jan 27, 2017
2 parents 9d5cd18 + 7e131c4 commit cc184fe
Show file tree
Hide file tree
Showing 2 changed files with 37 additions and 20 deletions.
24 changes: 12 additions & 12 deletions src/main/java/jenkins/branch/MultiBranchProject.java
Expand Up @@ -1231,8 +1231,8 @@ private int processHeadCreate(SCMHeadEvent<?> event, TaskListener global, String
listener = new LogTaskListener(LOGGER, Level.FINE);
}
long start = System.currentTimeMillis();
listener.getLogger().format("[%tc] Received %s event with timestamp %tc%n",
start, eventType, eventTimestamp);
listener.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
start, eventClass, eventType, eventTimestamp);
ChildObserver childObserver = p.createEventsChildObserver();
try {
for (SCMSource source : p.getSCMSources()) {
Expand All @@ -1255,8 +1255,8 @@ p.new SCMHeadObserverImpl(
e.printStackTrace(listener.error(e.getMessage()));
} finally {
long end = System.currentTimeMillis();
listener.getLogger().format("[%tc] %s event processed in %s%n",
end, eventType, Util.getTimeSpanString(end - start));
listener.getLogger().format("[%tc] %s %s event processed in %s%n",
end, eventClass, eventType, Util.getTimeSpanString(end - start));
}
}
}
Expand Down Expand Up @@ -1456,8 +1456,8 @@ private int processHeadUpdate(SCMHeadEvent<?> event, TaskListener global, String
listener = new LogTaskListener(LOGGER, Level.FINE);
}
long start = System.currentTimeMillis();
listener.getLogger().format("[%tc] Received %s event with timestamp %tc%n",
start, eventType, eventTimestamp);
listener.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
start, eventClass, eventType, eventTimestamp);
ChildObserver childObserver = p.createEventsChildObserver();
try {
for (Map.Entry<SCMSource, SCMHead> m : matches.entrySet()) {
Expand Down Expand Up @@ -1503,8 +1503,8 @@ p.new SCMHeadObserverImpl(
e.printStackTrace(listener.error(e.getMessage()));
} finally {
long end = System.currentTimeMillis();
listener.getLogger().format("[%tc] %s event processed in %s%n",
end, eventType, Util.getTimeSpanString(end - start));
listener.getLogger().format("[%tc] %s %s event processed in %s%n",
end, eventClass, eventType, Util.getTimeSpanString(end - start));
}
} else {
// didn't match an existing branch, maybe the criteria now match against an updated branch
Expand Down Expand Up @@ -1533,8 +1533,8 @@ p.new SCMHeadObserverImpl(
listener = new LogTaskListener(LOGGER, Level.FINE);
}
long start = System.currentTimeMillis();
listener.getLogger().format("[%tc] Received %s event with timestamp %tc%n",
start, eventType, eventTimestamp);
listener.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
start, eventClass, eventType, eventTimestamp);
ChildObserver childObserver = p.createEventsChildObserver();
try {
for (SCMSource source : p.getSCMSources()) {
Expand All @@ -1558,8 +1558,8 @@ p.new SCMHeadObserverImpl(
e.printStackTrace(listener.error(e.getMessage()));
} finally {
long end = System.currentTimeMillis();
listener.getLogger().format("[%tc] %s event processed in %s%n",
end, eventType, Util.getTimeSpanString(end - start));
listener.getLogger().format("[%tc] %s %s event processed in %s%n",
end, eventClass, eventType, Util.getTimeSpanString(end - start));
}
}
}
Expand Down
33 changes: 25 additions & 8 deletions src/main/java/jenkins/branch/OrganizationFolder.java
Expand Up @@ -934,16 +934,17 @@ public void onSCMHeadEvent(SCMHeadEvent<?> event) {
}
ChildObserver childObserver = p.createEventsChildObserver();
long start = System.currentTimeMillis();
listener.getLogger().format("[%tc] Received %s event with timestamp %tc%n",
start, event.getType().name(), event.getTimestamp());
listener.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
start, event.getClass().getName(), event.getType().name(), event.getTimestamp());
try {
navigator.visitSources(p.new SCMSourceObserverImpl(listener, childObserver, event), event);
} catch (IOException | InterruptedException e) {
e.printStackTrace(listener.error(e.getMessage()));
} finally {
long end = System.currentTimeMillis();
listener.getLogger().format("[%tc] %s event processed in %s%n",
end, event.getType().name(), Util.getTimeSpanString(end - start));
listener.getLogger().format("[%tc] %s %s event processed in %s%n",
end, event.getClass().getName(), event.getType().name(),
Util.getTimeSpanString(end - start));
}
}
}
Expand All @@ -959,6 +960,11 @@ public void onSCMHeadEvent(SCMHeadEvent<?> event) {
*/
@Override
public void onSCMNavigatorEvent(SCMNavigatorEvent<?> event) {
TaskListener global = globalEventsListener();
global.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
System.currentTimeMillis(), event.getClass().getName(), event.getType().name(),
event.getTimestamp());
int matchCount = 0;
if (UPDATED == event.getType()) {
Set<SCMNavigator> matches = new HashSet<>();
for (OrganizationFolder p : Jenkins.getActiveInstance().getAllItems(OrganizationFolder.class)) {
Expand All @@ -969,6 +975,7 @@ public void onSCMNavigatorEvent(SCMNavigatorEvent<?> event) {
}
}
if (!matches.isEmpty()) {
matchCount++;
TaskListener listener;
try {
listener = p.getComputation().createEventsListener();
Expand Down Expand Up @@ -1014,6 +1021,9 @@ public void onSCMNavigatorEvent(SCMNavigatorEvent<?> event) {
}
}
}
global.getLogger().format("[%tc] Finished processing %s %s event with timestamp %tc. Matched %d.%n",
System.currentTimeMillis(), event.getClass().getName(), event.getType().name(),
event.getTimestamp(), matchCount);
}

/**
Expand All @@ -1025,6 +1035,7 @@ public void onSCMSourceEvent(SCMSourceEvent<?> event) {
global.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
System.currentTimeMillis(), event.getClass().getName(), event.getType().name(),
event.getTimestamp());
int matchCount = 0;
if (CREATED == event.getType()) {
for (OrganizationFolder p : Jenkins.getActiveInstance().getAllItems(OrganizationFolder.class)) {
boolean haveMatch = false;
Expand All @@ -1036,6 +1047,7 @@ public void onSCMSourceEvent(SCMSourceEvent<?> event) {
}
}
if (haveMatch) {
matchCount++;
TaskListener listener;
try {
listener = p.getComputation().createEventsListener();
Expand All @@ -1044,8 +1056,8 @@ public void onSCMSourceEvent(SCMSourceEvent<?> event) {
}
ChildObserver childObserver = p.createEventsChildObserver();
long start = System.currentTimeMillis();
listener.getLogger().format("[%tc] Received %s event with timestamp %tc%n",
start, event.getType().name(), event.getTimestamp());
listener.getLogger().format("[%tc] Received %s %s event with timestamp %tc%n",
start, event.getClass().getName(), event.getType().name(), event.getTimestamp());
try {
for (SCMNavigator n : p.getSCMNavigators()) {
if (event.isMatch(n)) {
Expand All @@ -1060,13 +1072,18 @@ public void onSCMSourceEvent(SCMSourceEvent<?> event) {
e.printStackTrace(listener.error(e.getMessage()));
} finally {
long end = System.currentTimeMillis();
listener.getLogger().format("[%tc] %s event processed in %s%n",
end, event.getType().name(), Util.getTimeSpanString(end - start));
listener.getLogger().format("[%tc] %s %s event processed in %s%n",
end, event.getClass().getName(), event.getType().name(),
Util.getTimeSpanString(end - start));
}

}
}
}
global.getLogger().format("[%tc] Finished processing %s %s event with timestamp %tc. Matched %d.%n",
System.currentTimeMillis(), event.getClass().getName(), event.getType().name(),
event.getTimestamp(), matchCount);

}
}

Expand Down

0 comments on commit cc184fe

Please sign in to comment.