Skip to content

Commit f4c3059

Browse files
dhaval24dhaval24
authored
Improved logging (#493)
* 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
1 parent 98d6e1b commit f4c3059

37 files changed

Lines changed: 200 additions & 51 deletions

File tree

‎core/src/main/java/com/microsoft/applicationinsights/TelemetryClient.java‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323

2424
import java.util.Date;
2525
import java.util.Map;
26+
import java.util.concurrent.atomic.AtomicLong;
2627

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

62+
private static AtomicLong generateCounter = new AtomicLong(0);
6163
/**
6264
* Initializes a new instance of the TelemetryClient class. Send telemetry with the specified configuration.
6365
* @param configuration The configuration this instance will work with.
@@ -385,6 +387,11 @@ public void trackPageView(PageViewTelemetry telemetry) {
385387
* @param telemetry The {@link com.microsoft.applicationinsights.telemetry.Telemetry} instance.
386388
*/
387389
public void track(Telemetry telemetry) {
390+
391+
if (generateCounter.incrementAndGet() % 10000 == 0) {
392+
InternalLogger.INSTANCE.info("Total events generated till now %d", generateCounter.get());
393+
}
394+
388395
if (telemetry == null) {
389396
throw new IllegalArgumentException("telemetry item cannot be null");
390397
}

‎core/src/main/java/com/microsoft/applicationinsights/channel/concrete/inprocess/InProcessTelemetryChannel.java‎

Lines changed: 39 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,12 @@
2222
package com.microsoft.applicationinsights.channel.concrete.inprocess;
2323

2424
import java.io.IOException;
25+
import java.io.PrintWriter;
2526
import java.io.StringWriter;
2627
import java.net.URI;
2728
import java.util.Map;
2829
import java.util.concurrent.TimeUnit;
30+
import java.util.concurrent.atomic.AtomicLong;
2931

3032
import com.microsoft.applicationinsights.internal.channel.TelemetriesTransmitter;
3133
import com.microsoft.applicationinsights.channel.TelemetrySampler;
@@ -42,25 +44,26 @@
4244

4345
import com.google.common.base.Strings;
4446
import com.google.common.base.Preconditions;
47+
import org.apache.commons.lang3.exception.ExceptionUtils;
4548

4649
/**
4750
* An implementation of {@link com.microsoft.applicationinsights.channel.TelemetryChannel}
48-
*
51+
* <p>
4952
* The channel holds two main entities:
50-
*
53+
* <p>
5154
* A buffer for incoming {@link com.microsoft.applicationinsights.telemetry.Telemetry} instances
5255
* A transmitter
53-
*
56+
* <p>
5457
* The buffer is stores incoming telemetry instances. Every new buffer starts a timer.
5558
* When the timer expires, or when the buffer is 'full' (whichever happens first), the
5659
* transmitter will pick up that buffer and will handle its sending to the server. For example,
5760
* a transmitter will be responsible for compressing, sending and activate a policy in case of failures.
58-
*
61+
* <p>
5962
* The model here is:
60-
*
63+
* <p>
6164
* Use application threads to populate the buffer
6265
* Use channel's threads to send buffers to the server
63-
*
66+
* <p>
6467
* Created by gupele on 12/17/2014.
6568
*/
6669
public final class InProcessTelemetryChannel implements TelemetryChannel {
@@ -90,6 +93,8 @@ public final class InProcessTelemetryChannel implements TelemetryChannel {
9093
private TelemetryBuffer telemetryBuffer;
9194
private TelemetrySampler telemetrySampler;
9295

96+
private static AtomicLong itemsSent = new AtomicLong(0);
97+
9398
public InProcessTelemetryChannel() {
9499
boolean developerMode = false;
95100
try {
@@ -99,6 +104,8 @@ public InProcessTelemetryChannel() {
99104
}
100105
} catch (Throwable t) {
101106
developerMode = false;
107+
InternalLogger.INSTANCE.trace("%s generated exception in parsing," +
108+
"stack trace is %s", DEVELOPER_MODE_SYSTEM_PROPRETY_NAME, ExceptionUtils.getStackTrace(t));
102109
}
103110
initialize(null,
104111
null,
@@ -110,25 +117,27 @@ public InProcessTelemetryChannel() {
110117

111118
/**
112119
* Ctor
113-
* @param endpointAddress Must be empty string or a valid uri, else an exception will be thrown
114-
* @param developerMode True will behave in a 'non-production' mode to ease the debugging
120+
*
121+
* @param endpointAddress Must be empty string or a valid uri, else an exception will be thrown
122+
* @param developerMode True will behave in a 'non-production' mode to ease the debugging
115123
* @param maxTelemetryBufferCapacity Max number of Telemetries we keep in the buffer, when reached we will send the buffer
116-
* Note, value should be between TRANSMIT_BUFFER_MIN_TIMEOUT_IN_MILLIS and TRANSMIT_BUFFER_MAX_TIMEOUT_IN_MILLIS inclusive
117-
* @param sendIntervalInMillis The maximum number of milliseconds to wait before we send the buffer
118-
* Note, value should be between MIN_MAX_TELEMETRY_BUFFER_CAPACITY and MAX_MAX_TELEMETRY_BUFFER_CAPACITY inclusive
124+
* Note, value should be between TRANSMIT_BUFFER_MIN_TIMEOUT_IN_MILLIS and TRANSMIT_BUFFER_MAX_TIMEOUT_IN_MILLIS inclusive
125+
* @param sendIntervalInMillis The maximum number of milliseconds to wait before we send the buffer
126+
* Note, value should be between MIN_MAX_TELEMETRY_BUFFER_CAPACITY and MAX_MAX_TELEMETRY_BUFFER_CAPACITY inclusive
119127
*/
120128
public InProcessTelemetryChannel(String endpointAddress, boolean developerMode, int maxTelemetryBufferCapacity, int sendIntervalInMillis) {
121129
initialize(endpointAddress,
122-
null,
123-
developerMode,
124-
createDefaultMaxTelemetryBufferCapacityEnforcer(maxTelemetryBufferCapacity),
125-
createDefaultSendIntervalInSecondsEnforcer(sendIntervalInMillis),
126-
true);
130+
null,
131+
developerMode,
132+
createDefaultMaxTelemetryBufferCapacityEnforcer(maxTelemetryBufferCapacity),
133+
createDefaultSendIntervalInSecondsEnforcer(sendIntervalInMillis),
134+
true);
127135
}
128136

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

159168
/**
160-
* Gets value indicating whether this channel is in developer mode.
169+
* Gets value indicating whether this channel is in developer mode.
161170
*/
162171
@Override
163172
public boolean isDeveloperMode() {
@@ -166,6 +175,7 @@ public boolean isDeveloperMode() {
166175

167176
/**
168177
* Sets value indicating whether this channel is in developer mode.
178+
*
169179
* @param developerMode True or false
170180
*/
171181
@Override
@@ -179,7 +189,7 @@ public void setDeveloperMode(boolean developerMode) {
179189
}
180190

181191
/**
182-
* Sends a Telemetry instance through the channel.
192+
* Sends a Telemetry instance through the channel.
183193
*/
184194
@Override
185195
public void send(Telemetry telemetry) {
@@ -204,8 +214,13 @@ public void send(Telemetry telemetry) {
204214
String asJson = writer.toString();
205215
telemetryBuffer.add(asJson);
206216
telemetry.reset();
217+
if (itemsSent.incrementAndGet() % 10000 == 0) {
218+
InternalLogger.INSTANCE.info("items sent till now %d", itemsSent.get());
219+
}
220+
207221
} catch (IOException e) {
208222
InternalLogger.INSTANCE.error("Failed to serialize Telemetry");
223+
InternalLogger.INSTANCE.trace("Stack trace is %s", ExceptionUtils.getStackTrace(e));
209224
return;
210225
}
211226

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

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

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

264283
/**
265284
* Sets the time tow wait before flushing the internal buffer
285+
*
266286
* @param transmitBufferTimeoutInSeconds should be between MIN_FLUSH_BUFFER_TIMEOUT_IN_SECONDS
267287
* and MAX_FLUSH_BUFFER_TIMEOUT_IN_SECONDS inclusive
268288
* if the number is lower than the minimum then the minimum will be used
@@ -297,6 +317,7 @@ private synchronized void initialize(String endpointAddress,
297317
/**
298318
* The method will throw IllegalArgumentException if the endpointAddress is not a valid uri
299319
* Please note that a null or empty string is valid as far as the class is concerned and thus considered valid
320+
*
300321
* @param endpointAddress
301322
*/
302323
private void makeSureEndpointAddressIsValid(String endpointAddress) {

‎core/src/main/java/com/microsoft/applicationinsights/common/CommonUtils.java‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,9 @@
2121

2222
package com.microsoft.applicationinsights.common;
2323

24+
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
25+
import org.apache.commons.lang3.exception.ExceptionUtils;
26+
2427
import java.net.InetAddress;
2528
import java.net.UnknownHostException;
2629

@@ -41,6 +44,7 @@ public static String getHostName(){
4144
}
4245
catch (UnknownHostException ex) {
4346
// optional parameter. do nothing if unresolvable
47+
InternalLogger.INSTANCE.trace("Unresolvable host error. Stack trace generated is %s", ExceptionUtils.getStackTrace(ex));
4448
return null;
4549
}
4650
}

‎core/src/main/java/com/microsoft/applicationinsights/extensibility/initializer/docker/internal/DockerContextPoller.java‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323

2424
import java.io.File;
2525
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
26+
import org.apache.commons.lang3.exception.ExceptionUtils;
2627

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

6061
continue;
6162
} catch (InterruptedException e) {
63+
InternalLogger.INSTANCE.error("Error while executing docker context poller");
64+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
6265
}
6366
}
6467
}
@@ -69,6 +72,7 @@ public void run() {
6972
InternalLogger.INSTANCE.info("Docker context file has been deserialized successfully");
7073
} catch (Exception e) {
7174
InternalLogger.INSTANCE.error("Docker context file failed to be parsed with error: " + e.getMessage());
75+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
7276
}
7377

7478
InternalLogger.INSTANCE.info("Docker context poller finished polling for context file.");

‎core/src/main/java/com/microsoft/applicationinsights/internal/annotation/AnnotationPackageScanner.java‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323

2424
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
2525
import eu.infomas.annotation.AnnotationDetector;
26+
import org.apache.commons.lang3.exception.ExceptionUtils;
2627

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

6264
return performanceModuleNames;

‎core/src/main/java/com/microsoft/applicationinsights/internal/channel/common/TransmissionNetworkOutput.java‎

Lines changed: 14 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -21,11 +21,23 @@
2121

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

24+
import com.google.common.base.Preconditions;
25+
import com.google.common.base.Strings;
26+
import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
27+
import com.microsoft.applicationinsights.internal.channel.TransmissionOutput;
28+
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
29+
import org.apache.http.Header;
30+
import org.apache.http.HttpEntity;
31+
import org.apache.http.HttpResponse;
32+
import org.apache.http.HttpStatus;
33+
import org.apache.http.client.methods.HttpPost;
34+
import org.apache.http.conn.ConnectionPoolTimeoutException;
35+
import org.apache.http.entity.ByteArrayEntity;
36+
2437
import java.io.BufferedReader;
2538
import java.io.IOException;
2639
import java.io.InputStream;
2740
import java.io.InputStreamReader;
28-
import java.net.ConnectException;
2941
import java.net.SocketException;
3042
import java.net.UnknownHostException;
3143
import java.text.DateFormat;
@@ -35,22 +47,6 @@
3547
import java.util.TimeZone;
3648
import java.util.concurrent.TimeUnit;
3749

38-
import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
39-
import com.microsoft.applicationinsights.internal.channel.TransmissionOutput;
40-
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
41-
42-
import org.apache.http.Header;
43-
import org.apache.http.HttpEntity;
44-
import org.apache.http.HttpResponse;
45-
import org.apache.http.HttpStatus;
46-
import org.apache.http.client.methods.HttpPost;
47-
import org.apache.http.conn.ConnectTimeoutException;
48-
import org.apache.http.conn.ConnectionPoolTimeoutException;
49-
import org.apache.http.entity.ByteArrayEntity;
50-
51-
import com.google.common.base.Preconditions;
52-
import com.google.common.base.Strings;
53-
5450
/**
5551
* The class is responsible for the actual sending of {@link com.microsoft.applicationinsights.internal.channel.common.Transmission}
5652
*
@@ -185,6 +181,7 @@ public boolean send(Transmission transmission) {
185181
httpClient.dispose(response);
186182
// backoff before trying again
187183
if (shouldBackoff) {
184+
InternalLogger.INSTANCE.trace("Backing off for %s seconds", DEFAULT_BACKOFF_TIME_SECONDS);
188185
transmissionPolicyManager.suspendInSeconds(TransmissionPolicy.BLOCKED_BUT_CAN_BE_PERSISTED, DEFAULT_BACKOFF_TIME_SECONDS);
189186
}
190187
}

‎core/src/main/java/com/microsoft/applicationinsights/internal/channel/common/TransmitterImpl.java‎

Lines changed: 16 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,10 +31,12 @@
3131
import com.microsoft.applicationinsights.internal.channel.TelemetrySerializer;
3232
import com.microsoft.applicationinsights.internal.channel.TransmissionDispatcher;
3333
import com.microsoft.applicationinsights.internal.channel.TransmissionsLoader;
34+
import com.microsoft.applicationinsights.internal.logger.InternalLogger;
3435
import com.microsoft.applicationinsights.internal.util.ThreadPoolUtils;
3536

3637
import com.google.common.base.Optional;
3738
import com.google.common.base.Preconditions;
39+
import org.apache.commons.lang3.exception.ExceptionUtils;
3840

3941
/**
4042
* The default implementation of the {@link TelemetriesTransmitter}
@@ -162,8 +164,9 @@ public void run() {
162164
semaphore.release();
163165
command.run();
164166
} catch (Exception e) {
165-
e.printStackTrace();
167+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
166168
} catch (Throwable t) {
169+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
167170
} finally {
168171
}
169172
}
@@ -172,8 +175,12 @@ public void run() {
172175
return true;
173176
} catch (Exception e) {
174177
semaphore.release();
178+
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetriesFetcher.fetch().size());
179+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
175180
} catch (Throwable t) {
176181
semaphore.release();
182+
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetriesFetcher.fetch().size());
183+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
177184
}
178185

179186
return true;
@@ -195,7 +202,11 @@ public void run() {
195202
semaphore.release();
196203
command.run();
197204
} catch (Exception e) {
205+
InternalLogger.INSTANCE.error("exception in runnable sendNow()");
206+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
198207
} catch (Throwable t) {
208+
InternalLogger.INSTANCE.error("exception while executing thread in sendNow()");
209+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
199210
} finally {
200211
}
201212
}
@@ -204,8 +215,12 @@ public void run() {
204215
return true;
205216
} catch (Exception e) {
206217
semaphore.release();
218+
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetries.size());
219+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(e));
207220
} catch (Throwable t) {
208221
semaphore.release();
222+
InternalLogger.INSTANCE.error("Error in scheduledSend of telemetry items failed. %d items were not sent ", telemetries.size());
223+
InternalLogger.INSTANCE.trace("Stack trace generated is %s", ExceptionUtils.getStackTrace(t));
209224
}
210225

211226
return false;

0 commit comments

Comments
 (0)