Skip to content

Fix backend logging initialization #154

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
pricejc-sublime merged 1 commit into from
Feb 5, 2026
+21 −16
Merged

Fix backend logging initialization #154

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 8 additions & 8 deletions src/go/cmd/strelka-frontend/main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ var (

func DebugLog(msg string, fields ...zap.Field) {
// The value here doesn't matter, we'll just check for its existence
if _, enableDebugLogging := os.LookupEnv("ENABLE_DEBUG_LOGGING"); !enableDebugLogging {
if _, enableDebugLogging := os.LookupEnv("ENABLE_VERBOSE_LOGGING"); !enableDebugLogging {
return
}

Expand Down Expand Up @@ -226,15 +226,15 @@ func (s *server) ScanFile(stream strelka.Frontend_ScanFileServer) error {
Member: id,
},
).Err(); err != nil {
DebugLog("[DEBUG] Failed to queue task",
DebugLog("[VERBOSE] Failed to queue task",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("took", time.Since(startQueueTask)),
zap.Error(err),
)
return fmt.Errorf("sending task: %w", err)
} else {
DebugLog("[DEBUG] Queued task",
DebugLog("[VERBOSE] Queued task",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Time("deadline", deadline),
Expand All @@ -252,7 +252,7 @@ func (s *server) ScanFile(stream strelka.Frontend_ScanFileServer) error {
startAwaitResponse := time.Now()
for {
if err := stream.Context().Err(); err != nil {
DebugLog("[DEBUG] Stream error",
DebugLog("[VERBOSE] Stream error",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("waited", time.Since(startAwaitResponse)),
Expand All @@ -276,15 +276,15 @@ func (s *server) ScanFile(stream strelka.Frontend_ScanFileServer) error {

lpop := res[1]
if lpop == "FIN" {
DebugLog("[DEBUG] FIN response received",
DebugLog("[VERBOSE] FIN response received",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("waited", time.Since(startAwaitResponse)),
)
break
}

DebugLog("[DEBUG] Response received",
DebugLog("[VERBOSE] Response received",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("waited", time.Since(startAwaitResponse)),
Expand Down Expand Up @@ -320,15 +320,15 @@ func (s *server) ScanFile(stream strelka.Frontend_ScanFileServer) error {

startSendResponse := time.Now()
if err := stream.Send(resp); err != nil {
DebugLog("[DEBUG] Error sending response",
DebugLog("[VERBOSE] Error sending response",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("took", time.Since(startSendResponse)),
zap.Error(err),
)
return fmt.Errorf("send stream: %w", err)
} else {
DebugLog("[DEBUG] Sent response",
DebugLog("[VERBOSE] Sent response",
zap.String("request_id", req.Id),
zap.String("strelka_id", id),
zap.Duration("took", time.Since(startSendResponse)),
Expand Down
21 changes: 13 additions & 8 deletions src/python/bin/strelka-backend
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,8 +33,8 @@ from pythonjsonlogger.json import JsonFormatter

shutdown_event = threading.Event()

def init_logging():
if 'ENABLE_DEBUG_LOGGING' in os.environ:
def init_verbose_logging():
if 'ENABLE_VERBOSE_LOGGING' in os.environ:
logger = logging.getLogger('debugging')
logger.setLevel(logging.INFO)
logHandler = logging.StreamHandler()
Expand All @@ -44,7 +44,7 @@ def init_logging():


def debug_log(msg, extra):
if 'ENABLE_DEBUG_LOGGING' in os.environ:
if 'ENABLE_VERBOSE_LOGGING' in os.environ:
logger = logging.getLogger('debugging')
logger.info(msg, extra=extra)

Expand Down Expand Up @@ -102,6 +102,7 @@ class Backend(object):

task = self.coordinator.bzpopmin(['tasks', 'tasks_compile_yara', 'tasks_compile_and_sync_yara'], timeout=5)
if task is None:
debug_log('[VERBOSE] Received no tasks')
continue

(queue_name, root_id, expire_at) = task
Expand All @@ -110,6 +111,10 @@ class Backend(object):
timeout = math.ceil(expire_at - time.time())

if timeout <= 0:
debug_log('[VERBOSE] Received expired task', extra={
'strelka_id': root_id,
'expires_at': expire_at
})
continue

if shutdown_event.is_set():
Expand All @@ -119,7 +124,7 @@ class Backend(object):
break

if queue_name == b'tasks':
debug_log('[DEBUG] Received task', extra={
debug_log('[VERBOSE] Received task', extra={
'strelka_id': root_id,
'expires_at': expire_at
})
Expand All @@ -132,7 +137,7 @@ class Backend(object):
self.distribute(root_id, file, expire_at)

end_distribute = datetime.now()
debug_log('[DEBUG] Scanning complete', extra={
debug_log('[VERBOSE] Scanning complete', extra={
'strelka_id': root_id,
'expires_at': expire_at,
'took_ms': (end_distribute - start_distribute).total_seconds() * 1000
Expand All @@ -144,14 +149,14 @@ class Backend(object):
p.expireat(f'event:{root_id}', expire_at)
p.execute()
end_emit_result = datetime.now()
debug_log('[DEBUG] Result event emitted', extra={
debug_log('[VERBOSE] Result event emitted', extra={
'strelka_id': root_id,
'expires_at': expire_at,
'took_ms': (end_emit_result - start_emit_result).total_seconds() * 1000
})

except strelka.RequestTimeout:
debug_log('[DEBUG] Task timeout', extra={
debug_log('[VERBOSE] Task timeout', extra={
'strelka_id': root_id
})
logging.debug(f'request {root_id} timed out')
Expand Down Expand Up @@ -498,7 +503,6 @@ def handle_sigint(signum, frame):


def main():
init_logging()
signal.signal(signal.SIGINT, handle_sigint)

parser = argparse.ArgumentParser(prog='strelka-worker',
Expand Down Expand Up @@ -528,6 +532,7 @@ def main():
log_cfg_path = backend_cfg.get('logging_cfg')
with open(log_cfg_path) as f:
logging.config.dictConfig(yaml.safe_load(f.read()))
init_verbose_logging()
logging.info(f'using backend configuration {backend_cfg_path}')

try:
Expand Down