Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

Sign up
Appearance settings

fix: include all log args in the log message #2101

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

Merged
kittaakos merged 1 commit into main from log-debug
Jul 7, 2023
Merged

fix: include all log args in the log message #2101

kittaakos merged 1 commit into main from log-debug
Jul 7, 2023

Conversation

Copy link
Contributor

@kittaakos kittaakos commented Jun 16, 2023
edited
Loading

Motivation

debug messages logged by the Theia logger were not forwarded to the file logger. This PR fixes it.

Change description

  • In the bundled application, the customized logger that writes the log
    files bogusly includes only the first message fragment in the log
    message. This PR ensures all message fragments are included in the final
    message before it is printed to the console/terminal and persisted to
    the rotating log files.
  • Includes messages with debug severity in the log.
  • Disables the ANSI coloring in the CLI daemon log by adding the
    NO_COLOR=true environment variable to the spawned CLI daemon process.
  • Trims trailing line ending of the daemon log.

Other information

Steps to verify:

  • Start IDE2 with debug log level from a terminal. On macOS, it is similar to /Applications/Arduino\ IDE\ 2.1.0.app/Contents/MacOS/Arduino\ IDE --log-level debug.
  • Attach then detach a board. Verify that you see root DEBUG Board config changed: messages in the terminal.
  • Make sure messages consisting of multiple fragments are logged correctly. A good example is DEBUG Starting the deployer with the list of resolvers. You see the list of resolvers as a JSON string.
  • Quit IDE2 and open up the most recent log file. It is under /Library/Logs/Arduino IDE on macOS. Verify that the root DEBUG Board config changed: messages are inside the file. This does not work with 2.1.0.
  • Verify the followings:
    • no ANSI control codes in the log, and
    • no unnecessary empty lines.

Before:

INFO[0000] Required tool tool="rp2040:pqt-gcc@1.5.0-b-c7bab52"

After:

2023年06月23日T11:47:18.237Z daemon INFO time="2023-06-23T13:47:18+02:00" level=info msg="Required tool" tool="rp2040:pqt-elf2uf2@1.5.0-b-c7bab52"
time="2023-06-23T13:47:18+02:00" level=info msg="Required tool" tool="rp2040:pqt-gcc@1.5.0-b-c7bab52"

Before:

2023年06月23日T11:35:13.406Z daemon INFO DEBU[0002] Querying installed cores for board identification... 
2023年06月23日T11:35:13.406Z daemon INFO DEBU[0002] Querying installed cores for board identification... 

After:

time="2023-06-23T13:47:09+02:00" level=debug msg="Querying installed cores for board identification..."
time="2023-06-23T13:47:09+02:00" level=debug msg="Querying installed cores for board identification..."

Ref: #2100 (comment)

Reviewer checklist

  • PR addresses a single concern.
  • The PR has no duplicates (please search among the Pull Requests before creating one)
  • PR title and description are properly filled.
  • Docs have been added / updated (for bug fixes / features)

@kittaakos kittaakos self-assigned this Jun 16, 2023
@kittaakos kittaakos added topic: code Related to content of the project itself type: imperfection Perceived defect in any part of project labels Jun 16, 2023
Copy link
Contributor

@per1234 per1234 left a comment

Choose a reason for hiding this comment

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

I'm seeing a difference in the terminal output when I compare the build from this PR to the build from the main branch.

For example, here is the first part of the terminal output from main:

$ ./Arduino\ IDE.exe --log-level debug
Arduino IDE 2.1.1-snapshot-8f8b46f
Starting backend process. PID: 30036
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/per/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T05:19:23.855Z root INFO Backend Object.initialize: 3.2 ms [Finished 0.645 s after backend start]
2023年06月23日T05:19:23.855Z root INFO Backend Object.configure: 2.6 ms [Finished 0.645 s after backend start]
2023年06月23日T05:19:23.856Z root INFO Backend MessagingContribution.onStart: 1.0 ms [Finished 0.645 s after backend start]
2023年06月23日T05:19:23.856Z root INFO Backend OSBackendApplicationContribution.configure: 0.2 ms [Finished 0.668 s after backend start]
2023年06月23日T05:19:23.856Z root INFO Backend DefaultWorkspaceServer.onStart: 0.2 ms [Finished 0.668 s after backend start]
2023年06月23日T05:19:23.857Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.1 ms [Finished 0.668 s after backend start]
2023年06月23日T05:19:23.857Z root INFO Backend PluginLocalizationBackendContribution.initialize: 22.9 ms [Finished 0.669 s after backend start]
2023年06月23日T05:19:23.857Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.1 ms [Finished 0.669 s after backend start]
2023年06月23日T05:19:23.858Z root DEBUG Starting the deployer with the list of resolvers [
 LocalDirectoryPluginDeployerResolverWithFallback {},
 GithubPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\per\\AppData\\Local\\Temp\\github-remote',
 request: ElectronBackendRequestService {}
 },
 HttpPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\per\\AppData\\Local\\Temp\\http-remote',
 request: ElectronBackendRequestService {}
 },
 LocalVSIXFilePluginDeployerResolver {
 environment: PluginVSCodeEnvironment { environments: [EnvVariablesServer] }
 }
]
2023年06月23日T05:19:23.859Z root INFO Backend ElectronTokenBackendContribution.configure: 0.5 ms [Finished 0.669 s after backend start]

(note that it prints the list of "resolvers")

This is the start of the terminal output when using the build from this PR:

$ ./Arduino\ IDE.exe --log-level debug
Arduino IDE 2.1.1-snapshot-315e9eb
Starting backend process. PID: 15004
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/per/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T05:28:13.801Z root INFO Backend Object.initialize: 3.0 ms [Finished 1.729 s after backend start]
2023年06月23日T05:28:13.801Z root INFO Backend Object.configure: 2.4 ms [Finished 1.729 s after backend start]
2023年06月23日T05:28:13.801Z root INFO Backend MessagingContribution.onStart: 1.0 ms [Finished 1.729 s after backend start]
2023年06月23日T05:28:13.801Z root INFO Backend OSBackendApplicationContribution.configure: 0.2 ms [Finished 1.750 s after backend start]
2023年06月23日T05:28:13.802Z root INFO Backend DefaultWorkspaceServer.onStart: 0.2 ms [Finished 1.750 s after backend start]
2023年06月23日T05:28:13.802Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.1 ms [Finished 1.750 s after backend start]
2023年06月23日T05:28:13.803Z root INFO Backend PluginLocalizationBackendContribution.initialize: 21.3 ms [Finished 1.750 s after backend start]
2023年06月23日T05:28:13.803Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.1 ms [Finished 1.750 s after backend start]
2023年06月23日T05:28:13.803Z root DEBUG Starting the deployer with the list of resolvers
2023年06月23日T05:28:13.803Z root INFO Backend ElectronTokenBackendContribution.configure: 0.6 ms [Finished 1.751 s after backend start]

(Note that it does not print the list of "resolvers")

Copy link
Contributor Author

'm seeing a difference in the terminal output when I compare the build from this PR to the build from the main branch.

Thank you! Interesting one. I could reproduce it with CMD.EXE.

2.1.0 with --log-level debug:

C:\Users\kittaakos\Desktop\ide2 2.1.0>"Arduino IDE.exe" --log-level debug
C:\Users\kittaakos\Desktop\ide2 2.1.0>
Arduino IDE 2.1.0
Starting backend process. PID: 6592
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.theia'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T07:56:46.709Z root INFO Backend Object.initialize: 6.2 ms [Finished 2.133 s after backend start]
2023年06月23日T07:56:46.709Z root INFO Backend Object.configure: 5.3 ms [Finished 2.133 s after backend start]
2023年06月23日T07:56:46.710Z root INFO Backend MessagingContribution.onStart: 2.5 ms [Finished 2.133 s after backend start]
2023年06月23日T07:56:46.711Z root INFO Backend OSBackendApplicationContribution.configure: 0.5 ms [Finished 2.197 s after backend start]
2023年06月23日T07:56:46.713Z root INFO Backend DefaultWorkspaceServer.onStart: 0.4 ms [Finished 2.197 s after backend start]
2023年06月23日T07:56:46.715Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.1 ms [Finished 2.197 s after backend start]
2023年06月23日T07:56:46.716Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 63.4 ms [Finished 2.197 s after backend start]
2023年06月23日T07:56:46.716Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.3 ms [Finished 2.197 s after backend start]
2023年06月23日T07:56:46.717Z root DEBUG Starting the deployer with the list of resolvers [
 LocalDirectoryPluginDeployerResolverWithFallback {},
 GithubPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\KITTAA~1\\AppData\\Local\\Temp\\github-remote'
 },
 HttpPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\KITTAA~1\\AppData\\Local\\Temp\\http-remote'
 },
 LocalVSIXFilePluginDeployerResolver {
 environment: PluginVSCodeEnvironment { environments: [EnvVariablesServer] }
 }
]
2023年06月23日T07:56:46.719Z root INFO Backend ElectronTokenBackendContribution.configure: 2.3 ms [Finished 2.200 s after backend start]

