/** Make sure {@link FileUsageCounter#reset()} works. */
public void testReset() throws IOException, InterruptedException {
NDC.push("testReset");
try {
File f = createNonexistentDirect();
FileUsageCounter counter =
new FileUsageCounter("test", new TimeBasedUsage(), createTarget(), f);
long delay = 100;
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
Thread.sleep(delay);
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
counter.consume(new DataSample<Double>("source", "signature", null, new Error()));
logger.debug("Consumed: " + counter.getUsageAbsolute());
// Can't really assert much, the timer is too inexact
assertTrue("Consumed value less than time passed???", counter.getUsageAbsolute() > delay);
counter.reset();
assertEquals("Wrong value after reset", 0, counter.getUsageAbsolute());
} finally {
NDC.pop();
}
}
public void onMessage(Message message) {
NDC.push(clientId);
log.debug("public void onMessage(Message message = " + message + "): called");
if (!init) {
start = System.nanoTime() / 1000000;
count = 0;
init = true;
}
try {
if (isShutdown(message)) {
log.debug("Got a shutdown message.");
shutdown();
} else if (isReport(message)) {
log.debug("Got a report request message.");
// Send the report.
report();
init = false;
}
} catch (JMSException e) {
log.warn("There was a JMSException during onMessage.", e);
} finally {
NDC.pop();
}
}
/** Removes the log message from the Log4J NDC after the request is processed. */
@Override
public void afterCompletion(WebRequest request, Exception ex) throws Exception {
NDC.pop();
if (NDC.getDepth() == 0) {
NDC.remove();
}
}
/**
* actual log statements
*
* @throws Exception
*/
private void doLogging() throws Exception {
// These messages with Level >= set level will be logged to
// the database.
logger.debug("debug DOM");
// this not, because Priority DEBUG is less than INFO
logger.info("info'test DOM");
logger.error(
"nested nullpointer error",
new RemoteException("test", new RemoteException("test2", new NullPointerException())));
logger.fatal("fatal DOM");
// NDC/MDC
logger.info(new Timestamp(1)); // object logging
NDC.push("MyNDC");
logger.info("info MyNDC");
MDC.put("MyMDC", "MyMDC");
MDC.put("MyMDC2", new Exception("MDC2").toString());
logger.info("info MyNDC MyMDC");
NDC.pop();
logger.info("info MyMDC");
// null tests
logger.fatal(null);
MDC.remove("MyMDC");
}
/**
* Removes the log message from the Log4J NDC when the processing thread is exited after the start
* of asynchronous request handling.
*/
@Override
public void afterConcurrentHandlingStarted(WebRequest request) {
NDC.pop();
if (NDC.getDepth() == 0) {
NDC.remove();
}
}
public void testFastStart() {
NDC.push("testFastStart");
try {
ScheduleUpdater u =
new ScheduleUpdater() {
@Override
public Map<Thermostat, SortedMap<Period, ZoneStatus>> update() throws IOException {
// Bad implementation, but shouldn't break anything
return null;
}
};
Scheduler s = new Scheduler(u);
s.setScheduleGranularity(50);
// This instance will run until the JVM is gone or Scheduler#ScheduledExecutorService is
// otherwise stopped
s.start(0);
Thread.sleep(100);
} catch (InterruptedException ex) {
throw new IllegalStateException(ex);
} finally {
NDC.pop();
}
}
public static void main(String[] argv) throws Exception {
clientId = "Listener-" + System.currentTimeMillis();
NDC.push(clientId);
Config config = new Config();
config.setOptions(argv);
// Connection con = config.createConnection();
Connection con =
new AMQConnection(
"amqp://*****:*****@testid/test?brokerlist='"
+ config.getHost()
+ ":"
+ config.getPort()
+ "'");
if (config.getClientId() != null) {
con.setClientID(config.getClientId());
}
new Listener(con, config.getAckMode(), config.getSubscriptionId());
NDC.pop();
NDC.remove();
}
/**
* Update the running state of a ticket
*
* <p>// TODO: add manifest ingest as form/multipart
*
* @param ticket
* @param isError
* @param description
* @param isFinished
* @param response
*/
@POST
@Path("{ticket}")
public void setStatus(
@PathParam("ticket") String ticket,
@FormParam("isError") @DefaultValue(value = "false") boolean isError,
@FormParam("description") String description,
@FormParam("isFinished") @DefaultValue(value = "false") boolean isFinished,
@Context HttpServletResponse response) {
try {
NDC.push("U" + ticket);
LOG.info("Ticket Request ID: " + ticket + " error: " + isError + " finished: " + isFinished);
if (isError) {
tm.errorTicket(ticket, description);
} else if (isFinished) {
tm.completeTicket(ticket, description);
} else {
tm.updateMessage(ticket, description);
}
} finally {
LOG.info("Completed Ticket Request ID: " + ticket);
NDC.pop();
}
}
@Override
public final void execute() throws BuildException {
if (NDC.getDepth() <= 0) {
NDC.push(_groupName);
}
validate();
doExecute(createEc2());
}
private void runWithContext() {
HaWorkVO work = null;
try {
s_logger.trace("Checking the database");
work = _haDao.take(_serverId);
if (work == null) {
try {
synchronized (this) {
wait(_timeToSleep);
}
return;
} catch (final InterruptedException e) {
s_logger.info("Interrupted");
return;
}
}
NDC.push("work-" + work.getId());
s_logger.info("Processing " + work);
try {
final WorkType wt = work.getWorkType();
Long nextTime = null;
if (wt == WorkType.Migration) {
nextTime = migrate(work);
} else if (wt == WorkType.HA) {
nextTime = restart(work);
} else if (wt == WorkType.Stop || wt == WorkType.CheckStop || wt == WorkType.ForceStop) {
nextTime = stopVM(work);
} else if (wt == WorkType.Destroy) {
nextTime = destroyVM(work);
} else {
assert false : "How did we get here with " + wt.toString();
return;
}
if (nextTime == null) {
s_logger.info("Completed " + work);
work.setStep(Step.Done);
} else {
s_logger.info("Rescheduling " + work + " to try again at " + new Date(nextTime << 10));
work.setTimeToTry(nextTime);
work.setServerId(null);
work.setDateTaken(null);
}
} catch (Exception e) {
s_logger.error("Terminating " + work, e);
work.setStep(Step.Error);
}
_haDao.update(work.getId(), work);
} catch (final Throwable th) {
s_logger.error("Caught this throwable, ", th);
} finally {
if (work != null) {
NDC.pop();
}
}
}
@Override
public final void run() {
NDC.inherit(ndcStack);
try {
runInternal();
} finally {
NDC.clear();
}
}
@Override
public TaskList retrieveTasks(StoryList stories)
throws IOException, ClientProtocolException, ConnectorException, TransformerException,
URISyntaxException {
RallyRestApi restApi = new RallyRestApi(new URI(RALLY_SERVER_URL), username, password);
QueryRequest taskQuery = new QueryRequest("Task");
TaskList taskList = objFactory.createTaskList();
try {
for (StoryType story : stories.getStory()) {
String storyID = story.getIdentifier();
Link storyLink = findLinkByRel(story, RALLY_OBJECT_URL_REL);
if (storyLink != null) {
storyLink.setRel(RALLY_PARENT_URL_REL);
}
NDC.push("retrieving tasks for " + storyID);
logger.debug(NDC.peek());
QueryFilter filter = new QueryFilter("WorkProduct.FormattedID", "=", storyID);
taskQuery.setQueryFilter(filter);
QueryResponse query = restApi.query(taskQuery);
if (query.wasSuccessful()) {
for (JsonElement e : query.getResults()) {
if (e == null) continue;
TaskType task = objFactory.createTaskType();
JsonObject jsonTask = e.getAsJsonObject();
String taskName = jsonTask.get("Name").getAsString();
task.setParentIdentifier(storyID);
task.setDescription(fixDescription(getValueOrDefault(jsonTask.get("Description"), "")));
if (!jsonTask.get("Owner").isJsonNull()) {
task.setOwner(
getValueOrDefault(
jsonTask.get("Owner").getAsJsonObject().get("_refObjectName"), ""));
}
task.setFullName(taskName);
task.setShortName((taskName.length() > 30) ? taskName.substring(0, 30) : taskName);
task.setIdentifier(jsonTask.get("FormattedID").getAsString());
task.setDetailedEstimate(getValueOrDefault(jsonTask.get("Estimate"), new Double(0.0)));
task.setTodoRemaining(getValueOrDefault(jsonTask.get("Estimate"), new Double(0.0)));
task.setEffortApplied(getValueOrDefault(jsonTask.get("Actuals"), new Double(0.0)));
task.setDescription(fixDescription(getValueOrDefault(jsonTask.get("Description"), "")));
addLink(story, jsonTask.get("_ref").getAsString(), RALLY_OBJECT_URL_REL);
addLink(task, jsonTask.get("_ref").getAsString(), RALLY_OBJECT_URL_REL);
addLink(task, storyLink);
taskList.getTask().add(task);
}
}
}
} finally {
NDC.pop();
restApi.close();
}
return taskList;
}
/**
* Set the new configuration after a reload.
*
* @param serverConfigurationCopy
*/
public synchronized void setNextConfiguration(SubnodeConfiguration serverConfigurationCopy) {
// Must be synchronized because the attribute is accessed from different threads
NDC.push(getServerDesc());
try {
EventLog.log("evt.configReloadScheduled", this.getClass());
nextConfig = serverConfigurationCopy;
} finally {
NDC.pop();
}
}
/** Test the no-argument {@link Scheduler#start()} method. */
public void testStart() {
NDC.push("testStart");
try {
Scheduler s = new Scheduler();
s.start();
} finally {
NDC.pop();
}
}
/**
* Called synchronously when the daemon receives a new request.
*
* @param request
*/
private void requestReceived(final DaemonRequest request) {
if (!isEnabled()) {
return;
}
try {
NDC.push(request.getWorkPacket().getTaskId().toString());
requestCount.incrementAndGet();
sendResponse(request, new DaemonProgressMessage(DaemonProgress.RequestEnqueued), false);
processRequest(request);
} finally {
NDC.pop();
}
}
public void testExisting() throws IOException, InterruptedException {
NDC.push("testExisting");
try {
File f = File.createTempFile("counter", "");
f.deleteOnExit();
PrintWriter pw = new PrintWriter(new FileWriter(f));
pw.println("# comment");
pw.println("threshold=100");
pw.println("current=0");
pw.close();
FileUsageCounter counter =
new FileUsageCounter("name", new TimeBasedUsage(), createTarget(), f);
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
Thread.sleep(25);
// This will cause a debug message
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
logger.debug("Consumed: " + counter.getUsageRelative());
Thread.sleep(25);
// This will cause an info message
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
Thread.sleep(30);
// This will cause a warning message
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
Thread.sleep(30);
// This *will* cause an alert (error message)
counter.consume(new DataSample<Double>("source", "signature", 1d, null));
logger.debug("Consumed: " + counter.getUsageRelative());
} finally {
NDC.pop();
}
}
/** Pushes a UUID into the Log4J NDC for request tracking and debugging. */
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws ServletException, IOException {
String requestId = UUID.randomUUID().toString();
request.setAttribute(ATTRIBUTE_REQUEST_ID, requestId);
NDC.push(requestId);
// Execute the rest of the filters in the chain and then whatever Servlet is bound to the
// current request URI
chain.doFilter(request, response);
// cleanup -- remove the NDC for the current thread
NDC.remove();
}
/** Remove the appender and context from the NDC */
private void resetNDCLogging() {
if (ndcSet) {
ndcAppender.close();
Logger.getRootLogger().removeAppender(ndcAppender);
NDC.pop();
}
}
public static CallContext unregister() {
CallContext context = s_currentContext.get();
if (context == null) {
return null;
}
s_currentContext.remove();
if (s_logger.isTraceEnabled()) {
s_logger.trace("Unregistered: " + context);
}
String contextId = context.getContextId();
String sessionIdOnStack = null;
String sessionIdPushedToNDC = "ctx-" + UuidUtils.first(contextId);
while ((sessionIdOnStack = NDC.pop()) != null) {
if (sessionIdPushedToNDC.equals(sessionIdOnStack)) {
break;
}
if (s_logger.isTraceEnabled()) {
s_logger.trace("Popping from NDC: " + contextId);
}
}
Stack<CallContext> stack = s_currentContextStack.get();
stack.pop();
if (!stack.isEmpty()) {
s_currentContext.set(stack.peek());
}
return context;
}
/**
* response set to bad_request for non-existent tickets 200/OK for open tickets 201/CREATED for
* successfully finished tickets 500/INTERNAL ERROR for requests that errored out 404/NOT_FOUND
*
* @param ticket
* @param response
* @return ticket object
*/
@GET
@Path("{ticket}")
@Produces("application/json")
public Response getStatus(
@PathParam("ticket") String ticketId, @Context HttpServletResponse response) {
try {
NDC.push("T" + ticketId);
LOG.info("Ticket Request ID: " + ticketId);
Ticket ticket = tm.getTicket(ticketId);
ResponseBuilder rb;
if (ticket != null) {
switch (ticket.getStatus()) {
case Ticket.STATUS_OPEN:
rb = Response.status(Status.OK).header("Retry-After", "120").entity(ticket);
break;
case Ticket.STATUS_FINISHED:
// finished case, return 201, response body set to stored manifest
return Response.status(Status.CREATED).entity(ticket).build();
case Ticket.STATUS_ERROR:
rb = Response.status(Status.INTERNAL_SERVER_ERROR).entity(ticket);
break;
default:
LOG.error("Unknown response case: " + ticket.getStatusMessage());
rb = Response.status(Status.INTERNAL_SERVER_ERROR).entity(ticket);
}
} else {
LOG.debug("Returning not-found, ticket ID unknown: " + ticketId);
rb = Response.status(Status.NOT_FOUND);
rb.type(MediaType.TEXT_PLAIN_TYPE);
rb.entity("No such ticket " + ticketId);
}
return rb.build();
} finally {
LOG.info("Completed Ticket Request ID: " + ticketId);
NDC.pop();
}
}
@Override
public void onTestStart(ITestResult result) {
logLine();
logger.info(
String.format(
"Testing going to start for: %s.%s %s",
result.getTestClass().getName(),
result.getName(),
Arrays.toString(result.getParameters())));
NDC.push(result.getName());
}
private void logEndOfTest(ITestResult result, String outcome) {
logger.info(
String.format(
"Testing going to end for: %s.%s(%s) %s",
result.getTestClass().getName(),
result.getName(),
Arrays.toString(result.getParameters()),
outcome));
NDC.pop();
logLine();
}
public void testAllGood() {
StatusParser p = new StatusParser();
for (int offset = 0; offset < inputs.length; offset++) {
NDC.push("[" + offset + "]");
try {
ZoneStatus status = p.parse(inputs[offset]);
logger.info("Status: " + status);
assertEquals("Failed to parse '" + inputs[offset], outputs[offset], status);
} finally {
NDC.pop();
}
}
}
public void testExecute(int id, final Map<Thermostat, SortedMap<Period, ZoneStatus>> schedule) {
NDC.push("testExecute:" + id);
try {
ScheduleUpdater u =
new ScheduleUpdater() {
@Override
public Map<Thermostat, SortedMap<Period, ZoneStatus>> update() throws IOException {
return schedule;
}
};
Scheduler s = new Scheduler(u);
s.setScheduleGranularity(50);
// This instance will run until the JVM is gone or Scheduler#ScheduledExecutorService is
// otherwise stopped
s.start(0);
Thread.sleep(50);
s.stop();
} catch (InterruptedException ex) {
throw new IllegalStateException(ex);
} finally {
NDC.pop();
}
}
/** @return Time for 00:00 of current week's Monday. */
private Calendar getMondayStart() {
NDC.push("getMondayStart");
try {
Calendar cal = new GregorianCalendar();
logger.debug("calendar: " + cal);
cal.set(Calendar.DAY_OF_WEEK, Calendar.MONDAY);
cal.set(Calendar.HOUR_OF_DAY, 0);
cal.set(Calendar.MINUTE, 0);
cal.set(Calendar.SECOND, 0);
cal.set(Calendar.MILLISECOND, 0);
logger.debug("calendar: " + cal);
return cal;
} finally {
NDC.pop();
}
}
@Test
public void testSimpleInfo() throws Exception {
Logger logger = Logger.getLogger(getClass());
NDC.clear();
NDC.push("ndc message");
logger.info(LOG_MESSAGE);
NDC.clear();
assertEquals(1, GelfTestSender.getMessages().size());
GelfMessage gelfMessage = GelfTestSender.getMessages().get(0);
assertEquals(EXPECTED_LOG_MESSAGE, gelfMessage.getFullMessage());
assertEquals(EXPECTED_LOG_MESSAGE, gelfMessage.getShortMessage());
assertEquals("ndc message", gelfMessage.getField("NDC"));
assertNotNull(gelfMessage.getField("MyTime"));
assertEquals("6", gelfMessage.getLevel());
assertEquals(8192, gelfMessage.getMaximumMessageSize());
assertEquals(GelfMessage.GELF_VERSION_1_1, gelfMessage.getVersion());
// this is because of default-logstash-fields.properties
assertEquals("INFO", gelfMessage.getAdditonalFields().get("MySeverity"));
}
/** Add a new appender and context to the NDC for this execution of the step */
private void setupNDCLogging() {
String nestedDiagnosticContext = getNestedDiagnosticContext();
logFileName = getLogFileName(nestedDiagnosticContext);
ndcAppender = null;
ndcSet = false;
try {
ndcAppender = new FileAppender(BatchLogger.getLogFileAppenderLayout(), logFileName);
ndcAppender.addFilter(new NDCFilter(nestedDiagnosticContext));
Logger.getRootLogger().addAppender(ndcAppender);
NDC.push(nestedDiagnosticContext);
ndcSet = true;
} catch (Exception ex) {
LOG.warn("Could not initialize custom logging for step: " + step.getName(), ex);
}
}
/**
* This method should only be called if you can propagate the context id from another CallContext.
*
* @param callingUser calling user
* @param callingAccount calling account
* @param contextId context id propagated from another call context
* @return CallContext
*/
public static CallContext register(User callingUser, Account callingAccount, String contextId) {
/*
Unit tests will have multiple times of setup/tear-down call to this, remove assertions to all unit test to run
assert s_currentContext.get() == null : "There's a context already so what does this new register context mean? " + s_currentContext.get().toString();
if (s_currentContext.get() != null) { // FIXME: This should be removed soon. I added this check only to surface all the places that have this problem.
throw new CloudRuntimeException("There's a context already so what does this new register context mean? " + s_currentContext.get().toString());
}
*/
CallContext callingContext = new CallContext(callingUser, callingAccount, contextId);
s_currentContext.set(callingContext);
NDC.push("ctx-" + UuidUtils.first(contextId));
if (s_logger.isTraceEnabled()) {
s_logger.trace("Registered: " + callingContext);
}
s_currentContextStack.get().push(callingContext);
return callingContext;
}
/** Freigabe des aktuellen Debug - Contextes ( Log4J ). */
public void unsetDebugContext() {
NDC.pop();
NDC.remove();
}
/**
* Setzen des aktuellen Debug - Contextes ( Log4J ).
*
* @param theRemoteUser das aktuell angemeldete Benutzer
*/
public void setDebugContext(String theRemoteUser) {
NDC.push(theRemoteUser);
}
