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.

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

Jump to bottom

Remove changes to support logging for AI #661

Merged
merged 5 commits into from
Sep 5, 2024
Merged

Remove changes to support logging for AI #661

merged 5 commits into from
Sep 5, 2024

Conversation

jlewi
Copy link
Contributor

@jlewi jlewi commented Aug 30, 2024 •
edited
Loading

As described in jlewi/foyle#211 we will no longer rely on processing RunMe grpc logs to train the AI. This means we can simplify the Runme logging code and revert some of the changes in #585

  • We can simplify initialization and configuration of the logger because we no longer need to always log to a file

  • We can remove the tests to verify the log messages for the request are always there

  • The ai-logs flag should no longer be needed but I think its best to keep it until we have rolled out the changes to the frontend to ensure it never sets the flag.

  • Related to Use the Foyle API to report Log Events vscode-runme#1589

@jlewi jlewi changed the title Jlewi/logscleanup Remove changes to support logging for AI Aug 30, 2024
@jlewi jlewi marked this pull request as ready for review August 30, 2024 17:57
This was referenced Aug 30, 2024
Merged
Closed
sourishkrout
sourishkrout requested changes Sep 4, 2024
View reviewed changes
Copy link
Member

@sourishkrout sourishkrout left a comment

Choose a reason for hiding this comment

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

One minor thing, @jlewi.

internal/cmd/server.go Outdated
@@ -137,9 +137,10 @@ The kernel is used to run long running processes like shells and interacting wit
cmd.Flags().StringVarP(&addr, "address", "a", defaultAddr, "Address to create unix (unix:///path/to/socket) or IP socket (localhost:7890)")
cmd.Flags().BoolVar(&devMode, "dev", false, "Enable development mode")
cmd.Flags().BoolVar(&enableRunner, "runner", true, "Enable runner service (legacy, defaults to true)")
cmd.Flags().BoolVar(&enableAILogs, "ai-logs", false, "Enable logs to support training an AI")
// The AIFlag is no longer used, we can remove it as soon as the option has been removed from the frontend.
cmd.Flags().BoolVar(&enableAILogs, "ai-logs", false, "(Obsolete) This flag is no longer used.")
Copy link
Member

Choose a reason for hiding this comment

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

Perhaps add _ = cmd.Flags().MarkDeprecated("ai-logs", "This flag is no longer used.") instead of a note?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done.

@jlewi
Copy link
Contributor Author

jlewi commented Sep 5, 2024

Re test failures. Seems like test passes locally at.
fba24dd

/opt/homebrew/opt/go/libexec/bin/go tool test2json -t /Users/jlewi/Library/Caches/JetBrains/GoLand2023.2/tmp/GoLand/___project_service_test_go.test -test.v -test.paniconexit0 -test.run ^\QTestProjectServiceServer_Load\E|\QTestProjectServiceServer_Load_ClientConnClosed\E$
=== RUN   TestProjectServiceServer_Load
=== PAUSE TestProjectServiceServer_Load
=== RUN   TestProjectServiceServer_Load_ClientConnClosed
=== PAUSE TestProjectServiceServer_Load_ClientConnClosed
=== CONT  TestProjectServiceServer_Load
=== CONT  TestProjectServiceServer_Load_ClientConnClosed
=== RUN   TestProjectServiceServer_Load/GitProject
=== PAUSE TestProjectServiceServer_Load/GitProject
=== RUN   TestProjectServiceServer_Load/FileProject
=== PAUSE TestProjectServiceServer_Load/FileProject
=== CONT  TestProjectServiceServer_Load/GitProject
=== CONT  TestProjectServiceServer_Load/FileProject
--- PASS: TestProjectServiceServer_Load_ClientConnClosed (0.05s)
--- PASS: TestProjectServiceServer_Load (0.00s)
    --- PASS: TestProjectServiceServer_Load/FileProject (0.05s)
    --- PASS: TestProjectServiceServer_Load/GitProject (0.05s)
PASS

Process finished with the exit code 0

Lets hope it passes at the latest commit in CI.

@jlewi
Copy link
Contributor Author

jlewi commented Sep 5, 2024

Seems like a different error this time in CI

   --- FAIL: TestCommand_SetWinsize/Terminal (5.00s)
        command_unix_test.go:394: 
            	Error Trace:	/home/runner/work/runme/runme/internal/command/command_unix_test.go:394
            	Error:      	Received unexpected error:
            	            	signal: killed

When I ran it locally; I got a different test failure.

/opt/homebrew/opt/go/libexec/bin/go tool test2json -t /Users/jlewi/Library/Caches/JetBrains/GoLand2023.2/tmp/GoLand/___command_unix_test_go.test -test.v -test.paniconexit0 -test.run ^\QTestCommand\E|\QTestCommand_FromCodeBlocks\E|\QTestCommand_Getters\E|\QTestCommand_InvalidProgram\E|\QTestCommand_InvalidScript\E|\QTestCommand_SetWinsize\E|\QTestCommand_Session\E|\QTestCommand_SimulateCtrlC\E|\QTestCommand_StopWithSignal\E$
=== RUN   TestCommand
--- PASS: TestCommand (0.00s)
=== RUN   TestCommand/Echo
=== PAUSE TestCommand/Echo
=== CONT  TestCommand/Echo
    logger.go:146: 2024-09-04T19:49:10.653-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E", "program": "/bin/echo", "args": ["-n", "test"]}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E", "config": "program_name:\"echo\" arguments:\"-n\" arguments:\"test\" interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E", "count": 0}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E", "count": 4}
    logger.go:146: 2024-09-04T19:49:10.666-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.666-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.666-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    logger.go:146: 2024-09-04T19:49:10.666-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXQWJ3680SHBNRQ6KM6E"}
    --- PASS: TestCommand/Echo (0.01s)
