Skip to content

Commit

Permalink
Improved logging (#493)
Browse files Browse the repository at this point in the history 
* Adding counting as log statements to determine generated and outgoing packets

* Adding verbose logging to exceptions caught

* updating to create formated string while logging in some cases, fixing braces

* some more fixes to formated string

* moving stack traces to sdk logger

* removing missing print stack traces and adding them to logger

* fixing some more similar issues

* making some more similar changes at missed places
  • Loading branch information
@dhaval24
dhaval24 authored Dec 13, 2017
1 parent 98d6e1b commit f4c3059
Show file tree
Hide file tree
Showing 37 changed files with 200 additions and 51 deletions.
7 changes: 7 additions & 0 deletions core/src/main/java/com/microsoft/applicationinsights/TelemetryClient.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@

import java.util.Date;
import java.util.Map;
import java.util.concurrent.atomic.AtomicLong;

import com.microsoft.applicationinsights.common.CommonUtils;
import com.microsoft.applicationinsights.extensibility.ContextInitializer;
Expand Down Expand Up @@ -58,6 +59,7 @@ public TelemetryChannel fetch() {
private static final Object TELEMETRY_STOP_HOOK_LOCK = new Object();
private static final Object TELEMETRY_CONTEXT_LOCK = new Object();

private static AtomicLong generateCounter = new AtomicLong(0);
/**
* Initializes a new instance of the TelemetryClient class. Send telemetry with the specified configuration.
* @param configuration The configuration this instance will work with.
Expand Down Expand Up @@ -385,6 +387,11 @@ public void trackPageView(PageViewTelemetry telemetry) {
* @param telemetry The {@link com.microsoft.applicationinsights.telemetry.Telemetry} instance.
*/
public void track(Telemetry telemetry) {

if (generateCounter.incrementAndGet() % 10000 == 0) {
InternalLogger.INSTANCE.info("Total events generated till now %d", generateCounter.get());
}

if (telemetry == null) {
throw new IllegalArgumentException("telemetry item cannot be null");
}
Expand Down
57 changes: 39 additions & 18 deletions ...m/microsoft/applicationinsights/channel/concrete/inprocess/InProcessTelemetryChannel.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,10 +22,12 @@
package com.microsoft.applicationinsights.channel.concrete.inprocess;

import java.io.IOException;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.net.URI;
import java.util.Map;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;

import com.microsoft.applicationinsights.internal.channel.TelemetriesTransmitter;
import com.microsoft.applicationinsights.channel.TelemetrySampler;
Expand All @@ -42,25 +44,26 @@

import com.google.common.base.Strings;
import com.google.common.base.Preconditions;
import org.apache.commons.lang3.exception.ExceptionUtils;

/**
* An implementation of {@link com.microsoft.applicationinsights.channel.TelemetryChannel}
*
* <p>
* The channel holds two main entities:
*
* <p>
* A buffer for incoming {@link com.microsoft.applicationinsights.telemetry.Telemetry} instances
* A transmitter
*
* <p>
* The buffer is stores incoming telemetry instances. Every new buffer starts a timer.
* When the timer expires, or when the buffer is 'full' (whichever happens first), the
* transmitter will pick up that buffer and will handle its sending to the server. For example,
* a transmitter will be responsible for compressing, sending and activate a policy in case of failures.
*
* <p>
* The model here is:
*
* <p>
* Use application threads to populate the buffer
* Use channel's threads to send buffers to the server
*
* <p>
* Created by gupele on 12/17/2014.
*/
public final class InProcessTelemetryChannel implements TelemetryChannel {
Expand Down Expand Up @@ -90,6 +93,8 @@ public final class InProcessTelemetryChannel implements TelemetryChannel {
private TelemetryBuffer telemetryBuffer;
private TelemetrySampler telemetrySampler;

private static AtomicLong itemsSent = new AtomicLong(0);

public InProcessTelemetryChannel() {
boolean developerMode = false;
try {
Expand All @@ -99,6 +104,8 @@ public InProcessTelemetryChannel() {
}
} catch (Throwable t) {
developerMode = false;
InternalLogger.INSTANCE.trace("%s generated exception in parsing," +
"stack trace is %s", DEVELOPER_MODE_SYSTEM_PROPRETY_NAME, ExceptionUtils.getStackTrace(t));
}
initialize(null,
null,
Expand All @@ -110,25 +117,27 @@ public InProcessTelemetryChannel() {

/**
* Ctor
* @param endpointAddress Must be empty string or a valid uri, else an exception will be thrown
* @param developerMode True will behave in a 'non-production' mode to ease the debugging
*
* @param endpointAddress Must be empty string or a valid uri, else an exception will be thrown
* @param developerMode True will behave in a 'non-production' mode to ease the debugging
* @param maxTelemetryBufferCapacity Max number of Telemetries we keep in the buffer, when reached we will send the buffer
* Note, value should be between TRANSMIT_BUFFER_MIN_TIMEOUT_IN_MILLIS and TRANSMIT_BUFFER_MAX_TIMEOUT_IN_MILLIS inclusive
* @param sendIntervalInMillis The maximum number of milliseconds to wait before we send the buffer
* Note, value should be between MIN_MAX_TELEMETRY_BUFFER_CAPACITY and MAX_MAX_TELEMETRY_BUFFER_CAPACITY inclusive
* Note, value should be between TRANSMIT_BUFFER_MIN_TIMEOUT_IN_MILLIS and TRANSMIT_BUFFER_MAX_TIMEOUT_IN_MILLIS inclusive
* @param sendIntervalInMillis The maximum number of milliseconds to wait before we send the buffer
* Note, value should be between MIN_MAX_TELEMETRY_BUFFER_CAPACITY and MAX_MAX_TELEMETRY_BUFFER_CAPACITY inclusive
*/
public InProcessTelemetryChannel(String endpointAddress, boolean developerMode, int maxTelemetryBufferCapacity, int sendIntervalInMillis) {
initialize(endpointAddress,
null,
developerMode,
createDefaultMaxTelemetryBufferCapacityEnforcer(maxTelemetryBufferCapacity),
createDefaultSendIntervalInSecondsEnforcer(sendIntervalInMillis),
true);
null,
developerMode,
createDefaultMaxTelemetryBufferCapacityEnforcer(maxTelemetryBufferCapacity),
createDefaultSendIntervalInSecondsEnforcer(sendIntervalInMillis),
true);
}

/**
* This Ctor will query the 'namesAndValues' map for data to initialize itself
* It will ignore data that is not of its interest, this Ctor is useful for building an instance from configuration
*
* @param namesAndValues - The data passed as name and value pairs
*/
public InProcessTelemetryChannel(Map<String, String> namesAndValues) {
Expand Down Expand Up @@ -157,7 +166,7 @@ public InProcessTelemetryChannel(Map<String, String> namesAndValues) {
}

/**
* Gets value indicating whether this channel is in developer mode.
* Gets value indicating whether this channel is in developer mode.
*/
@Override
public boolean isDeveloperMode() {
Expand All @@ -166,6 +175,7 @@ public boolean isDeveloperMode() {

/**
* Sets value indicating whether this channel is in developer mode.
*
* @param developerMode True or false
*/
@Override
Expand All @@ -179,7 +189,7 @@ public void setDeveloperMode(boolean developerMode) {
}

/**
* Sends a Telemetry instance through the channel.
* Sends a Telemetry instance through the channel.
*/
@Override
public void send(Telemetry telemetry) {
Expand All @@ -204,8 +214,13 @@ public void send(Telemetry telemetry) {
String asJson = writer.toString();
telemetryBuffer.add(asJson);
telemetry.reset();
if (itemsSent.incrementAndGet() % 10000 == 0) {
InternalLogger.INSTANCE.info("items sent till now %d", itemsSent.get());
}

} catch (IOException e) {
InternalLogger.INSTANCE.error("Failed to serialize Telemetry");
InternalLogger.INSTANCE.trace("Stack trace is %s", ExceptionUtils.getStackTrace(e));
return;
}

Expand All @@ -227,6 +242,8 @@ public synchronized void stop(long timeout, TimeUnit timeUnit) {
telemetriesTransmitter.stop(timeout, timeUnit);
stopped = true;
} catch (Throwable t) {
InternalLogger.INSTANCE.error("Exception generated while stopping telemetry transmitter");
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
}
}

Expand All @@ -241,6 +258,7 @@ public void flush() {
/**
* Sets an optional Sampler that can sample out telemetries
* Currently, we don't allow to replace a valid telemtry sampler.
*
* @param telemetrySampler - The sampler
*/
@Override
Expand All @@ -252,6 +270,7 @@ public void setSampler(TelemetrySampler telemetrySampler) {

/**
* Sets the buffer size
*
* @param maxTelemetriesInBatch should be between MIN_MAX_TELEMETRY_BUFFER_CAPACITY
* and MAX_MAX_TELEMETRY_BUFFER_CAPACITY inclusive
* if the number is lower than the minimum then the minimum will be used
Expand All @@ -263,6 +282,7 @@ public void setMaxTelemetriesInBatch(int maxTelemetriesInBatch) {

/**
* Sets the time tow wait before flushing the internal buffer
*
* @param transmitBufferTimeoutInSeconds should be between MIN_FLUSH_BUFFER_TIMEOUT_IN_SECONDS
* and MAX_FLUSH_BUFFER_TIMEOUT_IN_SECONDS inclusive
* if the number is lower than the minimum then the minimum will be used
Expand Down Expand Up @@ -297,6 +317,7 @@ private synchronized void initialize(String endpointAddress,
/**
* The method will throw IllegalArgumentException if the endpointAddress is not a valid uri
* Please note that a null or empty string is valid as far as the class is concerned and thus considered valid
*
* @param endpointAddress
*/
private void makeSureEndpointAddressIsValid(String endpointAddress) {
Expand Down
4 changes: 4 additions & 0 deletions core/src/main/java/com/microsoft/applicationinsights/common/CommonUtils.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,9 @@

package com.microsoft.applicationinsights.common;

import com.microsoft.applicationinsights.internal.logger.InternalLogger;
import org.apache.commons.lang3.exception.ExceptionUtils;

import java.net.InetAddress;
import java.net.UnknownHostException;

Expand All @@ -41,6 +44,7 @@ public static String getHostName(){
}
catch (UnknownHostException ex) {
// optional parameter. do nothing if unresolvable
InternalLogger.INSTANCE.trace("Unresolvable host error. Stack trace generated is %s", ExceptionUtils.getStackTrace(ex));
return null;
}
}
Expand Down
4 changes: 4 additions & 0 deletions ...ft/applicationinsights/extensibility/initializer/docker/internal/DockerContextPoller.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@

import java.io.File;
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
import org.apache.commons.lang3.exception.ExceptionUtils;

/**
* Created by yonisha on 7/29/2015.
Expand Down Expand Up @@ -59,6 +60,8 @@ public void run() {

continue;
} catch (InterruptedException e) {
InternalLogger.INSTANCE.error("Error while executing docker context poller");
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
}
}
}
Expand All @@ -69,6 +72,7 @@ public void run() {
InternalLogger.INSTANCE.info("Docker context file has been deserialized successfully");
} catch (Exception e) {
InternalLogger.INSTANCE.error("Docker context file failed to be parsed with error: " + e.getMessage());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
}

InternalLogger.INSTANCE.info("Docker context poller finished polling for context file.");
Expand Down
2 changes: 2 additions & 0 deletions .../java/com/microsoft/applicationinsights/internal/annotation/AnnotationPackageScanner.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@

import com.microsoft.applicationinsights.internal.logger.InternalLogger;
import eu.infomas.annotation.AnnotationDetector;
import org.apache.commons.lang3.exception.ExceptionUtils;

import java.lang.annotation.Annotation;
import java.util.ArrayList;
Expand Down Expand Up @@ -57,6 +58,7 @@ public void reportTypeAnnotation(Class<? extends Annotation> annotation, String
annotationDetector.detect(packageToScan);
} catch (Throwable t) {
InternalLogger.INSTANCE.error("Failed to scan packages '%s': exception: '%s'", packageToScan, t.getMessage());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
}

return performanceModuleNames;
Expand Down
31 changes: 14 additions & 17 deletions .../com/microsoft/applicationinsights/internal/channel/common/TransmissionNetworkOutput.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,11 +21,23 @@

package com.microsoft.applicationinsights.internal.channel.common;

import com.google.common.base.Preconditions;
import com.google.common.base.Strings;
import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
import com.microsoft.applicationinsights.internal.channel.TransmissionOutput;
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
import org.apache.http.Header;
import org.apache.http.HttpEntity;
import org.apache.http.HttpResponse;
import org.apache.http.HttpStatus;
import org.apache.http.client.methods.HttpPost;
import org.apache.http.conn.ConnectionPoolTimeoutException;
import org.apache.http.entity.ByteArrayEntity;

import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.net.ConnectException;
import java.net.SocketException;
import java.net.UnknownHostException;
import java.text.DateFormat;
Expand All @@ -35,22 +47,6 @@
import java.util.TimeZone;
import java.util.concurrent.TimeUnit;

import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
import com.microsoft.applicationinsights.internal.channel.TransmissionOutput;
import com.microsoft.applicationinsights.internal.logger.InternalLogger;

import org.apache.http.Header;
import org.apache.http.HttpEntity;
import org.apache.http.HttpResponse;
import org.apache.http.HttpStatus;
import org.apache.http.client.methods.HttpPost;
import org.apache.http.conn.ConnectTimeoutException;
import org.apache.http.conn.ConnectionPoolTimeoutException;
import org.apache.http.entity.ByteArrayEntity;

import com.google.common.base.Preconditions;
import com.google.common.base.Strings;

/**
* The class is responsible for the actual sending of {@link com.microsoft.applicationinsights.internal.channel.common.Transmission}
*
Expand Down Expand Up @@ -185,6 +181,7 @@ public boolean send(Transmission transmission) {
httpClient.dispose(response);
// backoff before trying again
if (shouldBackoff) {
InternalLogger.INSTANCE.trace("Backing off for %s seconds", DEFAULT_BACKOFF_TIME_SECONDS);
transmissionPolicyManager.suspendInSeconds(TransmissionPolicy.BLOCKED_BUT_CAN_BE_PERSISTED, DEFAULT_BACKOFF_TIME_SECONDS);
}
}
Expand Down
17 changes: 16 additions & 1 deletion .../main/java/com/microsoft/applicationinsights/internal/channel/common/TransmitterImpl.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,10 +31,12 @@
import com.microsoft.applicationinsights.internal.channel.TelemetrySerializer;
import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
import com.microsoft.applicationinsights.internal.channel.TransmissionsLoader;
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
import com.microsoft.applicationinsights.internal.util.ThreadPoolUtils;

import com.google.common.base.Optional;
import com.google.common.base.Preconditions;
import org.apache.commons.lang3.exception.ExceptionUtils;

/**
* The default implementation of the {@link TelemetriesTransmitter}
Expand Down Expand Up @@ -162,8 +164,9 @@ public void run() {
semaphore.release();
command.run();
} catch (Exception e) {
e.printStackTrace();
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
} catch (Throwable t) {
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
} finally {
}
}
Expand All @@ -172,8 +175,12 @@ public void run() {
return true;
} catch (Exception e) {
semaphore.release();
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetriesFetcher.fetch().size());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
} catch (Throwable t) {
semaphore.release();
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetriesFetcher.fetch().size());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
}

return true;
Expand All @@ -195,7 +202,11 @@ public void run() {
semaphore.release();
command.run();
} catch (Exception e) {
InternalLogger.INSTANCE.error("exception in runnable sendNow()");
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
} catch (Throwable t) {
InternalLogger.INSTANCE.error("exception while executing thread in sendNow()");
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
} finally {
}
}
Expand All @@ -204,8 +215,12 @@ public void run() {
return true;
} catch (Exception e) {
semaphore.release();
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetries.size());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
} catch (Throwable t) {
semaphore.release();
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetries.size());
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
}

return false;
Expand Down
Loading

0 comments on commit f4c3059

Please sign in to comment.