-
Notifications
You must be signed in to change notification settings - Fork 91
Improve client call logs #1126
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.
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
Open
bgardner8008
wants to merge
11
commits into
main
Choose a base branch
from
MM-67452-call-logs
base: main
Could not load branches
Branch not found: {{ refName }}
Loading
Could not load tags
Nothing to show
Loading
Are you sure you want to change the base?
Some commits from the old base branch may be removed from the timeline,
and old review comments may become outdated.
Open
Improve client call logs #1126
Changes from 3 commits
Commits
Show all changes
11 commits
Select commit
Hold shift + click to select a range
0408925
logging improvements, record all call logs and stats in one buffer wh…
bgardner8008 b9faf19
add tests for log accumulation and truncation
bgardner8008 a7b56af
fix linter issues
bgardner8008 4925f5a
add callID to stats, via CallsClientJoinData
bgardner8008 b9ca2bb
Revert "add callID to stats, via CallsClientJoinData"
bgardner8008 c4a4d86
log IDs on call_start and call_join
bgardner8008 3a19639
implement log file upload to @calls bot DM channel and make ephemeral…
bgardner8008 de27793
remove periodic cleanup of in-memory log
bgardner8008 a4cffec
fix linter issue
bgardner8008 a01838a
restrict log downloads to files that are in DM channel between user a…
bgardner8008 67b4391
add validation to handleLogsCommand to prevent malicious injection to…
bgardner8008 File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,304 @@ | ||
| // Copyright (c) 2020-present Mattermost, Inc. All Rights Reserved. | ||
| // See LICENSE.txt for license information. | ||
|
|
||
| import {MAX_ACCUMULATED_LOG_SIZE, STORAGE_CALLS_CLIENT_LOGS_KEY} from 'src/constants'; | ||
| import type {CallsClientStats} from 'src/types/types'; | ||
|
|
||
| import {flushLogsToAccumulated, getClientLogs, logDebug, logErr, logInfo, logWarn} from './log'; | ||
|
|
||
| // Mock the manifest | ||
| jest.mock('./manifest', () => ({ | ||
| pluginId: 'com.mattermost.calls', | ||
| })); | ||
|
|
||
| // Mock getPersistentStorage | ||
| const mockStorage = new Map<string, string>(); | ||
| jest.mock('./utils', () => ({ | ||
| getPersistentStorage: () => ({ | ||
| getItem: (key: string) => mockStorage.get(key) || null, | ||
| setItem: (key: string, value: string) => mockStorage.set(key, value), | ||
| removeItem: (key: string) => mockStorage.delete(key), | ||
| }), | ||
| })); | ||
|
|
||
| describe('log', () => { | ||
| /* eslint-disable no-console */ | ||
| const originalConsole = { | ||
| error: console.error, | ||
| warn: console.warn, | ||
| info: console.info, | ||
| debug: console.debug, | ||
| }; | ||
|
|
||
| beforeAll(() => { | ||
| console.error = jest.fn(); | ||
| console.warn = jest.fn(); | ||
| console.info = jest.fn(); | ||
| console.debug = jest.fn(); | ||
| }); | ||
|
|
||
| afterAll(() => { | ||
| console.error = originalConsole.error; | ||
| console.warn = originalConsole.warn; | ||
| console.info = originalConsole.info; | ||
| console.debug = originalConsole.debug; | ||
| }); | ||
| /* eslint-enable no-console */ | ||
|
|
||
| beforeEach(() => { | ||
| flushLogsToAccumulated(); | ||
| mockStorage.clear(); | ||
| jest.clearAllMocks(); | ||
| }); | ||
|
|
||
| describe('flushLogsToAccumulated', () => { | ||
| test('should append in-memory logs to accumulated buffer', () => { | ||
| logDebug('test message 1'); | ||
| logInfo('test message 2'); | ||
|
|
||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('test message 1'); | ||
| expect(accumulated).toContain('test message 2'); | ||
| expect(accumulated).toContain('debug'); | ||
| expect(accumulated).toContain('info'); | ||
| }); | ||
|
|
||
| test('should include timestamp in log entries', () => { | ||
| const beforeTime = new Date().toISOString().slice(0, 10); // YYYY-MM-DD | ||
| logDebug('test message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain(beforeTime); | ||
| }); | ||
|
|
||
| test('should append stats when provided', () => { | ||
| const stats: CallsClientStats = { | ||
| initTime: 123456, | ||
| channelID: 'test-channel', | ||
| tracksInfo: [], | ||
| rtcStats: { | ||
| ssrcStats: {}, | ||
| iceStats: { | ||
| 'in-progress': [], | ||
| succeeded: [], | ||
| waiting: [], | ||
| }, | ||
| }, | ||
| }; | ||
|
|
||
| flushLogsToAccumulated(stats); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('--- Call Stats ---'); | ||
| expect(accumulated).toContain(JSON.stringify(stats)); | ||
| expect(accumulated).toContain('---'); | ||
| }); | ||
|
|
||
| test('should handle empty logs gracefully', () => { | ||
| // Don't log anything, just flush | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toBe(''); | ||
| }); | ||
|
|
||
| test('should clear in-memory logs after flush', () => { | ||
| logDebug('test message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const firstAccumulated = getClientLogs(); | ||
| expect(firstAccumulated).toContain('test message'); | ||
|
|
||
| // Flush again without logging - should not duplicate | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const secondAccumulated = getClientLogs(); | ||
| expect(secondAccumulated).toBe(firstAccumulated); | ||
| }); | ||
|
|
||
| test('should accumulate logs across multiple flushes', () => { | ||
| logDebug('message 1'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| logDebug('message 2'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('message 1'); | ||
| expect(accumulated).toContain('message 2'); | ||
| }); | ||
|
|
||
| test('should truncate when exceeding MAX_ACCUMULATED_LOG_SIZE', () => { | ||
| // Create a large log that definitely exceeds the 1MB limit | ||
| // Use a clearly identifiable pattern at start and end | ||
| const oldLogsStart = 'START_MARKER_SHOULD_BE_REMOVED\n'; | ||
| const oldLogsMiddle = 'x'.repeat(MAX_ACCUMULATED_LOG_SIZE); | ||
| const oldLogsEnd = '\nEND_MARKER_SHOULD_BE_KEPT\n'; | ||
| const largeMessage = oldLogsStart + oldLogsMiddle + oldLogsEnd; | ||
|
|
||
| mockStorage.set(STORAGE_CALLS_CLIENT_LOGS_KEY, largeMessage); | ||
|
|
||
| logDebug('newest message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
|
|
||
| // Should be at or under the limit | ||
| expect(accumulated.length).toBeLessThanOrEqual(MAX_ACCUMULATED_LOG_SIZE); | ||
|
|
||
| // Should contain truncation marker | ||
| expect(accumulated).toContain('[... older logs truncated ...]'); | ||
|
|
||
| // Should contain new message (most recent) | ||
| expect(accumulated).toContain('newest message'); | ||
|
|
||
| // Should NOT contain the start marker (old logs were truncated from the beginning) | ||
| expect(accumulated).not.toContain('START_MARKER_SHOULD_BE_REMOVED'); | ||
|
|
||
| // Should contain the end marker (keeps most recent logs) | ||
| expect(accumulated).toContain('END_MARKER_SHOULD_BE_KEPT'); | ||
| }); | ||
|
|
||
| test('should keep most recent logs when truncating', () => { | ||
| // Fill storage with old logs | ||
| const oldLogs = 'old log line\n'.repeat(100000); // Very large | ||
| mockStorage.set(STORAGE_CALLS_CLIENT_LOGS_KEY, oldLogs); | ||
|
|
||
| logDebug('newest message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
|
|
||
| // Should contain the newest message | ||
| expect(accumulated).toContain('newest message'); | ||
|
|
||
| // Should be properly sized | ||
| expect(accumulated.length).toBeLessThanOrEqual(MAX_ACCUMULATED_LOG_SIZE); | ||
| }); | ||
|
|
||
| test('should handle truncation edge case: exactly at limit', () => { | ||
| const exactSizeLog = 'y'.repeat(MAX_ACCUMULATED_LOG_SIZE - 100); | ||
| mockStorage.set(STORAGE_CALLS_CLIENT_LOGS_KEY, exactSizeLog); | ||
|
|
||
| logDebug('new message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated.length).toBeLessThanOrEqual(MAX_ACCUMULATED_LOG_SIZE); | ||
| }); | ||
|
|
||
| test('should handle truncation with stats', () => { | ||
| // Fill storage near the limit | ||
| const largeLogs = 'log line\n'.repeat(MAX_ACCUMULATED_LOG_SIZE / 10); | ||
| mockStorage.set(STORAGE_CALLS_CLIENT_LOGS_KEY, largeLogs); | ||
|
|
||
| const stats: CallsClientStats = { | ||
| initTime: 123456, | ||
| channelID: 'test-channel', | ||
| tracksInfo: [], | ||
| rtcStats: { | ||
| ssrcStats: {}, | ||
| iceStats: { | ||
| 'in-progress': [], | ||
| succeeded: [], | ||
| waiting: [], | ||
| }, | ||
| }, | ||
| }; | ||
|
|
||
| flushLogsToAccumulated(stats); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
|
|
||
| // Stats should be present | ||
| expect(accumulated).toContain('--- Call Stats ---'); | ||
|
|
||
| // Should not exceed limit | ||
| expect(accumulated.length).toBeLessThanOrEqual(MAX_ACCUMULATED_LOG_SIZE); | ||
| }); | ||
| }); | ||
|
|
||
| describe('logging functions', () => { | ||
| test('logErr should append error logs', () => { | ||
| logErr('error message', 'additional', 'args'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('error'); | ||
| expect(accumulated).toContain('error message'); | ||
| expect(accumulated).toContain('additional'); | ||
| expect(accumulated).toContain('args'); | ||
| }); | ||
|
|
||
| test('logWarn should append warning logs', () => { | ||
| logWarn('warning message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('warn'); | ||
| expect(accumulated).toContain('warning message'); | ||
| }); | ||
|
|
||
| test('logInfo should append info logs', () => { | ||
| logInfo('info message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('info'); | ||
| expect(accumulated).toContain('info message'); | ||
| }); | ||
|
|
||
| test('logDebug should append debug logs', () => { | ||
| logDebug('debug message'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('debug'); | ||
| expect(accumulated).toContain('debug message'); | ||
| }); | ||
|
|
||
| test('should handle multiple log levels in order', () => { | ||
| logErr('first'); | ||
| logWarn('second'); | ||
| logInfo('third'); | ||
| logDebug('fourth'); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| const firstPos = accumulated.indexOf('first'); | ||
| const secondPos = accumulated.indexOf('second'); | ||
| const thirdPos = accumulated.indexOf('third'); | ||
| const fourthPos = accumulated.indexOf('fourth'); | ||
|
|
||
| expect(firstPos).toBeLessThan(secondPos); | ||
| expect(secondPos).toBeLessThan(thirdPos); | ||
| expect(thirdPos).toBeLessThan(fourthPos); | ||
| }); | ||
|
|
||
| test('should handle objects in log messages', () => { | ||
| const obj = {foo: 'bar', nested: {value: 123}}; | ||
| logDebug('object:', obj); | ||
| flushLogsToAccumulated(); | ||
|
|
||
| const accumulated = getClientLogs(); | ||
| expect(accumulated).toContain('object:'); | ||
| expect(accumulated).toContain('[object Object]'); | ||
| }); | ||
| }); | ||
|
|
||
| describe('getClientLogs', () => { | ||
| test('should return empty string when no logs', () => { | ||
| const logs = getClientLogs(); | ||
| expect(logs).toBe(''); | ||
| }); | ||
|
|
||
| test('should return accumulated logs', () => { | ||
| mockStorage.set(STORAGE_CALLS_CLIENT_LOGS_KEY, 'test logs'); | ||
| const logs = getClientLogs(); | ||
| expect(logs).toBe('test logs'); | ||
| }); | ||
| }); | ||
| }); | ||
Oops, something went wrong.
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
just curious if this is the best we can do for logging something useful for objects? totally fine if it is, but thought I'd ask.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks for pointing that out, those generic "object" logs are not helpful.