Skip to content
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

Add async logger for telemetry #2278

Open
wants to merge 61 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 54 commits
Commits
Show all changes
61 commits
Select commit Hold shift + click to select a range
ab10720
squash all commits
shreyas-goenka Jan 20, 2025
3964d8d
[WIP] In process telemetry logger
shreyas-goenka Jan 22, 2025
01d63dd
Merge remote-tracking branch 'origin' into implement-async-logger
shreyas-goenka Jan 23, 2025
155fe7b
-
shreyas-goenka Jan 29, 2025
acd64fa
merge
shreyas-goenka Jan 29, 2025
ee3568c
-'
shreyas-goenka Jan 29, 2025
8f8463f
-
shreyas-goenka Jan 29, 2025
f092e21
add back worker input
shreyas-goenka Jan 29, 2025
5d75c3f
Merge remote-tracking branch 'origin' into implement-async-logger
shreyas-goenka Feb 2, 2025
427c755
major cleanup
shreyas-goenka Feb 3, 2025
b83e576
-
shreyas-goenka Feb 3, 2025
f09a780
fix panic
shreyas-goenka Feb 3, 2025
90148d8
replace os
shreyas-goenka Feb 3, 2025
259a21a
-
shreyas-goenka Feb 3, 2025
e4a1f42
-
shreyas-goenka Feb 3, 2025
d7bf1dc
add test for upload
shreyas-goenka Feb 3, 2025
382efe4
-
shreyas-goenka Feb 3, 2025
c412eb7
-
shreyas-goenka Feb 3, 2025
da0cf95
-
shreyas-goenka Feb 3, 2025
8801587
pass test
shreyas-goenka Feb 3, 2025
5385faf
fix test
shreyas-goenka Feb 3, 2025
c1a3225
fx test
shreyas-goenka Feb 3, 2025
4f97900
-
shreyas-goenka Feb 3, 2025
a8b366e
-
shreyas-goenka Feb 3, 2025
5c2205a
-
shreyas-goenka Feb 3, 2025
dc0ab30
-
shreyas-goenka Feb 3, 2025
2cd25e3
-
shreyas-goenka Feb 3, 2025
2cbc39f
-
shreyas-goenka Feb 3, 2025
f3e7594
fx test
shreyas-goenka Feb 3, 2025
403f612
address comments
shreyas-goenka Feb 3, 2025
0423b09
add filtering for auth
shreyas-goenka Feb 3, 2025
981dbf7
add bash script for waiting
shreyas-goenka Feb 4, 2025
918af62
remove eventually files
shreyas-goenka Feb 4, 2025
39ff290
pass test
shreyas-goenka Feb 4, 2025
33ff865
cleaner output
shreyas-goenka Feb 4, 2025
17698a5
-
shreyas-goenka Feb 4, 2025
5b6ffd5
-
shreyas-goenka Feb 4, 2025
963022a
-
shreyas-goenka Feb 4, 2025
9e2a689
-
shreyas-goenka Feb 4, 2025
0abba86
=
shreyas-goenka Feb 4, 2025
407e9e0
-
shreyas-goenka Feb 4, 2025
414a94d
-
shreyas-goenka Feb 4, 2025
d5e03f0
-
shreyas-goenka Feb 4, 2025
8c90ad0
clean
shreyas-goenka Feb 4, 2025
1bb4537
Merge remote-tracking branch 'origin' into async-logger-clean
shreyas-goenka Feb 5, 2025
c9ebc82
add error test case'
shreyas-goenka Feb 5, 2025
fd6b129
make test generic
shreyas-goenka Feb 5, 2025
73fac82
remove pid file
shreyas-goenka Feb 5, 2025
5e2e03a
fix test
shreyas-goenka Feb 5, 2025
0253039
-
shreyas-goenka Feb 5, 2025
369faff
return 501
shreyas-goenka Feb 5, 2025
e43a0a0
skip end to end integration tests
shreyas-goenka Feb 6, 2025
f88db77
-
shreyas-goenka Feb 10, 2025
a6e8e92
Merge remote-tracking branch 'origin' into async-logger-clean
shreyas-goenka Feb 10, 2025
23b42e9
Merge remote-tracking branch 'origin' into async-logger-clean
shreyas-goenka Feb 10, 2025
9d65761
pretty print
shreyas-goenka Feb 10, 2025
c8ac08c
consolidate test.toml
shreyas-goenka Feb 10, 2025
58bf931
comment
shreyas-goenka Feb 10, 2025
79fad7a
pass test
shreyas-goenka Feb 10, 2025
4cdcbd6
Merge remote-tracking branch 'origin' into async-logger-clean
shreyas-goenka Feb 11, 2025
f98369d
-
shreyas-goenka Feb 11, 2025
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
27 changes: 27 additions & 0 deletions acceptance/bin/wait_file
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
#!/bin/bash