=== RUN   TestCommand/EchoInteractive
=== PAUSE TestCommand/EchoInteractive
=== CONT  TestCommand/EchoInteractive
    logger.go:146: 2024-09-04T19:49:10.653-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ", "program": "/bin/echo", "args": ["-n", "test"]}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ", "config": "program_name:\"echo\" arguments:\"-n\" arguments:\"test\" interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ", "count": 4}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ", "count": 0}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXQXZS1DCC6PBY4X57MQ"}
    --- PASS: TestCommand/EchoInteractive (0.01s)
=== RUN   TestCommand/ShellScript
=== PAUSE TestCommand/ShellScript
=== CONT  TestCommand/ShellScript
    logger.go:146: 2024-09-04T19:49:10.656-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXQXZS1DCC6PCN36TQ2H", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\n#!/usr/local/bin/bash\n\nset -x -e -o pipefail\n\necho -n test\n"}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXQXZS1DCC6PCHXKEAYY", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\n#!/usr/local/bin/bash\n\nset -x -e -o pipefail\n\necho -n test\n"]}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXQXZS1DCC6PCHXKEAYY", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1924718942/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\n#!/usr/local/bin/bash\\n\\nset -x -e -o pipefail\\n\\necho -n test\\n\" script:\"#!/usr/local/bin/bash\\n\\nset -x -e -o pipefail\\n\\necho -n test\\n\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXQXZS1DCC6PCHXKEAYY"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXQXZS1DCC6PCHXKEAYY"}
    logger.go:146: 2024-09-04T19:49:10.692-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXQXZS1DCC6PCHXKEAYY", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.692-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXQXZS1DCC6PCN36TQ2H"}
    logger.go:146: 2024-09-04T19:49:10.692-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXQXZS1DCC6PCN36TQ2H"}
    --- PASS: TestCommand/ShellScript (0.04s)
=== RUN   TestCommand/Input
=== PAUSE TestCommand/Input
=== CONT  TestCommand/Input
    logger.go:146: 2024-09-04T19:49:10.656-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXQYFK9TJ1XADAQDQ82H", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z"}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXQYFK9TJ1XAD8YTG65D", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z"]}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXQYFK9TJ1XAD8YTG65D", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3481896703/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nread line; echo $line | tr a-z A-Z\" script:\"read line; echo $line | tr a-z A-Z\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXQYFK9TJ1XAD8YTG65D"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXQYFK9TJ1XAD8YTG65D"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXQYFK9TJ1XAD8YTG65D", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXQYFK9TJ1XADAQDQ82H"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXQYFK9TJ1XADAQDQ82H"}
    --- PASS: TestCommand/Input (0.04s)
=== RUN   TestCommand/InputInteractive
=== PAUSE TestCommand/InputInteractive
=== CONT  TestCommand/InputInteractive
    logger.go:146: 2024-09-04T19:49:10.656-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXQXZS1DCC6PCFC9R00K", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z"}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z"]}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3926229854/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nread line; echo $line | tr a-z A-Z\" script:\"read line; echo $line | tr a-z A-Z\" interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.665-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R", "count": 5}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R", "count": 6}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXQWJ3680SHBNSCWR03R"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXQXZS1DCC6PCFC9R00K"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXQXZS1DCC6PCFC9R00K"}
    --- PASS: TestCommand/InputInteractive (0.05s)
=== RUN   TestCommand/StdoutStderr
=== PAUSE TestCommand/StdoutStderr
=== CONT  TestCommand/StdoutStderr
    logger.go:146: 2024-09-04T19:49:10.656-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXQYFK9TJ1XAD6CF7S5A", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho test | tee >(cat >&2)\n"}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXQYFK9TJ1XAD3F5KPHW", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho test | tee >(cat >&2)\n"]}
    logger.go:146: 2024-09-04T19:49:10.656-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXQYFK9TJ1XAD3F5KPHW", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-579220688/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho test | tee >(cat >&2)\\n\" commands:{items:\"echo test | tee >(cat >&2)\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.669-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXQYFK9TJ1XAD3F5KPHW"}
    logger.go:146: 2024-09-04T19:49:10.669-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXQYFK9TJ1XAD3F5KPHW"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXQYFK9TJ1XAD3F5KPHW", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXQYFK9TJ1XAD6CF7S5A"}
    logger.go:146: 2024-09-04T19:49:10.697-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXQYFK9TJ1XAD6CF7S5A"}
    --- PASS: TestCommand/StdoutStderr (0.04s)
