Skip to content

Commit f0c6e8b

Browse files
swathipilswathipil
authored
[EventHubs] split stress logs (Azure#37235)
* update debug logs to split into different files * add args for log file size/backup count * typo * another typo * consumer typo * timed rotating handler * utc and rotate logs 2x per hour for debug * fix * update logger sb * logging level * fix sb logger process monitor * add to same log file * add threading to log format
1 parent cfb1ad3 commit f0c6e8b

File tree

14 files changed

+824
-417
lines changed

14 files changed

+824
-417
lines changed

‎sdk/eventhub/azure-eventhub/stress/scripts/app_insights_metric.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -85,5 +85,5 @@ def record_error(self, error, extra=None):
8585
self.mmap.measure_int_put(self.error_measure, 1)
8686
self.mmap.record()
8787
self.azure_logger.exception(
88-
"Error happened when running {}: {}. Extra info: {}".format(self.name, repr(error), extra)
88+
"Error happened when running %s: %s. Extra info: %s", self.name, repr(error), extra
8989
)

‎sdk/eventhub/azure-eventhub/stress/scripts/azure_eventhub_consumer_stress_async.py‎

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -99,7 +99,19 @@ def parse_starting_position(args):
9999
debug_level = getattr(logging, args.debug_level.upper(), logging.ERROR)
100100

101101

102-
LOGGER = get_logger(args.log_filename, "stress_receive_async", level=debug_level, print_console=args.print_console)
102+
log_filename = args.log_filename if args.log_filename else "consumer_async"
103+
if args.transport_type == 1:
104+
log_filename += "_ws.log"
105+
else:
106+
log_filename += ".log"
107+
logdir = os.environ.get("DEBUG_SHARE")
108+
logfilepath = f"{logdir}/{log_filename}"
109+
LOGGER = get_logger(
110+
logfilepath,
111+
"stress_receive_async",
112+
level=debug_level,
113+
print_console=args.print_console
114+
)
103115
LOG_PER_COUNT = args.output_interval
104116

105117
start_time = time.perf_counter()

‎sdk/eventhub/azure-eventhub/stress/scripts/azure_eventhub_consumer_stress_sync.py‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -97,8 +97,15 @@ def parse_starting_position(args):
9797
debug_level = getattr(logging, args.debug_level.upper(), logging.ERROR)
9898

9999

100+
log_filename = args.log_filename if args.log_filename else "consumer_sync"
101+
if args.transport_type == 1:
102+
log_filename += "_ws.log"
103+
else:
104+
log_filename += ".log"
105+
logdir = os.environ.get("DEBUG_SHARE")
106+
logfilepath = f"{logdir}/{log_filename}"
100107
LOGGER = get_logger(
101-
args.log_filename,
108+
logfilepath,
102109
"stress_receive_sync",
103110
level=debug_level,
104111
print_console=print_console

‎sdk/eventhub/azure-eventhub/stress/scripts/azure_eventhub_producer_stress.py‎

Lines changed: 31 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@
2525

2626

2727
def handle_exception(error, ignore_send_failure, stress_logger, azure_monitor_metric):
28-
err_msg = "Sync send failed due to error: {}".format(repr(error))
28+
err_msg = "Sync send failed due to error: %s", repr(error)
2929
azure_monitor_metric.record_error(error)
3030
if ignore_send_failure:
3131
stress_logger.warning(err_msg)
@@ -262,8 +262,12 @@ def run(self):
262262

263263
def run_sync(self):
264264
self.debug_level = getattr(logging, self.args.debug_level.upper(), logging.ERROR)
265-
266-
with ProcessMonitor("monitor_{}".format(self.args.log_filename), "producer_stress_sync", print_console=self.args.print_console) as process_monitor:
265+
log_filename = self.args.log_filename if self.args.log_filename else "producer_sync"
266+
if self.args.transport_type == 1:
267+
log_filename += "_ws.log"
268+
else:
269+
log_filename += ".log"
270+
with ProcessMonitor("monitor_{}".format(log_filename), "producer_stress_sync", print_console=self.args.print_console) as process_monitor:
267271
class EventHubProducerClientTest(EventHubProducerClient):
268272
def get_partition_ids(self_inner):
269273
if self.args.partitions != 0:
@@ -272,8 +276,15 @@ def get_partition_ids(self_inner):
272276
return super(EventHubProducerClientTest, self_inner).get_partition_ids()
273277

274278
method_name = self.args.method
275-
logger = get_logger(self.args.log_filename, method_name,
276-
level=self.debug_level, print_console=self.args.print_console)
279+
logdir = os.environ.get("DEBUG_SHARE")
280+
logfilepath = f"{logdir}/{log_filename}"
281+
282+
logger = get_logger(
283+
logfilepath,
284+
method_name,
285+
level=self.debug_level,
286+
print_console=self.args.print_console,
287+
)
277288
test_method = globals()[method_name]
278289
self.running = True
279290

@@ -365,7 +376,12 @@ def run_test_method_parallel(self, test_method, workers, logger, process_monitor
365376

366377
async def run_async(self):
367378
self.debug_level = getattr(logging, self.args.debug_level.upper(), logging.ERROR)
368-
with ProcessMonitor("monitor_{}".format(self.args.log_filename), "producer_stress_async", print_console=self.args.print_console) as process_monitor:
379+
log_filename = self.args.log_filename if self.args.log_filename else "producer_async"
380+
if self.args.transport_type == 1:
381+
log_filename += "_ws.log"
382+
else:
383+
log_filename += ".log"
384+
with ProcessMonitor("monitor_{}".format(log_filename), "producer_stress_async", print_console=self.args.print_console) as process_monitor:
369385
class EventHubProducerClientTestAsync(EventHubProducerClientAsync):
370386
async def get_partition_ids(self_inner):
371387
if self.args.partitions != 0:
@@ -374,8 +390,15 @@ async def get_partition_ids(self_inner):
374390
return await super(EventHubProducerClientTestAsync, self_inner).get_partition_ids()
375391

376392
method_name = self.args.method
377-
logger = get_logger(self.args.log_filename, method_name,
378-
level=self.debug_level, print_console=self.args.print_console)
393+
logdir = os.environ.get("DEBUG_SHARE")
394+
logfilepath = f"{logdir}/{log_filename}"
395+
396+
logger = get_logger(
397+
logfilepath,
398+
method_name,
399+
level=self.debug_level,
400+
print_console=self.args.print_console
401+
)
379402
test_method = globals()[method_name]
380403
self.running = True
381404

‎sdk/eventhub/azure-eventhub/stress/scripts/logger.py‎

Lines changed: 34 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -3,43 +3,65 @@
33
# Licensed under the MIT License. See License.txt in the project root for license information.
44
# --------------------------------------------------------------------------------------------
55

6+
import os
67
import sys
78
import logging
8-
from logging.handlers import RotatingFileHandler
9+
from logging.handlers import TimedRotatingFileHandler
910

1011
from opencensus.ext.azure.log_exporter import AzureLogHandler
1112

1213

13-
def get_base_logger(log_filename, logger_name, level=logging.ERROR, print_console=False, log_format=None,
14-
log_file_max_bytes=20 * 1024 * 1024, log_file_backup_count=3):
14+
15+
def get_base_logger(log_filename, logger_name, level=logging.ERROR, print_console=False, log_format=None):
1516
logger = logging.getLogger(logger_name)
1617
logger.setLevel(level)
17-
formatter = log_format or logging.Formatter('%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
18+
formatter = log_format or logging.Formatter('%(asctime)s - [%(thread)d.%(threadName)s] - %(name)s - %(levelname)s - %(message)s')
1819

1920
if print_console:
2021
console_handler = logging.StreamHandler(stream=sys.stdout)
2122
if not logger.handlers:
2223
console_handler.setFormatter(formatter)
2324
logger.addHandler(console_handler)
25+
else:
26+
# rotated hourly if small file, o/w rotated bi-hourly
27+
if level == logging.DEBUG or level == logging.INFO:
28+
time = 30
29+
else:
30+
time = 60
31+
file_handler = TimedRotatingFileHandler(log_filename, when='M', interval=time, utc=True)
32+
if not logger.handlers:
33+
file_handler.setFormatter(formatter)
34+
logger.addHandler(file_handler)
2435

2536
return logger
2637

2738

28-
def get_logger(log_filename, logger_name, level=logging.ERROR, print_console=False, log_format=None,
29-
log_file_max_bytes=20 * 1024 * 1024, log_file_backup_count=3):
39+
def get_logger(
40+
log_filename,
41+
logger_name,
42+
level=logging.ERROR,
43+
print_console=False,
44+
log_format=None,
45+
):
3046
stress_logger = logging.getLogger(logger_name)
3147
stress_logger.setLevel(level)
3248
eventhub_logger = logging.getLogger("azure.eventhub")
3349
eventhub_logger.setLevel(level)
3450
uamqp_logger = logging.getLogger("uamqp")
3551
uamqp_logger.setLevel(level)
3652

37-
formatter = log_format or logging.Formatter('%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
38-
console_handler = logging.FileHandler(log_filename)
39-
console_handler.setFormatter(formatter)
40-
eventhub_logger.addHandler(console_handler)
41-
uamqp_logger.addHandler(console_handler)
42-
stress_logger.addHandler(console_handler)
53+
formatter = log_format or logging.Formatter('%(asctime)s - [%(thread)d.%(threadName)s] - %(name)-12s %(levelname)-8s %(funcName)s(%(lineno)d) %(message)s')
54+
55+
# rotated hourly if small file, o/w rotated bi-hourly
56+
if level == logging.DEBUG or level == logging.INFO:
57+
time = 30
58+
else:
59+
time = 60
60+
file_handler = TimedRotatingFileHandler(log_filename, when='M', interval=time, utc=True)
61+
file_handler.setFormatter(formatter)
62+
eventhub_logger.addHandler(file_handler)
63+
uamqp_logger.addHandler(file_handler)
64+
stress_logger.addHandler(file_handler)
4365

4466
return stress_logger
4567

‎sdk/eventhub/azure-eventhub/stress/scripts/process_monitor.py‎

Lines changed: 9 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -47,14 +47,13 @@ def __exit__(self, *args):
4747

4848
def _monitor_work(self):
4949
while self.running:
50-
log_content = "process status: {}," \
51-
"process cpu usage percent: {}," \
52-
"process memory usage percent: {:.3f}".format(
53-
self._process_instance.status(),
54-
self._process_instance.cpu_percent(),
55-
self._process_instance.memory_percent()
56-
)
57-
self._logger.info(log_content)
50+
log_content = "process status: %s, process cpu usage percent: %s, process memory usage percent: %.3f"
51+
self._logger.info(
52+
log_content,
53+
self._process_instance.status(),
54+
self._process_instance.cpu_percent(),
55+
self._process_instance.memory_percent()
56+
)
5857
time.sleep(self._log_interval)
5958

6059
@property
@@ -69,10 +68,10 @@ def start(self):
6968
self.running = True
7069
self._monitor_thread = threading.Thread(target=self._monitor_work, daemon=True)
7170
self._monitor_thread.start()
72-
self._logger.info("Start monitoring process id:{}".format(self._pid))
71+
self._logger.info("Start monitoring process id: %d", self._pid)
7372

7473
def stop(self):
7574
self.running = False
7675
self._monitor_thread.join()
77-
self._logger.info("Stop monitoring process id:{}".format(self._pid))
76+
self._logger.ino("Stop monitoring process id: %d", self._pid)
7877
self._monitor_thread = None

‎sdk/eventhub/azure-eventhub/stress/templates/testjob.yaml‎

Lines changed: 12 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -15,51 +15,51 @@ spec:
1515
cpu: "1"
1616

1717
{{ if eq .Stress.testTarget "event-async" }}
18-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
18+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --pyamqp_logging_enable']
1919
{{- end -}}
2020

2121
{{ if eq .Stress.testTarget "event-sync" }}
22-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
22+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --pyamqp_logging_enable']
2323
{{- end -}}
2424

2525
{{ if eq .Stress.testTarget "batch-async" }}
26-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable ']
26+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --pyamqp_logging_enable ']
2727
{{- end -}}
2828

2929
{{ if eq .Stress.testTarget "batch-sync" }}
30-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable ']
30+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --pyamqp_logging_enable ']
3131
{{- end -}}
3232

3333
{{ if eq .Stress.testTarget "bplistsync" }}
34-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --buffered_mode --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
34+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --buffered_mode --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --pyamqp_logging_enable']
3535
{{- end -}}
3636

3737
{{ if eq .Stress.testTarget "bpasync" }}
38-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --buffered_mode --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
38+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --buffered_mode --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --pyamqp_logging_enable']
3939
{{- end -}}
4040

4141
{{ if eq .Stress.testTarget "bplistasync" }}
42-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --buffered_mode --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable ']
42+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --buffered_mode --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --pyamqp_logging_enable ']
4343
{{- end -}}
4444

4545
{{ if eq .Stress.testTarget "bpsync" }}
46-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --buffered_mode --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
46+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --buffered_mode --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --pyamqp_logging_enable']
4747
{{- end -}}
4848

4949
{{ if eq .Stress.testTarget "syncwebsockets" }}
50-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
50+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_sync --duration 259200 --transport_type 1 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --transport_type 1 --pyamqp_logging_enable']
5151
{{- end -}}
5252

5353
{{ if eq .Stress.testTarget "asyncwebsockets" }}
54-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
54+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_async --duration 259200 --transport_type 1 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --transport_type 1 --pyamqp_logging_enable']
5555
{{- end -}}
5656

5757
{{ if eq .Stress.testTarget "sync-batch-web" }}
58-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
58+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_sync --duration 259200 --transport_type 1 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_sync.py --duration 259200 --transport_type 1 --pyamqp_logging_enable']
5959
{{- end -}}
6060

6161
{{ if eq .Stress.testTarget "async-batch-web" }}
62-
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && cat > $DEBUG_SHARE/output && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --transport_type 1 --log_filename $DEBUG_SHARE/output --pyamqp_logging_enable']
62+
command: ['bash', '-c', 'mkdir -p $DEBUG_SHARE && python3 azure_eventhub_producer_stress.py -m stress_send_list_async --duration 259200 --transport_type 1 --pyamqp_logging_enable & python3 azure_eventhub_consumer_stress_async.py --duration 259200 --transport_type 1 --pyamqp_logging_enable']
6363
{{- end -}}
6464

6565
{{- include "stress-test-addons.container-env" . | nindent 6 }}

‎sdk/servicebus/azure-servicebus/stress/scripts/app_insights_metric.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -100,5 +100,5 @@ def record_error(self, error, extra=None):
100100
self.mmap.measure_int_put(self.error_measure, 1)
101101
self.mmap.record()
102102
self.azure_logger.exception(
103-
"Error happened when running {}: {}. Extra info: {}".format(self.name, repr(error), extra)
103+
"Error happened when running %s: %s. Extra info: %s", self.name, repr(error), extra
104104
)

0 commit comments

Comments
 (0)