2.1.0 normal IDE2 start:

C:\Users\kittaakos\Desktop\ide2 2.1.0>"Arduino IDE.exe"
C:\Users\kittaakos\Desktop\ide2 2.1.0>
Arduino IDE 2.1.0
Starting backend process. PID: 9072
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.theia'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T07:59:45.743Z root INFO Backend Object.initialize: 11.5 ms [Finished 2.126 s after backend start]
2023年06月23日T07:59:45.744Z root INFO Backend Object.configure: 9.5 ms [Finished 2.127 s after backend start]
2023年06月23日T07:59:45.744Z root INFO Backend MessagingContribution.onStart: 4.6 ms [Finished 2.127 s after backend start]
2023年06月23日T07:59:45.745Z root INFO Backend OSBackendApplicationContribution.configure: 0.5 ms [Finished 2.183 s after backend start]
2023年06月23日T07:59:45.747Z root INFO Backend DefaultWorkspaceServer.onStart: 0.5 ms [Finished 2.183 s after backend start]
2023年06月23日T07:59:45.748Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.1 ms [Finished 2.183 s after backend start]
2023年06月23日T07:59:45.749Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 55.6 ms [Finished 2.183 s after backend start]
2023年06月23日T07:59:45.749Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.3 ms [Finished 2.183 s after backend start]
2023年06月23日T07:59:45.751Z root INFO Backend ElectronTokenBackendContribution.configure: 1.9 ms [Finished 2.185 s after backend start]

2.1.1-nightly with --log-level debug:

C:\Users\kittaakos\Desktop\ide2 2.1.1-nightly>"Arduino IDE.exe" --log-level debug
C:\Users\kittaakos\Desktop\ide2 2.1.1-nightly>
Arduino IDE 2.1.1-nightly-20230623
Starting backend process. PID: 2720
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:05:36.490Z root INFO Backend Object.initialize: 9.6 ms [Finished 2.573 s after backend start]
2023年06月23日T08:05:36.492Z root INFO Backend Object.configure: 7.8 ms [Finished 2.573 s after backend start]
2023年06月23日T08:05:36.493Z root INFO Backend MessagingContribution.onStart: 2.7 ms [Finished 2.573 s after backend start]
2023年06月23日T08:05:36.495Z root INFO Backend OSBackendApplicationContribution.configure: 0.9 ms [Finished 2.639 s after backend start]
2023年06月23日T08:05:36.497Z root INFO Backend DefaultWorkspaceServer.onStart: 0.8 ms [Finished 2.639 s after backend start]
2023年06月23日T08:05:36.500Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.5 ms [Finished 2.640 s after backend start]
2023年06月23日T08:05:36.503Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 66.9 ms [Finished 2.641 s after backend start]
2023年06月23日T08:05:36.504Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.7 ms [Finished 2.641 s after backend start]
2023年06月23日T08:05:36.505Z root DEBUG Starting the deployer with the list of resolvers [
 LocalDirectoryPluginDeployerResolverWithFallback {},
 GithubPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\KITTAA~1\\AppData\\Local\\Temp\\github-remote',
 request: ElectronBackendRequestService {}
 },
 HttpPluginDeployerResolver {
 unpackedFolder: 'C:\\Users\\KITTAA~1\\AppData\\Local\\Temp\\http-remote',
 request: ElectronBackendRequestService {}
 },
 LocalVSIXFilePluginDeployerResolver {
 environment: PluginVSCodeEnvironment { environments: [EnvVariablesServer] }
 }
]
2023年06月23日T08:05:36.511Z root INFO Backend ElectronTokenBackendContribution.configure: 3.5 ms [Finished 2.644 s after backend start]