=== RUN   TestCommand/MultiWordProgramName
=== PAUSE TestCommand/MultiWordProgramName
=== CONT  TestCommand/MultiWordProgramName
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXQXZS1DCC6PC7CTJP35", "program": "/bin/echo", "args": ["-n", "test"]}
    logger.go:146: 2024-09-04T19:49:10.657-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXQXZS1DCC6PC7CTJP35", "config": "program_name:\"echo -n test\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.667-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXQXZS1DCC6PC7CTJP35"}
    logger.go:146: 2024-09-04T19:49:10.667-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXQXZS1DCC6PC7CTJP35"}
    logger.go:146: 2024-09-04T19:49:10.669-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXQXZS1DCC6PC7CTJP35", "stderr": ""}
    --- PASS: TestCommand/MultiWordProgramName (0.02s)
=== RUN   TestCommand_FromCodeBlocks
--- PASS: TestCommand_FromCodeBlocks (0.00s)
=== RUN   TestCommand_FromCodeBlocks/BasicShell
=== PAUSE TestCommand_FromCodeBlocks/BasicShell
=== CONT  TestCommand_FromCodeBlocks/BasicShell
    logger.go:146: 2024-09-04T19:49:10.700-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSCZF6VRP7R7B9X05S7", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n test\n"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSCZF6VRP7R79GCVAJV", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n test\n"]}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSCZF6VRP7R79GCVAJV", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1692965071/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho -n test\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"echo -n test\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.725-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSCZF6VRP7R79GCVAJV"}
    logger.go:146: 2024-09-04T19:49:10.725-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSCZF6VRP7R79GCVAJV"}
    logger.go:146: 2024-09-04T19:49:10.745-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSCZF6VRP7R79GCVAJV", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.745-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSCZF6VRP7R7B9X05S7"}
    logger.go:146: 2024-09-04T19:49:10.745-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSCZF6VRP7R7B9X05S7"}
    --- PASS: TestCommand_FromCodeBlocks/BasicShell (0.05s)
=== RUN   TestCommand_FromCodeBlocks/ShellScript
=== PAUSE TestCommand_FromCodeBlocks/ShellScript
=== CONT  TestCommand_FromCodeBlocks/ShellScript
    logger.go:146: 2024-09-04T19:49:10.717-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSW0Y1MQ6MWGNCFXSWG", "program": "/bin/bash", "args": ["runme-script-1903764956"]}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSW0Y1MQ6MWGNCFXSWG", "config": "arguments:\"runme-script-1903764956\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2530669019\" script:\"#!/usr/local/bin/bash\\n\\nset -x -e -o pipefail\\n\\necho -n test\" mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSW0Y1MQ6MWGNCFXSWG"}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSW0Y1MQ6MWGNCFXSWG"}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSW0Y1MQ6MWGNCFXSWG", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSW0Y1MQ6MWGQJF6VTW"}
    --- PASS: TestCommand_FromCodeBlocks/ShellScript (0.02s)
=== RUN   TestCommand_FromCodeBlocks/ShellScriptInteractive
=== PAUSE TestCommand_FromCodeBlocks/ShellScriptInteractive
=== CONT  TestCommand_FromCodeBlocks/ShellScriptInteractive
    logger.go:146: 2024-09-04T19:49:10.698-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.698-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45", "program": "/bin/bash", "args": ["runme-script-1287940532"]}
    logger.go:146: 2024-09-04T19:49:10.699-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45", "config": "arguments:\"runme-script-1287940532\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2399460318\" script:\"#!/usr/local/bin/bash\\n\\nset -x -e -o pipefail\\n\\necho -n test\" interactive:true mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.715-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.716-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.717-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45", "count": 20}
    logger.go:146: 2024-09-04T19:49:10.717-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.717-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45", "count": 0}
    logger.go:146: 2024-09-04T19:49:10.718-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXSAN91E4BEH9W22KJ45"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSAN91E4BEH9X45TQJ9"}
    --- PASS: TestCommand_FromCodeBlocks/ShellScriptInteractive (0.03s)
=== RUN   TestCommand_FromCodeBlocks/Python
=== PAUSE TestCommand_FromCodeBlocks/Python
=== CONT  TestCommand_FromCodeBlocks/Python
    logger.go:146: 2024-09-04T19:49:10.701-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEH9HE83EBX", "program": "/opt/homebrew/bin/python3", "args": ["runme-script-800451587.py"]}
    logger.go:146: 2024-09-04T19:49:10.701-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSAN91E4BEH9HE83EBX", "config": "arguments:\"runme-script-800451587.py\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3621131145\" script:\"print('test')\" mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.745-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSAN91E4BEH9HE83EBX"}
    logger.go:146: 2024-09-04T19:49:10.745-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEH9HE83EBX"}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSAN91E4BEH9HE83EBX", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSAN91E4BEH9R3HAY6B"}
    --- PASS: TestCommand_FromCodeBlocks/Python (0.12s)