wait_file() {
local file_path="$1"
local max_attempts=100
local attempt=0

while [ $attempt -lt $max_attempts ]; do
if [ -e "$file_path" ]; then
echo "File $file_path exists"
return 0
fi
sleep 0.1
attempt=$((attempt + 1))
done

echo "Timeout: File $file_path did not appear within 10 seconds"
return 1
}

if [ $# -eq 0 ]; then
echo "Usage: $0 <file_path>"
exit 1
fi

wait_file "$1"
exit $?
42 changes: 42 additions & 0 deletions acceptance/bin/wait_pid
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
#!/bin/bash


# wait <pid> in bash only works for processes that are direct children to the calling
# shell. This script is more general purpose.
wait_pid() {
local pid=$1
local max_attempts=100 # 100 * 0.1 seconds = 10 seconds
local attempt=0
local sleep_time=0.1

while [ $attempt -lt $max_attempts ]; do
if [[ "$OSTYPE" == "msys"* || "$OSTYPE" == "cygwin"* ]]; then
# Windows approach
if ! tasklist | grep -q $pid; then
echo "Process has ended"
return 0
fi
else
# Linux/macOS approach
if ! kill -0 $pid 2>/dev/null; then
echo "Process has ended"
return 0
fi
fi

sleep $sleep_time
attempt=$((attempt + 1))
done

echo "Timeout: Process $pid did not end within 10 seconds"
return 1
}

# Usage
if [ $# -eq 0 ]; then
echo "Usage: $0 <PID>"
exit 1
fi

wait_pid $1
exit $?
1 change: 1 addition & 0 deletions acceptance/telemetry/dummy-error/out.requests.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
{"method":"POST","path":"/telemetry-ext","body":{"uploadTime":"UNIX_TIME_MILLIS","items":[],"protoLogs":["{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"execution_context\":{\"cmd_exec_id\":\"[UUID]\",\"version\":\"[DEV_VERSION]\",\"command\":\"telemetry_dummy\",\"operating_system\":\"OS\",\"execution_time_ms\":\"SMALL_INT\",\"exit_code\":0},\"cli_test_event\":{\"name\":\"VALUE1\"}}}}","{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"execution_context\":{\"cmd_exec_id\":\"[UUID]\",\"version\":\"[DEV_VERSION]\",\"command\":\"telemetry_dummy\",\"operating_system\":\"OS\",\"execution_time_ms\":\"SMALL_INT\",\"exit_code\":0},\"cli_test_event\":{\"name\":\"VALUE2\"}}}}"]}}
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

#2329 will make this easier to review.

2 changes: 2 additions & 0 deletions acceptance/telemetry/dummy-error/out.upload.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
error: Failed to upload telemetry logs: Endpoint not implemented.

5 changes: 5 additions & 0 deletions acceptance/telemetry/dummy-error/output.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@

>>> [CLI] telemetry dummy
waiting for telemetry process to finish
File ./telemetry.pid exists
Process has ended
15 changes: 15 additions & 0 deletions acceptance/telemetry/dummy-error/script
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
export DATABRICKS_CLI_TELEMETRY_PID_FILE=./telemetry.pid
export DATABRICKS_CLI_TELEMETRY_UPLOAD_LOGS_FILE=./out.upload.txt

# This test ensures that the main CLI command does not error even if
# telemetry upload fails.
trace $CLI telemetry dummy

echo "waiting for telemetry process to finish"

# Wait for the child telemetry process to finish
wait_file ./telemetry.pid
wait_pid $(cat ./telemetry.pid)

# cleanup the pid file
rm -f ./telemetry.pid
24 changes: 24 additions & 0 deletions acceptance/telemetry/dummy-error/test.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
LocalOnly = true
RecordRequests = true

[[Server]]
Pattern = "POST /telemetry-ext"
Response.Body = '''
{
"error_code": "ERROR_CODE",
"message": "Endpoint not implemented."
}
'''
Response.StatusCode = 501

[[Repls]]
Old = '17\d{11}'
New = '"UNIX_TIME_MILLIS"'

[[Repls]]
Old = 'execution_time_ms\\\":\d{1,5},'
New = 'execution_time_ms\":\"SMALL_INT\",'

[[Repls]]
Old = 'darwin|linux|windows'
New = 'OS'
1 change: 1 addition & 0 deletions acceptance/telemetry/dummy/out.requests.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
{"method":"POST","path":"/telemetry-ext","body":{"uploadTime":"UNIX_TIME_MILLIS","items":[],"protoLogs":["{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"execution_context\":{\"cmd_exec_id\":\"[UUID]\",\"version\":\"[DEV_VERSION]\",\"command\":\"telemetry_dummy\",\"operating_system\":\"OS\",\"execution_time_ms\":\"SMALL_INT\",\"exit_code\":0},\"cli_test_event\":{\"name\":\"VALUE1\"}}}}","{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"execution_context\":{\"cmd_exec_id\":\"[UUID]\",\"version\":\"[DEV_VERSION]\",\"command\":\"telemetry_dummy\",\"operating_system\":\"OS\",\"execution_time_ms\":\"SMALL_INT\",\"exit_code\":0},\"cli_test_event\":{\"name\":\"VALUE2\"}}}}"]}}
3 changes: 3 additions & 0 deletions acceptance/telemetry/dummy/out.upload.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
Telemetry logs uploaded successfully
Response:
{"errors":null,"numProtoSuccess":2}
5 changes: 5 additions & 0 deletions acceptance/telemetry/dummy/output.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@

>>> [CLI] telemetry dummy
waiting for telemetry process to finish
File ./telemetry.pid exists
Process has ended
13 changes: 13 additions & 0 deletions acceptance/telemetry/dummy/script
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
export DATABRICKS_CLI_TELEMETRY_PID_FILE=./telemetry.pid
export DATABRICKS_CLI_TELEMETRY_UPLOAD_LOGS_FILE=./out.upload.txt

trace $CLI telemetry dummy

echo "waiting for telemetry process to finish"

# Wait for the child telemetry process to finish
wait_file ./telemetry.pid
wait_pid $(cat ./telemetry.pid)

# cleanup the pid file
rm -f ./telemetry.pid
22 changes: 22 additions & 0 deletions acceptance/telemetry/dummy/test.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,22 @@
LocalOnly = true
RecordRequests = true

[[Server]]
Pattern = "POST /telemetry-ext"
Response.Body = '''
{
"numProtoSuccess": 2
}
'''

[[Repls]]
Old = '17\d{11}'
New = '"UNIX_TIME_MILLIS"'

[[Repls]]
Old = 'execution_time_ms\\\":\d{1,5},'
New = 'execution_time_ms\":\"SMALL_INT\",'

[[Repls]]
Old = 'darwin|linux|windows'
New = 'OS'
1 change: 1 addition & 0 deletions acceptance/telemetry/upload/out.requests.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
{"method":"POST","path":"/telemetry-ext","body":{"uploadTime":"UNIX_TIME_MILLIS","items":[],"protoLogs":["{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"cli_test_event\":{\"name\":\"VALUE1\"}}}}","{\"frontend_log_event_id\":\"[UUID]\",\"entry\":{\"databricks_cli_log\":{\"cli_test_event\":{\"name\":\"VALUE2\"}}}}"]}}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unrelated to this PR, but this prompted me to check if we can pretty print it but keep storing it without the outside array -- it seems that it works fine with jq:

% cat test.jsonlines | jq .body
"one"
"two"

% cat test.jsonlines
{
    "body": "one"
}
{
    "body": "two"
}

So maybe you could do a separate PR to adopt this format?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll send a followup PR after this is merged

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The output requests log file is only written after the script is generated. Maybe we need to introduce some new hook to make it work?

3 changes: 3 additions & 0 deletions acceptance/telemetry/upload/out.upload.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
Telemetry logs uploaded successfully
Response:
{"errors":null,"numProtoSuccess":2}
2 changes: 2 additions & 0 deletions acceptance/telemetry/upload/output.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@

>>> [CLI] telemetry upload
5 changes: 5 additions & 0 deletions acceptance/telemetry/upload/script
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
export DATABRICKS_CLI_TELEMETRY_UPLOAD_LOGS_FILE=./out.upload.txt

# This command / test cannot be run in inprocess / debug mode. This is because
# it does not go through the [root.Execute] function.
trace $CLI telemetry upload < stdin
24 changes: 24 additions & 0 deletions acceptance/telemetry/upload/stdin
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
{
"logs": [
{
"frontend_log_event_id": "BB79BB52-96F6-42C5-9E44-E63EEA84888D",
"entry": {
"databricks_cli_log": {
"cli_test_event": {
"name": "VALUE1"
}
}
}
},
{
"frontend_log_event_id": "A7F597B0-66D1-462D-824C-C5C706F232E8",
"entry": {
"databricks_cli_log": {
"cli_test_event": {
"name": "VALUE2"
}
}
}
}
]
}
19 changes: 19 additions & 0 deletions acceptance/telemetry/upload/test.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
LocalOnly = true
RecordRequests = true

[[Server]]
Pattern = "POST /telemetry-ext"
Response.Body = '''
{
"numProtoSuccess": 2
}
'''


[[Repls]]
Old = '17\d{11}'
New = '"UNIX_TIME_MILLIS"'

[[Repls]]
Old = 'darwin|linux|windows'
New = 'OS'
3 changes: 2 additions & 1 deletion cmd/cmd.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ import (
"github.com/databricks/cli/cmd/labs"
"github.com/databricks/cli/cmd/root"
"github.com/databricks/cli/cmd/sync"
"github.com/databricks/cli/cmd/telemetry"
"github.com/databricks/cli/cmd/version"
"github.com/databricks/cli/cmd/workspace"
"github.com/spf13/cobra"
Expand Down Expand Up @@ -74,6 +75,6 @@ func New(ctx context.Context) *cobra.Command {
cli.AddCommand(labs.New(ctx))
cli.AddCommand(sync.New())
cli.AddCommand(version.New())

cli.AddCommand(telemetry.New())
return cli
}
Loading
Loading