2.1.1-nightly normal start:

C:\Users\kittaakos\Desktop\ide2 2.1.1-nightly>"Arduino IDE.exe"
C:\Users\kittaakos\Desktop\ide2 2.1.1-nightly>
Arduino IDE 2.1.1-nightly-20230623
Starting backend process. PID: 11832
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:06:37.476Z root INFO Backend Object.initialize: 9.0 ms [Finished 1.855 s after backend start]
2023年06月23日T08:06:37.477Z root INFO Backend Object.configure: 7.5 ms [Finished 1.855 s after backend start]
2023年06月23日T08:06:37.477Z root INFO Backend MessagingContribution.onStart: 4.1 ms [Finished 1.855 s after backend start]
2023年06月23日T08:06:37.478Z root INFO Backend OSBackendApplicationContribution.configure: 0.5 ms [Finished 1.905 s after backend start]
2023年06月23日T08:06:37.479Z root INFO Backend DefaultWorkspaceServer.onStart: 0.4 ms [Finished 1.905 s after backend start]
2023年06月23日T08:06:37.481Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.2 ms [Finished 1.905 s after backend start]
2023年06月23日T08:06:37.482Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 50.0 ms [Finished 1.905 s after backend start]
2023年06月23日T08:06:37.482Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.3 ms [Finished 1.905 s after backend start]
2023年06月23日T08:06:37.483Z root INFO Backend ElectronTokenBackendContribution.configure: 1.8 ms [Finished 1.907 s after backend start]

❌ The build from this PR with --log-level debug:

C:\Users\kittaakos\Desktop\ide2 2.1.1-GH-2101>"Arduino IDE.exe" --log-level debug
C:\Users\kittaakos\Desktop\ide2 2.1.1-GH-2101>
Arduino IDE 2.1.1-snapshot-315e9eb
Starting backend process. PID: 15820
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:10:39.864Z root INFO Backend Object.initialize: 10.5 ms [Finished 2.453 s after backend start]
2023年06月23日T08:10:39.865Z root INFO Backend Object.configure: 9.2 ms [Finished 2.454 s after backend start]
2023年06月23日T08:10:39.865Z root INFO Backend MessagingContribution.onStart: 4.5 ms [Finished 2.454 s after backend start]
2023年06月23日T08:10:39.867Z root INFO Backend OSBackendApplicationContribution.configure: 0.8 ms [Finished 2.552 s after backend start]
2023年06月23日T08:10:39.868Z root INFO Backend DefaultWorkspaceServer.onStart: 0.6 ms [Finished 2.552 s after backend start]
2023年06月23日T08:10:39.869Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.3 ms [Finished 2.552 s after backend start]
2023年06月23日T08:10:39.871Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 98.2 ms [Finished 2.553 s after backend start]
2023年06月23日T08:10:39.871Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.5 ms [Finished 2.553 s after backend start]
2023年06月23日T08:10:39.872Z root DEBUG Starting the deployer with the list of resolvers
2023年06月23日T08:10:39.872Z root INFO Backend ElectronTokenBackendContribution.configure: 2.4 ms [Finished 2.555 s after backend start]

✅ The build from this PR, normal start:

C:\Users\kittaakos\Desktop\ide2 2.1.1-GH-2101>"Arduino IDE.exe"
C:\Users\kittaakos\Desktop\ide2 2.1.1-GH-2101>
Arduino IDE 2.1.1-snapshot-315e9eb
Starting backend process. PID: 20476
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///c%3A/Users/kittaakos/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:12:28.212Z root INFO Backend Object.initialize: 8.0 ms [Finished 1.838 s after backend start]
2023年06月23日T08:12:28.213Z root INFO Backend Object.configure: 6.9 ms [Finished 1.838 s after backend start]
2023年06月23日T08:12:28.213Z root INFO Backend MessagingContribution.onStart: 3.7 ms [Finished 1.838 s after backend start]
2023年06月23日T08:12:28.214Z root INFO Backend OSBackendApplicationContribution.configure: 0.6 ms [Finished 1.901 s after backend start]
2023年06月23日T08:12:28.216Z root INFO Backend DefaultWorkspaceServer.onStart: 0.4 ms [Finished 1.901 s after backend start]
2023年06月23日T08:12:28.218Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.2 ms [Finished 1.902 s after backend start]
2023年06月23日T08:12:28.219Z root WARN Backend PluginLocalizationBackendContribution.initialize took longer than the expected maximum 50 milliseconds: 63.2 ms [Finished 1.902 s after backend start]
2023年06月23日T08:12:28.220Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.4 ms [Finished 1.902 s after backend start]
2023年06月23日T08:12:28.221Z root INFO Backend ElectronTokenBackendContribution.configure: 2.0 ms [Finished 1.904 s after backend start]

Copy link
Contributor Author

kittaakos commented Jun 23, 2023
edited
Loading

OK. I have noticed that this kind of works. Same behavior on macOS, but DEBUG works.

a.kitta@Akoss-MacBook-Pro Desktop % ./Arduino\ IDE.app/Contents/MacOS/Arduino\ IDE --log-level debug
Arduino IDE 2.1.1-snapshot-315e9eb
Starting backend process. PID: 65974
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///Users/a.kitta/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:33:38.142Z root INFO Backend Object.initialize: 5.2 ms [Finished 1.123 s after backend start]
2023年06月23日T08:33:38.145Z root INFO Backend Object.configure: 4.2 ms [Finished 1.123 s after backend start]
2023年06月23日T08:33:38.145Z root INFO Backend MessagingContribution.onStart: 1.6 ms [Finished 1.123 s after backend start]
2023年06月23日T08:33:38.146Z root INFO Backend OSBackendApplicationContribution.configure: 0.5 ms [Finished 1.172 s after backend start]
2023年06月23日T08:33:38.146Z root INFO Backend DefaultWorkspaceServer.onStart: 0.4 ms [Finished 1.172 s after backend start]
2023年06月23日T08:33:38.148Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.2 ms [Finished 1.172 s after backend start]
2023年06月23日T08:33:38.148Z root INFO Backend PluginLocalizationBackendContribution.initialize: 49.5 ms [Finished 1.173 s after backend start]
2023年06月23日T08:33:38.148Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.3 ms [Finished 1.173 s after backend start]
DEBUG IS HERE --> 2023年06月23日T08:33:38.149Z root DEBUG Starting the deployer with the list of resolvers
2023年06月23日T08:33:38.149Z root INFO Backend ElectronTokenBackendContribution.configure: 3.1 ms [Finished 1.176 s after backend start]
a.kitta@Akoss-MacBook-Pro Desktop % ./Arduino\ IDE.app/Contents/MacOS/Arduino\ IDE
Arduino IDE 2.1.1-snapshot-315e9eb
Starting backend process. PID: 66283
Using browser-only version of superagent in non-browser environment
Configuration directory URI: 'file:///Users/a.kitta/.arduinoIDE'
Configuring to accept webviews on '^.+\.webview\..+$' hostname.
2023年06月23日T08:36:37.939Z root INFO Backend Object.initialize: 5.5 ms [Finished 1.116 s after backend start]
2023年06月23日T08:36:37.941Z root INFO Backend Object.configure: 4.5 ms [Finished 1.116 s after backend start]
2023年06月23日T08:36:37.941Z root INFO Backend MessagingContribution.onStart: 1.7 ms [Finished 1.116 s after backend start]
2023年06月23日T08:36:37.942Z root INFO Backend OSBackendApplicationContribution.configure: 0.5 ms [Finished 1.165 s after backend start]
2023年06月23日T08:36:37.943Z root INFO Backend DefaultWorkspaceServer.onStart: 0.4 ms [Finished 1.166 s after backend start]
2023年06月23日T08:36:37.943Z root INFO Backend PluginLocalizationBackendContribution.configure: 0.1 ms [Finished 1.166 s after backend start]
2023年06月23日T08:36:37.944Z root INFO Backend PluginLocalizationBackendContribution.initialize: 49.4 ms [Finished 1.166 s after backend start]
2023年06月23日T08:36:37.944Z root INFO Backend TaskBackendApplicationContribution.onStart: 0.3 ms [Finished 1.166 s after backend start]
2023年06月23日T08:36:37.945Z root INFO Backend ElectronTokenBackendContribution.configure: 3.0 ms [Finished 1.169 s after backend start]