=== RUN   TestCommand_FromCodeBlocks/PythonInteractive
=== PAUSE TestCommand_FromCodeBlocks/PythonInteractive
=== CONT  TestCommand_FromCodeBlocks/PythonInteractive
    logger.go:146: 2024-09-04T19:49:10.699-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.701-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEHACR19MG0", "program": "/opt/homebrew/bin/python3", "args": ["runme-script-3672836728.py"]}
    logger.go:146: 2024-09-04T19:49:10.701-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXSAN91E4BEHACR19MG0", "config": "arguments:\"runme-script-3672836728.py\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2083050097\" script:\"print('test')\" interactive:true mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXSAN91E4BEHACR19MG0", "count": 0}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXSAN91E4BEHACR19MG0", "count": 6}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXSAN91E4BEHACR19MG0"}
    logger.go:146: 2024-09-04T19:49:10.815-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSAN91E4BEHAG8W0YDQ"}
    --- PASS: TestCommand_FromCodeBlocks/PythonInteractive (0.12s)
=== RUN   TestCommand_FromCodeBlocks/JavaScript
=== PAUSE TestCommand_FromCodeBlocks/JavaScript
=== CONT  TestCommand_FromCodeBlocks/JavaScript
    logger.go:146: 2024-09-04T19:49:10.698-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEHA12EC1DJ", "program": "/Users/jlewi/.nvm/versions/node/v18.19.0/bin/node", "args": ["runme-script-1512630539.js"]}
    logger.go:146: 2024-09-04T19:49:10.699-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSAN91E4BEHA12EC1DJ", "config": "arguments:\"runme-script-1512630539.js\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2917480768\" script:\"console.log('1'); console.log('2')\" mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.703-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSAN91E4BEHA12EC1DJ"}
    logger.go:146: 2024-09-04T19:49:10.703-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEHA12EC1DJ"}
    logger.go:146: 2024-09-04T19:49:10.831-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSAN91E4BEHA12EC1DJ", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.831-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSAN91E4BEHA46P1FZD"}
    --- PASS: TestCommand_FromCodeBlocks/JavaScript (0.13s)
=== RUN   TestCommand_FromCodeBlocks/Empty
=== PAUSE TestCommand_FromCodeBlocks/Empty
=== CONT  TestCommand_FromCodeBlocks/Empty
    logger.go:146: 2024-09-04T19:49:10.699-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSAN91E4BEHAA0XV2CX", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\n"}
    logger.go:146: 2024-09-04T19:49:10.699-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEHA9HRNWKM", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\n"]}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSAN91E4BEHA9HRNWKM", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4029165026/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.703-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSAN91E4BEHA9HRNWKM"}
    logger.go:146: 2024-09-04T19:49:10.703-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEHA9HRNWKM"}
    logger.go:146: 2024-09-04T19:49:10.711-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSAN91E4BEHA9HRNWKM", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.712-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSAN91E4BEHAA0XV2CX"}
    logger.go:146: 2024-09-04T19:49:10.715-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSAN91E4BEHAA0XV2CX"}
    --- PASS: TestCommand_FromCodeBlocks/Empty (0.02s)
=== RUN   TestCommand_FromCodeBlocks/WithInput
=== PAUSE TestCommand_FromCodeBlocks/WithInput
=== CONT  TestCommand_FromCodeBlocks/WithInput
    logger.go:146: 2024-09-04T19:49:10.699-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSB29HSYB54PJXXAHJS", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z\n"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEHAWZQEFEY", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z\n"]}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSAN91E4BEHAWZQEFEY", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4085339479/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nread line; echo $line | tr a-z A-Z\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"read line; echo $line | tr a-z A-Z\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.711-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSAN91E4BEHAWZQEFEY"}
    logger.go:146: 2024-09-04T19:49:10.711-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEHAWZQEFEY"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSAN91E4BEHAWZQEFEY", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSB29HSYB54PJXXAHJS"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSB29HSYB54PJXXAHJS"}
    --- PASS: TestCommand_FromCodeBlocks/WithInput (0.02s)
=== RUN   TestCommand_FromCodeBlocks/WithInputInteractive
=== PAUSE TestCommand_FromCodeBlocks/WithInputInteractive
=== CONT  TestCommand_FromCodeBlocks/WithInputInteractive
    logger.go:146: 2024-09-04T19:49:10.700-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSB29HSYB54PNQ6BG2J", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z\n"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXSB29HSYB54PK73RMVK", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nread line; echo $line | tr a-z A-Z\n"]}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXSB29HSYB54PK73RMVK", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1703726724/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nread line; echo $line | tr a-z A-Z\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"read line; echo $line | tr a-z A-Z\"} interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.744-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXSB29HSYB54PK73RMVK", "count": 5}
    logger.go:146: 2024-09-04T19:49:10.747-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXSB29HSYB54PK73RMVK", "count": 6}
    logger.go:146: 2024-09-04T19:49:10.747-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.748-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.748-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.748-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXSB29HSYB54PK73RMVK"}
    logger.go:146: 2024-09-04T19:49:10.748-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSB29HSYB54PNQ6BG2J"}
    logger.go:146: 2024-09-04T19:49:10.748-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSB29HSYB54PNQ6BG2J"}
    --- PASS: TestCommand_FromCodeBlocks/WithInputInteractive (0.05s)
=== RUN   TestCommand_FromCodeBlocks/Env
=== PAUSE TestCommand_FromCodeBlocks/Env
=== CONT  TestCommand_FromCodeBlocks/Env
    logger.go:146: 2024-09-04T19:49:10.698-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSAN91E4BEHAVEYXQFN", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n $MY_ENV\n"}
    logger.go:146: 2024-09-04T19:49:10.698-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSAN91E4BEHARXNAM9W", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n $MY_ENV\n"]}
    logger.go:146: 2024-09-04T19:49:10.698-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSAN91E4BEHARXNAM9W", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-3776835175/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho -n $MY_ENV\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"echo -n $MY_ENV\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSAN91E4BEHARXNAM9W"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSAN91E4BEHARXNAM9W"}
    logger.go:146: 2024-09-04T19:49:10.705-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSAN91E4BEHARXNAM9W", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.706-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSAN91E4BEHAVEYXQFN"}
    logger.go:146: 2024-09-04T19:49:10.711-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSAN91E4BEHAVEYXQFN"}
    --- PASS: TestCommand_FromCodeBlocks/Env (0.01s)
=== RUN   TestCommand_FromCodeBlocks/Interpreter
=== PAUSE TestCommand_FromCodeBlocks/Interpreter
=== CONT  TestCommand_FromCodeBlocks/Interpreter
    logger.go:146: 2024-09-04T19:49:10.700-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSCZF6VRP7R7916K45R", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n test\n"}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSB29HSYB54PQ2T26AX", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n test\n"]}
    logger.go:146: 2024-09-04T19:49:10.700-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSB29HSYB54PQ2T26AX", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2381926257/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho -n test\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"echo -n test\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.705-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSB29HSYB54PQ2T26AX"}
    logger.go:146: 2024-09-04T19:49:10.706-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSB29HSYB54PQ2T26AX"}
    logger.go:146: 2024-09-04T19:49:10.711-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSB29HSYB54PQ2T26AX", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.712-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSCZF6VRP7R7916K45R"}
    logger.go:146: 2024-09-04T19:49:10.712-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSCZF6VRP7R7916K45R"}
    --- PASS: TestCommand_FromCodeBlocks/Interpreter (0.02s)
=== RUN   TestCommand_FromCodeBlocks/FrontmatterShell
=== PAUSE TestCommand_FromCodeBlocks/FrontmatterShell
=== CONT  TestCommand_FromCodeBlocks/FrontmatterShell
    logger.go:146: 2024-09-04T19:49:10.719-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXSZH16VBEKHMAS1F5MK", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n $0 | xargs basename\n"}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSZH16VBEKHM88ZAYYV", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n $0 | xargs basename\n"]}
    logger.go:146: 2024-09-04T19:49:10.719-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSZH16VBEKHM88ZAYYV", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2925994824/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho -n $0 | xargs basename\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"echo -n $0 | xargs basename\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSZH16VBEKHM88ZAYYV"}
    logger.go:146: 2024-09-04T19:49:10.730-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSZH16VBEKHM88ZAYYV"}
    logger.go:146: 2024-09-04T19:49:10.740-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSZH16VBEKHM88ZAYYV", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.740-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXSZH16VBEKHMAS1F5MK"}
    logger.go:146: 2024-09-04T19:49:10.741-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXSZH16VBEKHMAS1F5MK"}
    --- PASS: TestCommand_FromCodeBlocks/FrontmatterShell (0.02s)
=== RUN   TestCommand_FromCodeBlocks/DefaultToCat
=== PAUSE TestCommand_FromCodeBlocks/DefaultToCat
=== CONT  TestCommand_FromCodeBlocks/DefaultToCat
    logger.go:146: 2024-09-04T19:49:10.712-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXSQ22MV6922WZGH6VEY", "program": "/bin/cat", "args": ["runme-script-2085464968"]}
    logger.go:146: 2024-09-04T19:49:10.712-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXSQ22MV6922WZGH6VEY", "config": "arguments:\"runme-script-2085464968\" directory:\"/var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2995052469\" script:\"SELECT * FROM users;\" mode:COMMAND_MODE_FILE"}
    logger.go:146: 2024-09-04T19:49:10.725-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXSQ22MV6922WZGH6VEY"}
    logger.go:146: 2024-09-04T19:49:10.725-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXSQ22MV6922WZGH6VEY"}
    logger.go:146: 2024-09-04T19:49:10.726-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXSQ22MV6922WZGH6VEY", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.726-0700	INFO	FileCommand	cleaning up the temporary dir	{"instanceID": "01J701BXSQ22MV6922X2TPV3SM"}
    --- PASS: TestCommand_FromCodeBlocks/DefaultToCat (0.02s)