I marked the relevant line with: DEBUG IS HERE --> 2023年06月23日T08:33:38.149Z root DEBUG Starting the deployer with the list of resolvers This difference can be seen in the Windows output in #2101 (comment). The plugins loading log output is different, however. Maybe related: eclipse-theia/theia#12224.

Copy link
Contributor Author

Maybe related: eclipse-theia/theia#12224.

TheiaBlueprint 1.38.0 works as expected. Starting the app with /Applications/TheiaBlueprint\ 1.38.0.app/Contents/MacOS/TheiaBlueprint --log-level debug command produces the expected 2023年06月23日T08:05:36.505Z root DEBUG Starting the deployer with the list of resolvers log.

@kittaakos kittaakos marked this pull request as draft June 23, 2023 09:30
Copy link
Contributor Author

I have figured out the problem; IDE2 needs a better logger framework.

The current file base logger is only part of the bundled application and has the following API: log(string).

In Theia, the console's log functions (such as info, debug, etc.) are bound to the logger. They have this API: log(args[]). There is no problem when the Theia/IDE2 code logs things in this format: console.log('foo'), but it is a problem when the log is called like this: console.log('foo', 'bar'). Any log info is lost after the first arg; bar is not logged.

  • We have to fix this as soon as possible. I'd like to know how much additional information (such as error messages and stack traces) we have lost due to this flaw. Hopefully not that much. 😊
  • IDE2 must use the same file logger in debug mode or when starting the app from the source code. Otherwise, it might take a long time to notice such issues.

 - In the bundled application, the customized logger that writes the log
files bogusly includes only the first message fragment in the log
message. This PR ensures all message fragments are included in the final
message before it is printed to the console/terminal and persisted to
the rotating log files.
 - Includes messages with `debug` severity in the log.
 - Disables the ANSI coloring in the CLI daemon log by adding the
`NO_COLOR=true` environment variable to the spawned CLI daemon process.
 - Trims trailing line ending of the daemon log.
Signed-off-by: Akos Kitta <a.kitta@arduino.cc>
@kittaakos kittaakos changed the title (削除) fix(log): include debug messages in the log file (削除ここまで) (追記) fix: include all log args in the log message (追記ここまで) Jun 23, 2023
@kittaakos kittaakos changed the title (削除) fix: include all log args in the log message (削除ここまで) (追記) fix: include all log args in the log message (追記ここまで) Jun 23, 2023
@kittaakos kittaakos marked this pull request as ready for review June 23, 2023 12:41
Copy link
Contributor Author

I'm seeing a difference

So great you have found it. This was the root cause of why we've never seen the actual exception in error logs 🤦 Enabling the debug severity to get logged and using the --log-level debug revealed that some part of the message was not logged. Now, it should work. I also disabled the ANSI colors in the daemon logs. Disabling the colors automatically has changed the daemon log format. This is most likely a problem with logrus on the CLI side. I tuned the daemon log messages and trimmed the unnecessary new lines.

Please review. Thank you!

Copy link
Contributor

@per1234 per1234 left a comment

Choose a reason for hiding this comment

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

Thanks Akos!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@per1234 per1234 per1234 approved these changes

@AlbyIanna AlbyIanna Awaiting requested review from AlbyIanna

Labels
topic: code Related to content of the project itself type: imperfection Perceived defect in any part of project
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

AltStyle によって変換されたページ (->オリジナル) /