=== RUN   TestCommand_Getters
=== PAUSE TestCommand_Getters
=== CONT  TestCommand_Getters
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701C2XBM741GS3H175SY9TV", "program": "/bin/sleep", "args": ["1"]}
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	starting	{"instanceID": "01J701C2XBM741GS3H175SY9TV", "config": "program_name:\"sleep\" arguments:\"1\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:15.952-0700	INFO	NativeCommand	started	{"instanceID": "01J701C2XBM741GS3H175SY9TV"}
    logger.go:146: 2024-09-04T19:49:15.953-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701C2XBM741GS3H175SY9TV"}
    logger.go:146: 2024-09-04T19:49:16.967-0700	INFO	NativeCommand	finished	{"instanceID": "01J701C2XBM741GS3H175SY9TV", "stderr": ""}
--- PASS: TestCommand_Getters (1.02s)
=== RUN   TestCommand_InvalidProgram
=== PAUSE TestCommand_InvalidProgram
=== CONT  TestCommand_InvalidProgram
--- PASS: TestCommand_InvalidProgram (0.01s)
=== RUN   TestCommand_InvalidScript
=== PAUSE TestCommand_InvalidScript
=== CONT  TestCommand_InvalidScript
    logger.go:146: 2024-09-04T19:49:15.947-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701C2XBM741GS3H1ZKYPAJ9", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nfailhereplease\necho executed\n"}
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701C2XBM741GS3H1YTS3M1V", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nfailhereplease\necho executed\n"]}
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	starting	{"instanceID": "01J701C2XBM741GS3H1YTS3M1V", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-4153583517/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nfailhereplease\\necho executed\\n\" commands:{items:\"failhereplease\" items:\"echo executed\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:15.959-0700	INFO	NativeCommand	started	{"instanceID": "01J701C2XBM741GS3H1YTS3M1V"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701C2XBM741GS3H1YTS3M1V"}
    logger.go:146: 2024-09-04T19:49:15.969-0700	INFO	NativeCommand	finished	{"instanceID": "01J701C2XBM741GS3H1YTS3M1V", "error": "exit status 127", "errorVerbose": "exit status 127\ngithub.com/stateful/runme/v3/internal/command.(*nativeCommand).Wait\n\t/Users/jlewi/git_runme/internal/command/command_native.go:106\ngithub.com/stateful/runme/v3/internal/command.(*inlineShellCommand).Wait\n\t/Users/jlewi/git_runme/internal/command/command_inline_shell.go:49\ngithub.com/stateful/runme/v3/internal/command.TestCommand_InvalidScript\n\t/Users/jlewi/git_runme/internal/command/command_unix_test.go:311\ntesting.tRunner\n\t/opt/homebrew/opt/go/libexec/src/testing/testing.go:1689\nruntime.goexit\n\t/opt/homebrew/opt/go/libexec/src/runtime/asm_arm64.s:1222", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:15.969-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701C2XBM741GS3H1ZKYPAJ9"}
    logger.go:146: 2024-09-04T19:49:15.969-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701C2XBM741GS3H1ZKYPAJ9"}
--- PASS: TestCommand_InvalidScript (0.02s)
=== RUN   TestCommand_SetWinsize
=== PAUSE TestCommand_SetWinsize
=== CONT  TestCommand_SetWinsize
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	TerminalCommand	starting a terminal command	{"instanceID": "01J701C2XBM741GS3H292G8TYA"}
    logger.go:146: 2024-09-04T19:49:15.947-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701C2XBM741GS3H24D9X6BY", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nsleep 1\ntput cols -T linux\ntput lines -T linux\n"}
    logger.go:146: 2024-09-04T19:49:15.948-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5", "program": "/bin/bash", "args": []}
    logger.go:146: 2024-09-04T19:49:15.948-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:15.950-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701C2XBM741GS3H20MJ86S4", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nsleep 1\ntput cols -T linux\ntput lines -T linux\n"]}
    logger.go:146: 2024-09-04T19:49:15.949-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5", "config": "program_name:\"bash\" interactive:true mode:COMMAND_MODE_TERMINAL"}
    logger.go:146: 2024-09-04T19:49:15.951-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701C2XBM741GS3H20MJ86S4", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2436406997/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nsleep 1\\ntput cols -T linux\\ntput lines -T linux\\n\" commands:{items:\"sleep 1\" items:\"tput cols -T linux\" items:\"tput lines -T linux\"} interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:15.960-0700	INFO	VirtualCommand	started	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	TerminalCommand	a terminal command started	{"instanceID": "01J701C2XBM741GS3H292G8TYA"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	VirtualCommand	started	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:16.962-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:16.980-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701C2XBM741GS3H20MJ86S4", "count": 8}
    logger.go:146: 2024-09-04T19:49:16.980-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:16.980-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5", "count": 1277}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5", "count": 467}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701C2XBM741GS3H27Y6AVV5"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701C2XBM741GS3H20MJ86S4"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701C2XBM741GS3H24D9X6BY"}
    logger.go:146: 2024-09-04T19:49:16.981-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701C2XBM741GS3H24D9X6BY"}
--- PASS: TestCommand_SetWinsize (0.00s)
=== RUN   TestCommand_SetWinsize/InlineInteractive
=== PAUSE TestCommand_SetWinsize/InlineInteractive
=== CONT  TestCommand_SetWinsize/InlineInteractive
    --- PASS: TestCommand_SetWinsize/InlineInteractive (1.03s)
=== RUN   TestCommand_SetWinsize/Terminal
=== PAUSE TestCommand_SetWinsize/Terminal
=== CONT  TestCommand_SetWinsize/Terminal
    --- PASS: TestCommand_SetWinsize/Terminal (1.03s)
=== RUN   TestCommand_Session
    logger.go:146: 2024-09-04T19:49:10.832-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXXFBAWNCSKTGH9F8FJC", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nexport TEST_ENV=test1\n"}
    logger.go:146: 2024-09-04T19:49:10.832-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXXFBAWNCSKTGECAEC2A", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nexport TEST_ENV=test1\n"]}
    logger.go:146: 2024-09-04T19:49:10.832-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXXFBAWNCSKTGECAEC2A", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2233818047/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nexport TEST_ENV=test1\\n\" commands:{items:\"export TEST_ENV=test1\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.833-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXXFBAWNCSKTGECAEC2A"}
    logger.go:146: 2024-09-04T19:49:10.833-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXXFBAWNCSKTGECAEC2A"}
    logger.go:146: 2024-09-04T19:49:10.836-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXXFBAWNCSKTGECAEC2A", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.836-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXXFBAWNCSKTGH9F8FJC"}
    logger.go:146: 2024-09-04T19:49:10.836-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXXFBAWNCSKTGH9F8FJC"}
    logger.go:146: 2024-09-04T19:49:10.837-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXXM8WG7SPY10JZJ3SXW", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n \"TEST_ENV equals $TEST_ENV\"\n"}
    logger.go:146: 2024-09-04T19:49:10.837-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701BXXM8WG7SPY10FHM5YK4", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\necho -n \"TEST_ENV equals $TEST_ENV\"\n"]}
    logger.go:146: 2024-09-04T19:49:10.837-0700	INFO	NativeCommand	starting	{"instanceID": "01J701BXXM8WG7SPY10FHM5YK4", "config": "program_name:\"bash\" arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-2537939887/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\necho -n \\\"TEST_ENV equals $TEST_ENV\\\"\\n\" commands:{items:\"echo -n \\\"TEST_ENV equals $TEST_ENV\\\"\"} mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.838-0700	INFO	NativeCommand	started	{"instanceID": "01J701BXXM8WG7SPY10FHM5YK4"}
    logger.go:146: 2024-09-04T19:49:10.838-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701BXXM8WG7SPY10FHM5YK4"}
    logger.go:146: 2024-09-04T19:49:10.840-0700	INFO	NativeCommand	finished	{"instanceID": "01J701BXXM8WG7SPY10FHM5YK4", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:10.840-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXXM8WG7SPY10JZJ3SXW"}
    logger.go:146: 2024-09-04T19:49:10.840-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXXM8WG7SPY10JZJ3SXW"}
--- PASS: TestCommand_Session (0.01s)
=== RUN   TestCommand_SimulateCtrlC
    logger.go:146: 2024-09-04T19:49:10.841-0700	DEBUG	InlineShellCommand	inline shell script	{"instanceID": "01J701BXXSE62EK2QMF7PD79RS", "script": "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nbash\n"}
    logger.go:146: 2024-09-04T19:49:10.841-0700	INFO	VirtualCommand	disabling echo	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:10.841-0700	INFO	VirtualCommand	detected program path and arguments	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99", "program": "/bin/bash", "args": ["-c", "set -e -o pipefail\n\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_pre.fifo\n __cleanup() {\nrv=$?\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_post.fifo\nexit $rv\n}\n trap -- \"__cleanup\" EXIT\nbash\n"]}
    logger.go:146: 2024-09-04T19:49:10.841-0700	INFO	VirtualCommand	starting	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99", "config": "arguments:\"-c\" arguments:\"set -e -o pipefail\\n\\n env -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_pre.fifo\\n __cleanup() {\\nrv=$?\\nenv -0 > /var/folders/pc/wqw4h6c54_x2s33qgmdzf9_w0000gn/T/runme-1450396292/env_post.fifo\\nexit $rv\\n}\\n trap -- \\\"__cleanup\\\" EXIT\\nbash\\n\" directory:\"/Users/jlewi/git_runme/internal/command\" commands:{items:\"bash\"} interactive:true mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:10.842-0700	INFO	VirtualCommand	started	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:12.345-0700	INFO	VirtualCommand	waiting for finish	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:12.345-0700	INFO	VirtualCommand	copied from stdin to pty	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99", "count": 11}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	VirtualCommand	copied from pty to stdout	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99", "count": 201}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	VirtualCommand	finished	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99", "error": "signal: killed", "errorVerbose": "signal: killed\ngithub.com/stateful/runme/v3/internal/command.(*virtualCommand).Wait\n\t/Users/jlewi/git_runme/internal/command/command_virtual.go:164\ngithub.com/stateful/runme/v3/internal/command.(*inlineShellCommand).Wait\n\t/Users/jlewi/git_runme/internal/command/command_inline_shell.go:49\ngithub.com/stateful/runme/v3/internal/command.TestCommand_SimulateCtrlC\n\t/Users/jlewi/git_runme/internal/command/command_unix_test.go:485\ntesting.tRunner\n\t/opt/homebrew/opt/go/libexec/src/testing/testing.go:1689\nruntime.goexit\n\t/opt/homebrew/opt/go/libexec/src/runtime/asm_arm64.s:1222"}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	VirtualCommand	closed IO	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	VirtualCommand	waiting IO goroutines	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	VirtualCommand	finished waiting for IO goroutines	{"instanceID": "01J701BXXSE62EK2QMF3WRCE99"}
    logger.go:146: 2024-09-04T19:49:15.844-0700	INFO	InlineShellCommand	collecting the environment after the script execution	{"instanceID": "01J701BXXSE62EK2QMF7PD79RS"}
    logger.go:146: 2024-09-04T19:49:15.946-0700	INFO	InlineShellCommand	collected the environment after the script execution	{"instanceID": "01J701BXXSE62EK2QMF7PD79RS"}
    command_unix_test.go:485: 
        	Error Trace:	/Users/jlewi/git_runme/internal/command/command_unix_test.go:485
        	Error:      	Error message not equal:
        	            	expected: "exit status 130"
        	            	actual  : "signal: killed"
        	Test:       	TestCommand_SimulateCtrlC
--- FAIL: TestCommand_SimulateCtrlC (5.11s)

=== RUN   TestCommand_StopWithSignal
=== PAUSE TestCommand_StopWithSignal
=== CONT  TestCommand_StopWithSignal
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701C2XBM741GS3H1PRX0T96", "program": "/bin/sleep", "args": ["10"]}
    logger.go:146: 2024-09-04T19:49:15.947-0700	INFO	NativeCommand	starting	{"instanceID": "01J701C2XBM741GS3H1PRX0T96", "config": "program_name:\"sleep\" arguments:\"10\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:15.960-0700	INFO	NativeCommand	started	{"instanceID": "01J701C2XBM741GS3H1PRX0T96"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701C2XBM741GS3H1PRX0T96"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	NativeCommand	stopping with signal	{"instanceID": "01J701C2XBM741GS3H1PRX0T96", "signal": "interrupt"}
    logger.go:146: 2024-09-04T19:49:15.961-0700	INFO	NativeCommand	signaling to the process group	{"instanceID": "01J701C2XBM741GS3H1PRX0T96", "signal": "interrupt"}
    logger.go:146: 2024-09-04T19:49:25.968-0700	INFO	NativeCommand	finished	{"instanceID": "01J701C2XBM741GS3H1PRX0T96", "stderr": ""}
    logger.go:146: 2024-09-04T19:49:25.968-0700	INFO	NativeCommand	detected program path and arguments	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7", "program": "/bin/sleep", "args": ["10"]}
    logger.go:146: 2024-09-04T19:49:25.968-0700	INFO	NativeCommand	starting	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7", "config": "program_name:\"sleep\" arguments:\"10\" mode:COMMAND_MODE_INLINE"}
    logger.go:146: 2024-09-04T19:49:25.970-0700	INFO	NativeCommand	started	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7"}
    logger.go:146: 2024-09-04T19:49:25.971-0700	INFO	NativeCommand	waiting for finish	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7"}
    logger.go:146: 2024-09-04T19:49:25.971-0700	INFO	NativeCommand	stopping with signal	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7", "signal": "killed"}
    logger.go:146: 2024-09-04T19:49:25.971-0700	INFO	NativeCommand	signaling to the process group	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7", "signal": "killed"}
    logger.go:146: 2024-09-04T19:49:25.972-0700	INFO	NativeCommand	finished	{"instanceID": "01J701CCPGNPNYHVN11ZBTSFA7", "error": "signal: killed", "errorVerbose": "signal: killed\ngithub.com/stateful/runme/v3/internal/command.(*nativeCommand).Wait\n\t/Users/jlewi/git_runme/internal/command/command_native.go:106\ngithub.com/stateful/runme/v3/internal/command.TestCommand_StopWithSignal.func2\n\t/Users/jlewi/git_runme/internal/command/command_unix_test.go:523\ntesting.tRunner\n\t/opt/homebrew/opt/go/libexec/src/testing/testing.go:1689\nruntime.goexit\n\t/opt/homebrew/opt/go/libexec/src/runtime/asm_arm64.s:1222", "stderr": ""}
--- FAIL: TestCommand_StopWithSignal (10.02s)
=== RUN   TestCommand_StopWithSignal/SIGINT
    command_unix_test.go:509: 
        	Error Trace:	/Users/jlewi/git_runme/internal/command/command_unix_test.go:509
        	Error:      	An error is expected but got nil.
        	Test:       	TestCommand_StopWithSignal/SIGINT
    --- FAIL: TestCommand_StopWithSignal/SIGINT (10.02s)

=== RUN   TestCommand_StopWithSignal/SIGKILL
    --- PASS: TestCommand_StopWithSignal/SIGKILL (0.00s)

FAIL

@sonarqubecloud SonarQubeCloud
Copy link

sonarqubecloud bot commented Sep 5, 2024

Quality Gate Failed Quality Gate failed

Failed conditions
22.2% Coverage on New Code (required ≥ 50%)

See analysis details on SonarCloud

@jlewi
Copy link
Contributor Author

jlewi commented Sep 5, 2024 •
edited
Loading

Tests pass on retry; seems like there might be some flakiness.

But I couldn't reproduce the flakiness locally.

go test -count=30 --run=TestCommand ./internal/command/... 
ok  	github.com/stateful/runme/v3/internal/command	79.113s

@sourishkrout sourishkrout self-requested a review September 5, 2024 15:01
sourishkrout
sourishkrout approved these changes Sep 5, 2024
View reviewed changes
Copy link
Member

@sourishkrout sourishkrout left a comment

Choose a reason for hiding this comment

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

✅ LGTM

@sourishkrout sourishkrout merged commit e781f00 into main Sep 5, 2024
6 of 7 checks passed
@sourishkrout sourishkrout deleted the jlewi/logscleanup branch September 5, 2024 15:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@sourishkrout sourishkrout sourishkrout approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@jlewi @sourishkrout